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

[Claudio Fontana <cfontana@suse.de>]

On 7/13/20 1:39 PM, Claudio Fontana wrote:
> Hello,
> 
> On 7/13/20 1:03 PM, Dr. David Alan Gilbert wrote:
>> * Claudio Fontana (cfontana@suse.de) wrote:
>>> 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;
>>>  }
>>
>> That's weird; I mean that's just turning a subsection on and off;
>> so you'd hope if this is a test that generates it's own snapshot and
>> then uses it then it should be consistent.
> 
> Indeed.
> 
>>
>>>  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?
>>
>> I didn't think it was required.
>> And qemu_put_buffer loops if needed and calls qemu_fflush internally.
> 
> This detail probably does not help in this case, because the buffer itself is fine (32678 zero bytes is actually correct).
> 
> The End Of Stream marker written just after with qemu_put_be64 is not ok,
> and anything past that point is just a whole bunch of zeroes in the stream when we hookup the calls to
> 
> qcow2_co_pwritev_task and qcow2_co_preadv_task
> 
> (see my response to Paolo in this thread).
> 
> 
>> It's possible here that the storage key code is just the canary - the
>> first thing that detects that the stream is invalid after it all goes
>> wrong.
> 
> Seems the exact opposite to me, ie, the stream seems just fine up to the point where the EOS marker after the keydata in "s390-skeys" should be.

Ah I might have misunderstood what you wrote there, you mean that the stream became invalid, and this just happened in the context of s390-skeys right..

To me it also looks like an underlying issue, not really related to skeys in particular, just that they exercise the underlying machinery is a very peculiar way,
in terms or field positions, sizes etc.

Ciao,

Claudio

> 
> Thanks!
> 
> Claudio
> 
>>
>> Dave
>>
>>
>>> Thanks,
>>>
>>> Claudio
>>>
>>>
>>> -- 
>>> Claudio Fontana
>>> Engineering Manager Virtualization, SUSE Labs Core
>>>
>>> SUSE Software Solutions Italy Srl
>>>
>> --
>> Dr. David Alan Gilbert / dgilbert@redhat.com / Manchester, UK
>>
>>
> 
>