[Qemu-devel] [PATCH v2 for 2.10] iotests: fix 185

[Qemu-devel] [PATCH v2 for 2.10] iotests: fix 185

[Vladimir Sementsov-Ogievskiy]

185 can sometimes produce wrong output like this:

=========================================
185 2s ... - output mismatch (see 185.out.bad)
--- /work/src/qemu/master/tests/qemu-iotests/185.out    2017-07-14 \
    15:14:29.520343805 +0300
+++ 185.out.bad 2017-08-07 16:51:02.231922900 +0300
@@ -37,7 +37,7 @@
 {"return": {}}
 {"return": {}}
 {"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, \
     "event": "SHUTDOWN", "data": {"guest": false}}
-{"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, \
    "event": "BLOCK_JOB_CANCELLED", "data": {"device": "disk", \
        "len": 4194304, "offset": 4194304, "speed": 65536, "type": \
            "mirror"}}
+{"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, \
    "event": "BLOCK_JOB_CANCELLED", "data": {"device": "disk", \
        "len": 0, "offset": 0, "speed": 65536, "type": "mirror"}}

 === Start backup job and exit qemu ===

Failures: 185
Failed 1 of 1 tests
=========================================

This is because quite happens before first mirror request is done
(and, in specified case, even before block-job len field is set).
To prevent it let's just add a sleep for 0.3 seconds before quite.

Signed-off-by: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>
---

v2: just add a sleep instead of filtering output (proposed by Kevin)

 tests/qemu-iotests/185 | 4 ++++
 1 file changed, 4 insertions(+)

diff --git a/tests/qemu-iotests/185 b/tests/qemu-iotests/185
index 0eda371f27..f5b47e4c1a 100755
--- a/tests/qemu-iotests/185
+++ b/tests/qemu-iotests/185
@@ -156,6 +156,10 @@ _send_qemu_cmd $h \
                       'speed': 65536 } }" \
     "return"
 
+# If we don't sleep here 'quit' command may be handled before
+# the first mirror iteration is done
+sleep 0.5
+
 _send_qemu_cmd $h "{ 'execute': 'quit' }" "return"
 wait=1 _cleanup_qemu
 
-- 
2.11.1

Re: [Qemu-devel] [PATCH v2 for 2.10] iotests: fix 185

[Vladimir Sementsov-Ogievskiy]

09.08.2017 18:17, Vladimir Sementsov-Ogievskiy wrote:
> 185 can sometimes produce wrong output like this:
>
> =========================================
> 185 2s ... - output mismatch (see 185.out.bad)
> --- /work/src/qemu/master/tests/qemu-iotests/185.out    2017-07-14 \
>      15:14:29.520343805 +0300
> +++ 185.out.bad 2017-08-07 16:51:02.231922900 +0300
> @@ -37,7 +37,7 @@
>   {"return": {}}
>   {"return": {}}
>   {"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, \
>       "event": "SHUTDOWN", "data": {"guest": false}}
> -{"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, \
>      "event": "BLOCK_JOB_CANCELLED", "data": {"device": "disk", \
>          "len": 4194304, "offset": 4194304, "speed": 65536, "type": \
>              "mirror"}}
> +{"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, \
>      "event": "BLOCK_JOB_CANCELLED", "data": {"device": "disk", \
>          "len": 0, "offset": 0, "speed": 65536, "type": "mirror"}}
>
>   === Start backup job and exit qemu ===
>
> Failures: 185
> Failed 1 of 1 tests
> =========================================
>
> This is because quite happens before first mirror request is done

s/quite/quit/

> (and, in specified case, even before block-job len field is set).
> To prevent it let's just add a sleep for 0.3 seconds before quite.
>
> Signed-off-by: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>
> ---
>
> v2: just add a sleep instead of filtering output (proposed by Kevin)
>
>   tests/qemu-iotests/185 | 4 ++++
>   1 file changed, 4 insertions(+)
>
> diff --git a/tests/qemu-iotests/185 b/tests/qemu-iotests/185
> index 0eda371f27..f5b47e4c1a 100755
> --- a/tests/qemu-iotests/185
> +++ b/tests/qemu-iotests/185
> @@ -156,6 +156,10 @@ _send_qemu_cmd $h \
>                         'speed': 65536 } }" \
>       "return"
>   
> +# If we don't sleep here 'quit' command may be handled before
> +# the first mirror iteration is done
> +sleep 0.5
> +
>   _send_qemu_cmd $h "{ 'execute': 'quit' }" "return"
>   wait=1 _cleanup_qemu
>   


-- 
Best regards,
Vladimir

Re: [Qemu-devel] [PATCH v2 for 2.10] iotests: fix 185

[Eric Blake]

[-- Attachment #1: Type: text/plain, Size: 1030 bytes --]

On 08/09/2017 10:19 AM, Vladimir Sementsov-Ogievskiy wrote:
> 09.08.2017 18:17, Vladimir Sementsov-Ogievskiy wrote:
>> 185 can sometimes produce wrong output like this:
>>

>>
>> This is because quite happens before first mirror request is done
> 
> s/quite/quit/
> 
>> (and, in specified case, even before block-job len field is set).
>> To prevent it let's just add a sleep for 0.3 seconds before quite.

Here, as well.

Maybe:

This is because, under heavy load, the quit can happen before the first
iteration of the mirror request has occurred.  To make sure we've had
time to iterate, let's just add a sleep for 0.3 seconds before quitting.


>>       "return"
>>   +# If we don't sleep here 'quit' command may be handled before
>> +# the first mirror iteration is done
>> +sleep 0.5

The commit message disagrees with the code (.3 vs. .5) - which one is
correct?

-- 
Eric Blake, Principal Software Engineer
Red Hat, Inc.           +1-919-301-3266
Virtualization:  qemu.org | libvirt.org


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 619 bytes --]

Re: [Qemu-devel] [PATCH v2 for 2.10] iotests: fix 185

[Vladimir Sementsov-Ogievskiy]

09.08.2017 18:41, Eric Blake wrote:
> On 08/09/2017 10:19 AM, Vladimir Sementsov-Ogievskiy wrote:
>> 09.08.2017 18:17, Vladimir Sementsov-Ogievskiy wrote:
>>> 185 can sometimes produce wrong output like this:
>>>
>>> This is because quite happens before first mirror request is done
>> s/quite/quit/
>>
>>> (and, in specified case, even before block-job len field is set).
>>> To prevent it let's just add a sleep for 0.3 seconds before quite.
> Here, as well.
>
> Maybe:
>
> This is because, under heavy load, the quit can happen before the first
> iteration of the mirror request has occurred.  To make sure we've had
> time to iterate, let's just add a sleep for 0.3 seconds before quitting.
>
>
>>>        "return"
>>>    +# If we don't sleep here 'quit' command may be handled before
>>> +# the first mirror iteration is done
>>> +sleep 0.5
> The commit message disagrees with the code (.3 vs. .5) - which one is
> correct?
>
Let it be .5, as I've tested it.


-- 
Best regards,
Vladimir

Re: [Qemu-devel] [PATCH v2 for 2.10] iotests: fix 185

[Eric Blake]

[-- Attachment #1: Type: text/plain, Size: 1099 bytes --]

On 08/09/2017 10:57 AM, Vladimir Sementsov-Ogievskiy wrote:

>>>> This is because quite happens before first mirror request is done
>>> s/quite/quit/
>>>
>>>> (and, in specified case, even before block-job len field is set).
>>>> To prevent it let's just add a sleep for 0.3 seconds before quite.
>> Here, as well.
>>
>> Maybe:
>>
>> This is because, under heavy load, the quit can happen before the first
>> iteration of the mirror request has occurred.  To make sure we've had
>> time to iterate, let's just add a sleep for 0.3 seconds before quitting.
>>
>>
>>>>        "return"
>>>>    +# If we don't sleep here 'quit' command may be handled before
>>>> +# the first mirror iteration is done
>>>> +sleep 0.5
>> The commit message disagrees with the code (.3 vs. .5) - which one is
>> correct?
>>
> Let it be .5, as I've tested it.

With a correct commit message (maintainer can touch it up),
Reviewed-by: Eric Blake <eblake@redhat.com>

-- 
Eric Blake, Principal Software Engineer
Red Hat, Inc.           +1-919-301-3266
Virtualization:  qemu.org | libvirt.org


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 619 bytes --]

Re: [Qemu-devel] [PATCH v2 for 2.10] iotests: fix 185

[Kevin Wolf]

Am 09.08.2017 um 17:17 hat Vladimir Sementsov-Ogievskiy geschrieben:
> 185 can sometimes produce wrong output like this:
> 
> =========================================
> 185 2s ... - output mismatch (see 185.out.bad)
> --- /work/src/qemu/master/tests/qemu-iotests/185.out    2017-07-14 \
>     15:14:29.520343805 +0300
> +++ 185.out.bad 2017-08-07 16:51:02.231922900 +0300
> @@ -37,7 +37,7 @@

For next time: This commit message really confuses 'git am' because it
thinks that this is already the real patch. Indenting a quoted diff
makes it much happier, so that's what I did instead of the '===' lines.

>  {"return": {}}
>  {"return": {}}
>  {"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, \
>      "event": "SHUTDOWN", "data": {"guest": false}}
> -{"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, \
>     "event": "BLOCK_JOB_CANCELLED", "data": {"device": "disk", \
>         "len": 4194304, "offset": 4194304, "speed": 65536, "type": \
>             "mirror"}}
> +{"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, \
>     "event": "BLOCK_JOB_CANCELLED", "data": {"device": "disk", \
>         "len": 0, "offset": 0, "speed": 65536, "type": "mirror"}}
> 
>  === Start backup job and exit qemu ===
> 
> Failures: 185
> Failed 1 of 1 tests
> =========================================
> 
> This is because quite happens before first mirror request is done
> (and, in specified case, even before block-job len field is set).
> To prevent it let's just add a sleep for 0.3 seconds before quite.
> 
> Signed-off-by: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>

Thanks, touched up the commit message according to your discussion with
Eric and applied to the block branch.

Kevin