xemu/tests
Paolo Bonzini eabc977973 AioContext: fix broken ctx->dispatching optimization
This patch rewrites the ctx->dispatching optimization, which was the cause
of some mysterious hangs that could be reproduced on aarch64 KVM only.
The hangs were indirectly caused by aio_poll() and in particular by
flash memory updates's call to blk_write(), which invokes aio_poll().
Fun stuff: they had an extremely short race window, so much that
adding all kind of tracing to either the kernel or QEMU made it
go away (a single printf made it half as reproducible).

On the plus side, the failure mode (a hang until the next keypress)
made it very easy to examine the state of the process with a debugger.
And there was a very nice reproducer from Laszlo, which failed pretty
often (more than half of the time) on any version of QEMU with a non-debug
kernel; it also failed fast, while still in the firmware.  So, it could
have been worse.

For some unknown reason they happened only with virtio-scsi, but
that's not important.  It's more interesting that they disappeared with
io=native, making thread-pool.c a likely suspect for where the bug arose.
thread-pool.c is also one of the few places which use bottom halves
across threads, by the way.

I hope that no other similar bugs exist, but just in case :) I am
going to describe how the successful debugging went...  Since the
likely culprit was the ctx->dispatching optimization, which mostly
affects bottom halves, the first observation was that there are two
qemu_bh_schedule() invocations in the thread pool: the one in the aio
worker and the one in thread_pool_completion_bh.  The latter always
causes the optimization to trigger, the former may or may not.  In
order to restrict the possibilities, I introduced new functions
qemu_bh_schedule_slow() and qemu_bh_schedule_fast():

     /* qemu_bh_schedule_slow: */
     ctx = bh->ctx;
     bh->idle = 0;
     if (atomic_xchg(&bh->scheduled, 1) == 0) {
         event_notifier_set(&ctx->notifier);
     }

     /* qemu_bh_schedule_fast: */
     ctx = bh->ctx;
     bh->idle = 0;
     assert(ctx->dispatching);
     atomic_xchg(&bh->scheduled, 1);

Notice how the atomic_xchg is still in qemu_bh_schedule_slow().  This
was already debated a few months ago, so I assumed it to be correct.
In retrospect this was a very good idea, as you'll see later.

Changing thread_pool_completion_bh() to qemu_bh_schedule_fast() didn't
trigger the assertion (as expected).  Changing the worker's invocation
to qemu_bh_schedule_slow() didn't hide the bug (another assumption
which luckily held).  This already limited heavily the amount of
interaction between the threads, hinting that the problematic events
must have triggered around thread_pool_completion_bh().

As mentioned early, invoking a debugger to examine the state of a
hung process was pretty easy; the iothread was always waiting on a
poll(..., -1) system call.  Infinite timeouts are much rarer on x86,
and this could be the reason why the bug was never observed there.
With the buggy sequence more or less resolved to an interaction between
thread_pool_completion_bh() and poll(..., -1), my "tracing" strategy was
to just add a few qemu_clock_get_ns(QEMU_CLOCK_REALTIME) calls, hoping
that the ordering of aio_ctx_prepare(), aio_ctx_dispatch, poll() and
qemu_bh_schedule_fast() would provide some hint.  The output was:

    (gdb) p last_prepare
    $3 = 103885451
    (gdb) p last_dispatch
    $4 = 103876492
    (gdb) p last_poll
    $5 = 115909333
    (gdb) p last_schedule
    $6 = 115925212

Notice how the last call to qemu_poll_ns() came after aio_ctx_dispatch().
This makes little sense unless there is an aio_poll() call involved,
and indeed with a slightly different instrumentation you can see that
there is one:

    (gdb) p last_prepare
    $3 = 107569679
    (gdb) p last_dispatch
    $4 = 107561600
    (gdb) p last_aio_poll
    $5 = 110671400
    (gdb) p last_schedule
    $6 = 110698917

So the scenario becomes clearer:

   iothread                   VCPU thread
--------------------------------------------------------------------------
   aio_ctx_prepare
   aio_ctx_check
   qemu_poll_ns(timeout=-1)
                              aio_poll
                                aio_dispatch
                                  thread_pool_completion_bh
                                    qemu_bh_schedule()

At this point bh->scheduled = 1 and the iothread has not been woken up.
The solution must be close, but this alone should not be a problem,
because the bottom half is only rescheduled to account for rare situations
(see commit 3c80ca1, thread-pool: avoid deadlock in nested aio_poll()
calls, 2014-07-15).

Introducing a third thread---a thread pool worker thread, which
also does qemu_bh_schedule()---does bring out the problematic case.
The third thread must be awakened *after* the callback is complete and
thread_pool_completion_bh has redone the whole loop, explaining the
short race window.  And then this is what happens:

                                                      thread pool worker
--------------------------------------------------------------------------
                                                      <I/O completes>
                                                      qemu_bh_schedule()

Tada, bh->scheduled is already 1, so qemu_bh_schedule() does nothing
and the iothread is never woken up.  This is where the bh->scheduled
optimization comes into play---it is correct, but removing it would
have masked the bug.

So, what is the bug?

Well, the question asked by the ctx->dispatching optimization ("is any
active aio_poll dispatching?") was wrong.  The right question to ask
instead is "is any active aio_poll *not* dispatching", i.e. in the prepare
or poll phases?  In that case, the aio_poll is sleeping or might go to
sleep anytime soon, and the EventNotifier must be invoked to wake
it up.

In any other case (including if there is *no* active aio_poll at all!)
we can just wait for the next prepare phase to pick up the event (e.g. a
bottom half); the prepare phase will avoid the blocking and service the
bottom half.

Expressing the invariant with a logic formula, the broken one looked like:

   !(exists(thread): in_dispatching(thread)) => !optimize

or equivalently:

   !(exists(thread):
          in_aio_poll(thread) && in_dispatching(thread)) => !optimize

In the correct one, the negation is in a slightly different place:

   (exists(thread):
         in_aio_poll(thread) && !in_dispatching(thread)) => !optimize

or equivalently:

   (exists(thread): in_prepare_or_poll(thread)) => !optimize

Even if the difference boils down to moving an exclamation mark :)
the implementation is quite different.  However, I think the new
one is simpler to understand.

In the old implementation, the "exists" was implemented with a boolean
value.  This didn't really support well the case of multiple concurrent
event loops, but I thought that this was okay: aio_poll holds the
AioContext lock so there cannot be concurrent aio_poll invocations, and
I was just considering nested event loops.  However, aio_poll _could_
indeed be concurrent with the GSource.  This is why I came up with the
wrong invariant.

In the new implementation, "exists" is computed simply by counting how many
threads are in the prepare or poll phases.  There are some interesting
points to consider, but the gist of the idea remains:

1) AioContext can be used through GSource as well; as mentioned in the
patch, bit 0 of the counter is reserved for the GSource.

2) the counter need not be updated for a non-blocking aio_poll, because
it won't sleep forever anyway.  This is just a matter of checking
the "blocking" variable.  This requires some changes to the win32
implementation, but is otherwise not too complicated.

3) as mentioned above, the new implementation will not call aio_notify
when there is *no* active aio_poll at all.  The tests have to be
adjusted for this change.  The calls to aio_notify in async.c are fine;
they only want to kick aio_poll out of a blocking wait, but need not
do anything if aio_poll is not running.

4) nested aio_poll: these just work with the new implementation; when
a nested event loop is invoked, the outer event loop is never in the
prepare or poll phases.  The outer event loop thus has already decremented
the counter.

Reported-by: Richard W. M. Jones <rjones@redhat.com>
Reported-by: Laszlo Ersek <lersek@redhat.com>
Signed-off-by: Paolo Bonzini <pbonzini@redhat.com>
Reviewed-by: Fam Zheng <famz@redhat.com>
Tested-by: Richard W.M. Jones <rjones@redhat.com>
Message-id: 1437487673-23740-5-git-send-email-pbonzini@redhat.com
Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
2015-07-22 12:41:40 +01:00
..
acpi-test-data acpi: update expected files for memory unplug 2015-05-11 09:21:37 +02:00
image-fuzzer block: delete cow block driver 2014-09-22 11:39:45 +01:00
libqos libqos/ahci: fix ahci_write_fis for ncq on ppc64 2015-07-08 11:46:16 -04:00
multiboot tests/multiboot: Add test for modules 2015-01-26 12:22:44 +01:00
qapi-schema qapi: Catch and reject flat union branch of array type 2015-06-18 14:19:47 +02:00
qemu-iotests iotests: Use event_wait in wait_ready 2015-07-02 10:06:23 +01:00
rocker rocker: tests: don't need to specify master/self when setting vlans 2015-07-07 13:13:22 +01:00
tcg target-xtensa: test cross-page opcode 2014-12-17 05:49:32 +03:00
vmstate-static-checker-data tests: vmstate static checker: add size mismatch inside substructure 2014-06-23 19:14:52 +02:00
.gitignore crypto: introduce generic cipher API & built-in implementation 2015-07-08 13:11:01 +02:00
ac97-test.c tests: Add ac97 qtest 2014-05-05 20:58:33 +02:00
ahci-test.c qtest/ahci: halted ncq migration test 2015-07-04 02:06:05 -04:00
bios-tables-test.c bios-tables-test: handle false-positive smbios signature matches 2015-06-10 08:06:47 +02:00
boot-order-test.c qtest: Use -display none by default 2013-11-19 10:28:14 +01:00
check-block.sh Add 'make check-block' 2012-03-12 15:14:07 +01:00
check-qdict.c check-qdict: Test cases for new functions 2015-06-12 16:58:06 +02:00
check-qfloat.c qapi: move include files to include/qobject/ 2012-12-19 08:31:31 +01:00
check-qint.c qapi: move include files to include/qobject/ 2012-12-19 08:31:31 +01:00
check-qjson.c qobject: Use 'bool' for qbool 2015-06-22 17:40:00 +02:00
check-qlist.c qapi: move include files to include/qobject/ 2012-12-19 08:31:31 +01:00
check-qom-interface.c tests: Test QOM interface casting 2013-12-24 17:27:17 +01:00
check-qom-proplist.c qom: Don't pass string table to object_get_enum() function 2015-06-19 18:42:48 +02:00
check-qstring.c qapi: move include files to include/qobject/ 2012-12-19 08:31:31 +01:00
display-vga-test.c virtio-gpu: add to display-vga test 2015-07-07 11:23:18 +02:00
drive_del-test.c qtests: Specify image format explicitly 2014-12-10 10:31:12 +01:00
e1000-test.c tests: Use qtest_add_data_func() consistently 2015-06-19 10:29:14 +02:00
eepro100-test.c tests: Use qtest_add_data_func() consistently 2015-06-19 10:29:14 +02:00
endianness-test.c tests: Use qtest_add_data_func() consistently 2015-06-19 10:29:14 +02:00
es1370-test.c tests: Add es1370 qtest 2014-05-05 20:58:33 +02:00
fdc-test.c fdc-test: Test state for existing cases more thoroughly 2015-06-02 13:34:45 -04:00
fw_cfg-test.c fw_cfg-test: Fix test path to include architecture 2015-03-30 19:19:42 +02:00
hd-geo-test.c tests/hd-geo-test.c: Remove unused test_image variable 2015-01-15 10:44:13 +03:00
i440fx-test.c i440fx-test: Fix test paths to include architecture 2015-03-30 19:24:54 +02:00
i82801b11-test.c tests: Add i82801b11 qtest 2014-03-31 22:36:17 +02:00
ide-test.c qtest/ide: add another short PRDT test flavor 2015-07-20 12:21:18 -04:00
intel-hda-test.c tests: Add intel-hda qtests 2014-05-05 20:58:33 +02:00
ioh3420-test.c tests: Add ioh3420 qtest 2014-05-05 20:58:33 +02:00
ipoctal232-test.c tests: Add ipoctal232 qtest 2014-02-14 21:07:13 +01:00
libqtest.c qtest: pre-buffer hex nibs 2015-05-22 15:58:22 -04:00
libqtest.h qtest: Add base64 encoded read/write 2015-05-22 15:58:22 -04:00
m48t59-test.c qtest: Include system headers before user headers 2014-02-17 23:10:02 +01:00
Makefile tests: Fix broken targets check-report-qtest-* 2015-07-20 14:26:41 -04:00
ne2000-test.c tests: Add ne2000 qtest 2014-02-14 20:50:19 +01:00
nvme-test.c qtests: Specify image format explicitly 2014-12-10 10:31:12 +01:00
pc-cpu-test.c tests: Use qtest_add_data_func() consistently 2015-06-19 10:29:14 +02:00
pcnet-test.c tests: Add pcnet qtest 2014-02-14 16:22:33 +01:00
pvpanic-test.c pvpanic-test: Assert pause event 2014-03-31 22:36:17 +02:00
q35-test.c q35: add test for SMRAM.D_LCK 2015-06-05 19:45:09 +02:00
qemu-iotests-quick.sh qemu-iotests: Speed up make check-block 2015-01-13 11:47:55 +00:00
qom-test.c tests: Use qtest_add_data_func() consistently 2015-06-19 10:29:14 +02:00
rcutorture.c rcu tests: fix compilation on 32-bit ppc 2015-03-25 13:37:10 +01:00
rtc-test.c qtest: Include system headers before user headers 2014-02-17 23:10:02 +01:00
rtl8139-test.c timer: rename NSEC_PER_SEC due to Mac OS X header clash 2015-07-20 17:01:00 +01:00
spapr-phb-test.c tests: Add spapr-pci-host-bridge qtest 2014-03-13 01:21:57 +01:00
tco-test.c tco-test: fix up config accesses and re-enable 2015-07-08 12:38:30 +03:00
test-aio.c AioContext: fix broken ctx->dispatching optimization 2015-07-22 12:41:40 +01:00
test-bitops.c tests: Add missing include to test-bitops.c 2014-11-02 10:04:34 +03:00
test-coroutine.c test-coroutine: Regression test for yield bug 2015-03-09 11:11:59 +01:00
test-crypto-cipher.c crypto: introduce generic cipher API & built-in implementation 2015-07-08 13:11:01 +02:00
test-crypto-hash.c crypto: introduce new module for computing hash digests 2015-07-07 12:04:07 +02:00
test-cutils.c cutils: unsigned int parsing functions 2013-02-04 14:38:33 -06:00
test-hbitmap.c util/hbitmap: Add an API to reset all set bits in hbitmap 2015-06-23 15:06:16 +01:00
test-int128.c tests/test-int128: Don't use __noclone__ attribute on clang 2014-03-02 17:20:37 +04:00
test-iov.c test-iov: add iov_discard_front/back() testcases 2013-01-02 15:58:09 +01:00
test-mul64.c tests: Add unit tests for mulu64 and muls64 2013-02-17 14:28:58 +00:00
test-opts-visitor.c QemuOpts: Wean off qerror_report_err() 2015-06-22 18:20:39 +02:00
test-qdev-global-props.c qdev: Move global validation to a single function 2014-09-18 21:51:24 +03:00
test-qemu-opts.c QemuOpts: Wean off qerror_report_err() 2015-06-22 18:20:39 +02:00
test-qmp-commands.c qapi: Support downstream events and commands 2015-05-14 18:21:27 +02:00
test-qmp-event.c qobject: Use 'bool' for qbool 2015-06-22 17:40:00 +02:00
test-qmp-input-strict.c qapi: Merge UserDefTwo and UserDefNested in tests 2015-05-05 18:39:02 +02:00
test-qmp-input-visitor.c qapi: Drop tests for inline nested structs 2015-05-05 18:39:02 +02:00
test-qmp-output-visitor.c qobject: Use 'bool' inside qdict 2015-06-22 17:40:00 +02:00
test-rcu-list.c rcu tests: fix compilation on 32-bit ppc 2015-03-25 13:37:10 +01:00
test-rfifolock.c rfifolock: add recursive FIFO lock 2014-03-13 14:42:21 +01:00
test-string-input-visitor.c tests: simplify code 2014-06-19 18:44:22 +03:00
test-string-output-visitor.c tests: Fix unterminated string output visitor enum human string 2014-07-14 12:03:20 +02:00
test-thread-pool.c block: Rename BlockDriverAIOCB* to BlockAIOCB* 2014-10-20 13:41:27 +02:00
test-throttle.c timer: rename NSEC_PER_SEC due to Mac OS X header clash 2015-07-20 17:01:00 +01:00
test-visitor-serialization.c qapi: Drop tests for inline nested structs 2015-05-05 18:39:02 +02:00
test-vmstate.c migration: Append JSON description of migration stream 2015-02-05 17:16:14 +01:00
test-write-threshold.c block: add event when disk usage exceeds threshold 2015-02-06 17:24:21 +01:00
test-x86-cpuid.c target-i386: Move topology.h to include/hw/i386 2015-03-09 16:30:02 -03:00
test-xbzrle.c Add XBZRLE testing 2013-02-01 08:32:20 +01:00
tmp105-test.c libqtest: escape strings in QMP commands, fix leak 2014-07-01 10:20:41 +02:00
tpci200-test.c tests: Add tpci200 qtest 2014-02-14 21:02:27 +01:00
usb-hcd-ehci-test.c tests: usb: Generic usb device hotplug 2014-10-15 05:03:13 +02:00
usb-hcd-ohci-test.c misc: fix typos in copyright declaration 2015-03-26 14:21:43 +01:00
usb-hcd-uhci-test.c misc: fix typos in copyright declaration 2015-03-26 14:21:43 +01:00
usb-hcd-xhci-test.c misc: fix typos in copyright declaration 2015-03-26 14:21:43 +01:00
vhost-user-test.c vhost-user-test: Fix 'make check' broken on glib < 2.26 2014-11-05 12:53:08 +00:00
virtio-9p-test.c tests: Add virtio-9p qtest 2014-03-31 22:35:50 +02:00
virtio-balloon-test.c tests: Add virtio-balloon qtest 2014-03-13 01:21:56 +01:00
virtio-blk-test.c tests: Check QVIRTIO_F_ANY_LAYOUT flag in virtio-blk test 2015-03-10 14:02:23 +01:00
virtio-console-test.c virtio-console-test: Test virtserialport as well 2014-03-13 21:12:07 +01:00
virtio-net-test.c tests: virtio-net: Check if hot-plug/unplug works 2014-10-15 05:03:12 +02:00
virtio-rng-test.c tests: virtio-rng: Check if hot-plug/unplug works 2014-10-15 05:03:12 +02:00
virtio-scsi-test.c tests: virtio-scsi: Add test for unaligned WRITE SAME 2015-06-19 12:27:12 +02:00
virtio-serial-test.c tests: virtio-serial: Check if hot-plug/unplug works 2014-10-15 05:03:12 +02:00
vmxnet3-test.c tests: Add vmxnet3 qtest 2014-02-14 16:22:33 +01:00
wdt_ib700-test.c timer: rename NSEC_PER_SEC due to Mac OS X header clash 2015-07-20 17:01:00 +01:00