Re: Failure in iotest 183

[Thomas Huth]

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