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

[Claudio Fontana]

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
>>
>>
> 
>