* Re: [Qemu-devel] [PATCH v2] iotests: 109: Filter out "len" of failed jobs
2017-04-19 9:17 [Qemu-devel] [PATCH v2] iotests: 109: Filter out "len" of failed jobs Fam Zheng
@ 2017-04-19 16:38 ` Paolo Bonzini
2017-04-20 0:53 ` Fam Zheng
2017-04-19 17:13 ` Kevin Wolf
1 sibling, 1 reply; 5+ messages in thread
From: Paolo Bonzini @ 2017-04-19 16:38 UTC (permalink / raw)
To: Fam Zheng, qemu-devel; +Cc: Kevin Wolf, qemu-block, Max Reitz
On 19/04/2017 11:17, Fam Zheng wrote:
> Mirror calculates job len from current I/O progress:
>
> s->common.len = s->common.offset +
> (cnt + s->sectors_in_flight) * BDRV_SECTOR_SIZE;
>
> The final "len" of a failed mirror job in iotests 109 depends on the
> subtle timing of the completion of read and write issued in the first
> mirror iteration. The second iteration may or may not have run when the
> I/O error happens, resulting in non-deterministic output of the
> BLOCK_JOB_COMPLETED event text.
>
> Similar to what was done in a752e4786, filter out the field to make the
> test robust.
There are more occurrences:
--- /home/pbonzini/work/upstream/qemu/tests/qemu-iotests/109.out 2017-04-19 16:29:31.821480839 +0200
+++ 109.out.bad 2017-04-19 18:26:54.537515323 +0200
@@ -135,7 +135,7 @@
Specify the 'raw' format explicitly to remove the restrictions.
{"return": {}}
{"timestamp": {"seconds": TIMESTAMP, "microseconds": TIMESTAMP}, "event": "BLOCK_JOB_ERROR", "data": {"device": "src", "operation": "write", "action": "report"}}
-{"timestamp": {"seconds": TIMESTAMP, "microseconds": TIMESTAMP}, "event": "BLOCK_JOB_COMPLETED", "data": {"device": "src", "len": 65536, "offset": OFFSET, "speed": 0, "type": "mirror", "error": "Operation not permitted"}}
+{"timestamp": {"seconds": TIMESTAMP, "microseconds": TIMESTAMP}, "event": "BLOCK_JOB_COMPLETED", "data": {"device": "src", "len": 2560, "offset": OFFSET, "speed": 0, "type": "mirror", "error": "Operation not permitted"}}
{"return": []}
read 65536/65536 bytes at offset 0
64 KiB, X ops; XX:XX:XX.X (XXX YYY/sec and XXX ops/sec)
@@ -195,7 +195,7 @@
Specify the 'raw' format explicitly to remove the restrictions.
{"return": {}}
{"timestamp": {"seconds": TIMESTAMP, "microseconds": TIMESTAMP}, "event": "BLOCK_JOB_ERROR", "data": {"device": "src", "operation": "write", "action": "report"}}
-{"timestamp": {"seconds": TIMESTAMP, "microseconds": TIMESTAMP}, "event": "BLOCK_JOB_COMPLETED", "data": {"device": "src", "len": 65536, "offset": OFFSET, "speed": 0, "type": "mirror", "error": "Operation not permitted"}}
+{"timestamp": {"seconds": TIMESTAMP, "microseconds": TIMESTAMP}, "event": "BLOCK_JOB_COMPLETED", "data": {"device": "src", "len": 2048, "offset": OFFSET, "speed": 0, "type": "mirror", "error": "Operation not permitted"}}
{"return": []}
read 65536/65536 bytes at offset 0
64 KiB, X ops; XX:XX:XX.X (XXX YYY/sec and XXX ops/sec)
Thanks,
Paolo
> Tested-by: Eric Blake <eblake@redhat.com>
> Reviewed-by: Eric Blake <eblake@redhat.com>
> Signed-off-by: Fam Zheng <famz@redhat.com>
>
> ---
>
> v2: Add Eric's r-b.
> Don't add '\' after '|'.
> Add '/g/'
> ---
> tests/qemu-iotests/109 | 3 ++-
> tests/qemu-iotests/109.out | 12 ++++++------
> tests/qemu-iotests/common.filter | 6 ++++++
> 3 files changed, 14 insertions(+), 7 deletions(-)
>
> diff --git a/tests/qemu-iotests/109 b/tests/qemu-iotests/109
> index 927151a..ce34c19 100755
> --- a/tests/qemu-iotests/109
> +++ b/tests/qemu-iotests/109
> @@ -80,7 +80,8 @@ for fmt in qcow qcow2 qed vdi vmdk vpc; do
>
> # This first test should fail: The image format was probed, we may not
> # write an image header at the start of the image
> - run_qemu "$TEST_IMG" "$TEST_IMG.src" "" "BLOCK_JOB_ERROR"
> + run_qemu "$TEST_IMG" "$TEST_IMG.src" "" "BLOCK_JOB_ERROR" |
> + _filter_block_job_len
> $QEMU_IO -c 'read -P 0 0 64k' "$TEST_IMG" | _filter_qemu_io
>
>
> diff --git a/tests/qemu-iotests/109.out b/tests/qemu-iotests/109.out
> index 55fe536..6454b7e 100644
> --- a/tests/qemu-iotests/109.out
> +++ b/tests/qemu-iotests/109.out
> @@ -10,7 +10,7 @@ Automatically detecting the format is dangerous for raw images, write operations
> Specify the 'raw' format explicitly to remove the restrictions.
> {"return": {}}
> {"timestamp": {"seconds": TIMESTAMP, "microseconds": TIMESTAMP}, "event": "BLOCK_JOB_ERROR", "data": {"device": "src", "operation": "write", "action": "report"}}
> -{"timestamp": {"seconds": TIMESTAMP, "microseconds": TIMESTAMP}, "event": "BLOCK_JOB_COMPLETED", "data": {"device": "src", "len": 65536, "offset": 0, "speed": 0, "type": "mirror", "error": "Operation not permitted"}}
> +{"timestamp": {"seconds": TIMESTAMP, "microseconds": TIMESTAMP}, "event": "BLOCK_JOB_COMPLETED", "data": {"device": "src", "len": LEN, "offset": 0, "speed": 0, "type": "mirror", "error": "Operation not permitted"}}
> {"return": []}
> read 65536/65536 bytes at offset 0
> 64 KiB, X ops; XX:XX:XX.X (XXX YYY/sec and XXX ops/sec)
> @@ -31,7 +31,7 @@ Automatically detecting the format is dangerous for raw images, write operations
> Specify the 'raw' format explicitly to remove the restrictions.
> {"return": {}}
> {"timestamp": {"seconds": TIMESTAMP, "microseconds": TIMESTAMP}, "event": "BLOCK_JOB_ERROR", "data": {"device": "src", "operation": "write", "action": "report"}}
> -{"timestamp": {"seconds": TIMESTAMP, "microseconds": TIMESTAMP}, "event": "BLOCK_JOB_COMPLETED", "data": {"device": "src", "len": 197120, "offset": 512, "speed": 0, "type": "mirror", "error": "Operation not permitted"}}
> +{"timestamp": {"seconds": TIMESTAMP, "microseconds": TIMESTAMP}, "event": "BLOCK_JOB_COMPLETED", "data": {"device": "src", "len": LEN, "offset": 512, "speed": 0, "type": "mirror", "error": "Operation not permitted"}}
> {"return": []}
> read 65536/65536 bytes at offset 0
> 64 KiB, X ops; XX:XX:XX.X (XXX YYY/sec and XXX ops/sec)
> @@ -52,7 +52,7 @@ Automatically detecting the format is dangerous for raw images, write operations
> Specify the 'raw' format explicitly to remove the restrictions.
> {"return": {}}
> {"timestamp": {"seconds": TIMESTAMP, "microseconds": TIMESTAMP}, "event": "BLOCK_JOB_ERROR", "data": {"device": "src", "operation": "write", "action": "report"}}
> -{"timestamp": {"seconds": TIMESTAMP, "microseconds": TIMESTAMP}, "event": "BLOCK_JOB_COMPLETED", "data": {"device": "src", "len": 327680, "offset": 262144, "speed": 0, "type": "mirror", "error": "Operation not permitted"}}
> +{"timestamp": {"seconds": TIMESTAMP, "microseconds": TIMESTAMP}, "event": "BLOCK_JOB_COMPLETED", "data": {"device": "src", "len": LEN, "offset": 262144, "speed": 0, "type": "mirror", "error": "Operation not permitted"}}
> {"return": []}
> read 65536/65536 bytes at offset 0
> 64 KiB, X ops; XX:XX:XX.X (XXX YYY/sec and XXX ops/sec)
> @@ -73,7 +73,7 @@ Automatically detecting the format is dangerous for raw images, write operations
> Specify the 'raw' format explicitly to remove the restrictions.
> {"return": {}}
> {"timestamp": {"seconds": TIMESTAMP, "microseconds": TIMESTAMP}, "event": "BLOCK_JOB_ERROR", "data": {"device": "src", "operation": "write", "action": "report"}}
> -{"timestamp": {"seconds": TIMESTAMP, "microseconds": TIMESTAMP}, "event": "BLOCK_JOB_COMPLETED", "data": {"device": "src", "len": 65536, "offset": 0, "speed": 0, "type": "mirror", "error": "Operation not permitted"}}
> +{"timestamp": {"seconds": TIMESTAMP, "microseconds": TIMESTAMP}, "event": "BLOCK_JOB_COMPLETED", "data": {"device": "src", "len": LEN, "offset": 0, "speed": 0, "type": "mirror", "error": "Operation not permitted"}}
> {"return": []}
> read 65536/65536 bytes at offset 0
> 64 KiB, X ops; XX:XX:XX.X (XXX YYY/sec and XXX ops/sec)
> @@ -94,7 +94,7 @@ Automatically detecting the format is dangerous for raw images, write operations
> Specify the 'raw' format explicitly to remove the restrictions.
> {"return": {}}
> {"timestamp": {"seconds": TIMESTAMP, "microseconds": TIMESTAMP}, "event": "BLOCK_JOB_ERROR", "data": {"device": "src", "operation": "write", "action": "report"}}
> -{"timestamp": {"seconds": TIMESTAMP, "microseconds": TIMESTAMP}, "event": "BLOCK_JOB_COMPLETED", "data": {"device": "src", "len": 65536, "offset": 0, "speed": 0, "type": "mirror", "error": "Operation not permitted"}}
> +{"timestamp": {"seconds": TIMESTAMP, "microseconds": TIMESTAMP}, "event": "BLOCK_JOB_COMPLETED", "data": {"device": "src", "len": LEN, "offset": 0, "speed": 0, "type": "mirror", "error": "Operation not permitted"}}
> {"return": []}
> read 65536/65536 bytes at offset 0
> 64 KiB, X ops; XX:XX:XX.X (XXX YYY/sec and XXX ops/sec)
> @@ -115,7 +115,7 @@ Automatically detecting the format is dangerous for raw images, write operations
> Specify the 'raw' format explicitly to remove the restrictions.
> {"return": {}}
> {"timestamp": {"seconds": TIMESTAMP, "microseconds": TIMESTAMP}, "event": "BLOCK_JOB_ERROR", "data": {"device": "src", "operation": "write", "action": "report"}}
> -{"timestamp": {"seconds": TIMESTAMP, "microseconds": TIMESTAMP}, "event": "BLOCK_JOB_COMPLETED", "data": {"device": "src", "len": 65536, "offset": 0, "speed": 0, "type": "mirror", "error": "Operation not permitted"}}
> +{"timestamp": {"seconds": TIMESTAMP, "microseconds": TIMESTAMP}, "event": "BLOCK_JOB_COMPLETED", "data": {"device": "src", "len": LEN, "offset": 0, "speed": 0, "type": "mirror", "error": "Operation not permitted"}}
> {"return": []}
> read 65536/65536 bytes at offset 0
> 64 KiB, X ops; XX:XX:XX.X (XXX YYY/sec and XXX ops/sec)
> diff --git a/tests/qemu-iotests/common.filter b/tests/qemu-iotests/common.filter
> index 1040013..5b2cb24 100644
> --- a/tests/qemu-iotests/common.filter
> +++ b/tests/qemu-iotests/common.filter
> @@ -92,6 +92,12 @@ _filter_block_job_offset()
> sed -e 's/, "offset": [0-9]\+,/, "offset": OFFSET,/'
> }
>
> +# replace block job len
> +_filter_block_job_len()
> +{
> + sed -e 's/, "len": [0-9]\+,/, "len": LEN,/g'
> +}
> +
> # replace driver-specific options in the "Formatting..." line
> _filter_img_create()
> {
>
^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: [Qemu-devel] [PATCH v2] iotests: 109: Filter out "len" of failed jobs
2017-04-19 9:17 [Qemu-devel] [PATCH v2] iotests: 109: Filter out "len" of failed jobs Fam Zheng
2017-04-19 16:38 ` Paolo Bonzini
@ 2017-04-19 17:13 ` Kevin Wolf
2017-04-20 0:53 ` Fam Zheng
1 sibling, 1 reply; 5+ messages in thread
From: Kevin Wolf @ 2017-04-19 17:13 UTC (permalink / raw)
To: Fam Zheng; +Cc: qemu-devel, Eric Blake, Max Reitz, qemu-block
Am 19.04.2017 um 11:17 hat Fam Zheng geschrieben:
> Mirror calculates job len from current I/O progress:
>
> s->common.len = s->common.offset +
> (cnt + s->sectors_in_flight) * BDRV_SECTOR_SIZE;
>
> The final "len" of a failed mirror job in iotests 109 depends on the
> subtle timing of the completion of read and write issued in the first
> mirror iteration. The second iteration may or may not have run when the
> I/O error happens, resulting in non-deterministic output of the
> BLOCK_JOB_COMPLETED event text.
>
> Similar to what was done in a752e4786, filter out the field to make the
> test robust.
>
> Tested-by: Eric Blake <eblake@redhat.com>
> Reviewed-by: Eric Blake <eblake@redhat.com>
> Signed-off-by: Fam Zheng <famz@redhat.com>
This improves things a bit, but the test case is still failing for me.
It's not deterministic, so the following is just an example.
Kevin
--- /home/kwolf/source/qemu/tests/qemu-iotests/109.out 2017-04-19 19:10:27.458121955 +0200
+++ 109.out.bad 2017-04-19 19:10:49.782467425 +0200
@@ -135,7 +135,7 @@
Specify the 'raw' format explicitly to remove the restrictions.
{"return": {}}
{"timestamp": {"seconds": TIMESTAMP, "microseconds": TIMESTAMP}, "event": "BLOCK_JOB_ERROR", "data": {"device": "src", "operation": "write", "action": "report"}}
-{"timestamp": {"seconds": TIMESTAMP, "microseconds": TIMESTAMP}, "event": "BLOCK_JOB_COMPLETED", "data": {"device": "src", "len": 65536, "offset": OFFSET, "speed": 0, "type": "mirror", "error": "Operation not permitted"}}
+{"timestamp": {"seconds": TIMESTAMP, "microseconds": TIMESTAMP}, "event": "BLOCK_JOB_COMPLETED", "data": {"device": "src", "len": 2560, "offset": OFFSET, "speed": 0, "type": "mirror", "error": "Operation not permitted"}}
{"return": []}
read 65536/65536 bytes at offset 0
64 KiB, X ops; XX:XX:XX.X (XXX YYY/sec and XXX ops/sec)
@@ -195,7 +195,7 @@
Specify the 'raw' format explicitly to remove the restrictions.
{"return": {}}
{"timestamp": {"seconds": TIMESTAMP, "microseconds": TIMESTAMP}, "event": "BLOCK_JOB_ERROR", "data": {"device": "src", "operation": "write", "action": "report"}}
-{"timestamp": {"seconds": TIMESTAMP, "microseconds": TIMESTAMP}, "event": "BLOCK_JOB_COMPLETED", "data": {"device": "src", "len": 65536, "offset": OFFSET, "speed": 0, "type": "mirror", "error": "Operation not permitted"}}
+{"timestamp": {"seconds": TIMESTAMP, "microseconds": TIMESTAMP}, "event": "BLOCK_JOB_COMPLETED", "data": {"device": "src", "len": 2048, "offset": OFFSET, "speed": 0, "type": "mirror", "error": "Operation not permitted"}}
{"return": []}
read 65536/65536 bytes at offset 0
64 KiB, X ops; XX:XX:XX.X (XXX YYY/sec and XXX ops/sec)
^ permalink raw reply [flat|nested] 5+ messages in thread