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
