Re: [Qemu-devel] [PATCH] AioContext: fix broken ctx-dispatching optimization
On 16/07/2015 11:14, Kevin Wolf wrote: With this information, I understand that what has changed is that the return value of g_main_context_iteration() changes from true before this patch (had the aio_notify() from aio_set_fd_handler() pending) to false after the patch (aio_notify() doesn't inject an event any more). This should mean that like above we can assert that the first iteration returns false, i.e. reverse the assertion (and indeed, with this change the test still passes for me). I was a bit undecided about this. In the end I decided that the calls to aio_poll/g_main_context_iteration were just to put the AioContext in a known state, and the assertions on the return value of g_assert were not really important. For this reason, the while loop seemed to express the intentions best, and I made it consistent between the AioContext and GSource cases. You changed the AioContext case in this same patch, even if you didn't quote my comment on that hunk. :-) Both cases were asserting the return value before. I'll change the testcase (other than the aio_notify testcase) in a separate patch. Paolo
Re: [Qemu-devel] [PATCH] AioContext: fix broken ctx-dispatching optimization
Am 16.07.2015 um 00:59 hat Paolo Bonzini geschrieben:
On 15/07/2015 22:14, Kevin Wolf wrote:
index 233d8f5..ae7c6cf 100644
--- a/aio-win32.c
+++ b/aio-win32.c
@@ -318,11 +313,11 @@ bool aio_poll(AioContext *ctx, bool blocking)
first = true;
/* wait until next event */
-while (count 0) {
+do {
HANDLE event;
int ret;
-timeout = blocking
+timeout = blocking !have_select_revents
? qemu_timeout_ns_to_ms(aio_compute_timeout(ctx)) : 0;
if (timeout) {
aio_context_release(ctx);
Here I'm not sure why you switched to a do..while loop? It's not obvious
to me how the change from aio_set_dispatching() to ctx-notify_me is
related to this.
I sort of expected a reviewer to ask me about this change. I would have
explained this in the commit message, but it was already long enough. :)
Rather than an extra section in the commit message, it should have been
a comment in the code at least because it's not just the change that is
confusing, but the resulting code is confusing as well.
The reason is that, at least to me, the do..while loop reads almost
like an assertion that count may indeed be 0.
The count on entry is never zero, because the ctx-notifier is always
registered.
I changed the while to do...while so that it's obvious that
ctx-notify_me is always decremented.
In retrospect I could have added simply
/* ctx-notifier is always registered. */
assert(count 0);
above the do.
Yes, please do that, it should be much clearer.
With this information, I understand that what has changed is that the
return value of g_main_context_iteration() changes from true before this
patch (had the aio_notify() from aio_set_fd_handler() pending) to false
after the patch (aio_notify() doesn't inject an event any more).
This should mean that like above we can assert that the first iteration
returns false, i.e. reverse the assertion (and indeed, with this
change the test still passes for me).
I was a bit undecided about this. In the end I decided that the calls
to aio_poll/g_main_context_iteration were just to put the AioContext in
a known state, and the assertions on the return value of g_assert were
not really important. For this reason, the while loop seemed to express
the intentions best, and I made it consistent between the AioContext and
GSource cases.
You changed the AioContext case in this same patch, even if you didn't
quote my comment on that hunk. :-)
Both cases were asserting the return value before.
Kevin
Re: [Qemu-devel] [PATCH] AioContext: fix broken ctx-dispatching optimization
On 16/07/2015 07:29, Fam Zheng wrote: This patch rewrites the ctx-dispatching optimization I lost track, but what was the justification of this optimization? qemu_bh_schedule's call to aio_notify were showing in the profile as 20% or so. Paolo Anyway, awesome debugging and explanations!
Re: [Qemu-devel] [PATCH] AioContext: fix broken ctx-dispatching optimization
On Thu, Jul 16, 2015 at 01:29:20PM +0800, Fam Zheng wrote: On Wed, 07/15 19:13, Paolo Bonzini wrote: This patch rewrites the ctx-dispatching optimization I lost track, but what was the justification of this optimization? To avoid signalling the event notifier when it's not necessary. pgpOBgCfD5TyW.pgp Description: PGP signature
Re: [Qemu-devel] [PATCH] AioContext: fix broken ctx-dispatching optimization
On Wed, Jul 15, 2015 at 07:13:23PM +0200, Paolo Bonzini wrote:
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,
Re: [Qemu-devel] [PATCH] AioContext: fix broken ctx-dispatching optimization
On Wed, 07/15 19:13, Paolo Bonzini wrote: This patch rewrites the ctx-dispatching optimization I lost track, but what was the justification of this optimization? Anyway, awesome debugging and explanations! Fam
Re: [Qemu-devel] [PATCH] AioContext: fix broken ctx-dispatching optimization
comments below
On 07/15/15 19:13, Paolo Bonzini wrote:
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,
[Qemu-devel] [PATCH] 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
Re: [Qemu-devel] [PATCH] AioContext: fix broken ctx-dispatching optimization
On 15/07/2015 22:14, Kevin Wolf wrote:
index 233d8f5..ae7c6cf 100644
--- a/aio-win32.c
+++ b/aio-win32.c
@@ -318,11 +313,11 @@ bool aio_poll(AioContext *ctx, bool blocking)
first = true;
/* wait until next event */
-while (count 0) {
+do {
HANDLE event;
int ret;
-timeout = blocking
+timeout = blocking !have_select_revents
? qemu_timeout_ns_to_ms(aio_compute_timeout(ctx)) : 0;
if (timeout) {
aio_context_release(ctx);
Here I'm not sure why you switched to a do..while loop? It's not obvious
to me how the change from aio_set_dispatching() to ctx-notify_me is
related to this.
I sort of expected a reviewer to ask me about this change. I would have
explained this in the commit message, but it was already long enough. :)
The count on entry is never zero, because the ctx-notifier is always
registered.
I changed the while to do...while so that it's obvious that
ctx-notify_me is always decremented.
In retrospect I could have added simply
/* ctx-notifier is always registered. */
assert(count 0);
above the do.
With this information, I understand that what has changed is that the
return value of g_main_context_iteration() changes from true before this
patch (had the aio_notify() from aio_set_fd_handler() pending) to false
after the patch (aio_notify() doesn't inject an event any more).
This should mean that like above we can assert that the first iteration
returns false, i.e. reverse the assertion (and indeed, with this
change the test still passes for me).
I was a bit undecided about this. In the end I decided that the calls
to aio_poll/g_main_context_iteration were just to put the AioContext in
a known state, and the assertions on the return value of g_assert were
not really important. For this reason, the while loop seemed to express
the intentions best, and I made it consistent between the AioContext and
GSource cases.
Paolo
Re: [Qemu-devel] [PATCH] AioContext: fix broken ctx-dispatching optimization
Am 15.07.2015 um 19:13 hat Paolo Bonzini geschrieben:
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).
[...]
Awesome commit message. :-)
Took a while to read, think about and understand everything, but you did
a great job on describing the bug. In the end, all the information I
needed was there.
I'm not sure if you want to trust my review, considering that I failed
the first time around, but for the most part, this looks good to me.
diff --git a/aio-win32.c b/aio-win32.c
index 233d8f5..ae7c6cf 100644
--- a/aio-win32.c
+++ b/aio-win32.c
@@ -318,11 +313,11 @@ bool aio_poll(AioContext *ctx, bool blocking)
first = true;
/* wait until next event */
-while (count 0) {
+do {
HANDLE event;
int ret;
-timeout = blocking
+timeout = blocking !have_select_revents
? qemu_timeout_ns_to_ms(aio_compute_timeout(ctx)) : 0;
if (timeout) {
aio_context_release(ctx);
Here I'm not sure why you switched to a do..while loop? It's not obvious
to me how the change from aio_set_dispatching() to ctx-notify_me is
related to this.
Does it mean that we can call WaitForMultipleObjects() with nCount == 0?
This seems to be forbidden.
diff --git a/tests/test-aio.c b/tests/test-aio.c
index a7cb5c9..217e337 100644
--- a/tests/test-aio.c
+++ b/tests/test-aio.c
@@ -97,14 +97,6 @@ static void event_ready_cb(EventNotifier *e)
/* Tests using aio_*. */
-static void test_notify(void)
-{
-g_assert(!aio_poll(ctx, false));
-aio_notify(ctx);
-g_assert(!aio_poll(ctx, true));
-g_assert(!aio_poll(ctx, false));
-}
-
typedef struct {
QemuMutex start_lock;
bool thread_acquired;
Okay. We don't actually notify any more, so this test hangs now.
Removing seems fine.
@@ -331,7 +323,7 @@ static void test_wait_event_notifier(void)
EventNotifierTestData data = { .n = 0, .active = 1 };
event_notifier_init(data.e, false);
aio_set_event_notifier(ctx, data.e, event_ready_cb);
-g_assert(!aio_poll(ctx, false));
+while (aio_poll(ctx, false));
g_assert_cmpint(data.n, ==, 0);
g_assert_cmpint(data.active, ==, 1);
@@ -356,7 +348,7 @@ static void test_flush_event_notifier(void)
EventNotifierTestData data = { .n = 0, .active = 10, .auto_set = true };
event_notifier_init(data.e, false);
aio_set_event_notifier(ctx, data.e, event_ready_cb);
-g_assert(!aio_poll(ctx, false));
+while (aio_poll(ctx, false));
g_assert_cmpint(data.n, ==, 0);
g_assert_cmpint(data.active, ==, 10);
These two hunks I don't understand. Where would an event come from that
needs to be handled here?
With these hunks reverted, the test still passes for me.
@@ -494,14 +486,6 @@ static void test_timer_schedule(void)
* works well, and that's what I am using.
*/
-static void test_source_notify(void)
-{
-while (g_main_context_iteration(NULL, false));
-aio_notify(ctx);
-g_assert(g_main_context_iteration(NULL, true));
-g_assert(!g_main_context_iteration(NULL, false));
-}
Same as above, good.
static void test_source_flush(void)
{
g_assert(!g_main_context_iteration(NULL, false));
@@ -669,7 +653,7 @@ static void test_source_wait_event_notifier(void)
EventNotifierTestData data = { .n = 0, .active = 1 };
event_notifier_init(data.e, false);
aio_set_event_notifier(ctx, data.e, event_ready_cb);
-g_assert(g_main_context_iteration(NULL, false));
+while (g_main_context_iteration(NULL, false));
g_assert_cmpint(data.n, ==, 0);
g_assert_cmpint(data.active, ==, 1);
@@ -694,7 +678,7 @@ static void test_source_flush_event_notifier(void)
EventNotifierTestData data = { .n = 0, .active = 10, .auto_set = true };
event_notifier_init(data.e, false);
aio_set_event_notifier(ctx, data.e, event_ready_cb);
-g_assert(g_main_context_iteration(NULL, false));
+while (g_main_context_iteration(NULL, false));
g_assert_cmpint(data.n, ==, 0);
g_assert_cmpint(data.active, ==, 10);
Okay, this one is confusing. Took me a while to realise that aio_poll()
returns false when the only event is an aio_notify(), whereas
g_main_context_iteration() returns true in the same case.
With this information, I understand that what has changed is that the
return value of g_main_context_iteration() changes from true before this
patch (had the aio_notify() from aio_set_fd_handler() pending) to false
after the patch (aio_notify() doesn't inject an event any more).
This
