)]}' { "commit": "eabc977973103527bbb8fed69c91cfaa6691f8ab", "tree": "3e777c3809cc2982d6da2322364bd2f650f1c759", "parents": [ "6493c975af75be5b8d9ade954239bdf5492b7911" ], "author": { "name": "Paolo Bonzini", "email": "pbonzini@redhat.com", "time": "Tue Jul 21 16:07:51 2015 +0200" }, "committer": { "name": "Stefan Hajnoczi", "email": "stefanha@redhat.com", "time": "Wed Jul 22 12:41:40 2015 +0100" }, "message": "AioContext: fix broken ctx-\u003edispatching optimization\n\nThis patch rewrites the ctx-\u003edispatching optimization, which was the cause\nof some mysterious hangs that could be reproduced on aarch64 KVM only.\nThe hangs were indirectly caused by aio_poll() and in particular by\nflash memory updates\u0027s call to blk_write(), which invokes aio_poll().\nFun stuff: they had an extremely short race window, so much that\nadding all kind of tracing to either the kernel or QEMU made it\ngo away (a single printf made it half as reproducible).\n\nOn the plus side, the failure mode (a hang until the next keypress)\nmade it very easy to examine the state of the process with a debugger.\nAnd there was a very nice reproducer from Laszlo, which failed pretty\noften (more than half of the time) on any version of QEMU with a non-debug\nkernel; it also failed fast, while still in the firmware. So, it could\nhave been worse.\n\nFor some unknown reason they happened only with virtio-scsi, but\nthat\u0027s not important. It\u0027s more interesting that they disappeared with\nio\u003dnative, making thread-pool.c a likely suspect for where the bug arose.\nthread-pool.c is also one of the few places which use bottom halves\nacross threads, by the way.\n\nI hope that no other similar bugs exist, but just in case :) I am\ngoing to describe how the successful debugging went... Since the\nlikely culprit was the ctx-\u003edispatching optimization, which mostly\naffects bottom halves, the first observation was that there are two\nqemu_bh_schedule() invocations in the thread pool: the one in the aio\nworker and the one in thread_pool_completion_bh. The latter always\ncauses the optimization to trigger, the former may or may not. In\norder to restrict the possibilities, I introduced new functions\nqemu_bh_schedule_slow() and qemu_bh_schedule_fast():\n\n /* qemu_bh_schedule_slow: */\n ctx \u003d bh-\u003ectx;\n bh-\u003eidle \u003d 0;\n if (atomic_xchg(\u0026bh-\u003escheduled, 1) \u003d\u003d 0) {\n event_notifier_set(\u0026ctx-\u003enotifier);\n }\n\n /* qemu_bh_schedule_fast: */\n ctx \u003d bh-\u003ectx;\n bh-\u003eidle \u003d 0;\n assert(ctx-\u003edispatching);\n atomic_xchg(\u0026bh-\u003escheduled, 1);\n\nNotice how the atomic_xchg is still in qemu_bh_schedule_slow(). This\nwas already debated a few months ago, so I assumed it to be correct.\nIn retrospect this was a very good idea, as you\u0027ll see later.\n\nChanging thread_pool_completion_bh() to qemu_bh_schedule_fast() didn\u0027t\ntrigger the assertion (as expected). Changing the worker\u0027s invocation\nto qemu_bh_schedule_slow() didn\u0027t hide the bug (another assumption\nwhich luckily held). This already limited heavily the amount of\ninteraction between the threads, hinting that the problematic events\nmust have triggered around thread_pool_completion_bh().\n\nAs mentioned early, invoking a debugger to examine the state of a\nhung process was pretty easy; the iothread was always waiting on a\npoll(..., -1) system call. Infinite timeouts are much rarer on x86,\nand this could be the reason why the bug was never observed there.\nWith the buggy sequence more or less resolved to an interaction between\nthread_pool_completion_bh() and poll(..., -1), my \"tracing\" strategy was\nto just add a few qemu_clock_get_ns(QEMU_CLOCK_REALTIME) calls, hoping\nthat the ordering of aio_ctx_prepare(), aio_ctx_dispatch, poll() and\nqemu_bh_schedule_fast() would provide some hint. The output was:\n\n (gdb) p last_prepare\n $3 \u003d 103885451\n (gdb) p last_dispatch\n $4 \u003d 103876492\n (gdb) p last_poll\n $5 \u003d 115909333\n (gdb) p last_schedule\n $6 \u003d 115925212\n\nNotice how the last call to qemu_poll_ns() came after aio_ctx_dispatch().\nThis makes little sense unless there is an aio_poll() call involved,\nand indeed with a slightly different instrumentation you can see that\nthere is one:\n\n (gdb) p last_prepare\n $3 \u003d 107569679\n (gdb) p last_dispatch\n $4 \u003d 107561600\n (gdb) p last_aio_poll\n $5 \u003d 110671400\n (gdb) p last_schedule\n $6 \u003d 110698917\n\nSo the scenario becomes clearer:\n\n iothread VCPU thread\n--------------------------------------------------------------------------\n aio_ctx_prepare\n aio_ctx_check\n qemu_poll_ns(timeout\u003d-1)\n aio_poll\n aio_dispatch\n thread_pool_completion_bh\n qemu_bh_schedule()\n\nAt this point bh-\u003escheduled \u003d 1 and the iothread has not been woken up.\nThe solution must be close, but this alone should not be a problem,\nbecause the bottom half is only rescheduled to account for rare situations\n(see commit 3c80ca1, thread-pool: avoid deadlock in nested aio_poll()\ncalls, 2014-07-15).\n\nIntroducing a third thread---a thread pool worker thread, which\nalso does qemu_bh_schedule()---does bring out the problematic case.\nThe third thread must be awakened *after* the callback is complete and\nthread_pool_completion_bh has redone the whole loop, explaining the\nshort race window. And then this is what happens:\n\n thread pool worker\n--------------------------------------------------------------------------\n \u003cI/O completes\u003e\n qemu_bh_schedule()\n\nTada, bh-\u003escheduled is already 1, so qemu_bh_schedule() does nothing\nand the iothread is never woken up. This is where the bh-\u003escheduled\noptimization comes into play---it is correct, but removing it would\nhave masked the bug.\n\nSo, what is the bug?\n\nWell, the question asked by the ctx-\u003edispatching optimization (\"is any\nactive aio_poll dispatching?\") was wrong. The right question to ask\ninstead is \"is any active aio_poll *not* dispatching\", i.e. in the prepare\nor poll phases? In that case, the aio_poll is sleeping or might go to\nsleep anytime soon, and the EventNotifier must be invoked to wake\nit up.\n\nIn any other case (including if there is *no* active aio_poll at all!)\nwe can just wait for the next prepare phase to pick up the event (e.g. a\nbottom half); the prepare phase will avoid the blocking and service the\nbottom half.\n\nExpressing the invariant with a logic formula, the broken one looked like:\n\n !(exists(thread): in_dispatching(thread)) \u003d\u003e !optimize\n\nor equivalently:\n\n !(exists(thread):\n in_aio_poll(thread) \u0026\u0026 in_dispatching(thread)) \u003d\u003e !optimize\n\nIn the correct one, the negation is in a slightly different place:\n\n (exists(thread):\n in_aio_poll(thread) \u0026\u0026 !in_dispatching(thread)) \u003d\u003e !optimize\n\nor equivalently:\n\n (exists(thread): in_prepare_or_poll(thread)) \u003d\u003e !optimize\n\nEven if the difference boils down to moving an exclamation mark :)\nthe implementation is quite different. However, I think the new\none is simpler to understand.\n\nIn the old implementation, the \"exists\" was implemented with a boolean\nvalue. This didn\u0027t really support well the case of multiple concurrent\nevent loops, but I thought that this was okay: aio_poll holds the\nAioContext lock so there cannot be concurrent aio_poll invocations, and\nI was just considering nested event loops. However, aio_poll _could_\nindeed be concurrent with the GSource. This is why I came up with the\nwrong invariant.\n\nIn the new implementation, \"exists\" is computed simply by counting how many\nthreads are in the prepare or poll phases. There are some interesting\npoints to consider, but the gist of the idea remains:\n\n1) AioContext can be used through GSource as well; as mentioned in the\npatch, bit 0 of the counter is reserved for the GSource.\n\n2) the counter need not be updated for a non-blocking aio_poll, because\nit won\u0027t sleep forever anyway. This is just a matter of checking\nthe \"blocking\" variable. This requires some changes to the win32\nimplementation, but is otherwise not too complicated.\n\n3) as mentioned above, the new implementation will not call aio_notify\nwhen there is *no* active aio_poll at all. The tests have to be\nadjusted for this change. The calls to aio_notify in async.c are fine;\nthey only want to kick aio_poll out of a blocking wait, but need not\ndo anything if aio_poll is not running.\n\n4) nested aio_poll: these just work with the new implementation; when\na nested event loop is invoked, the outer event loop is never in the\nprepare or poll phases. The outer event loop thus has already decremented\nthe counter.\n\nReported-by: Richard W. M. Jones \u003crjones@redhat.com\u003e\nReported-by: Laszlo Ersek \u003clersek@redhat.com\u003e\nSigned-off-by: Paolo Bonzini \u003cpbonzini@redhat.com\u003e\nReviewed-by: Fam Zheng \u003cfamz@redhat.com\u003e\nTested-by: Richard W.M. Jones \u003crjones@redhat.com\u003e\nMessage-id: 1437487673-23740-5-git-send-email-pbonzini@redhat.com\nSigned-off-by: Stefan Hajnoczi \u003cstefanha@redhat.com\u003e\n", "tree_diff": [ { "type": "modify", "old_id": "4abec38866ca8d1a8d7415865e6375a9b7380216", "old_mode": 33188, "old_path": "aio-posix.c", "new_id": "249889f14ce2a895fc6226422b1bef83310374de", "new_mode": 33188, "new_path": "aio-posix.c" }, { "type": "modify", "old_id": "9268b5c9fc35dc6b03da82a548b216d48022a9d9", "old_mode": 33188, "old_path": "aio-win32.c", "new_id": "ea655b0935dd4577be30bcacc5f2fc13e9971da6", "new_mode": 33188, "new_path": "aio-win32.c" }, { "type": "modify", "old_id": "77d080d6f5d6f8b28ce185444f5d4a32989e37e6", "old_mode": 33188, "old_path": "async.c", "new_id": "a23219214836d6ff221ede489d53d9751c282323", "new_mode": 33188, "new_path": "async.c" }, { "type": "modify", "old_id": "ad3f6f08b0d02541624d72642eb3c242da010164", "old_mode": 33188, "old_path": "docs/aio_notify.promela", "new_id": "fccc7ee1c393f80ca062e38c61998e98c6bb8f81", "new_mode": 33188, "new_path": "docs/aio_notify.promela" }, { "type": "modify", "old_id": "b46103ece71c26170b7cd5d07b537dbbf24d322f", "old_mode": 33188, "old_path": "include/block/aio.h", "new_id": "be91e3f7014d55ad585bd80dcdf4694bad992553", "new_mode": 33188, "new_path": "include/block/aio.h" }, { "type": "modify", "old_id": "e7bbb8345ac759d204b50601510ee37b6190c9c4", "old_mode": 33188, "old_path": "tests/test-aio.c", "new_id": "217e33772ec11327f99e22e8db69ddd4eaf1f1b4", "new_mode": 33188, "new_path": "tests/test-aio.c" } ] }