Re: [Qemu-block] [PATCH 1/2] qemu-iotests: reduce chance of races in 185

[Stefan Hajnoczi]

On Fri, May 04, 2018 at 08:43:43PM +0300, Vladimir Sementsov-Ogievskiy wrote:
> 04.05.2018 18:50, Stefan Hajnoczi wrote:
> > Commit 8565c3ab537e78f3e69977ec2c609dc9417a806e ("qemu-iotests: fix
> > 185") identified a race condition in a sub-test.
> > 
> > Similar issues also affect the other sub-tests.  If disk I/O completes
> > quickly, it races with the QMP 'quit' command.  This causes spurious
> > test failures because QMP events are emitted in an unpredictable order.
> > 
> > This test relies on QEMU internals and there is no QMP API for getting
> > deterministic behavior needed to make this test 100% reliable.  At the
> > same time, the test is useful and it would be a shame to remove it.
> > 
> > Add sleep 0.5 to reduce the chance of races.  This is not a real fix but
> > appears to reduce spurious failures in practice.
> > 
> > Cc: Vladimir Sementsov-Ogievskiy <address@hidden>
> > Signed-off-by: Stefan Hajnoczi <address@hidden>
> > ---
> >   tests/qemu-iotests/185     | 12 ++++++++++++
> >   tests/qemu-iotests/185.out |  4 ++--
> >   2 files changed, 14 insertions(+), 2 deletions(-)
> > 
> > diff --git a/tests/qemu-iotests/185 b/tests/qemu-iotests/185
> > index 298d88d04e..975404c99d 100755
> > --- a/tests/qemu-iotests/185
> > +++ b/tests/qemu-iotests/185
> > @@ -118,6 +118,9 @@ _send_qemu_cmd $h \
> >                         'speed': 65536 } }" \
> >       "return"
> > +# If we don't sleep here 'quit' command races with disk I/O
> > +sleep 0.5
> > +
> >   _send_qemu_cmd $h "{ 'execute': 'quit' }" "return"
> >   wait=1 _cleanup_qemu
> > @@ -137,6 +140,9 @@ _send_qemu_cmd $h \
> >                         'speed': 65536 } }" \
> >       "return"
> > +# If we don't sleep here 'quit' command races with disk I/O
> > +sleep 0.5
> > +
> >   _send_qemu_cmd $h "{ 'execute': 'quit' }" "return"
> >   wait=1 _cleanup_qemu
> > @@ -183,6 +189,9 @@ _send_qemu_cmd $h \
> >                         'speed': 65536 } }" \
> >       "return"
> > +# If we don't sleep here 'quit' command races with disk I/O
> > +sleep 0.5
> > +
> >   _send_qemu_cmd $h "{ 'execute': 'quit' }" "return"
> >   wait=1 _cleanup_qemu
> > @@ -201,6 +210,9 @@ _send_qemu_cmd $h \
> >                         'speed': 65536 } }" \
> >       "return"
> > +# If we don't sleep here 'quit' command races with disk I/O
> > +sleep 0.5
> > +
> >   _send_qemu_cmd $h "{ 'execute': 'quit' }" "return"
> >   wait=1 _cleanup_qemu
> > diff --git a/tests/qemu-iotests/185.out b/tests/qemu-iotests/185.out
> > index 2c4b04de73..1f21e79c13 100644
> > --- a/tests/qemu-iotests/185.out
> > +++ b/tests/qemu-iotests/185.out
> > @@ -26,9 +26,9 @@ Formatting 'TEST_DIR/t.qcow2', fmt=qcow2 size=67108864 
> > backing_file=TEST_DIR/t.q
> >   {"return": {}}
> >   {"return": {}}
> > -{"return": {}}
> > -{"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, 
> > "event": "SHUTDOWN", "data": {"guest": false}}
> >   {"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, 
> > "event": "BLOCK_JOB_READY", "data": {"device": "disk", "len": 4194304, 
> > "offset": 4194304, "speed": 65536, "type": "commit"}}
> > +{"return": {}}
> > +{"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, 
> > "event": "SHUTDOWN", "data": {"guest": false}}
> >   {"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, 
> > "event": "BLOCK_JOB_COMPLETED", "data": {"device": "disk", "len": 4194304, 
> > "offset": 4194304, "speed": 65536, "type": "commit"}}
> >   === Start mirror job and exit qemu ===
> 
> Hm, it looks strange, that commit was done with such a small speed in 0.5
> seconds...

Rate-limiting is broken in the mirror job (qemu.git/master), so that's
why it completes within 0.5s.

A separate patch (already in Jeff's tree) fixes the rate-limiting issue.

I will rebase onto Jeff's tree and resend.  Thanks for pointing this
out!

Stefan

signature.asc
Description: PGP signature