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

[Claudio Fontana]

On 7/20/20 8:24 PM, Claudio Fontana wrote:
> I have now been able to reproduce this on X86 as well.
> 
> It happens much more rarely, about once every 10 times.
> 
> I will sort out the data and try to make it even more reproducible, then post 
> my findings in detail.
> 
> Overall I proceeded as follows:
> 
> 1) hooked the savevm code to skip all fields with the exception of 
> "s390-skeys". So only s390-skeys are actually saved.
> 
> 2) reimplemented "s390-skeys" in a common implementation in cpus.c, used on 
> both x86 and s390, modeling the behaviour of save/load from hw/s390
> 
> 3) ran ./check -qcow2 267 on both x86 and s390.
> 
> In the case of s390, failure seems to be reproducible 100% of the times.
> On X86, it is as mentioned failing about 10% of the times.
> 
> Ciao,
> 
> Claudio


And here is a small series of two patches that can be used to reproduce the 
problem.

Clearly, this is not directly related to s390 or to skeys or to icount in 
particular, it is just an issue that happened to be more visible there.

If you could help with this, please apply the attached patches.

Patch 1 just adds a new "300" iotest. It is way easier to extract the relevant 
part out of test 267, which does a bit too much in the same file.
Also this allows easier use of valgrind, since it does not "require" anything.

Patch 2 hooks the savevm code to skip all fields during the snapshot with the 
exception of "s390-skeys", a new artificial field implemented to
model what the real s390-skeys is doing.

After applying patch 1 and patch 2, you can test (also on X86), with:

./check -qcow2 300

On X86 many runs will be successful, but a certain % of them will instead fail 
like this:


claudio@linux-ch70:~/git/qemu-pristine/qemu-build/tests/qemu-iotests> ./check 
-qcow2 300
QEMU          -- 
"/home/claudio/git/qemu-pristine/qemu-build/tests/qemu-iotests/../../x86_64-softmmu/qemu-system-x86_64"
 -nodefaults -display none -accel qtest
QEMU_IMG      -- 
"/home/claudio/git/qemu-pristine/qemu-build/tests/qemu-iotests/../../qemu-img" 
QEMU_IO       -- 
"/home/claudio/git/qemu-pristine/qemu-build/tests/qemu-iotests/../../qemu-io"  
--cache writeback --aio threads -f qcow2
QEMU_NBD      -- 
"/home/claudio/git/qemu-pristine/qemu-build/tests/qemu-iotests/../../qemu-nbd" 
IMGFMT        -- qcow2 (compat=1.1)
IMGPROTO      -- file
PLATFORM      -- Linux/x86_64 linux-ch70 4.12.14-lp151.28.36-default
TEST_DIR      -- 
/home/claudio/git/qemu-pristine/qemu-build/tests/qemu-iotests/scratch
SOCK_DIR      -- /tmp/tmp.gdcUu3l0SM
SOCKET_SCM_HELPER -- 
/home/claudio/git/qemu-pristine/qemu-build/tests/qemu-iotests/socket_scm_helper

300      fail       [10:14:05] [10:14:06]      (last: 0s)    output mismatch 
(see 300.out.bad)
--- /home/claudio/git/qemu-pristine/qemu/tests/qemu-iotests/300.out     
2020-07-21 10:03:54.468104764 +0200
+++ /home/claudio/git/qemu-pristine/qemu-build/tests/qemu-iotests/300.out.bad   
2020-07-21 10:14:06.098090543 +0200
@@ -12,6 +12,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 data: 0
+error while loading state for instance 0x0 of device 's390-skeys'
+Error: Error -22 while loading VM state
 (qemu) quit
 
 *** done
Failures: 300
Failed 1 of 1 iotests


At this point somebody more knowledgeable about QCOW2, coroutines and backing 
files could chime in?

Thanks,

Claudio

> 
> 
> On 7/16/20 2:58 PM, Claudio Fontana wrote:
>> Small update on this,
>>
>> On 7/15/20 1:10 PM, Claudio Fontana wrote:
>>> Hi Thomas,
>>>
>>> On 7/14/20 4:35 PM, Thomas Huth wrote:
>>>> On 14/07/2020 16.29, Claudio Fontana wrote:
>>>>> Hello,
>>>>>
>>>>> I have some tiny progress in narrowing down this issue, possibly a qcow2 
>>>>> issue, still unclear,
>>>>> but involving Kevin Wolf and Max Reitz.
>>>>>
>>>>>
>>>>> The reproducer again:
>>>>>
>>>>>> --------------------------------------------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-------------------------------------------
>>>>>
>>>>> This issue for now appears on s390 only:
>>>>>
>>>>> On s390 hardware, test 267 fails (both kvm and tcg) in the qcow2 backing 
>>>>> file part, with broken migration stream data in the s390-skeys vmsave 
>>>>> (old style).
>>>> [...]
>>>>> If someone has a good idea let me know - first attempts to reproduce on 
>>>>> x86 failed, but maybe more work could lead to it.
>>>>
>>>
>>> small update: in the GOOD case (enough padding added) a qcow_merge() is 
>>> triggered for the last write of 16202 bytes.
>>> In the BAD case (not enough padding added) a qcow_merge() is not triggered 
>>> for the last write of 16201 bytes.
>>>
>>> Note: manually flushing with qemu_fflush in s390-skeys vmsave also works 
>>> (maybe got lost in the noise).
>>>
>>>
>>>> Two questions:
>>>>
>>>> 1) Can you also reproduce the issue manually, without running iotest
>>>> 267? ... I tried, but so far I failed.
>>>
>>> Thanks for the suggestion, will try.
>>
>> Currently trying to reproduce manually an environment similar to that of the 
>> test,
>> at the moment I am not able to reproduce the issue manually.
>>
>> Not very familiar with s390,
>> I've been running with 
>>
>> export QEMU=/home/cfontana/qemu-build/s390x-softmmu/qemu-system-s390x
>>
>> $QEMU -nographic -monitor stdio -nodefaults -no-shutdown FILENAME
>>
>> where FILENAME is the qcow2 produced by the test.
>>
>> let me know if you have a suggestion on how to setup up something simple 
>> properly.
>>
>>
>>>
>>>>
>>>> 2) Since all the information so far sounds like the problem could be
>>>> elsewhere in the code, and the skeys just catch it by accident ... have
>>>> you tried running with valgrind? Maybe it catches something useful?
>>>
>>> Nothing yet, but will fiddle with the options a bit more.
>>
>> Only thing I have seen so far:
>>
>>
>> +==33321== 
>> +==33321== Warning: client switching stacks?  SP change: 0x1ffeffe5e8 --> 
>> 0x5d9cf60
>> +==33321==          to suppress, use: --max-stackframe=137324009096 or 
>> greater
>> +==33321== Warning: client switching stacks?  SP change: 0x5d9cd18 --> 
>> 0x1ffeffe5e8
>> +==33321==          to suppress, use: --max-stackframe=137324009680 or 
>> greater
>> +==33321== Warning: client switching stacks?  SP change: 0x1ffeffe8b8 --> 
>> 0x5d9ce58
>> +==33321==          to suppress, use: --max-stackframe=137324010080 or 
>> greater
>> +==33321==          further instances of this message will not be shown.
>> +==33321== Thread 4:
>> +==33321== Conditional jump or move depends on uninitialised value(s)
>> +==33321==    at 0x3AEC70: process_queued_cpu_work (cpus-common.c:331)
>> +==33321==    by 0x2753E1: qemu_wait_io_event_common (cpus.c:1213)
>> +==33321==    by 0x2755CD: qemu_wait_io_event (cpus.c:1253)
>> +==33321==    by 0x27596D: qemu_dummy_cpu_thread_fn (cpus.c:1337)
>> +==33321==    by 0x725C87: qemu_thread_start (qemu-thread-posix.c:521)
>> +==33321==    by 0x4D504E9: start_thread (in /lib64/libpthread-2.26.so)
>> +==33321==    by 0x4E72BBD: ??? (in /lib64/libc-2.26.so)
>> +==33321== 
>> +==33321== Conditional jump or move depends on uninitialised value(s)
>> +==33321==    at 0x3AEC74: process_queued_cpu_work (cpus-common.c:331)
>> +==33321==    by 0x2753E1: qemu_wait_io_event_common (cpus.c:1213)
>> +==33321==    by 0x2755CD: qemu_wait_io_event (cpus.c:1253)
>> +==33321==    by 0x27596D: qemu_dummy_cpu_thread_fn (cpus.c:1337)
>> +==33321==    by 0x725C87: qemu_thread_start (qemu-thread-posix.c:521)
>> +==33321==    by 0x4D504E9: start_thread (in /lib64/libpthread-2.26.so)
>> +==33321==    by 0x4E72BBD: ??? (in /lib64/libc-2.26.so)
>> +==33321== 
>> +==33321== 
>> +==33321== HEAP SUMMARY:
>> +==33321==     in use at exit: 2,138,442 bytes in 13,935 blocks
>> +==33321==   total heap usage: 19,089 allocs, 5,154 frees, 5,187,670 bytes 
>> allocated
>> +==33321== 
>> +==33321== LEAK SUMMARY:
>> +==33321==    definitely lost: 0 bytes in 0 blocks
>> +==33321==    indirectly lost: 0 bytes in 0 blocks
>> +==33321==      possibly lost: 7,150 bytes in 111 blocks
>> +==33321==    still reachable: 2,131,292 bytes in 13,824 blocks
>> +==33321==         suppressed: 0 bytes in 0 blocks
>> +==33321== Rerun with --leak-check=full to see details of leaked memory
>>
>>
>>>
>>>>
>>>>  Thomas
>>>>
>>>
>>> Ciao,
>>>
>>> Claudio
>>>
>>>
>>
>> A more interesting update is what follows I think.
>>
>> I was able to "fix" the problem shown by the reproducer:
>>
>> @@ -643,7 +643,7 @@ static void qemu_account_warp_tim@@ -643,7 +643,7 @@ 
>> static void qemu_account_warp_timer(void)
>>  
>>  static bool icount_state_needed(void *opaque)
>>  {
>> -    return use_icount;
>> +    return 0;
>>  }
>>  
>> by just slowing down qcow2_co_pwritev_task_entry with some tight loops,
>> without changing any fields between runs (other than the reproducer icount 
>> field removal).
>>
>> I tried to insert the same slowdown just in savevm.c at the end of 
>> save_snapshot, but that does not work, needs to be in the coroutine.
>>
>> Thanks,
>>
>> Claudio
>>
>>
> 
>

0002-XXX-reproducer-for-backing-file-migration-test-issue.patch
Description: Text Data

0001-iotests-300-new-test-for-catching-backing-file-migra.patch
Description: Text Data