qemu-iotests: post-QEMU 2.12 fixes for 185

PATCH Superseded Stefan Hajnoczi 4 participants 8 messages May 4, 2018 – May 8, 2018

Share & tools

Stefan Hajnoczi

author

2018-05-04 15:50 UTC #0 lore raw

cover qemu-iotests: post-QEMU 2.12 fixes for 185

The 185 qemu-iotests test case was in a bad state for the QEMU 2.12 release. We fudged the expected test output to make it pass, except for non-deterministic behavior.

These patches get us back to pre-QEMU 2.12. Notably the offsets reported in block job events now correspond to smaller buffer sizes because the job doesn't iterate during drain.

It's worth mentioning that the test case is still non-deterministic. For more on that, see the first patch.

Stefan Hajnoczi (2):
qemu-iotests: reduce chance of races in 185
blockjob: do not cancel timer in resume

 blockjob.c                 | 22 +++++++++++++++-------
 tests/qemu-iotests/185     | 12 ++++++++++++
 tests/qemu-iotests/185.out | 10 +++++-----
 3 files changed, 32 insertions(+), 12 deletions(-)

Signature · 1 line

2.14.3

Stefan Hajnoczi

author

2018-05-04 15:50 UTC #1 lore raw

PATCH 1/2 qemu-iotests: reduce chance of races in 185

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 <[email protected]>

Signed-off-by Stefan Hajnoczi <[email protected]>

---
 tests/qemu-iotests/185     | 12 ++++++++++++
 tests/qemu-iotests/185.out |  4 ++--
 2 files changed, 14 insertions(+), 2 deletions(-)

tests/qemu-iotests/185 +12 -0

index 298d88d04e..975404c99d 100755
@@ -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

tests/qemu-iotests/185.out +2 -2

index 2c4b04de73..1f21e79c13 100644
@@ -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 ===

Signature · 1 line

2.14.3

Vladimir Sementsov-Ogievskiy

2018-05-04 17:43 UTC #2 lore raw

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

Quoted 71 lines · Stefan Hajnoczi

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 <[email protected]>
Signed-off-by Stefan Hajnoczi <[email protected]>
---
  tests/qemu-iotests/185     | 12 ++++++++++++
  tests/qemu-iotests/185.out |  4 ++--
  2 files changed, 14 insertions(+), 2 deletions(-)
tests/qemu-iotests/185 +12 -0
index 298d88d04e..975404c99d 100755
@@ -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
 
tests/qemu-iotests/185.out +0 -0
index 2c4b04de73..1f21e79c13 100644
@@ -26,9 +26,9 @@ Formatting 'TEST_DIR/t.qcow2', fmt=qcow2 size=67108864 backing_file=TEST_DIR/t.q
 

tests/qemu-iotests/185.out Formatting 'TEST_DIR/t.qcow2', fmt=qcow2 size=67108864 backing_file=TEST_DIR/t.q · line 34

Quoted 10 lines

tests/qemu-iotests/185.out +2 -2

  {"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...

Signature · 2 lines

Best regards,
Vladimir

Stefan Hajnoczi

2018-05-08 13:06 UTC #3 lore raw

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

Quoted 67 lines · Vladimir Sementsov-Ogievskiy

Quoted 66 lines · Stefan Hajnoczi
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 <[email protected]>
Signed-off-by Stefan Hajnoczi <[email protected]>
---
  tests/qemu-iotests/185     | 12 ++++++++++++
  tests/qemu-iotests/185.out |  4 ++--
  2 files changed, 14 insertions(+), 2 deletions(-)
tests/qemu-iotests/185 +12 -0
index 298d88d04e..975404c99d 100755
@@ -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
tests/qemu-iotests/185.out +0 -2
index 2c4b04de73..1f21e79c13 100644
@@ -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}}

Quoted 8 lines

tests/qemu-iotests/185.out Formatting 'TEST_DIR/t.qcow2', fmt=qcow2 size=67108864 backing_file=TEST_DIR/t.q · line 34

Quoted 5 lines

tests/qemu-iotests/185.out +2 -0

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

Stefan Hajnoczi

author

2018-05-04 15:50 UTC #4 lore raw

PATCH 2/2 blockjob: do not cancel timer in resume

In reply to Stefan Hajnoczi

Currently the timer is cancelled and the block job is entered by block_job_resume(). This behavior causes drain to run extra blockjob iterations when the job was sleeping due to the ratelimit.

This patch leaves the job asleep when block_job_resume() is called. Jobs can still be forcibly woken up using block_job_enter(), which is used to cancel jobs.

After this patch drain no longer runs extra blockjob iterations. This is the expected behavior that qemu-iotests 185 used to rely on. We temporarily changed the 185 test output to make it pass for the QEMU 2.12 release but now it's time to address this issue.

Cc QingFeng Hao <[email protected]>

Signed-off-by Stefan Hajnoczi <[email protected]>

---
 blockjob.c                 | 22 +++++++++++++++-------
 tests/qemu-iotests/185.out |  6 +++---
 2 files changed, 18 insertions(+), 10 deletions(-)

blockjob.c +15 -7

index 27f957e571..70643890be 100644
@@ -209,6 +209,18 @@ static void block_job_txn_del_job(BlockJob *job)
     }
 }
 
+/* Assumes the block_job_mutex is held */
+static bool block_job_timer_pending(BlockJob *job)
+{
+    return timer_pending(&job->sleep_timer);
+}
+
+/* Assumes the block_job_mutex is held */
+static bool block_job_timer_not_pending(BlockJob *job)
+{
+    return !block_job_timer_pending(job);
+}
+
 static void block_job_pause(BlockJob *job)
 {
     job->pause_count++;

@@ -221,7 +233,9 @@ static void block_job_resume(BlockJob *job)
     if (job->pause_count) {
         return;
     }
-    block_job_enter(job);
+
+    /* kick only if no timer is pending */
+    block_job_enter_cond(job, block_job_timer_not_pending);
 }
 
 void block_job_ref(BlockJob *job)

@@ -651,12 +665,6 @@ static void block_job_completed_txn_success(BlockJob *job)
     }
 }
 
-/* Assumes the block_job_mutex is held */
-static bool block_job_timer_pending(BlockJob *job)
-{
-    return timer_pending(&job->sleep_timer);
-}
-
 void block_job_set_speed(BlockJob *job, int64_t speed, Error **errp)
 {
     Error *local_err = NULL;

tests/qemu-iotests/185.out +3 -3

index 1f21e79c13..e0b34d1725 100644
@@ -20,7 +20,7 @@ Formatting 'TEST_DIR/t.qcow2', fmt=qcow2 size=67108864 backing_file=TEST_DIR/t.q
 {"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": 67108864, "offset": 1048576, "speed": 65536, "type": "commit"}}
+{"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "BLOCK_JOB_CANCELLED", "data": {"device": "disk", "len": 67108864, "offset": 524288, "speed": 65536, "type": "commit"}}
 
 === Start active commit job and exit qemu ===

@@ -48,7 +48,7 @@ Formatting 'TEST_DIR/t.qcow2.copy', fmt=qcow2 size=67108864 cluster_size=65536 l
 {"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": 67108864, "offset": 131072, "speed": 65536, "type": "backup"}}
+{"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "BLOCK_JOB_CANCELLED", "data": {"device": "disk", "len": 67108864, "offset": 65536, "speed": 65536, "type": "backup"}}
 
 === Start streaming job and exit qemu ===

@@ -56,6 +56,6 @@ Formatting 'TEST_DIR/t.qcow2.copy', fmt=qcow2 size=67108864 cluster_size=65536 l
 {"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": 67108864, "offset": 1048576, "speed": 65536, "type": "stream"}}
+{"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "BLOCK_JOB_CANCELLED", "data": {"device": "disk", "len": 67108864, "offset": 524288, "speed": 65536, "type": "stream"}}
 No errors were found on the image.
 *** done

Signature · 1 line

2.14.3

Stefan Hajnoczi

2018-05-04 15:55 UTC #5 lore raw

In reply to Stefan Hajnoczi

Oops, the comments in 185 should be updated too. Will fix in v2.

Please go ahead an review the series anyway!

Stefan

Jeff Cody

2018-05-04 17:46 UTC #6 lore raw

In reply to Stefan Hajnoczi

Quoted 11 lines · Stefan Hajnoczi

The 185 qemu-iotests test case was in a bad state for the QEMU 2.12 release. We fudged the expected test output to make it pass, except for non-deterministic behavior.
These patches get us back to pre-QEMU 2.12. Notably the offsets reported in block job events now correspond to smaller buffer sizes because the job doesn't iterate during drain.
It's worth mentioning that the test case is still non-deterministic. For more on that, see the first patch.

Quoted 12 lines

Stefan Hajnoczi (2):
qemu-iotests: reduce chance of races in 185
blockjob: do not cancel timer in resume
 blockjob.c                 | 22 +++++++++++++++-------
 tests/qemu-iotests/185     | 12 ++++++++++++
 tests/qemu-iotests/185.out | 10 +++++-----
 3 files changed, 32 insertions(+), 12 deletions(-)
Signature · 1 line
2.14.3

This series has a minor collision with my block branch in the output; would you like me to just merge together the appropriate 185.out when applying?

-Jeff

Stefan Hajnoczi

2018-05-08 13:07 UTC #7 lore raw

Quoted 21 lines · Jeff Cody

Quoted 20 lines · Stefan Hajnoczi
The 185 qemu-iotests test case was in a bad state for the QEMU 2.12 release. We fudged the expected test output to make it pass, except for non-deterministic behavior.
These patches get us back to pre-QEMU 2.12. Notably the offsets reported in block job events now correspond to smaller buffer sizes because the job doesn't iterate during drain.
It's worth mentioning that the test case is still non-deterministic. For more on that, see the first patch.
Stefan Hajnoczi (2):
qemu-iotests: reduce chance of races in 185
blockjob: do not cancel timer in resume
 blockjob.c                 | 22 +++++++++++++++-------
 tests/qemu-iotests/185     | 12 ++++++++++++
 tests/qemu-iotests/185.out | 10 +++++-----
 3 files changed, 32 insertions(+), 12 deletions(-)

Quoted 6 lines

Quoted 3 lines
Signature · 1 line
2.14.3
This series has a minor collision with my block branch in the output; would you like me to just merge together the appropriate 185.out when applying?

I'll send a v2 based on your branch.

Stefan