migration: broken snapshot saves appear on s390 when small fields in migration stream removed

[Claudio Fontana <cfontana@suse.de>]

Hello all,

during unrelated work for splitting QTest from the TCG instruction counting module,

I encountered what seems to be a migration stream issue, which is apparent only on s390, and only shows in block test 267.

./check -qcow2 267

when it comes to snapshot save and load using backing file.

Here is a minimal reproducer patch that causes the issue on s390 only.

--------------------------------------------cut-------------------------------------------
diff --git a/cpus.c b/cpus.c
index 41d1c5099f..443b88697a 100644
--- a/cpus.c
+++ b/cpus.c
@@ -643,7 +643,7 @@ static void qemu_account_warp_timer(void)
 
 static bool icount_state_needed(void *opaque)
 {
-    return use_icount;
+    return 0;
 }
 
 static bool warp_timer_state_needed(void *opaque)
--------------------------------------------cut-------------------------------------------

config.status configure line:
exec '/home/cfontana/qemu-build/../qemu/configure' '--enable-tcg' '--disable-kvm' '--disable-hax' '--target-list=s390x-softmmu' '--enable-debug'

$ make check-block

TEST    iotest-qcow2: 267 [fail]
QEMU          -- "/home/cfontana/qemu-build/tests/qemu-iotests/../../s390x-softmmu/qemu-system-s390x" -nodefaults -display none -accel qtest
QEMU_IMG      -- "/home/cfontana/qemu-build/tests/qemu-iotests/../../qemu-img" 
QEMU_IO       -- "/home/cfontana/qemu-build/tests/qemu-iotests/../../qemu-io"  --cache writeback --aio threads -f qcow2
QEMU_NBD      -- "/home/cfontana/qemu-build/tests/qemu-iotests/../../qemu-nbd" 
IMGFMT        -- qcow2 (compat=1.1)
IMGPROTO      -- file
PLATFORM      -- Linux/s390x s390zp13 5.3.18-21-default
TEST_DIR      -- /home/cfontana/qemu-build/tests/qemu-iotests/scratch
SOCK_DIR      -- /tmp/tmp.bLJcJVtzk5
SOCKET_SCM_HELPER -- /home/cfontana/qemu-build/tests/qemu-iotests/socket_scm_helper

--- /home/cfontana/qemu/tests/qemu-iotests/267.out	2020-07-12 05:10:07.948262675 -0400
+++ /home/cfontana/qemu-build/tests/qemu-iotests/267.out.bad	2020-07-12 05:27:03.358362781 -0400
@@ -137,6 +137,9 @@
 ID        TAG                 VM SIZE                DATE       VM CLOCK
 --        snap0                  SIZE yyyy-mm-dd hh:mm:ss   00:00:00.000
 (qemu) loadvm snap0
+Unexpected storage key flag data: 0
+error while loading state for instance 0x0 of device 's390-skeys'
+Error: Error -22 while loading VM state
 (qemu) quit
 
 
-----------


Not run: 172 186 192 259 287
Failures: 267
Failed 1 of 115 iotests
make: *** [/home/cfontana/qemu/tests/Makefile.include:880: check-tests/check-block.sh] Error 1

-----------

Note: only the === -blockdev with a backing file === part of test 267 fails. -blockdev with NBD is ok, like all the rest.


Interesting facts about s390 in particular: its save/load code includes the transfer of "storage keys",
which include a buffer of 32768 bytes of keydata in the stream.

The code (hw/s390x/s390-skeys.c),
is modeled similarly to RAM transfer (like in migration/ram.c), with an EOS (end of stream) marker.

Countrary to RAM transfer code though, after qemu_put_be64(f, EOS), the s390 code does not qemu_fflush(f).

----------
Observation: the migration/qemu-file.c shows an IO_BUF_SIZE of 32768.

--

The following workarounds hide the problem (make the test pass):

1) always including the icount field in the (unrelated) timers field that are sent before in the migration stream (ie not applying the reproducer patch).

2) increasing the IO_BUF_SIZE also hides the problem:

----------------------cut--------------------------
diff --git a/migration/qemu-file.c b/migration/qemu-file.c
index be21518c57..f81d1272eb 100644
--- a/migration/qemu-file.c
+++ b/migration/qemu-file.c
@@ -30,7 +30,7 @@
 #include "trace.h"
 #include "qapi/error.h"
 
-#define IO_BUF_SIZE 32768
+#define IO_BUF_SIZE 65536
 #define MAX_IOV_SIZE MIN_CONST(IOV_MAX, 64)
 
 struct QEMUFile {
----------------------cut--------------------------

3) adding a qemu_fflush in hw/s390x/s390-skeys.c after EOS also "fixes" the problem:

----------------------cut--------------------------
diff --git a/hw/s390x/s390-skeys.c b/hw/s390x/s390-skeys.c
index 1e036cc602..47c9a015af 100644
--- a/hw/s390x/s390-skeys.c
+++ b/hw/s390x/s390-skeys.c
@@ -252,6 +252,8 @@ static const TypeInfo qemu_s390_skeys_info = {
     .class_size    = sizeof(S390SKeysClass),
 };
 
+extern void qemu_fflush(QEMUFile *f);
+
 static void s390_storage_keys_save(QEMUFile *f, void *opaque)
 {
     S390SKeysState *ss = S390_SKEYS(opaque);
@@ -302,6 +304,7 @@ static void s390_storage_keys_save(QEMUFile *f, void *opaque)
     g_free(buf);
 end_stream:
     qemu_put_be64(f, eos);
+    qemu_fflush(f);
 }
 
 static int s390_storage_keys_load(QEMUFile *f, void *opaque, int version_id)
----------------------cut--------------------------

Do any of you with better understanding of migration/, block and s390 have a suggestion on what could be the issue here,
and what could be the next step in the investigation?

Is the fact that migration/ram.c always does fflush after writing the EOS have any relevance here? why does it do it,
and should s390 code also follow the same pattern?

Thanks,

Claudio


-- 
Claudio Fontana
Engineering Manager Virtualization, SUSE Labs Core

SUSE Software Solutions Italy Srl