* Failure in iotest 183
@ 2022-07-05 9:35 Thomas Huth
2022-07-05 9:58 ` Hanna Reitz
0 siblings, 1 reply; 4+ messages in thread
From: Thomas Huth @ 2022-07-05 9:35 UTC (permalink / raw)
To: Qemu-block, Hanna Reitz, Kevin Wolf; +Cc: QEMU Developers
Hi!
I've just hit a failure in iotest 183:
--- /home/thuth/devel/qemu/tests/qemu-iotests/183.out
+++ /home/thuth/tmp/qemu-build/tests/qemu-iotests/scratch/183/183.out.bad
@@ -30,7 +30,7 @@
'arguments': { 'uri': 'unix:SOCK_DIR/migrate', 'blk': true } }
{"return": {}}
{ 'execute': 'query-status' }
-{"return": {"status": "postmigrate", "singlestep": false, "running": false}}
+{"return": {"status": "completed", "setup-time": 0, "downtime": 2448, "total-time": 2872, "ram": {"total": 134750208, "postcopy-requests": 0, "dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 0, "downtime-bytes": 0, "page-size": 4096, "remaining": 0, "postcopy-bytes": 0, "mbps": 188.63209192200557, "transferred": 496829, "precopy-bytes": 496829, "duplicate": 32849, "dirty-pages-rate": 0, "skipped": 0, "normal-bytes": 200704, "normal": 49}}}
=== Do some I/O on the destination ===
@@ -53,8 +53,31 @@
=== Shut down and check image ===
{"execute":"quit"}
+{"return": {"status": "completed", "setup-time": 0, "downtime": 2448, "total-time": 2872, "ram": {"total": 134750208, "postcopy-requests": 0, "dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 0, "downtime-bytes": 0, "page-size": 4096, "remaining": 0, "postcopy-bytes": 0, "mbps": 188.63209192200557, "transferred": 496829, "precopy-bytes": 496829, "duplicate": 32849, "dirty-pages-rate": 0, "skipped": 0, "normal-bytes": 200704, "normal": 49}}}
+{"execute":"quit"}
{"return": {}}
-{"execute":"quit"}
+{"return": {"status": "completed", "setup-time": 0, "downtime": 2448, "total-time": 2872, "ram": {"total": 134750208, "postcopy-requests": 0, "dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 0, "downtime-bytes": 0, "page-size": 4096, "remaining": 0, "postcopy-bytes": 0, "mbps": 188.63209192200557, "transferred": 496829, "precopy-bytes": 496829, "duplicate": 32849, "dirty-pages-rate": 0, "skipped": 0, "normal-bytes": 200704, "normal": 49}}}
+{"return": {"status": "completed", "setup-time": 0, "downtime": 2448, "total-time": 2872, "ram": {"total": 134750208, "postcopy-requests": 0, "dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 0, "downtime-bytes": 0, "page-size": 4096, "remaining": 0, "postcopy-bytes": 0, "mbps": 188.63209192200557, "transferred": 496829, "precopy-bytes": 496829, "duplicate": 32849, "dirty-pages-rate": 0, "skipped": 0, "normal-bytes": 200704, "normal": 49}}}
+{"return": {"status": "completed", "setup-time": 0, "downtime": 2448, "total-time": 2872, "ram": {"total": 134750208, "postcopy-requests": 0, "dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 0, "downtime-bytes": 0, "page-size": 4096, "remaining": 0, "postcopy-bytes": 0, "mbps": 188.63209192200557, "transferred": 496829, "precopy-bytes": 496829, "duplicate": 32849, "dirty-pages-rate": 0, "skipped": 0, "normal-bytes": 200704, "normal": 49}}}
+{"return": {"status": "completed", "setup-time": 0, "downtime": 2448, "total-time": 2872, "ram": {"total": 134750208, "postcopy-requests": 0, "dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 0, "downtime-bytes": 0, "page-size": 4096, "remaining": 0, "postcopy-bytes": 0, "mbps": 188.63209192200557, "transferred": 496829, "precopy-bytes": 496829, "duplicate": 32849, "dirty-pages-rate": 0, "skipped": 0, "normal-bytes": 200704, "normal": 49}}}
+{"return": {"status": "completed", "setup-time": 0, "downtime": 2448, "total-time": 2872, "ram": {"total": 134750208, "postcopy-requests": 0, "dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 0, "downtime-bytes": 0, "page-size": 4096, "remaining": 0, "postcopy-bytes": 0, "mbps": 188.63209192200557, "transferred": 496829, "precopy-bytes": 496829, "duplicate": 32849, "dirty-pages-rate": 0, "skipped": 0, "normal-bytes": 200704, "normal": 49}}}
+{"return": {"status": "completed", "setup-time": 0, "downtime": 2448, "total-time": 2872, "ram": {"total": 134750208, "postcopy-requests": 0, "dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 0, "downtime-bytes": 0, "page-size": 4096, "remaining": 0, "postcopy-bytes": 0, "mbps": 188.63209192200557, "transferred": 496829, "precopy-bytes": 496829, "duplicate": 32849, "dirty-pages-rate": 0, "skipped": 0, "normal-bytes": 200704, "normal": 49}}}
+{"return": {"status": "completed", "setup-time": 0, "downtime": 2448, "total-time": 2872, "ram": {"total": 134750208, "postcopy-requests": 0, "dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 0, "downtime-bytes": 0, "page-size": 4096, "remaining": 0, "postcopy-bytes": 0, "mbps": 188.63209192200557, "transferred": 496829, "precopy-bytes": 496829, "duplicate": 32849, "dirty-pages-rate": 0, "skipped": 0, "normal-bytes": 200704, "normal": 49}}}
+{"return": {"status": "completed", "setup-time": 0, "downtime": 2448, "total-time": 2872, "ram": {"total": 134750208, "postcopy-requests": 0, "dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 0, "downtime-bytes": 0, "page-size": 4096, "remaining": 0, "postcopy-bytes": 0, "mbps": 188.63209192200557, "transferred": 496829, "precopy-bytes": 496829, "duplicate": 32849, "dirty-pages-rate": 0, "skipped": 0, "normal-bytes": 200704, "normal": 49}}}
+{"return": {"status": "completed", "setup-time": 0, "downtime": 2448, "total-time": 2872, "ram": {"total": 134750208, "postcopy-requests": 0, "dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 0, "downtime-bytes": 0, "page-size": 4096, "remaining": 0, "postcopy-bytes": 0, "mbps": 188.63209192200557, "transferred": 496829, "precopy-bytes": 496829, "duplicate": 32849, "dirty-pages-rate": 0, "skipped": 0, "normal-bytes": 200704, "normal": 49}}}
+{"return": {"status": "completed", "setup-time": 0, "downtime": 2448, "total-time": 2872, "ram": {"total": 134750208, "postcopy-requests": 0, "dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 0, "downtime-bytes": 0, "page-size": 4096, "remaining": 0, "postcopy-bytes": 0, "mbps": 188.63209192200557, "transferred": 496829, "precopy-bytes": 496829, "duplicate": 32849, "dirty-pages-rate": 0, "skipped": 0, "normal-bytes": 200704, "normal": 49}}}
+{"return": {"status": "completed", "setup-time": 0, "downtime": 2448, "total-time": 2872, "ram": {"total": 134750208, "postcopy-requests": 0, "dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 0, "downtime-bytes": 0, "page-size": 4096, "remaining": 0, "postcopy-bytes": 0, "mbps": 188.63209192200557, "transferred": 496829, "precopy-bytes": 496829, "duplicate": 32849, "dirty-pages-rate": 0, "skipped": 0, "normal-bytes": 200704, "normal": 49}}}
+{"return": {"status": "completed", "setup-time": 0, "downtime": 2448, "total-time": 2872, "ram": {"total": 134750208, "postcopy-requests": 0, "dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 0, "downtime-bytes": 0, "page-size": 4096, "remaining": 0, "postcopy-bytes": 0, "mbps": 188.63209192200557, "transferred": 496829, "precopy-bytes": 496829, "duplicate": 32849, "dirty-pages-rate": 0, "skipped": 0, "normal-bytes": 200704, "normal": 49}}}
+{"return": {"status": "completed", "setup-time": 0, "downtime": 2448, "total-time": 2872, "ram": {"total": 134750208, "postcopy-requests": 0, "dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 0, "downtime-bytes": 0, "page-size": 4096, "remaining": 0, "postcopy-bytes": 0, "mbps": 188.63209192200557, "transferred": 496829, "precopy-bytes": 496829, "duplicate": 32849, "dirty-pages-rate": 0, "skipped": 0, "normal-bytes": 200704, "normal": 49}}}
+{"return": {"status": "completed", "setup-time": 0, "downtime": 2448, "total-time": 2872, "ram": {"total": 134750208, "postcopy-requests": 0, "dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 0, "downtime-bytes": 0, "page-size": 4096, "remaining": 0, "postcopy-bytes": 0, "mbps": 188.63209192200557, "transferred": 496829, "precopy-bytes": 496829, "duplicate": 32849, "dirty-pages-rate": 0, "skipped": 0, "normal-bytes": 200704, "normal": 49}}}
+{"return": {"status": "completed", "setup-time": 0, "downtime": 2448, "total-time": 2872, "ram": {"total": 134750208, "postcopy-requests": 0, "dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 0, "downtime-bytes": 0, "page-size": 4096, "remaining": 0, "postcopy-bytes": 0, "mbps": 188.63209192200557, "transferred": 496829, "precopy-bytes": 496829, "duplicate": 32849, "dirty-pages-rate": 0, "skipped": 0, "normal-bytes": 200704, "normal": 49}}}
+{"return": {"status": "completed", "setup-time": 0, "downtime": 2448, "total-time": 2872, "ram": {"total": 134750208, "postcopy-requests": 0, "dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 0, "downtime-bytes": 0, "page-size": 4096, "remaining": 0, "postcopy-bytes": 0, "mbps": 188.63209192200557, "transferred": 496829, "precopy-bytes": 496829, "duplicate": 32849, "dirty-pages-rate": 0, "skipped": 0, "normal-bytes": 200704, "normal": 49}}}
+{"return": {"status": "completed", "setup-time": 0, "downtime": 2448, "total-time": 2872, "ram": {"total": 134750208, "postcopy-requests": 0, "dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 0, "downtime-bytes": 0, "page-size": 4096, "remaining": 0, "postcopy-bytes": 0, "mbps": 188.63209192200557, "transferred": 496829, "precopy-bytes": 496829, "duplicate": 32849, "dirty-pages-rate": 0, "skipped": 0, "normal-bytes": 200704, "normal": 49}}}
+{"return": {"status": "completed", "setup-time": 0, "downtime": 2448, "total-time": 2872, "ram": {"total": 134750208, "postcopy-requests": 0, "dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 0, "downtime-bytes": 0, "page-size": 4096, "remaining": 0, "postcopy-bytes": 0, "mbps": 188.63209192200557, "transferred": 496829, "precopy-bytes": 496829, "duplicate": 32849, "dirty-pages-rate": 0, "skipped": 0, "normal-bytes": 200704, "normal": 49}}}
+{"return": {"status": "completed", "setup-time": 0, "downtime": 2448, "total-time": 2872, "ram": {"total": 134750208, "postcopy-requests": 0, "dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 0, "downtime-bytes": 0, "page-size": 4096, "remaining": 0, "postcopy-bytes": 0, "mbps": 188.63209192200557, "transferred": 496829, "precopy-bytes": 496829, "duplicate": 32849, "dirty-pages-rate": 0, "skipped": 0, "normal-bytes": 200704, "normal": 49}}}
+{"return": {"status": "completed", "setup-time": 0, "downtime": 2448, "total-time": 2872, "ram": {"total": 134750208, "postcopy-requests": 0, "dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 0, "downtime-bytes": 0, "page-size": 4096, "remaining": 0, "postcopy-bytes": 0, "mbps": 188.63209192200557, "transferred": 496829, "precopy-bytes": 496829, "duplicate": 32849, "dirty-pages-rate": 0, "skipped": 0, "normal-bytes": 200704, "normal": 49}}}
+{"return": {"status": "completed", "setup-time": 0, "downtime": 2448, "total-time": 2872, "ram": {"total": 134750208, "postcopy-requests": 0, "dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 0, "downtime-bytes": 0, "page-size": 4096, "remaining": 0, "postcopy-bytes": 0, "mbps": 188.63209192200557, "transferred": 496829, "precopy-bytes": 496829, "duplicate": 32849, "dirty-pages-rate": 0, "skipped": 0, "normal-bytes": 200704, "normal": 49}}}
+{"return": {"status": "postmigrate", "singlestep": false, "running": false}}
{"return": {}}
{"timestamp": {"seconds": TIMESTAMP, "microseconds": TIMESTAMP}, "event": "SHUTDOWN", "data": {"guest": false, "reason": "host-qmp-quit"}}
{"timestamp": {"seconds": TIMESTAMP, "microseconds": TIMESTAMP}, "event": "SHUTDOWN", "data": {"guest": false, "reason": "host-qmp-quit"}}
Is that a known problem already? (I haven't seen anything
related on the list)
Thomas
^ permalink raw reply [flat|nested] 4+ messages in thread* Re: Failure in iotest 183
2022-07-05 9:35 Failure in iotest 183 Thomas Huth
@ 2022-07-05 9:58 ` Hanna Reitz
2022-07-05 10:20 ` Thomas Huth
0 siblings, 1 reply; 4+ messages in thread
From: Hanna Reitz @ 2022-07-05 9:58 UTC (permalink / raw)
To: Thomas Huth, Qemu-block, Kevin Wolf; +Cc: QEMU Developers
On 05.07.22 11:35, Thomas Huth wrote:
>
> Hi!
>
> I've just hit a failure in iotest 183:
>
> --- /home/thuth/devel/qemu/tests/qemu-iotests/183.out
> +++ /home/thuth/tmp/qemu-build/tests/qemu-iotests/scratch/183/183.out.bad
> @@ -30,7 +30,7 @@
> 'arguments': { 'uri': 'unix:SOCK_DIR/migrate', 'blk': true } }
> {"return": {}}
> { 'execute': 'query-status' }
> -{"return": {"status": "postmigrate", "singlestep": false, "running":
> false}}
> +{"return": {"status": "completed", "setup-time": 0, "downtime": 2448,
> "total-time": 2872, "ram": {"total": 134750208, "postcopy-requests":
> 0, "dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 0,
> "downtime-bytes": 0, "page-size": 4096, "remaining": 0,
> "postcopy-bytes": 0, "mbps": 188.63209192200557, "transferred":
> 496829, "precopy-bytes": 496829, "duplicate": 32849,
> "dirty-pages-rate": 0, "skipped": 0, "normal-bytes": 200704, "normal":
> 49}}}
Weird because query-status cannot return something with '"status":
"completed"' in it. We can see the '"status": "postmigrate"' object
somewhere below, so it seems to me like the silent=yes part for the
query-migrate execution didn’t work as intended.
(And it does seem to work below, when waiting for a “100 %” to appear on
$dest.)
It’s been a while since we’ve touched common.qemu, so nothing comes to
my mind immediately that might have broken this.
>
> === Do some I/O on the destination ===
>
> @@ -53,8 +53,31 @@
> === Shut down and check image ===
>
> {"execute":"quit"}
> +{"return": {"status": "completed", "setup-time": 0, "downtime": 2448,
> "total-time": 2872, "ram": {"total": 134750208, "postcopy-requests":
> 0, "dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 0,
> "downtime-bytes": 0, "page-size": 4096, "remaining": 0,
> "postcopy-bytes": 0, "mbps": 188.63209192200557, "transferred":
> 496829, "precopy-bytes": 496829, "duplicate": 32849,
> "dirty-pages-rate": 0, "skipped": 0, "normal-bytes": 200704, "normal":
> 49}}}
> +{"execute":"quit"}
> {"return": {}}
> -{"execute":"quit"}
> +{"return": {"status": "completed", "setup-time": 0, "downtime": 2448,
> "total-time": 2872, "ram": {"total": 134750208, "postcopy-requests":
> 0, "dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 0,
> "downtime-bytes": 0, "page-size": 4096, "remaining": 0,
> "postcopy-bytes": 0, "mbps": 188.63209192200557, "transferred":
> 496829, "precopy-bytes": 496829, "duplicate": 32849,
> "dirty-pages-rate": 0, "skipped": 0, "normal-bytes": 200704, "normal":
> 49}}}
> +{"return": {"status": "completed", "setup-time": 0, "downtime": 2448,
> "total-time": 2872, "ram": {"total": 134750208, "postcopy-requests":
> 0, "dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 0,
> "downtime-bytes": 0, "page-size": 4096, "remaining": 0,
> "postcopy-bytes": 0, "mbps": 188.63209192200557, "transferred":
> 496829, "precopy-bytes": 496829, "duplicate": 32849,
> "dirty-pages-rate": 0, "skipped": 0, "normal-bytes": 200704, "normal":
> 49}}}
> +{"return": {"status": "completed", "setup-time": 0, "downtime": 2448,
> "total-time": 2872, "ram": {"total": 134750208, "postcopy-requests":
> 0, "dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 0,
> "downtime-bytes": 0, "page-size": 4096, "remaining": 0,
> "postcopy-bytes": 0, "mbps": 188.63209192200557, "transferred":
> 496829, "precopy-bytes": 496829, "duplicate": 32849,
> "dirty-pages-rate": 0, "skipped": 0, "normal-bytes": 200704, "normal":
> 49}}}
> +{"return": {"status": "completed", "setup-time": 0, "downtime": 2448,
> "total-time": 2872, "ram": {"total": 134750208, "postcopy-requests":
> 0, "dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 0,
> "downtime-bytes": 0, "page-size": 4096, "remaining": 0,
> "postcopy-bytes": 0, "mbps": 188.63209192200557, "transferred":
> 496829, "precopy-bytes": 496829, "duplicate": 32849,
> "dirty-pages-rate": 0, "skipped": 0, "normal-bytes": 200704, "normal":
> 49}}}
> +{"return": {"status": "completed", "setup-time": 0, "downtime": 2448,
> "total-time": 2872, "ram": {"total": 134750208, "postcopy-requests":
> 0, "dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 0,
> "downtime-bytes": 0, "page-size": 4096, "remaining": 0,
> "postcopy-bytes": 0, "mbps": 188.63209192200557, "transferred":
> 496829, "precopy-bytes": 496829, "duplicate": 32849,
> "dirty-pages-rate": 0, "skipped": 0, "normal-bytes": 200704, "normal":
> 49}}}
> +{"return": {"status": "completed", "setup-time": 0, "downtime": 2448,
> "total-time": 2872, "ram": {"total": 134750208, "postcopy-requests":
> 0, "dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 0,
> "downtime-bytes": 0, "page-size": 4096, "remaining": 0,
> "postcopy-bytes": 0, "mbps": 188.63209192200557, "transferred":
> 496829, "precopy-bytes": 496829, "duplicate": 32849,
> "dirty-pages-rate": 0, "skipped": 0, "normal-bytes": 200704, "normal":
> 49}}}
> +{"return": {"status": "completed", "setup-time": 0, "downtime": 2448,
> "total-time": 2872, "ram": {"total": 134750208, "postcopy-requests":
> 0, "dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 0,
> "downtime-bytes": 0, "page-size": 4096, "remaining": 0,
> "postcopy-bytes": 0, "mbps": 188.63209192200557, "transferred":
> 496829, "precopy-bytes": 496829, "duplicate": 32849,
> "dirty-pages-rate": 0, "skipped": 0, "normal-bytes": 200704, "normal":
> 49}}}
> +{"return": {"status": "completed", "setup-time": 0, "downtime": 2448,
> "total-time": 2872, "ram": {"total": 134750208, "postcopy-requests":
> 0, "dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 0,
> "downtime-bytes": 0, "page-size": 4096, "remaining": 0,
> "postcopy-bytes": 0, "mbps": 188.63209192200557, "transferred":
> 496829, "precopy-bytes": 496829, "duplicate": 32849,
> "dirty-pages-rate": 0, "skipped": 0, "normal-bytes": 200704, "normal":
> 49}}}
> +{"return": {"status": "completed", "setup-time": 0, "downtime": 2448,
> "total-time": 2872, "ram": {"total": 134750208, "postcopy-requests":
> 0, "dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 0,
> "downtime-bytes": 0, "page-size": 4096, "remaining": 0,
> "postcopy-bytes": 0, "mbps": 188.63209192200557, "transferred":
> 496829, "precopy-bytes": 496829, "duplicate": 32849,
> "dirty-pages-rate": 0, "skipped": 0, "normal-bytes": 200704, "normal":
> 49}}}
> +{"return": {"status": "completed", "setup-time": 0, "downtime": 2448,
> "total-time": 2872, "ram": {"total": 134750208, "postcopy-requests":
> 0, "dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 0,
> "downtime-bytes": 0, "page-size": 4096, "remaining": 0,
> "postcopy-bytes": 0, "mbps": 188.63209192200557, "transferred":
> 496829, "precopy-bytes": 496829, "duplicate": 32849,
> "dirty-pages-rate": 0, "skipped": 0, "normal-bytes": 200704, "normal":
> 49}}}
> +{"return": {"status": "completed", "setup-time": 0, "downtime": 2448,
> "total-time": 2872, "ram": {"total": 134750208, "postcopy-requests":
> 0, "dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 0,
> "downtime-bytes": 0, "page-size": 4096, "remaining": 0,
> "postcopy-bytes": 0, "mbps": 188.63209192200557, "transferred":
> 496829, "precopy-bytes": 496829, "duplicate": 32849,
> "dirty-pages-rate": 0, "skipped": 0, "normal-bytes": 200704, "normal":
> 49}}}
> +{"return": {"status": "completed", "setup-time": 0, "downtime": 2448,
> "total-time": 2872, "ram": {"total": 134750208, "postcopy-requests":
> 0, "dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 0,
> "downtime-bytes": 0, "page-size": 4096, "remaining": 0,
> "postcopy-bytes": 0, "mbps": 188.63209192200557, "transferred":
> 496829, "precopy-bytes": 496829, "duplicate": 32849,
> "dirty-pages-rate": 0, "skipped": 0, "normal-bytes": 200704, "normal":
> 49}}}
> +{"return": {"status": "completed", "setup-time": 0, "downtime": 2448,
> "total-time": 2872, "ram": {"total": 134750208, "postcopy-requests":
> 0, "dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 0,
> "downtime-bytes": 0, "page-size": 4096, "remaining": 0,
> "postcopy-bytes": 0, "mbps": 188.63209192200557, "transferred":
> 496829, "precopy-bytes": 496829, "duplicate": 32849,
> "dirty-pages-rate": 0, "skipped": 0, "normal-bytes": 200704, "normal":
> 49}}}
> +{"return": {"status": "completed", "setup-time": 0, "downtime": 2448,
> "total-time": 2872, "ram": {"total": 134750208, "postcopy-requests":
> 0, "dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 0,
> "downtime-bytes": 0, "page-size": 4096, "remaining": 0,
> "postcopy-bytes": 0, "mbps": 188.63209192200557, "transferred":
> 496829, "precopy-bytes": 496829, "duplicate": 32849,
> "dirty-pages-rate": 0, "skipped": 0, "normal-bytes": 200704, "normal":
> 49}}}
> +{"return": {"status": "completed", "setup-time": 0, "downtime": 2448,
> "total-time": 2872, "ram": {"total": 134750208, "postcopy-requests":
> 0, "dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 0,
> "downtime-bytes": 0, "page-size": 4096, "remaining": 0,
> "postcopy-bytes": 0, "mbps": 188.63209192200557, "transferred":
> 496829, "precopy-bytes": 496829, "duplicate": 32849,
> "dirty-pages-rate": 0, "skipped": 0, "normal-bytes": 200704, "normal":
> 49}}}
> +{"return": {"status": "completed", "setup-time": 0, "downtime": 2448,
> "total-time": 2872, "ram": {"total": 134750208, "postcopy-requests":
> 0, "dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 0,
> "downtime-bytes": 0, "page-size": 4096, "remaining": 0,
> "postcopy-bytes": 0, "mbps": 188.63209192200557, "transferred":
> 496829, "precopy-bytes": 496829, "duplicate": 32849,
> "dirty-pages-rate": 0, "skipped": 0, "normal-bytes": 200704, "normal":
> 49}}}
> +{"return": {"status": "completed", "setup-time": 0, "downtime": 2448,
> "total-time": 2872, "ram": {"total": 134750208, "postcopy-requests":
> 0, "dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 0,
> "downtime-bytes": 0, "page-size": 4096, "remaining": 0,
> "postcopy-bytes": 0, "mbps": 188.63209192200557, "transferred":
> 496829, "precopy-bytes": 496829, "duplicate": 32849,
> "dirty-pages-rate": 0, "skipped": 0, "normal-bytes": 200704, "normal":
> 49}}}
> +{"return": {"status": "completed", "setup-time": 0, "downtime": 2448,
> "total-time": 2872, "ram": {"total": 134750208, "postcopy-requests":
> 0, "dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 0,
> "downtime-bytes": 0, "page-size": 4096, "remaining": 0,
> "postcopy-bytes": 0, "mbps": 188.63209192200557, "transferred":
> 496829, "precopy-bytes": 496829, "duplicate": 32849,
> "dirty-pages-rate": 0, "skipped": 0, "normal-bytes": 200704, "normal":
> 49}}}
> +{"return": {"status": "completed", "setup-time": 0, "downtime": 2448,
> "total-time": 2872, "ram": {"total": 134750208, "postcopy-requests":
> 0, "dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 0,
> "downtime-bytes": 0, "page-size": 4096, "remaining": 0,
> "postcopy-bytes": 0, "mbps": 188.63209192200557, "transferred":
> 496829, "precopy-bytes": 496829, "duplicate": 32849,
> "dirty-pages-rate": 0, "skipped": 0, "normal-bytes": 200704, "normal":
> 49}}}
> +{"return": {"status": "completed", "setup-time": 0, "downtime": 2448,
> "total-time": 2872, "ram": {"total": 134750208, "postcopy-requests":
> 0, "dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 0,
> "downtime-bytes": 0, "page-size": 4096, "remaining": 0,
> "postcopy-bytes": 0, "mbps": 188.63209192200557, "transferred":
> 496829, "precopy-bytes": 496829, "duplicate": 32849,
> "dirty-pages-rate": 0, "skipped": 0, "normal-bytes": 200704, "normal":
> 49}}}
> +{"return": {"status": "completed", "setup-time": 0, "downtime": 2448,
> "total-time": 2872, "ram": {"total": 134750208, "postcopy-requests":
> 0, "dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 0,
> "downtime-bytes": 0, "page-size": 4096, "remaining": 0,
> "postcopy-bytes": 0, "mbps": 188.63209192200557, "transferred":
> 496829, "precopy-bytes": 496829, "duplicate": 32849,
> "dirty-pages-rate": 0, "skipped": 0, "normal-bytes": 200704, "normal":
> 49}}}
> +{"return": {"status": "postmigrate", "singlestep": false, "running":
> false}}
> {"return": {}}
> {"timestamp": {"seconds": TIMESTAMP, "microseconds": TIMESTAMP},
> "event": "SHUTDOWN", "data": {"guest": false, "reason": "host-qmp-quit"}}
> {"timestamp": {"seconds": TIMESTAMP, "microseconds": TIMESTAMP},
> "event": "SHUTDOWN", "data": {"guest": false, "reason": "host-qmp-quit"}}
>
> Is that a known problem already? (I haven't seen anything
> related on the list)
I’ve never hit this so far.
The only things to try I can come up with would be to bisect, or to try
adding `silent=$silent` to the `_timed_wait_for` calls in `send_qemu_cmd`...
Hanna
^ permalink raw reply [flat|nested] 4+ messages in thread* Re: Failure in iotest 183
2022-07-05 9:58 ` Hanna Reitz
@ 2022-07-05 10:20 ` Thomas Huth
2022-07-21 9:01 ` Thomas Huth
0 siblings, 1 reply; 4+ messages in thread
From: Thomas Huth @ 2022-07-05 10:20 UTC (permalink / raw)
To: Hanna Reitz, Qemu-block, Kevin Wolf; +Cc: QEMU Developers
On 05/07/2022 11.58, Hanna Reitz wrote:
> On 05.07.22 11:35, Thomas Huth wrote:
>>
>> Hi!
>>
>> I've just hit a failure in iotest 183:
>>
>> --- /home/thuth/devel/qemu/tests/qemu-iotests/183.out
>> +++ /home/thuth/tmp/qemu-build/tests/qemu-iotests/scratch/183/183.out.bad
>> @@ -30,7 +30,7 @@
>> 'arguments': { 'uri': 'unix:SOCK_DIR/migrate', 'blk': true } }
>> {"return": {}}
>> { 'execute': 'query-status' }
>> -{"return": {"status": "postmigrate", "singlestep": false, "running": false}}
>> +{"return": {"status": "completed", "setup-time": 0, "downtime": 2448,
>> "total-time": 2872, "ram": {"total": 134750208, "postcopy-requests": 0,
>> "dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 0,
>> "downtime-bytes": 0, "page-size": 4096, "remaining": 0, "postcopy-bytes":
>> 0, "mbps": 188.63209192200557, "transferred": 496829, "precopy-bytes":
>> 496829, "duplicate": 32849, "dirty-pages-rate": 0, "skipped": 0,
>> "normal-bytes": 200704, "normal": 49}}}
>
> Weird because query-status cannot return something with '"status":
> "completed"' in it. We can see the '"status": "postmigrate"' object
> somewhere below, so it seems to me like the silent=yes part for the
> query-migrate execution didn’t work as intended.
>
> (And it does seem to work below, when waiting for a “100 %” to appear on
> $dest.)
>
> It’s been a while since we’ve touched common.qemu, so nothing comes to my
> mind immediately that might have broken this.
...
> I’ve never hit this so far.
>
> The only things to try I can come up with would be to bisect, or to try
> adding `silent=$silent` to the `_timed_wait_for` calls in `send_qemu_cmd`...
Seems also like it does not reproduce that easily, though - I've just seen
it once so far while running "make -j6 check SPEED=slow", so lots of other
stuff was happening at the same time. I'll keep an eye on it to see whether
I can reproduce it more easily somehow.
Thomas
^ permalink raw reply [flat|nested] 4+ messages in thread* Re: Failure in iotest 183
2022-07-05 10:20 ` Thomas Huth
@ 2022-07-21 9:01 ` Thomas Huth
0 siblings, 0 replies; 4+ messages in thread
From: Thomas Huth @ 2022-07-21 9:01 UTC (permalink / raw)
To: Hanna Reitz, Qemu-block, Kevin Wolf; +Cc: QEMU Developers
On 05/07/2022 12.20, Thomas Huth wrote:
> On 05/07/2022 11.58, Hanna Reitz wrote:
>> On 05.07.22 11:35, Thomas Huth wrote:
>>>
>>> Hi!
>>>
>>> I've just hit a failure in iotest 183:
>>>
>>> --- /home/thuth/devel/qemu/tests/qemu-iotests/183.out
>>> +++ /home/thuth/tmp/qemu-build/tests/qemu-iotests/scratch/183/183.out.bad
>>> @@ -30,7 +30,7 @@
>>> 'arguments': { 'uri': 'unix:SOCK_DIR/migrate', 'blk': true } }
>>> {"return": {}}
>>> { 'execute': 'query-status' }
>>> -{"return": {"status": "postmigrate", "singlestep": false, "running":
>>> false}}
>>> +{"return": {"status": "completed", "setup-time": 0, "downtime": 2448,
>>> "total-time": 2872, "ram": {"total": 134750208, "postcopy-requests": 0,
>>> "dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 0,
>>> "downtime-bytes": 0, "page-size": 4096, "remaining": 0, "postcopy-bytes":
>>> 0, "mbps": 188.63209192200557, "transferred": 496829, "precopy-bytes":
>>> 496829, "duplicate": 32849, "dirty-pages-rate": 0, "skipped": 0,
>>> "normal-bytes": 200704, "normal": 49}}}
>>
>> Weird because query-status cannot return something with '"status":
>> "completed"' in it. We can see the '"status": "postmigrate"' object
>> somewhere below, so it seems to me like the silent=yes part for the
>> query-migrate execution didn’t work as intended.
>>
>> (And it does seem to work below, when waiting for a “100 %” to appear on
>> $dest.)
>>
>> It’s been a while since we’ve touched common.qemu, so nothing comes to my
>> mind immediately that might have broken this.
> ...
>> I’ve never hit this so far.
>>
>> The only things to try I can come up with would be to bisect, or to try
>> adding `silent=$silent` to the `_timed_wait_for` calls in `send_qemu_cmd`...
>
> Seems also like it does not reproduce that easily, though - I've just seen
> it once so far while running "make -j6 check SPEED=slow", so lots of other
> stuff was happening at the same time. I'll keep an eye on it to see whether
> I can reproduce it more easily somehow.
I just reproduced it by running "./check -raw -j8" directly:
--- /home/thuth/devel/qemu/tests/qemu-iotests/183.out
+++ /home/thuth/tmp/qemu-build/tests/qemu-iotests/scratch/183/183.out.bad
@@ -30,7 +30,7 @@
'arguments': { 'uri': 'unix:SOCK_DIR/migrate', 'blk': true } }
{"return": {}}
{ 'execute': 'query-status' }
-{"return": {"status": "postmigrate", "singlestep": false, "running": false}}
+{"return": {"status": "completed", "setup-time": 0, "downtime": 1003,
"total-time": 1537, "ram": {"total": 134750208, "postcopy-requests": 0,
"dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 288578,
"downtime-bytes": 0, "page-size": 4096, "remaining": 0, "postcopy-bytes": 0,
"mbps": 352.48204554326611, "transferred": 497205, "precopy-bytes": 497205,
"duplicate": 32849, "dirty-pages-rate": 0, "skipped": 0, "normal-bytes":
200704, "normal": 49}}}
=== Do some I/O on the destination ===
@@ -53,8 +53,16 @@
=== Shut down and check image ===
{"execute":"quit"}
+{"return": {"status": "completed", "setup-time": 0, "downtime": 1003,
"total-time": 1537, "ram": {"total": 134750208, "postcopy-requests": 0,
"dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 288578,
"downtime-bytes": 0, "page-size": 4096, "remaining": 0, "postcopy-bytes": 0,
"mbps": 352.48204554326611, "transferred": 497205, "precopy-bytes": 497205,
"duplicate": 32849, "dirty-pages-rate": 0, "skipped": 0, "normal-bytes":
200704, "normal": 49}}}
+{"execute":"quit"}
{"return": {}}
-{"execute":"quit"}
+{"return": {"status": "completed", "setup-time": 0, "downtime": 1003,
"total-time": 1537, "ram": {"total": 134750208, "postcopy-requests": 0,
"dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 288578,
"downtime-bytes": 0, "page-size": 4096, "remaining": 0, "postcopy-bytes": 0,
"mbps": 352.48204554326611, "transferred": 497205, "precopy-bytes": 497205,
"duplicate": 32849, "dirty-pages-rate": 0, "skipped": 0, "normal-bytes":
200704, "normal": 49}}}
+{"return": {"status": "completed", "setup-time": 0, "downtime": 1003,
"total-time": 1537, "ram": {"total": 134750208, "postcopy-requests": 0,
"dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 288578,
"downtime-bytes": 0, "page-size": 4096, "remaining": 0, "postcopy-bytes": 0,
"mbps": 352.48204554326611, "transferred": 497205, "precopy-bytes": 497205,
"duplicate": 32849, "dirty-pages-rate": 0, "skipped": 0, "normal-bytes":
200704, "normal": 49}}}
+{"return": {"status": "completed", "setup-time": 0, "downtime": 1003,
"total-time": 1537, "ram": {"total": 134750208, "postcopy-requests": 0,
"dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 288578,
"downtime-bytes": 0, "page-size": 4096, "remaining": 0, "postcopy-bytes": 0,
"mbps": 352.48204554326611, "transferred": 497205, "precopy-bytes": 497205,
"duplicate": 32849, "dirty-pages-rate": 0, "skipped": 0, "normal-bytes":
200704, "normal": 49}}}
+{"return": {"status": "completed", "setup-time": 0, "downtime": 1003,
"total-time": 1537, "ram": {"total": 134750208, "postcopy-requests": 0,
"dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 288578,
"downtime-bytes": 0, "page-size": 4096, "remaining": 0, "postcopy-bytes": 0,
"mbps": 352.48204554326611, "transferred": 497205, "precopy-bytes": 497205,
"duplicate": 32849, "dirty-pages-rate": 0, "skipped": 0, "normal-bytes":
200704, "normal": 49}}}
+{"return": {"status": "completed", "setup-time": 0, "downtime": 1003,
"total-time": 1537, "ram": {"total": 134750208, "postcopy-requests": 0,
"dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 288578,
"downtime-bytes": 0, "page-size": 4096, "remaining": 0, "postcopy-bytes": 0,
"mbps": 352.48204554326611, "transferred": 497205, "precopy-bytes": 497205,
"duplicate": 32849, "dirty-pages-rate": 0, "skipped": 0, "normal-bytes":
200704, "normal": 49}}}
+{"return": {"status": "completed", "setup-time": 0, "downtime": 1003,
"total-time": 1537, "ram": {"total": 134750208, "postcopy-requests": 0,
"dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 288578,
"downtime-bytes": 0, "page-size": 4096, "remaining": 0, "postcopy-bytes": 0,
"mbps": 352.48204554326611, "transferred": 497205, "precopy-bytes": 497205,
"duplicate": 32849, "dirty-pages-rate": 0, "skipped": 0, "normal-bytes":
200704, "normal": 49}}}
+{"return": {"status": "postmigrate", "singlestep": false, "running": false}}
{"return": {}}
{"timestamp": {"seconds": TIMESTAMP, "microseconds": TIMESTAMP},
"event": "SHUTDOWN", "data": {"guest": false, "reason": "host-qmp-quit"}}
{"timestamp": {"seconds": TIMESTAMP, "microseconds": TIMESTAMP},
"event": "SHUTDOWN", "data": {"guest": false, "reason": "host-qmp-quit"}}
It does not seem to happen if I run with "-j1" instead.
Thomas
^ permalink raw reply [flat|nested] 4+ messages in thread
end of thread, other threads:[~2022-07-21 9:07 UTC | newest]
Thread overview: 4+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2022-07-05 9:35 Failure in iotest 183 Thomas Huth
2022-07-05 9:58 ` Hanna Reitz
2022-07-05 10:20 ` Thomas Huth
2022-07-21 9:01 ` Thomas Huth
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).