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
On 12/07/20 12:00, Claudio Fontana wrote: > 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). 1) Are there unexpected differences in the migration stream? That is, you could modify qcow2.c to fopen/fwrite/fclose the bytes as they're written and read, and see if something does not match. 2) If it matches, are there unexpected differences other than the lack of icount section when you apply the reproducer patch? The fflush part makes me put more hope in the first, but both could help you debug it. Thanks, Paolo
Hi Paolo,
On 7/12/20 6:11 PM, Paolo Bonzini wrote:
> On 12/07/20 12:00, Claudio Fontana wrote:
>> 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).
>
> 1) Are there unexpected differences in the migration stream? That is,
> you could modify qcow2.c to fopen/fwrite/fclose the bytes as they're
> written and read, and see if something does not match.
I hooked qcow2_co_pwritev_task and qcow2_co_preadv_task to also write to an external file using your suggestion.
I am seeing very interesting differences with and without the reproducer patch (ie, forcing icount_state_needed to 0 or not):
* without the reproducer patch, everything past the s390-skeys data field is in order: there is the EOS, and then the next idstr follows ("cpu_common").
* with the reproducer patch, every single byte past the s390-skeys data field is ZERO. There is no EOS, there is no next idstr "cpu_common", there is absolutely nothing else than zeroes until the end of the file.
>
> 2) If it matches, are there unexpected differences other than the lack
> of icount section when you apply the reproducer patch?
they do not match at all.
>
> The fflush part makes me put more hope in the first, but both could help
> you debug it.
>
> Thanks,
>
> Paolo
>
Thanks,
Claudio
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).
What is new?
It is possible to work around the problem by adding back to the stream simply by extending, for example, the existing UNUSED field in the timers vmstate.
So this "fixes it", applied on top of the reproducer:
--------------------------------------------cut-------------------------------------------
@@ -728,7 +728,7 @@ static const VMStateDescription vmstate_timers = {
.minimum_version_id = 1,
.fields = (VMStateField[]) {
VMSTATE_INT64(cpu_ticks_offset, TimersState),
- VMSTATE_UNUSED(8),
+ VMSTATE_UNUSED(119),
VMSTATE_INT64_V(cpu_clock_offset, TimersState, 2),
VMSTATE_END_OF_LIST()
},
--------------------------------------------cut-------------------------------------------
NB: Exactly 111 bytes need to be added, not one byte less.
Using VMSTATE_UNUSED(118) again breaks.
Using VMSTATE_UNUSED(120) or more is _fine_. Seems that a certain threshold needs to be reached in the stream, before the transfer of old style vmsave fields in s390-skeys is successful.
So here is the output, with some logging, of the VMSTATE_UNUSED(118) run (FAILURE, marked by error "-22"), followed by the VMSTATE_UNUSED(119) run (SUCCESS).
qemu_fflush logs when called, as well as s390 save key code, just before and just after writing the skey fields.
VMSTATE_UNUSED(118):
QA output created by 267
=== -blockdev with a backing file ===
Formatting 'TEST_DIR/t.IMGFMT.base', fmt=IMGFMT size=134217728
Formatting 'TEST_DIR/t.IMGFMT', fmt=IMGFMT size=134217728 backing_file=TEST_DIR/t.IMGFMT.base
Testing: -blockdev driver=file,filename=TEST_DIR/t.IMGFMT.base,node-name=backing-file -blockdev driver=file,filename=TEST_DIR/t.IMGFMT,node-name=file -blockdev driver=IMGFMT,file=file,backing=backing-file,node-name=fmt
QEMU X.Y.Z monitor - type 'help' for more information
(qemu) savevm snap0
qemu_fflush: written: 82, expected: 82 - done.
qemu_fflush: written: 78, expected: 78 - done.
qemu_fflush: - done.
qemu_fflush: written: 32768, expected: 32768 - done.
qemu_fflush: written: 32768, expected: 32768 - done.
qemu_fflush: written: 32768, expected: 32768 - done.
qemu_fflush: written: 32768, expected: 32768 - done.
qemu_fflush: written: 32768, expected: 32768 - done.
qemu_fflush: written: 32768, expected: 32768 - done.
qemu_fflush: written: 32768, expected: 32768 - done.
qemu_fflush: written: 32768, expected: 32768 - done.
qemu_fflush: written: 81907, expected: 81907 - done.
qemu_fflush: written: 36, expected: 36 - done.
saving keys to stream...
bytes_xfer=344418 xfer_limit=0 pos=344247 buf_index=331 buf_size=0
iov cnt=1
[0] base=0x2aa38733778 len=331 [~]
qemu_fflush: written: 32768, expected: 32768 - done.
saved keys to stream.
bytes_xfer=377210 xfer_limit=0 pos=377015 buf_index=355 buf_size=0
iov cnt=1
[0] base=0x2aa38733778 len=355 []
qemu_fflush: written: 16201, expected: 16201 - done.
qemu_fflush: - done.
qemu_fflush: - done.
(qemu) info snapshots
List of snapshots present on all disks:
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'
qemu_fflush: not writable!
Error: Error -22 while loading VM state
(qemu) quit
*** done
===================================================================================================================================
VMSTATE_UNUSED(119):
QA output created by 267
=== -blockdev with a backing file ===
Formatting 'TEST_DIR/t.IMGFMT.base', fmt=IMGFMT size=134217728
Formatting 'TEST_DIR/t.IMGFMT', fmt=IMGFMT size=134217728 backing_file=TEST_DIR/t.IMGFMT.base
Testing: -blockdev driver=file,filename=TEST_DIR/t.IMGFMT.base,node-name=backing-file -blockdev driver=file,filename=TEST_DIR/t.IMGFMT,node-name=file -blockdev driver=IMGFMT,file=file,backing=backing-file,node-name=fmt
QEMU X.Y.Z monitor - type 'help' for more information
(qemu) savevm snap0
qemu_fflush: written: 82, expected: 82 - done.
qemu_fflush: written: 78, expected: 78 - done.
qemu_fflush: - done.
qemu_fflush: written: 32768, expected: 32768 - done.
qemu_fflush: written: 32768, expected: 32768 - done.
qemu_fflush: written: 32768, expected: 32768 - done.
qemu_fflush: written: 32768, expected: 32768 - done.
qemu_fflush: written: 32768, expected: 32768 - done.
qemu_fflush: written: 32768, expected: 32768 - done.
qemu_fflush: written: 32768, expected: 32768 - done.
qemu_fflush: written: 32768, expected: 32768 - done.
qemu_fflush: written: 81907, expected: 81907 - done.
qemu_fflush: written: 36, expected: 36 - done.
saving keys to stream...
bytes_xfer=344419 xfer_limit=0 pos=344247 buf_index=332 buf_size=0
iov cnt=1
[0] base=0x2aa1bc41778 len=332 [~]
qemu_fflush: written: 32768, expected: 32768 - done.
saved keys to stream.
bytes_xfer=377211 xfer_limit=0 pos=377015 buf_index=356 buf_size=0
iov cnt=1
[0] base=0x2aa1bc41778 len=356 []
qemu_fflush: written: 16202, expected: 16202 - done.
qemu_fflush: - done.
qemu_fflush: - done.
(qemu) info snapshots
List of snapshots present on all disks:
=================================================
Here is the diff between failed and successful runs:
--- bad_extra_118.txt 2020-07-14 09:52:48.054023509 -0400
+++ good_extra_119.txt 2020-07-14 09:48:30.823977732 -0400
@@ -21,17 +21,17 @@
qemu_fflush: written: 81907, expected: 81907 - done.
qemu_fflush: written: 36, expected: 36 - done.
saving keys to stream...
-bytes_xfer=344418 xfer_limit=0 pos=344247 buf_index=331 buf_size=0
+bytes_xfer=344419 xfer_limit=0 pos=344247 buf_index=332 buf_size=0
iov cnt=1
-[0] base=0x2aa38733778 len=331 [~]
+[0] base=0x2aa1bc41778 len=332 [~]
qemu_fflush: written: 32768, expected: 32768 - done.
saved keys to stream.
-bytes_xfer=377210 xfer_limit=0 pos=377015 buf_index=355 buf_size=0
+bytes_xfer=377211 xfer_limit=0 pos=377015 buf_index=356 buf_size=0
iov cnt=1
-[0] base=0x2aa38733778 len=355 []
+[0] base=0x2aa1bc41778 len=356 []
-qemu_fflush: written: 16201, expected: 16201 - done.
+qemu_fflush: written: 16202, expected: 16202 - done.
qemu_fflush: - done.
qemu_fflush: - done.
(qemu) info snapshots
@@ -39,10 +39,7 @@
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'
qemu_fflush: not writable!
-Error: Error -22 while loading VM state
(qemu) quit
*** done
=================================================
If someone has a good idea let me know - first attempts to reproduce on x86 failed, but maybe more work could lead to it.
Thanks,
Claudio
On 7/13/20 11:11 AM, Claudio Fontana wrote:
> Hi Paolo,
>
> On 7/12/20 6:11 PM, Paolo Bonzini wrote:
>> On 12/07/20 12:00, Claudio Fontana wrote:
>>> 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).
>>
>> 1) Are there unexpected differences in the migration stream? That is,
>> you could modify qcow2.c to fopen/fwrite/fclose the bytes as they're
>> written and read, and see if something does not match.
>
> I hooked qcow2_co_pwritev_task and qcow2_co_preadv_task to also write to an external file using your suggestion.
>
> I am seeing very interesting differences with and without the reproducer patch (ie, forcing icount_state_needed to 0 or not):
>
> * without the reproducer patch, everything past the s390-skeys data field is in order: there is the EOS, and then the next idstr follows ("cpu_common").
>
> * with the reproducer patch, every single byte past the s390-skeys data field is ZERO. There is no EOS, there is no next idstr "cpu_common", there is absolutely nothing else than zeroes until the end of the file.
>
>
>>
>> 2) If it matches, are there unexpected differences other than the lack
>> of icount section when you apply the reproducer patch?
>
> they do not match at all.
>
>
>>
>> The fflush part makes me put more hope in the first, but both could help
>> you debug it.
>>
>> Thanks,
>>
>> Paolo
>>
>
> Thanks,
>
> Claudio
>
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.
Two questions:
1) Can you also reproduce the issue manually, without running iotest
267? ... I tried, but so far I failed.
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?
Thomas
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.
>
> 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.
>
> Thomas
>
Ciao,
Claudio
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.
I am talking about merge_cow() here, and it is more complicated. Will post a better explanation later on.
>
> Note: manually flushing with qemu_fflush in s390-skeys vmsave also works (maybe got lost in the noise).
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
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
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
>
>
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
>>
>>
>
>
On Tue, 2020-07-21 at 10:22 +0200, Claudio Fontana wrote:
> 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?
>
<trim>
I used the reproducer you provide here to do a git bisect as I assume
whatever is now broken wasn't always broken, and it pointed to the
following commit:
commit df893d25ceea3c0dcbe6d6b425309317fab6b22e (refs/bisect/bad)
Author: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>
Date: Tue Jun 4 19:15:13 2019 +0300
block/qcow2: implement .bdrv_co_preadv_part
Indeed, I am currently able to reliable reproduce the issue with this
commit applied, and not reproduce it without it.
That said, I've not been able to identify exactly what is going wrong.
I'm fairly confident the savevm data is correctly written out, but on
the loadvm side, somehow the last part of the s390 data is not
correctly read in the data (it's in the second pass through the while
loop in qcow2_co_preadv_part() where that happens.)
If anyone familiar with this code can have a look or provide some
pointers, it would be much appreciated.
Adding commit author to CC.
Thanks,
Bruce
28.07.2020 02:09, Bruce Rogers wrote: > On Tue, 2020-07-21 at 10:22 +0200, Claudio Fontana wrote: >> 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? >> > <trim> > > I used the reproducer you provide here to do a git bisect as I assume > whatever is now broken wasn't always broken, and it pointed to the > following commit: > > commit df893d25ceea3c0dcbe6d6b425309317fab6b22e (refs/bisect/bad) > Author: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com> > Date: Tue Jun 4 19:15:13 2019 +0300 > > block/qcow2: implement .bdrv_co_preadv_part > > Indeed, I am currently able to reliable reproduce the issue with this > commit applied, and not reproduce it without it. > > That said, I've not been able to identify exactly what is going wrong. > I'm fairly confident the savevm data is correctly written out, but on > the loadvm side, somehow the last part of the s390 data is not > correctly read in the data (it's in the second pass through the while > loop in qcow2_co_preadv_part() where that happens.) > > If anyone familiar with this code can have a look or provide some > pointers, it would be much appreciated. > > Adding commit author to CC. Ooops :) I'll look at it of course. -- Best regards, Vladimir
28.07.2020 02:09, Bruce Rogers wrote:
> On Tue, 2020-07-21 at 10:22 +0200, Claudio Fontana wrote:
>> 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?
>>
> <trim>
>
> I used the reproducer you provide here to do a git bisect as I assume
> whatever is now broken wasn't always broken, and it pointed to the
> following commit:
>
> commit df893d25ceea3c0dcbe6d6b425309317fab6b22e (refs/bisect/bad)
> Author: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>
> Date: Tue Jun 4 19:15:13 2019 +0300
>
> block/qcow2: implement .bdrv_co_preadv_part
>
> Indeed, I am currently able to reliable reproduce the issue with this
> commit applied, and not reproduce it without it.
Do you have a reproducer on top of df893d25ceea? I tried to apply the patches on it, there are a lot of conflicts and after solving them, the test not work for me.
What do you mean by not reproduce without df893d25ceea3c0d? I also tried to do "git rebase df893d25ceea3c0d --onto df893d25ceea3c0d^", after applying the reproducing patches on master, but again, there are conflicts..
How did you applied
commit 88f468e54696cd9ffc28ecf96f18f04125402541
Author: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>
Date: Mon Sep 16 20:53:22 2019 +0300
block/qcow2: refactor qcow2_co_preadv_part
and, which is more important further
commit d710cf575ad5fb3ab329204620de45bfe50caa53
Author: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>
Date: Mon Sep 16 20:53:24 2019 +0300
block/qcow2: introduce parallel subrequest handling in read and write
without df893d25ceea3c0d ?
I can reproduce the bug on master with Claudio's two patches, but how to reproduce the relation with df893d25ceea3c0d?
>
> That said, I've not been able to identify exactly what is going wrong.
> I'm fairly confident the savevm data is correctly written out, but on
> the loadvm side, somehow the last part of the s390 data is not
> correctly read in the data (it's in the second pass through the while
> loop in qcow2_co_preadv_part() where that happens.)
>
> If anyone familiar with this code can have a look or provide some
> pointers, it would be much appreciated.
>
--
Best regards,
Vladimir
On Tue, 2020-07-28 at 11:43 +0300, Vladimir Sementsov-Ogievskiy wrote: > 28.07.2020 02:09, Bruce Rogers wrote: > > On Tue, 2020-07-21 at 10:22 +0200, Claudio Fontana wrote: > > > 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? > > > > > <trim> > > > > I used the reproducer you provide here to do a git bisect as I > > assume > > whatever is now broken wasn't always broken, and it pointed to the > > following commit: > > > > commit df893d25ceea3c0dcbe6d6b425309317fab6b22e (refs/bisect/bad) > > Author: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com> > > Date: Tue Jun 4 19:15:13 2019 +0300 > > > > block/qcow2: implement .bdrv_co_preadv_part > > > > Indeed, I am currently able to reliable reproduce the issue with > > this > > commit applied, and not reproduce it without it. > > Do you have a reproducer on top of df893d25ceea? I tried to apply the > patches on it, there are a lot of conflicts and after solving them, > the test not work for me. > > What do you mean by not reproduce without df893d25ceea3c0d? I also > tried to do "git rebase df893d25ceea3c0d --onto df893d25ceea3c0d^", > after applying the reproducing patches on master, but again, there > are conflicts.. > > How did you applied > > commit 88f468e54696cd9ffc28ecf96f18f04125402541 > Author: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com> > Date: Mon Sep 16 20:53:22 2019 +0300 > > block/qcow2: refactor qcow2_co_preadv_part > > and, which is more important further > > commit d710cf575ad5fb3ab329204620de45bfe50caa53 > Author: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com> > Date: Mon Sep 16 20:53:24 2019 +0300 > > block/qcow2: introduce parallel subrequest handling in read and > write > > without df893d25ceea3c0d ? > > > I can reproduce the bug on master with Claudio's two patches, but how > to reproduce the relation with df893d25ceea3c0d? > > Yeah, I didn't provide full reproducer info for the point where the patch I mention got applied. No matter, it looks like a fix has been identified in the mean time. Thanks for the quick response, though. Bruce
On 28.07.20 01:09, Bruce Rogers wrote: > On Tue, 2020-07-21 at 10:22 +0200, Claudio Fontana wrote: >> 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? >> > <trim> > > I used the reproducer you provide here to do a git bisect as I assume > whatever is now broken wasn't always broken, and it pointed to the > following commit: > > commit df893d25ceea3c0dcbe6d6b425309317fab6b22e (refs/bisect/bad) > Author: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com> > Date: Tue Jun 4 19:15:13 2019 +0300 > > block/qcow2: implement .bdrv_co_preadv_part > > Indeed, I am currently able to reliable reproduce the issue with this > commit applied, and not reproduce it without it. > > That said, I've not been able to identify exactly what is going wrong. > I'm fairly confident the savevm data is correctly written out, but on > the loadvm side, somehow the last part of the s390 data is not > correctly read in the data (it's in the second pass through the while > loop in qcow2_co_preadv_part() where that happens.) > > If anyone familiar with this code can have a look or provide some > pointers, it would be much appreciated. Thanks for both your investigation. Does the attached patch help? Max
28.07.2020 14:10, Max Reitz wrote:
> On 28.07.20 01:09, Bruce Rogers wrote:
>> On Tue, 2020-07-21 at 10:22 +0200, Claudio Fontana wrote:
>>> 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?
>>>
>> <trim>
>>
>> I used the reproducer you provide here to do a git bisect as I assume
>> whatever is now broken wasn't always broken, and it pointed to the
>> following commit:
>>
>> commit df893d25ceea3c0dcbe6d6b425309317fab6b22e (refs/bisect/bad)
>> Author: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>
>> Date: Tue Jun 4 19:15:13 2019 +0300
>>
>> block/qcow2: implement .bdrv_co_preadv_part
>>
>> Indeed, I am currently able to reliable reproduce the issue with this
>> commit applied, and not reproduce it without it.
>>
>> That said, I've not been able to identify exactly what is going wrong.
>> I'm fairly confident the savevm data is correctly written out, but on
>> the loadvm side, somehow the last part of the s390 data is not
>> correctly read in the data (it's in the second pass through the while
>> loop in qcow2_co_preadv_part() where that happens.)
>>
>> If anyone familiar with this code can have a look or provide some
>> pointers, it would be much appreciated.
>
> Thanks for both your investigation. Does the attached patch help?
>
> Max
>
Oh, I'm stupid. Great bug!
So (at least what you fix, not sure about reported bug, but it seems very close),
it's a degradation in
commit 65cd4424b9df03bb5195351c33e04cbbecc0705c
Author: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>
Date: Tue Jun 4 19:15:09 2019 +0300
block/io: bdrv_aligned_preadv: use and support qiov_offset
And broken since 4.2...
--
Best regards,
Vladimir
28.07.2020 14:10, Max Reitz wrote: > On 28.07.20 01:09, Bruce Rogers wrote: >> On Tue, 2020-07-21 at 10:22 +0200, Claudio Fontana wrote: >>> 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? >>> >> <trim> >> >> I used the reproducer you provide here to do a git bisect as I assume >> whatever is now broken wasn't always broken, and it pointed to the >> following commit: >> >> commit df893d25ceea3c0dcbe6d6b425309317fab6b22e (refs/bisect/bad) >> Author: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com> >> Date: Tue Jun 4 19:15:13 2019 +0300 >> >> block/qcow2: implement .bdrv_co_preadv_part >> >> Indeed, I am currently able to reliable reproduce the issue with this >> commit applied, and not reproduce it without it. >> >> That said, I've not been able to identify exactly what is going wrong. >> I'm fairly confident the savevm data is correctly written out, but on >> the loadvm side, somehow the last part of the s390 data is not >> correctly read in the data (it's in the second pass through the while >> loop in qcow2_co_preadv_part() where that happens.) >> >> If anyone familiar with this code can have a look or provide some >> pointers, it would be much appreciated. > > Thanks for both your investigation. Does the attached patch help? > For me, the reproducer is fixed with your patch. -- Best regards, Vladimir
On 28/07/20 13:33, Vladimir Sementsov-Ogievskiy wrote: >> Thanks for both your investigation. Does the attached patch help? > > For me, the reproducer is fixed with your patch. Is it possible to make a quick testcase using qemu-io? Paolo
On 28.07.20 13:35, Paolo Bonzini wrote: > On 28/07/20 13:33, Vladimir Sementsov-Ogievskiy wrote: >>> Thanks for both your investigation. Does the attached patch help? >> >> For me, the reproducer is fixed with your patch. > > Is it possible to make a quick testcase using qemu-io? This seems to work: $ qemu-img create -f qcow2 -o cluster_size=512 base.qcow2 512 $ qemu-img create -f qcow2 -o cluster_size=512 -F qcow2 -b base.qcow2 \ top.qcow2 1024 $ qemu-io -c 'write -P 42 0 512' top.qcow2 $ qemu-io -c 'read -v 0 1024' top.qcow2 That should print 512 times “2a” and then 512 times “00”, but beyond 512, the buffer stays uninitialized; instead, the first 512 bytes are zeroed. (With the patch, it works as expected.)
On 28/07/20 13:45, Max Reitz wrote: >> Is it possible to make a quick testcase using qemu-io? > This seems to work: > > $ qemu-img create -f qcow2 -o cluster_size=512 base.qcow2 512 > $ qemu-img create -f qcow2 -o cluster_size=512 -F qcow2 -b base.qcow2 \ > top.qcow2 1024 > $ qemu-io -c 'write -P 42 0 512' top.qcow2 > $ qemu-io -c 'read -v 0 1024' top.qcow2 > > That should print 512 times “2a” and then 512 times “00”, but beyond > 512, the buffer stays uninitialized; instead, the first 512 bytes are > zeroed. (With the patch, it works as expected.) > Wow, that's great (and a good recipe for qemu-iotests too). Thanks. Paolo
On 7/28/20 1:10 PM, Max Reitz wrote: > On 28.07.20 01:09, Bruce Rogers wrote: >> On Tue, 2020-07-21 at 10:22 +0200, Claudio Fontana wrote: >>> 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? >>> >> <trim> >> >> I used the reproducer you provide here to do a git bisect as I assume >> whatever is now broken wasn't always broken, and it pointed to the >> following commit: >> >> commit df893d25ceea3c0dcbe6d6b425309317fab6b22e (refs/bisect/bad) >> Author: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com> >> Date: Tue Jun 4 19:15:13 2019 +0300 >> >> block/qcow2: implement .bdrv_co_preadv_part >> >> Indeed, I am currently able to reliable reproduce the issue with this >> commit applied, and not reproduce it without it. >> >> That said, I've not been able to identify exactly what is going wrong. >> I'm fairly confident the savevm data is correctly written out, but on >> the loadvm side, somehow the last part of the s390 data is not >> correctly read in the data (it's in the second pass through the while >> loop in qcow2_co_preadv_part() where that happens.) >> >> If anyone familiar with this code can have a look or provide some >> pointers, it would be much appreciated. > > Thanks for both your investigation. Does the attached patch help? > > Max > Hello Max, yes, this solves the problem everywhere (on s390, on X86, based on all the reproducers so far). Thanks a lot for the help! Claudio
* 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.
> 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.
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.
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
On Mon, 13 Jul 2020 12:03:33 +0100
"Dr. David Alan Gilbert" <dgilbert@redhat.com> wrote:
> * Claudio Fontana (cfontana@suse.de) wrote:
> > 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.
> 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.
Yes, that seems possible. Especially as we end up with all zeroes after
the skeys section in the bad case -- it seems like weird problem to
have to be cured by an individual device. No good idea *what* actually
goes wrong, though.
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.
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
>
>
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
>>
>>
>
>
© 2016 - 2024 Red Hat, Inc.