[Qemu-devel] [PATCH v2 0/3] AioContext: ctx->dispatching is dead, all hail ctx->notify_me

[Qemu-devel] [PATCH v2 0/3] AioContext: ctx->dispatching is dead, all hail ctx->notify_me

[Paolo Bonzini]

Apart from an additional assertion this is exactly the same code as v1,
but split across three patches so that the important one focuses on the
optimization.

Paolo

v1->v2
        Split some changes to the tests to a separate patch
        Fix commit message [Laszlo]
        Clarify do...while loop in aio-win32.c [Kevin]

Paolo Bonzini (3):
  tests: remove irrelevant assertions from test-aio
  aio-win32: reorganize polling loop
  AioContext: fix broken ctx->dispatching optimization

 aio-posix.c             | 19 ++++++------
 aio-win32.c             | 41 ++++++++++++++------------
 async.c                 | 21 +++++---------
 docs/aio_notify.promela | 77 +++++++++++++++++++++----------------------------
 include/block/aio.h     | 29 +++++++++++++++----
 tests/test-aio.c        | 26 +++--------------
 6 files changed, 98 insertions(+), 115 deletions(-)

-- 
2.4.3

diff from v1:
diff --git a/aio-win32.c b/aio-win32.c
index ae7c6cf..9d6c12f 100644
--- a/aio-win32.c
+++ b/aio-win32.c
@@ -312,7 +312,13 @@ bool aio_poll(AioContext *ctx, bool blocking)
     ctx->walking_handlers--;
     first = true;
 
-    /* wait until next event */
+    /* ctx->notifier is always registered.  */
+    assert(count > 0);
+
+    /* Multiple iterations, all of them non-blocking except the first,
+     * may be necessary to process all pending events.  After the first
+     * WaitForMultipleObjects call ctx->notify_me will be decremented.
+     */
     do {
         HANDLE event;
         int ret;

[Qemu-devel] [PATCH v2 1/3] tests: remove irrelevant assertions from test-aio

[Paolo Bonzini]

In these tests, the purpose of the initial calls to aio_poll and
g_main_context_iteration is simply to put the AioContext in a
known state; the return value of the function does not really
matter.  The next patch will change those return values; change
the assertions to a while loop which expresses the intention
better.

Signed-off-by: Paolo Bonzini <pbonzini@redhat.com>
---
 tests/test-aio.c | 8 ++++----
 1 file changed, 4 insertions(+), 4 deletions(-)

diff --git a/tests/test-aio.c b/tests/test-aio.c
index a7cb5c9..e7bbb83 100644
--- a/tests/test-aio.c
+++ b/tests/test-aio.c
@@ -331,7 +331,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 +356,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);
 
@@ -669,7 +669,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 +694,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);
 
-- 
2.4.3

[Qemu-devel] [PATCH v2 2/3] aio-win32: reorganize polling loop

[Paolo Bonzini]

Preparatory bugfixes and tweaks to the loop before the next patch:

- disable dispatch optimization during aio_prepare.  This fixes a bug.

- do not modify "blocking" until after the first WaitForMultipleObjects
call.  This is needed in the next patch.

- change the loop to do...while.  This makes it obvious that the loop
is always entered at least once.  In the next patch this is important
because the first iteration undoes the ctx->notify_me increment that
happened before entering the loop.

Signed-off-by: Paolo Bonzini <pbonzini@redhat.com>
---
 aio-win32.c | 21 ++++++++++++---------
 1 file changed, 12 insertions(+), 9 deletions(-)

diff --git a/aio-win32.c b/aio-win32.c
index 233d8f5..9268b5c 100644
--- a/aio-win32.c
+++ b/aio-win32.c
@@ -284,11 +284,6 @@ bool aio_poll(AioContext *ctx, bool blocking)
     int timeout;
 
     aio_context_acquire(ctx);
-    have_select_revents = aio_prepare(ctx);
-    if (have_select_revents) {
-        blocking = false;
-    }
-
     was_dispatching = ctx->dispatching;
     progress = false;
 
@@ -304,6 +299,8 @@ bool aio_poll(AioContext *ctx, bool blocking)
      */
     aio_set_dispatching(ctx, !blocking);
 
+    have_select_revents = aio_prepare(ctx);
+
     ctx->walking_handlers++;
 
     /* fill fd sets */
@@ -317,12 +314,18 @@ bool aio_poll(AioContext *ctx, bool blocking)
     ctx->walking_handlers--;
     first = true;
 
-    /* wait until next event */
-    while (count > 0) {
+    /* ctx->notifier is always registered.  */
+    assert(count > 0);
+
+    /* Multiple iterations, all of them non-blocking except the first,
+     * may be necessary to process all pending events.  After the first
+     * WaitForMultipleObjects call ctx->notify_me will be decremented.
+     */
+    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);
@@ -351,7 +354,7 @@ bool aio_poll(AioContext *ctx, bool blocking)
         blocking = false;
 
         progress |= aio_dispatch_handlers(ctx, event);
-    }
+    } while (count > 0);
 
     progress |= timerlistgroup_run_timers(&ctx->tlg);
 
-- 
2.4.3

[Qemu-devel] [PATCH v2 3/3] AioContext: fix broken ctx->dispatching optimization

[Paolo Bonzini]

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) as an extra optimization, 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.

3) as mentioned above, the new implementation will not call aio_notify
when there is *no* active aio_poll at all.  test-aio.c has to be
adjusted for this change; the tests I'm removing simply make no sense
anymore with the new optimization.  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>
---
 aio-posix.c             | 19 ++++++------
 aio-win32.c             | 20 ++++++-------
 async.c                 | 21 +++++---------
 docs/aio_notify.promela | 77 +++++++++++++++++++++----------------------------
 include/block/aio.h     | 29 +++++++++++++++----
 tests/test-aio.c        | 18 ------------
 6 files changed, 82 insertions(+), 102 deletions(-)

diff --git a/aio-posix.c b/aio-posix.c
index 4abec38..268d14d 100644
--- a/aio-posix.c
+++ b/aio-posix.c
@@ -233,26 +233,23 @@ static void add_pollfd(AioHandler *node)
 bool aio_poll(AioContext *ctx, bool blocking)
 {
     AioHandler *node;
-    bool was_dispatching;
     int i, ret;
     bool progress;
     int64_t timeout;
 
     aio_context_acquire(ctx);
-    was_dispatching = ctx->dispatching;
     progress = false;
 
     /* aio_notify can avoid the expensive event_notifier_set if
      * everything (file descriptors, bottom halves, timers) will
      * be re-evaluated before the next blocking poll().  This is
      * already true when aio_poll is called with blocking == false;
-     * if blocking == true, it is only true after poll() returns.
-     *
-     * If we're in a nested event loop, ctx->dispatching might be true.
-     * In that case we can restore it just before returning, but we
-     * have to clear it now.
+     * if blocking == true, it is only true after poll() returns,
+     * so disable the optimization now.
      */
-    aio_set_dispatching(ctx, !blocking);
+    if (blocking) {
+        atomic_add(&ctx->notify_me, 2);
+    }
 
     ctx->walking_handlers++;
 
@@ -286,13 +283,15 @@ bool aio_poll(AioContext *ctx, bool blocking)
     npfd = 0;
     ctx->walking_handlers--;
 
+    if (blocking) {
+        atomic_sub(&ctx->notify_me, 2);
+    }
+
     /* Run dispatch even if there were no readable fds to run timers */
-    aio_set_dispatching(ctx, true);
     if (aio_dispatch(ctx)) {
         progress = true;
     }
 
-    aio_set_dispatching(ctx, was_dispatching);
     aio_context_release(ctx);
 
     return progress;
diff --git a/aio-win32.c b/aio-win32.c
index 9268b5c..9d6c12f 100644
--- a/aio-win32.c
+++ b/aio-win32.c
@@ -279,25 +279,23 @@ bool aio_poll(AioContext *ctx, bool blocking)
 {
     AioHandler *node;
     HANDLE events[MAXIMUM_WAIT_OBJECTS + 1];
-    bool was_dispatching, progress, have_select_revents, first;
+    bool progress, have_select_revents, first;
     int count;
     int timeout;
 
     aio_context_acquire(ctx);
-    was_dispatching = ctx->dispatching;
     progress = false;
 
     /* aio_notify can avoid the expensive event_notifier_set if
      * everything (file descriptors, bottom halves, timers) will
      * be re-evaluated before the next blocking poll().  This is
      * already true when aio_poll is called with blocking == false;
-     * if blocking == true, it is only true after poll() returns.
-     *
-     * If we're in a nested event loop, ctx->dispatching might be true.
-     * In that case we can restore it just before returning, but we
-     * have to clear it now.
+     * if blocking == true, it is only true after poll() returns,
+     * so disable the optimization now.
      */
-    aio_set_dispatching(ctx, !blocking);
+    if (blocking) {
+        atomic_add(&ctx->notify_me, 2);
+    }
 
     have_select_revents = aio_prepare(ctx);
 
@@ -334,7 +332,10 @@ bool aio_poll(AioContext *ctx, bool blocking)
         if (timeout) {
             aio_context_acquire(ctx);
         }
-        aio_set_dispatching(ctx, true);
+        if (blocking) {
+            assert(first);
+            atomic_sub(&ctx->notify_me, 2);
+        }
 
         if (first && aio_bh_poll(ctx)) {
             progress = true;
@@ -358,7 +359,6 @@ bool aio_poll(AioContext *ctx, bool blocking)
 
     progress |= timerlistgroup_run_timers(&ctx->tlg);
 
-    aio_set_dispatching(ctx, was_dispatching);
     aio_context_release(ctx);
     return progress;
 }
diff --git a/async.c b/async.c
index 77d080d..a232192 100644
--- a/async.c
+++ b/async.c
@@ -184,6 +184,8 @@ aio_ctx_prepare(GSource *source, gint    *timeout)
 {
     AioContext *ctx = (AioContext *) source;
 
+    atomic_or(&ctx->notify_me, 1);
+
     /* We assume there is no timeout already supplied */
     *timeout = qemu_timeout_ns_to_ms(aio_compute_timeout(ctx));
 
@@ -200,6 +202,7 @@ aio_ctx_check(GSource *source)
     AioContext *ctx = (AioContext *) source;
     QEMUBH *bh;
 
+    atomic_and(&ctx->notify_me, ~1);
     for (bh = ctx->first_bh; bh; bh = bh->next) {
         if (!bh->deleted && bh->scheduled) {
             return true;
@@ -254,23 +257,13 @@ ThreadPool *aio_get_thread_pool(AioContext *ctx)
     return ctx->thread_pool;
 }
 
-void aio_set_dispatching(AioContext *ctx, bool dispatching)
-{
-    ctx->dispatching = dispatching;
-    if (!dispatching) {
-        /* Write ctx->dispatching before reading e.g. bh->scheduled.
-         * Optimization: this is only needed when we're entering the "unsafe"
-         * phase where other threads must call event_notifier_set.
-         */
-        smp_mb();
-    }
-}
-
 void aio_notify(AioContext *ctx)
 {
-    /* Write e.g. bh->scheduled before reading ctx->dispatching.  */
+    /* Write e.g. bh->scheduled before reading ctx->notify_me.  Pairs
+     * with atomic_or in aio_ctx_prepare or atomic_add in aio_poll.
+     */
     smp_mb();
-    if (!ctx->dispatching) {
+    if (ctx->notify_me) {
         event_notifier_set(&ctx->notifier);
     }
 }
diff --git a/docs/aio_notify.promela b/docs/aio_notify.promela
index ad3f6f0..fccc7ee 100644
--- a/docs/aio_notify.promela
+++ b/docs/aio_notify.promela
@@ -1,5 +1,5 @@
 /*
- * This model describes the interaction between aio_set_dispatching()
+ * This model describes the interaction between ctx->notify_me
  * and aio_notify().
  *
  * Author: Paolo Bonzini <pbonzini@redhat.com>
@@ -14,57 +14,53 @@
  *     spin -a docs/aio_notify.promela
  *     gcc -O2 pan.c
  *     ./a.out -a
+ *
+ * To verify it (with a bug planted in the model):
+ *     spin -a -DBUG docs/aio_notify.promela
+ *     gcc -O2 pan.c
+ *     ./a.out -a
  */
 
 #define MAX   4
 #define LAST  (1 << (MAX - 1))
 #define FINAL ((LAST << 1) - 1)
 
-bool dispatching;
+bool notify_me;
 bool event;
 
-int req, done;
+int req;
+int done;
 
 active proctype waiter()
 {
-     int fetch, blocking;
+    int fetch;
 
-     do
-        :: done != FINAL -> {
-            // Computing "blocking" is separate from execution of the
-            // "bottom half"
-            blocking = (req == 0);
-
-            // This is our "bottom half"
-            atomic { fetch = req; req = 0; }
-            done = done | fetch;
-
-            // Wait for a nudge from the other side
-            do
-                :: event == 1 -> { event = 0; break; }
-                :: !blocking  -> break;
-            od;
+    do
+        :: true -> {
+            notify_me++;
 
-            dispatching = 1;
+            if
+#ifndef BUG
+                :: (req > 0) -> skip;
+#endif
+                :: else ->
+                    // Wait for a nudge from the other side
+                    do
+                        :: event == 1 -> { event = 0; break; }
+                    od;
+            fi;
 
-            // If you are simulating this model, you may want to add
-            // something like this here:
-            //
-            //      int foo; foo++; foo++; foo++;
-            //
-            // This only wastes some time and makes it more likely
-            // that the notifier process hits the "fast path".
+            notify_me--;
 
-            dispatching = 0;
+            atomic { fetch = req; req = 0; }
+            done = done | fetch;
         }
-        :: else -> break;
     od
 }
 
 active proctype notifier()
 {
     int next = 1;
-    int sets = 0;
 
     do
         :: next <= LAST -> {
@@ -74,8 +70,8 @@ active proctype notifier()
 
             // aio_notify
             if
-                :: dispatching == 0 -> sets++; event = 1;
-                :: else             -> skip;
+                :: notify_me == 1 -> event = 1;
+                :: else           -> printf("Skipped event_notifier_set\n"); skip;
             fi;
 
             // Test both synchronous and asynchronous delivery
@@ -86,19 +82,12 @@ active proctype notifier()
                 :: 1 -> skip;
             fi;
         }
-        :: else -> break;
     od;
-    printf("Skipped %d event_notifier_set\n", MAX - sets);
 }
 
-#define p (done == FINAL)
-
-never  {
-    do
-        :: 1                      // after an arbitrarily long prefix
-        :: p -> break             // p becomes true
-    od;
-    do
-        :: !p -> accept: break    // it then must remains true forever after
-    od
+never { /* [] done < FINAL */
+accept_init:
+        do
+        :: done < FINAL -> skip;
+        od;
 }
diff --git a/include/block/aio.h b/include/block/aio.h
index b46103e..be91e3f 100644
--- a/include/block/aio.h
+++ b/include/block/aio.h
@@ -63,10 +63,30 @@ struct AioContext {
      */
     int walking_handlers;
 
-    /* Used to avoid unnecessary event_notifier_set calls in aio_notify.
-     * Writes protected by lock or BQL, reads are lockless.
+    /* Used to avoid unnecessary event_notifier_set calls in aio_notify;
+     * accessed with atomic primitives.  If this field is 0, everything
+     * (file descriptors, bottom halves, timers) will be re-evaluated
+     * before the next blocking poll(), thus the event_notifier_set call
+     * can be skipped.  If it is non-zero, you may need to wake up a
+     * concurrent aio_poll or the glib main event loop, making
+     * event_notifier_set necessary.
+     *
+     * Bit 0 is reserved for GSource usage of the AioContext, and is 1
+     * between a call to aio_ctx_check and the next call to aio_ctx_dispatch.
+     * Bits 1-31 simply count the number of active calls to aio_poll
+     * that are in the prepare or poll phase.
+     *
+     * The GSource and aio_poll must use a different mechanism because
+     * there is no certainty that a call to GSource's prepare callback
+     * (via g_main_context_prepare) is indeed followed by check and
+     * dispatch.  It's not clear whether this would be a bug, but let's
+     * play safe and allow it---it will just cause extra calls to
+     * event_notifier_set until the next call to dispatch.
+     *
+     * Instead, the aio_poll calls include both the prepare and the
+     * dispatch phase, hence a simple counter is enough for them.
      */
-    bool dispatching;
+    uint32_t notify_me;
 
     /* lock to protect between bh's adders and deleter */
     QemuMutex bh_lock;
@@ -89,9 +109,6 @@ struct AioContext {
     QEMUTimerListGroup tlg;
 };
 
-/* Used internally to synchronize aio_poll against qemu_bh_schedule.  */
-void aio_set_dispatching(AioContext *ctx, bool dispatching);
-
 /**
  * aio_context_new: Allocate a new AioContext.
  *
diff --git a/tests/test-aio.c b/tests/test-aio.c
index e7bbb83..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;
@@ -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));
-}
-
 static void test_source_flush(void)
 {
     g_assert(!g_main_context_iteration(NULL, false));
@@ -830,7 +814,6 @@ int main(int argc, char **argv)
     while (g_main_context_iteration(NULL, false));
 
     g_test_init(&argc, &argv, NULL);
-    g_test_add_func("/aio/notify",                  test_notify);
     g_test_add_func("/aio/acquire",                 test_acquire);
     g_test_add_func("/aio/bh/schedule",             test_bh_schedule);
     g_test_add_func("/aio/bh/schedule10",           test_bh_schedule10);
@@ -845,7 +828,6 @@ int main(int argc, char **argv)
     g_test_add_func("/aio/event/flush",             test_flush_event_notifier);
     g_test_add_func("/aio/timer/schedule",          test_timer_schedule);
 
-    g_test_add_func("/aio-gsource/notify",                  test_source_notify);
     g_test_add_func("/aio-gsource/flush",                   test_source_flush);
     g_test_add_func("/aio-gsource/bh/schedule",             test_source_bh_schedule);
     g_test_add_func("/aio-gsource/bh/schedule10",           test_source_bh_schedule10);
-- 
2.4.3

Re: [Qemu-devel] [PATCH v2 0/3] AioContext: ctx->dispatching is dead, all hail ctx->notify_me

[Kevin Wolf]

Am 16.07.2015 um 11:56 hat Paolo Bonzini geschrieben:
> Apart from an additional assertion this is exactly the same code as v1,
> but split across three patches so that the important one focuses on the
> optimization.
> 
> Paolo
> 
> v1->v2
>         Split some changes to the tests to a separate patch
>         Fix commit message [Laszlo]
>         Clarify do...while loop in aio-win32.c [Kevin]
> 
> Paolo Bonzini (3):
>   tests: remove irrelevant assertions from test-aio
>   aio-win32: reorganize polling loop
>   AioContext: fix broken ctx->dispatching optimization

Reviewed-by: Kevin Wolf <kwolf@redhat.com>

Re: [Qemu-devel] [PATCH v2 0/3] AioContext: ctx->dispatching is dead, all hail ctx->notify_me

[Richard W.M. Jones]

[-- Attachment #1: Type: text/plain, Size: 1249 bytes --]

Sorry for the very long delay in replying to this.  I wanted to be
absolutely sure I was reproducing the bug.

Unfortunately I'm only able to reproduce the bug with qemu 2.3.0
(both the version in Fedora Rawhide, or the tagged v2.3.0 from git).

I cannot currently reproduce it at all with upstream qemu from git.

The patches understandably only apply to upstream qemu from git, and
have quite a few tricky conflicts with v2.3.0.

I'll keep trying on this one.  It may be that the window for the
bug to reproduce with qemu.git has got smaller.

Rich.

----------------------------------------------------------------------

Notes on how I try to reproduce this:

(1) Using Fedora Rawhide aarch64

(2) libguestfs checked out and compiled from git

(3) kraxel's edk2.git-aarch64-0-20150713.b1115.g2ad9cf3.noarch

(4) heisenscsi.pl (attached).

$ export LIBGUESTFS_HV=/path/to/qemu/aarch64-softmmu/qemu-system-aarch64
$ while true; do echo .; ./run ./heisenscsi.pl ; done



-- 
Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones
Read my programming and virtualization blog: http://rwmj.wordpress.com
libguestfs lets you edit virtual machines.  Supports shell scripting,
bindings from many languages.  http://libguestfs.org

[-- Attachment #2: heisenscsi.pl --]
[-- Type: application/x-perl, Size: 561 bytes --]

Re: [Qemu-devel] [PATCH v2 0/3] AioContext: ctx->dispatching is dead, all hail ctx->notify_me

[Richard W.M. Jones]

Sorry to spoil things, but I'm still seeing this bug, although it is
now a lot less frequent with your patch.  I would estimate it happens
more often than 1 in 5 runs with qemu.git, and probably 1 in 200 runs
with qemu.git + the v2 patch series.

It's the exact same hang in both cases.

Is it possible that this patch doesn't completely close any race?

Still, it is an improvement, so there is that.

Rich.

-- 
Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones
Read my programming and virtualization blog: http://rwmj.wordpress.com
libguestfs lets you edit virtual machines.  Supports shell scripting,
bindings from many languages.  http://libguestfs.org

Re: [Qemu-devel] [PATCH v2 0/3] AioContext: ctx->dispatching is dead, all hail ctx->notify_me

[Paolo Bonzini]

On 16/07/2015 21:05, Richard W.M. Jones wrote:
> Sorry to spoil things, but I'm still seeing this bug, although it is
> now a lot less frequent with your patch.  I would estimate it happens
> more often than 1 in 5 runs with qemu.git, and probably 1 in 200 runs
> with qemu.git + the v2 patch series.
> 
> It's the exact same hang in both cases.
> 
> Is it possible that this patch doesn't completely close any race?
> 
> Still, it is an improvement, so there is that.

I would guess instead that there are two separate bugs, but it's not
impossible that it's still there.

Paolo

Re: [Qemu-devel] [PATCH v2 0/3] AioContext: ctx->dispatching is dead, all hail ctx->notify_me

[Paolo Bonzini]

On 17/07/2015 00:06, Paolo Bonzini wrote:
> 
> 
> On 16/07/2015 21:05, Richard W.M. Jones wrote:
>> Sorry to spoil things, but I'm still seeing this bug, although it is
>> now a lot less frequent with your patch.  I would estimate it happens
>> more often than 1 in 5 runs with qemu.git, and probably 1 in 200 runs
>> with qemu.git + the v2 patch series.
>>
>> It's the exact same hang in both cases.
>>
>> Is it possible that this patch doesn't completely close any race?
>>
>> Still, it is an improvement, so there is that.
> 
> I would guess instead that there are two separate bugs, but it's not
> impossible that it's still there.

Reproduced after ~80 runs...

Paolo

Re: [Qemu-devel] [PATCH v2 3/3] AioContext: fix broken ctx->dispatching optimization

[Fam Zheng]

On Thu, 07/16 11:56, Paolo Bonzini wrote:
> diff --git a/aio-posix.c b/aio-posix.c
> index 4abec38..268d14d 100644
> --- a/aio-posix.c
> +++ b/aio-posix.c
> @@ -233,26 +233,23 @@ static void add_pollfd(AioHandler *node)
>  bool aio_poll(AioContext *ctx, bool blocking)
>  {
>      AioHandler *node;
> -    bool was_dispatching;
>      int i, ret;
>      bool progress;
>      int64_t timeout;
>  
>      aio_context_acquire(ctx);
> -    was_dispatching = ctx->dispatching;
>      progress = false;
>  
>      /* aio_notify can avoid the expensive event_notifier_set if
>       * everything (file descriptors, bottom halves, timers) will
>       * be re-evaluated before the next blocking poll().  This is
>       * already true when aio_poll is called with blocking == false;
> -     * if blocking == true, it is only true after poll() returns.
> -     *
> -     * If we're in a nested event loop, ctx->dispatching might be true.
> -     * In that case we can restore it just before returning, but we
> -     * have to clear it now.
> +     * if blocking == true, it is only true after poll() returns,
> +     * so disable the optimization now.
>       */
> -    aio_set_dispatching(ctx, !blocking);
> +    if (blocking) {
> +        atomic_add(&ctx->notify_me, 2);
> +    }

Sorry if my questions are stupid, but I'm having difficulties in fully
understanding it.

What if aio_notify happens after the previous aio_dispatch() but before the
next necessary atomic_add? The aio_notify would still skip the
event_notifier_set(), and the next ppoll() will not return. For example:

  Thread A                             Thread B
------------------------------------------------------------------------
  aio_poll(blocking=true)
                                       aio_notify()
                                         smp_mb()
                                         if (ctx->notify_me) /* false! */
    atomic_add(ctx->notify_me, 2)
    ppoll()
    atomic_sub(ctx->notify_me, 2)           event_notifier_set() /* not run */


And if that's not a problem, why don't we need something like ACCESS_ONCE in
aio_noitfy()?

Fam

>  
>      ctx->walking_handlers++;
>  
> @@ -286,13 +283,15 @@ bool aio_poll(AioContext *ctx, bool blocking)
>      npfd = 0;
>      ctx->walking_handlers--;
>  
> +    if (blocking) {
> +        atomic_sub(&ctx->notify_me, 2);
> +    }
> +
>      /* Run dispatch even if there were no readable fds to run timers */
> -    aio_set_dispatching(ctx, true);
>      if (aio_dispatch(ctx)) {
>          progress = true;
>      }
>  
> -    aio_set_dispatching(ctx, was_dispatching);
>      aio_context_release(ctx);
>  
>      return progress;
> diff --git a/aio-win32.c b/aio-win32.c
> index 9268b5c..9d6c12f 100644
> --- a/aio-win32.c
> +++ b/aio-win32.c
> @@ -279,25 +279,23 @@ bool aio_poll(AioContext *ctx, bool blocking)
>  {
>      AioHandler *node;
>      HANDLE events[MAXIMUM_WAIT_OBJECTS + 1];
> -    bool was_dispatching, progress, have_select_revents, first;
> +    bool progress, have_select_revents, first;
>      int count;
>      int timeout;
>  
>      aio_context_acquire(ctx);
> -    was_dispatching = ctx->dispatching;
>      progress = false;
>  
>      /* aio_notify can avoid the expensive event_notifier_set if
>       * everything (file descriptors, bottom halves, timers) will
>       * be re-evaluated before the next blocking poll().  This is
>       * already true when aio_poll is called with blocking == false;
> -     * if blocking == true, it is only true after poll() returns.
> -     *
> -     * If we're in a nested event loop, ctx->dispatching might be true.
> -     * In that case we can restore it just before returning, but we
> -     * have to clear it now.
> +     * if blocking == true, it is only true after poll() returns,
> +     * so disable the optimization now.
>       */
> -    aio_set_dispatching(ctx, !blocking);
> +    if (blocking) {
> +        atomic_add(&ctx->notify_me, 2);
> +    }
>  
>      have_select_revents = aio_prepare(ctx);
>  
> @@ -334,7 +332,10 @@ bool aio_poll(AioContext *ctx, bool blocking)
>          if (timeout) {
>              aio_context_acquire(ctx);
>          }
> -        aio_set_dispatching(ctx, true);
> +        if (blocking) {
> +            assert(first);
> +            atomic_sub(&ctx->notify_me, 2);
> +        }
>  
>          if (first && aio_bh_poll(ctx)) {
>              progress = true;
> @@ -358,7 +359,6 @@ bool aio_poll(AioContext *ctx, bool blocking)
>  
>      progress |= timerlistgroup_run_timers(&ctx->tlg);
>  
> -    aio_set_dispatching(ctx, was_dispatching);
>      aio_context_release(ctx);
>      return progress;
>  }
> diff --git a/async.c b/async.c
> index 77d080d..a232192 100644
> --- a/async.c
> +++ b/async.c
> @@ -184,6 +184,8 @@ aio_ctx_prepare(GSource *source, gint    *timeout)
>  {
>      AioContext *ctx = (AioContext *) source;
>  
> +    atomic_or(&ctx->notify_me, 1);
> +
>      /* We assume there is no timeout already supplied */
>      *timeout = qemu_timeout_ns_to_ms(aio_compute_timeout(ctx));
>  
> @@ -200,6 +202,7 @@ aio_ctx_check(GSource *source)
>      AioContext *ctx = (AioContext *) source;
>      QEMUBH *bh;
>  
> +    atomic_and(&ctx->notify_me, ~1);
>      for (bh = ctx->first_bh; bh; bh = bh->next) {
>          if (!bh->deleted && bh->scheduled) {
>              return true;
> @@ -254,23 +257,13 @@ ThreadPool *aio_get_thread_pool(AioContext *ctx)
>      return ctx->thread_pool;
>  }
>  
> -void aio_set_dispatching(AioContext *ctx, bool dispatching)
> -{
> -    ctx->dispatching = dispatching;
> -    if (!dispatching) {
> -        /* Write ctx->dispatching before reading e.g. bh->scheduled.
> -         * Optimization: this is only needed when we're entering the "unsafe"
> -         * phase where other threads must call event_notifier_set.
> -         */
> -        smp_mb();
> -    }
> -}
> -
>  void aio_notify(AioContext *ctx)
>  {
> -    /* Write e.g. bh->scheduled before reading ctx->dispatching.  */
> +    /* Write e.g. bh->scheduled before reading ctx->notify_me.  Pairs
> +     * with atomic_or in aio_ctx_prepare or atomic_add in aio_poll.
> +     */
>      smp_mb();
> -    if (!ctx->dispatching) {
> +    if (ctx->notify_me) {
>          event_notifier_set(&ctx->notifier);
>      }
>  }
> diff --git a/docs/aio_notify.promela b/docs/aio_notify.promela
> index ad3f6f0..fccc7ee 100644
> --- a/docs/aio_notify.promela
> +++ b/docs/aio_notify.promela
> @@ -1,5 +1,5 @@
>  /*
> - * This model describes the interaction between aio_set_dispatching()
> + * This model describes the interaction between ctx->notify_me
>   * and aio_notify().
>   *
>   * Author: Paolo Bonzini <pbonzini@redhat.com>
> @@ -14,57 +14,53 @@
>   *     spin -a docs/aio_notify.promela
>   *     gcc -O2 pan.c
>   *     ./a.out -a
> + *
> + * To verify it (with a bug planted in the model):
> + *     spin -a -DBUG docs/aio_notify.promela
> + *     gcc -O2 pan.c
> + *     ./a.out -a
>   */
>  
>  #define MAX   4
>  #define LAST  (1 << (MAX - 1))
>  #define FINAL ((LAST << 1) - 1)
>  
> -bool dispatching;
> +bool notify_me;
>  bool event;
>  
> -int req, done;
> +int req;
> +int done;
>  
>  active proctype waiter()
>  {
> -     int fetch, blocking;
> +    int fetch;
>  
> -     do
> -        :: done != FINAL -> {
> -            // Computing "blocking" is separate from execution of the
> -            // "bottom half"
> -            blocking = (req == 0);
> -
> -            // This is our "bottom half"
> -            atomic { fetch = req; req = 0; }
> -            done = done | fetch;
> -
> -            // Wait for a nudge from the other side
> -            do
> -                :: event == 1 -> { event = 0; break; }
> -                :: !blocking  -> break;
> -            od;
> +    do
> +        :: true -> {
> +            notify_me++;
>  
> -            dispatching = 1;
> +            if
> +#ifndef BUG
> +                :: (req > 0) -> skip;
> +#endif
> +                :: else ->
> +                    // Wait for a nudge from the other side
> +                    do
> +                        :: event == 1 -> { event = 0; break; }
> +                    od;
> +            fi;
>  
> -            // If you are simulating this model, you may want to add
> -            // something like this here:
> -            //
> -            //      int foo; foo++; foo++; foo++;
> -            //
> -            // This only wastes some time and makes it more likely
> -            // that the notifier process hits the "fast path".
> +            notify_me--;
>  
> -            dispatching = 0;
> +            atomic { fetch = req; req = 0; }
> +            done = done | fetch;
>          }
> -        :: else -> break;
>      od
>  }
>  
>  active proctype notifier()
>  {
>      int next = 1;
> -    int sets = 0;
>  
>      do
>          :: next <= LAST -> {
> @@ -74,8 +70,8 @@ active proctype notifier()
>  
>              // aio_notify
>              if
> -                :: dispatching == 0 -> sets++; event = 1;
> -                :: else             -> skip;
> +                :: notify_me == 1 -> event = 1;
> +                :: else           -> printf("Skipped event_notifier_set\n"); skip;
>              fi;
>  
>              // Test both synchronous and asynchronous delivery
> @@ -86,19 +82,12 @@ active proctype notifier()
>                  :: 1 -> skip;
>              fi;
>          }
> -        :: else -> break;
>      od;
> -    printf("Skipped %d event_notifier_set\n", MAX - sets);
>  }
>  
> -#define p (done == FINAL)
> -
> -never  {
> -    do
> -        :: 1                      // after an arbitrarily long prefix
> -        :: p -> break             // p becomes true
> -    od;
> -    do
> -        :: !p -> accept: break    // it then must remains true forever after
> -    od
> +never { /* [] done < FINAL */
> +accept_init:
> +        do
> +        :: done < FINAL -> skip;
> +        od;
>  }
> diff --git a/include/block/aio.h b/include/block/aio.h
> index b46103e..be91e3f 100644
> --- a/include/block/aio.h
> +++ b/include/block/aio.h
> @@ -63,10 +63,30 @@ struct AioContext {
>       */
>      int walking_handlers;
>  
> -    /* Used to avoid unnecessary event_notifier_set calls in aio_notify.
> -     * Writes protected by lock or BQL, reads are lockless.
> +    /* Used to avoid unnecessary event_notifier_set calls in aio_notify;
> +     * accessed with atomic primitives.  If this field is 0, everything
> +     * (file descriptors, bottom halves, timers) will be re-evaluated
> +     * before the next blocking poll(), thus the event_notifier_set call
> +     * can be skipped.  If it is non-zero, you may need to wake up a
> +     * concurrent aio_poll or the glib main event loop, making
> +     * event_notifier_set necessary.
> +     *
> +     * Bit 0 is reserved for GSource usage of the AioContext, and is 1
> +     * between a call to aio_ctx_check and the next call to aio_ctx_dispatch.
> +     * Bits 1-31 simply count the number of active calls to aio_poll
> +     * that are in the prepare or poll phase.
> +     *
> +     * The GSource and aio_poll must use a different mechanism because
> +     * there is no certainty that a call to GSource's prepare callback
> +     * (via g_main_context_prepare) is indeed followed by check and
> +     * dispatch.  It's not clear whether this would be a bug, but let's
> +     * play safe and allow it---it will just cause extra calls to
> +     * event_notifier_set until the next call to dispatch.
> +     *
> +     * Instead, the aio_poll calls include both the prepare and the
> +     * dispatch phase, hence a simple counter is enough for them.
>       */
> -    bool dispatching;
> +    uint32_t notify_me;
>  
>      /* lock to protect between bh's adders and deleter */
>      QemuMutex bh_lock;
> @@ -89,9 +109,6 @@ struct AioContext {
>      QEMUTimerListGroup tlg;
>  };
>  
> -/* Used internally to synchronize aio_poll against qemu_bh_schedule.  */
> -void aio_set_dispatching(AioContext *ctx, bool dispatching);
> -
>  /**
>   * aio_context_new: Allocate a new AioContext.
>   *
> diff --git a/tests/test-aio.c b/tests/test-aio.c
> index e7bbb83..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;
> @@ -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));
> -}
> -
>  static void test_source_flush(void)
>  {
>      g_assert(!g_main_context_iteration(NULL, false));
> @@ -830,7 +814,6 @@ int main(int argc, char **argv)
>      while (g_main_context_iteration(NULL, false));
>  
>      g_test_init(&argc, &argv, NULL);
> -    g_test_add_func("/aio/notify",                  test_notify);
>      g_test_add_func("/aio/acquire",                 test_acquire);
>      g_test_add_func("/aio/bh/schedule",             test_bh_schedule);
>      g_test_add_func("/aio/bh/schedule10",           test_bh_schedule10);
> @@ -845,7 +828,6 @@ int main(int argc, char **argv)
>      g_test_add_func("/aio/event/flush",             test_flush_event_notifier);
>      g_test_add_func("/aio/timer/schedule",          test_timer_schedule);
>  
> -    g_test_add_func("/aio-gsource/notify",                  test_source_notify);
>      g_test_add_func("/aio-gsource/flush",                   test_source_flush);
>      g_test_add_func("/aio-gsource/bh/schedule",             test_source_bh_schedule);
>      g_test_add_func("/aio-gsource/bh/schedule10",           test_source_bh_schedule10);
> -- 
> 2.4.3
> 
> 

Re: [Qemu-devel] [PATCH v2 3/3] AioContext: fix broken ctx->dispatching optimization

[Paolo Bonzini]

On 17/07/2015 04:25, Fam Zheng wrote:
> What if aio_notify happens after the previous aio_dispatch() but before the
> next necessary atomic_add? The aio_notify would still skip the
> event_notifier_set(), and the next ppoll() will not return. For example:
> 
>   Thread A                             Thread B
> ------------------------------------------------------------------------
>   aio_poll(blocking=true)
>                                        aio_notify()
>                                          smp_mb()
>                                          if (ctx->notify_me) /* false! */
>     atomic_add(ctx->notify_me, 2)
>     ppoll()
>     atomic_sub(ctx->notify_me, 2)           event_notifier_set() /* not run */

It's not a problem because ppoll() has exited.  The next call to
aio_poll or aio_ctx_prepare will notice the bottom half, do a
non-blocking ppoll(), and then service the bottom half.

> 
> And if that's not a problem, why don't we need something like ACCESS_ONCE in
> aio_noitfy()?

Because there's already a smp_mb() which is stronger.

Paolo

Re: [Qemu-devel] [PATCH v2 3/3] AioContext: fix broken ctx->dispatching optimization

[Paolo Bonzini]

On 16/07/2015 11:56, Paolo Bonzini wrote:
> @@ -286,13 +283,15 @@ bool aio_poll(AioContext *ctx, bool blocking)
>      npfd = 0;
>      ctx->walking_handlers--;
>  
> +    if (blocking) {
> +        atomic_sub(&ctx->notify_me, 2);
> +    }
> +

I kept this place for subtracting notify_me because it is the same place
where aio_set_dispatching was called.  However, it can be anticipated to

     /* if we have any readable fds, dispatch event */
     if (ret > 0) {
         for (i = 0; i < npfd; i++) {

i.e. right after poll.  As poll has exited, it can't be blocking the
thread anymore.  Stefan, please let me send v3 on Monday.

Paolo

> 
>      /* Run dispatch even if there were no readable fds to run timers */
> -    aio_set_dispatching(ctx, true);
>      if (aio_dispatch(ctx)) {
>          progress = true;
>      }
>  

Re: [Qemu-devel] [PATCH v2 0/3] AioContext: ctx->dispatching is dead, all hail ctx->notify_me

[Paolo Bonzini]

On 16/07/2015 21:05, Richard W.M. Jones wrote:
> 
> Sorry to spoil things, but I'm still seeing this bug, although it is
> now a lot less frequent with your patch.  I would estimate it happens
> more often than 1 in 5 runs with qemu.git, and probably 1 in 200 runs
> with qemu.git + the v2 patch series.
> 
> It's the exact same hang in both cases.
> 
> Is it possible that this patch doesn't completely close any race?
> 
> Still, it is an improvement, so there is that.

Would seem at first glance like a different bug.

Interestingly, adding some "tracing" (qemu_clock_get_ns) makes the bug
more likely: now it reproduces in about 10 tries.  Of course :) adding
other kinds of tracing instead make it go away again (>50 tries).

Perhaps this:

   i/o thread         vcpu thread                   worker thread
   ---------------------------------------------------------------------
   lock_iothread
   notify_me = 1
   ...
   unlock_iothread
                      lock_iothread
                      notify_me = 3
                      ppoll
                      notify_me = 1
                                                     bh->scheduled = 1
                                                     event_notifier_set
                      event_notifier_test_and_clear
   ppoll
    ^^ hang
	
In the exact shape above, it doesn't seem too likely to happen, but
perhaps there's another simpler case.  Still, the bug exists.

The above is not really related to notify_me.  Here the notification is
not being optimized away!  So I wonder if this one has been there forever.

Fam suggested putting the event_notifier_test_and_clear before
aio_bh_poll(), but it does not work.  I'll look more close

However, an unconditional event_notifier_test_and_clear is pretty
expensive.  On one hand, obviously correctness comes first.  On the
other hand, an expensive operation at the wrong place can mask the race
very easily; I'll let the fix run for a while, but I'm not sure if a
successful test really says anything useful.

Paolo

Re: [Qemu-devel] [PATCH v2 3/3] AioContext: fix broken ctx->dispatching optimization

[Stefan Hajnoczi]

[-- Attachment #1: Type: text/plain, Size: 781 bytes --]

On Fri, Jul 17, 2015 at 06:17:47AM +0200, Paolo Bonzini wrote:
> 
> 
> On 16/07/2015 11:56, Paolo Bonzini wrote:
> > @@ -286,13 +283,15 @@ bool aio_poll(AioContext *ctx, bool blocking)
> >      npfd = 0;
> >      ctx->walking_handlers--;
> >  
> > +    if (blocking) {
> > +        atomic_sub(&ctx->notify_me, 2);
> > +    }
> > +
> 
> I kept this place for subtracting notify_me because it is the same place
> where aio_set_dispatching was called.  However, it can be anticipated to
> 
>      /* if we have any readable fds, dispatch event */
>      if (ret > 0) {
>          for (i = 0; i < npfd; i++) {
> 
> i.e. right after poll.  As poll has exited, it can't be blocking the
> thread anymore.  Stefan, please let me send v3 on Monday.

Sure.

Stefan

[-- Attachment #2: Type: application/pgp-signature, Size: 473 bytes --]

Re: [Qemu-devel] [PATCH v2 0/3] AioContext: ctx->dispatching is dead, all hail ctx->notify_me

[Paolo Bonzini]

On 17/07/2015 06:44, Paolo Bonzini wrote:
> 
> 
> On 16/07/2015 21:05, Richard W.M. Jones wrote:
>>
>> Sorry to spoil things, but I'm still seeing this bug, although it is
>> now a lot less frequent with your patch.  I would estimate it happens
>> more often than 1 in 5 runs with qemu.git, and probably 1 in 200 runs
>> with qemu.git + the v2 patch series.
>>
>> It's the exact same hang in both cases.
>>
>> Is it possible that this patch doesn't completely close any race?
>>
>> Still, it is an improvement, so there is that.
> 
> Would seem at first glance like a different bug.
> 
> Interestingly, adding some "tracing" (qemu_clock_get_ns) makes the bug
> more likely: now it reproduces in about 10 tries.  Of course :) adding
> other kinds of tracing instead make it go away again (>50 tries).
> 
> Perhaps this:
> 
>    i/o thread         vcpu thread                   worker thread
>    ---------------------------------------------------------------------
>    lock_iothread
>    notify_me = 1
>    ...
>    unlock_iothread
>                       lock_iothread
>                       notify_me = 3
>                       ppoll
>                       notify_me = 1
>                                                      bh->scheduled = 1
>                                                      event_notifier_set
>                       event_notifier_test_and_clear
>    ppoll
>     ^^ hang
> 	
> In the exact shape above, it doesn't seem too likely to happen, but
> perhaps there's another simpler case.  Still, the bug exists.
> 
> The above is not really related to notify_me.  Here the notification is
> not being optimized away!  So I wonder if this one has been there forever.
> 
> Fam suggested putting the event_notifier_test_and_clear before
> aio_bh_poll(), but it does not work.  I'll look more close
> 
> However, an unconditional event_notifier_test_and_clear is pretty
> expensive.  On one hand, obviously correctness comes first.  On the
> other hand, an expensive operation at the wrong place can mask the race
> very easily; I'll let the fix run for a while, but I'm not sure if a
> successful test really says anything useful.

So it may not be useful, but still successful test is successful. :)
The following patch, which also includes the delta between v2 and v3
of this series, survived 674 reboots before hitting a definitely
unrelated problem:

error: kvm run failed Function not implemented
PC=00000000bf671210  SP=00000000c00001f0
X00=000000000a003e70 X01=0000000000000000 X02=00000000bf680548 X03=0000000000000030
X04=00000000bbb5fc18 X05=00000000004b7770 X06=00000000bf721930 X07=000000000000009a
X08=00000000bf716858 X09=0000000000000090 X10=0000000000000000 X11=0000000000000046
X12=00000000a007e03a X13=0000000000000000 X14=0000000000000000 X15=0000000000000000
X16=00000000bf716df0 X17=0000000000000000 X18=0000000000000000 X19=00000000bf6f5f18
X20=0000000000000000 X21=0000000000000000 X22=0000000000000000 X23=0000000000000000
X24=0000000000000000 X25=0000000000000000 X26=0000000000000000 X27=0000000000000000
X28=0000000000000000 X29=0000000000000000 X30=0000000000000000 PSTATE=60000305 (flags -ZC-)

For the record, this is the kvm_run struct:

$6 = {request_interrupt_window = 0 '\000', padding1 = "\000\000\000\000\000\000", exit_reason = 0, 
  ready_for_interrupt_injection = 0 '\000', if_flag = 0 '\000', flags = 0, cr8 = 0, apic_base = 0, {hw = {
      hardware_exit_reason = 150994968}, fail_entry = {hardware_entry_failure_reason = 150994968}, ex = {
      exception = 150994968, error_code = 0}, io = {direction = 24 '\030', size = 0 '\000', port = 2304, 
      count = 0, data_offset = 144}, debug = {arch = {<No data fields>}}, mmio = {phys_addr = 150994968, 
      data = "\220\000\000\000\000\000\000", len = 4, is_write = 0 '\000'}, hypercall = {nr = 150994968, 
      args = {144, 4, 0, 0, 0, 0}, ret = 0, longmode = 0, pad = 0}, tpr_access = {rip = 150994968, 
      is_write = 144, pad = 0}, s390_sieic = {icptcode = 24 '\030', ipa = 2304, ipb = 0}, 
    s390_reset_flags = 150994968, s390_ucontrol = {trans_exc_code = 150994968, pgm_code = 144}, dcr = {
      dcrn = 150994968, data = 0, is_write = 144 '\220'}, internal = {suberror = 150994968, ndata = 0, 
      data = {144, 4, 0 <repeats 14 times>}}, osi = {gprs = {150994968, 144, 4, 0 <repeats 29 times>}}, 
    papr_hcall = {nr = 150994968, ret = 144, args = {4, 0, 0, 0, 0, 0, 0, 0, 0}}, s390_tsch = {
      subchannel_id = 24, subchannel_nr = 2304, io_int_parm = 0, io_int_word = 144, ipb = 0, 
      dequeued = 4 '\004'}, epr = {epr = 150994968}, system_event = {type = 150994968, flags = 144}, 
    s390_stsi = {addr = 150994968, ar = 144 '\220', reserved = 0 '\000', fc = 0 '\000', sel1 = 0 '\000', 
      sel2 = 0}, 
    padding = "\030\000\000\t\000\000\000\000\220\000\000\000\000\000\000\000\004", '\000' <repeats 238 times>}, kvm_valid_regs = 0, kvm_dirty_regs = 0, s = {regs = {<No data fields>}, 
    padding = '\000' <repeats 2047 times>}}

Marc, does it ring any bell?

Paolo

diff --git a/aio-posix.c b/aio-posix.c
index 268d14d..d2011d0 100644
--- a/aio-posix.c
+++ b/aio-posix.c
@@ -273,6 +273,13 @@ bool aio_poll(AioContext *ctx, bool blocking)
         aio_context_acquire(ctx);
     }
 
+    /* This should be optimized... */
+    event_notifier_test_and_clear(&ctx->notifier);
+
+    if (blocking) {
+        atomic_sub(&ctx->notify_me, 2);
+    }
+
     /* if we have any readable fds, dispatch event */
     if (ret > 0) {
         for (i = 0; i < npfd; i++) {
@@ -283,10 +290,6 @@ bool aio_poll(AioContext *ctx, bool blocking)
     npfd = 0;
     ctx->walking_handlers--;
 
-    if (blocking) {
-        atomic_sub(&ctx->notify_me, 2);
-    }
-
     /* Run dispatch even if there were no readable fds to run timers */
     if (aio_dispatch(ctx)) {
         progress = true;
diff --git a/aio-win32.c b/aio-win32.c
index 2bfd5f8..33809fd 100644
--- a/aio-win32.c
+++ b/aio-win32.c
@@ -326,6 +326,10 @@ bool aio_poll(AioContext *ctx, bool blocking)
         if (timeout) {
             aio_context_acquire(ctx);
         }
+
+        /* This should be optimized... */
+        event_notifier_test_and_clear(&ctx->notifier);
+
         if (blocking) {
             assert(first);
             atomic_sub(&ctx->notify_me, 2);
diff --git a/async.c b/async.c
index 9204907..120e183 100644
--- a/async.c
+++ b/async.c
@@ -202,6 +202,9 @@ aio_ctx_check(GSource *source)
     AioContext *ctx = (AioContext *) source;
     QEMUBH *bh;
 
+    /* This should be optimized... */
+    event_notifier_test_and_clear(&ctx->notifier);
+
     atomic_and(&ctx->notify_me, ~1);
     for (bh = ctx->first_bh; bh; bh = bh->next) {
         if (!bh->deleted && bh->scheduled) {
@@ -280,6 +280,10 @@ static void aio_rfifolock_cb(void *opaque)
     aio_notify(opaque);
 }
 
+static void event_notifier_dummy_cb(EventNotifier *e)
+{
+}
+
 AioContext *aio_context_new(Error **errp)
 {
     int ret;
@@ -292,7 +296,7 @@ AioContext *aio_context_new(Error **errp)
         return NULL;
     }
     g_source_set_can_recurse(&ctx->source, true);
-    aio_set_event_notifier(ctx, &ctx->notifier, NULL);
+    aio_set_event_notifier(ctx, &ctx->notifier, event_notifier_dummy_cb);
     ctx->thread_pool = NULL;
     qemu_mutex_init(&ctx->bh_lock);
     rfifolock_init(&ctx->lock, aio_rfifolock_cb, ctx);

Re: [Qemu-devel] [PATCH v2 0/3] AioContext: ctx->dispatching is dead, all hail ctx->notify_me

[Richard W.M. Jones]

On Fri, Jul 17, 2015 at 11:30:38AM +0200, Paolo Bonzini wrote:
> error: kvm run failed Function not implemented
> PC=00000000bf671210  SP=00000000c00001f0
> X00=000000000a003e70 X01=0000000000000000 X02=00000000bf680548 X03=0000000000000030
> X04=00000000bbb5fc18 X05=00000000004b7770 X06=00000000bf721930 X07=000000000000009a
> X08=00000000bf716858 X09=0000000000000090 X10=0000000000000000 X11=0000000000000046
> X12=00000000a007e03a X13=0000000000000000 X14=0000000000000000 X15=0000000000000000
> X16=00000000bf716df0 X17=0000000000000000 X18=0000000000000000 X19=00000000bf6f5f18
> X20=0000000000000000 X21=0000000000000000 X22=0000000000000000 X23=0000000000000000
> X24=0000000000000000 X25=0000000000000000 X26=0000000000000000 X27=0000000000000000
> X28=0000000000000000 X29=0000000000000000 X30=0000000000000000 PSTATE=60000305 (flags -ZC-)

Vaguely reminiscent of this bug:

https://bugzilla.redhat.com/show_bug.cgi?id=1194366

(See comment 7 in particular)

> diff --git a/aio-posix.c b/aio-posix.c
> index 268d14d..d2011d0 100644
> --- a/aio-posix.c
> +++ b/aio-posix.c
> @@ -273,6 +273,13 @@ bool aio_poll(AioContext *ctx, bool blocking)
>          aio_context_acquire(ctx);
>      }
>  
> +    /* This should be optimized... */
> +    event_notifier_test_and_clear(&ctx->notifier);
> +
> +    if (blocking) {
> +        atomic_sub(&ctx->notify_me, 2);
> +    }
> +
>      /* if we have any readable fds, dispatch event */
>      if (ret > 0) {
>          for (i = 0; i < npfd; i++) {
> @@ -283,10 +290,6 @@ bool aio_poll(AioContext *ctx, bool blocking)
>      npfd = 0;
>      ctx->walking_handlers--;
>  
> -    if (blocking) {
> -        atomic_sub(&ctx->notify_me, 2);
> -    }
> -
>      /* Run dispatch even if there were no readable fds to run timers */
>      if (aio_dispatch(ctx)) {
>          progress = true;
> diff --git a/aio-win32.c b/aio-win32.c
> index 2bfd5f8..33809fd 100644
> --- a/aio-win32.c
> +++ b/aio-win32.c
> @@ -326,6 +326,10 @@ bool aio_poll(AioContext *ctx, bool blocking)
>          if (timeout) {
>              aio_context_acquire(ctx);
>          }
> +
> +        /* This should be optimized... */
> +        event_notifier_test_and_clear(&ctx->notifier);
> +
>          if (blocking) {
>              assert(first);
>              atomic_sub(&ctx->notify_me, 2);
> diff --git a/async.c b/async.c
> index 9204907..120e183 100644
> --- a/async.c
> +++ b/async.c
> @@ -202,6 +202,9 @@ aio_ctx_check(GSource *source)
>      AioContext *ctx = (AioContext *) source;
>      QEMUBH *bh;
>  
> +    /* This should be optimized... */
> +    event_notifier_test_and_clear(&ctx->notifier);
> +
>      atomic_and(&ctx->notify_me, ~1);
>      for (bh = ctx->first_bh; bh; bh = bh->next) {
>          if (!bh->deleted && bh->scheduled) {
> @@ -280,6 +280,10 @@ static void aio_rfifolock_cb(void *opaque)
>      aio_notify(opaque);
>  }
>  
> +static void event_notifier_dummy_cb(EventNotifier *e)
> +{
> +}
> +
>  AioContext *aio_context_new(Error **errp)
>  {
>      int ret;
> @@ -292,7 +296,7 @@ AioContext *aio_context_new(Error **errp)
>          return NULL;
>      }
>      g_source_set_can_recurse(&ctx->source, true);
> -    aio_set_event_notifier(ctx, &ctx->notifier, NULL);
> +    aio_set_event_notifier(ctx, &ctx->notifier, event_notifier_dummy_cb);
>      ctx->thread_pool = NULL;
>      qemu_mutex_init(&ctx->bh_lock);
>      rfifolock_init(&ctx->lock, aio_rfifolock_cb, ctx);

With this patch, I've got to 500 iterations without seeing the error.

Still testing it however ...

Rich.

-- 
Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones
Read my programming and virtualization blog: http://rwmj.wordpress.com
virt-df lists disk usage of guests without needing to install any
software inside the virtual machine.  Supports Linux and Windows.
http://people.redhat.com/~rjones/virt-df/

Re: [Qemu-devel] [PATCH v2 0/3] AioContext: ctx->dispatching is dead, all hail ctx->notify_me

[Paolo Bonzini]

On 17/07/2015 14:58, Richard W.M. Jones wrote:
> On Fri, Jul 17, 2015 at 11:30:38AM +0200, Paolo Bonzini wrote:
>> error: kvm run failed Function not implemented
>> PC=00000000bf671210  SP=00000000c00001f0
>> X00=000000000a003e70 X01=0000000000000000 X02=00000000bf680548 X03=0000000000000030
>> X04=00000000bbb5fc18 X05=00000000004b7770 X06=00000000bf721930 X07=000000000000009a
>> X08=00000000bf716858 X09=0000000000000090 X10=0000000000000000 X11=0000000000000046
>> X12=00000000a007e03a X13=0000000000000000 X14=0000000000000000 X15=0000000000000000
>> X16=00000000bf716df0 X17=0000000000000000 X18=0000000000000000 X19=00000000bf6f5f18
>> X20=0000000000000000 X21=0000000000000000 X22=0000000000000000 X23=0000000000000000
>> X24=0000000000000000 X25=0000000000000000 X26=0000000000000000 X27=0000000000000000
>> X28=0000000000000000 X29=0000000000000000 X30=0000000000000000 PSTATE=60000305 (flags -ZC-)
> 
> Vaguely reminiscent of this bug:
> 
> https://bugzilla.redhat.com/show_bug.cgi?id=1194366
> 
> (See comment 7 in particular)

Must be it, I was using an old kernel.

Thanks!

Paolo

>> diff --git a/aio-posix.c b/aio-posix.c
>> index 268d14d..d2011d0 100644
>> --- a/aio-posix.c
>> +++ b/aio-posix.c
>> @@ -273,6 +273,13 @@ bool aio_poll(AioContext *ctx, bool blocking)
>>          aio_context_acquire(ctx);
>>      }
>>  
>> +    /* This should be optimized... */
>> +    event_notifier_test_and_clear(&ctx->notifier);
>> +
>> +    if (blocking) {
>> +        atomic_sub(&ctx->notify_me, 2);
>> +    }
>> +
>>      /* if we have any readable fds, dispatch event */
>>      if (ret > 0) {
>>          for (i = 0; i < npfd; i++) {
>> @@ -283,10 +290,6 @@ bool aio_poll(AioContext *ctx, bool blocking)
>>      npfd = 0;
>>      ctx->walking_handlers--;
>>  
>> -    if (blocking) {
>> -        atomic_sub(&ctx->notify_me, 2);
>> -    }
>> -
>>      /* Run dispatch even if there were no readable fds to run timers */
>>      if (aio_dispatch(ctx)) {
>>          progress = true;
>> diff --git a/aio-win32.c b/aio-win32.c
>> index 2bfd5f8..33809fd 100644
>> --- a/aio-win32.c
>> +++ b/aio-win32.c
>> @@ -326,6 +326,10 @@ bool aio_poll(AioContext *ctx, bool blocking)
>>          if (timeout) {
>>              aio_context_acquire(ctx);
>>          }
>> +
>> +        /* This should be optimized... */
>> +        event_notifier_test_and_clear(&ctx->notifier);
>> +
>>          if (blocking) {
>>              assert(first);
>>              atomic_sub(&ctx->notify_me, 2);
>> diff --git a/async.c b/async.c
>> index 9204907..120e183 100644
>> --- a/async.c
>> +++ b/async.c
>> @@ -202,6 +202,9 @@ aio_ctx_check(GSource *source)
>>      AioContext *ctx = (AioContext *) source;
>>      QEMUBH *bh;
>>  
>> +    /* This should be optimized... */
>> +    event_notifier_test_and_clear(&ctx->notifier);
>> +
>>      atomic_and(&ctx->notify_me, ~1);
>>      for (bh = ctx->first_bh; bh; bh = bh->next) {
>>          if (!bh->deleted && bh->scheduled) {
>> @@ -280,6 +280,10 @@ static void aio_rfifolock_cb(void *opaque)
>>      aio_notify(opaque);
>>  }
>>  
>> +static void event_notifier_dummy_cb(EventNotifier *e)
>> +{
>> +}
>> +
>>  AioContext *aio_context_new(Error **errp)
>>  {
>>      int ret;
>> @@ -292,7 +296,7 @@ AioContext *aio_context_new(Error **errp)
>>          return NULL;
>>      }
>>      g_source_set_can_recurse(&ctx->source, true);
>> -    aio_set_event_notifier(ctx, &ctx->notifier, NULL);
>> +    aio_set_event_notifier(ctx, &ctx->notifier, event_notifier_dummy_cb);
>>      ctx->thread_pool = NULL;
>>      qemu_mutex_init(&ctx->bh_lock);
>>      rfifolock_init(&ctx->lock, aio_rfifolock_cb, ctx);
> 
> With this patch, I've got to 500 iterations without seeing the error.
> 
> Still testing it however ...
> 
> Rich.
> 

Re: [Qemu-devel] [PATCH v2 0/3] AioContext: ctx->dispatching is dead, all hail ctx->notify_me

[Marc Zyngier]

On Fri, 17 Jul 2015 10:30:38 +0100
Paolo Bonzini <pbonzini@redhat.com> wrote:

> 
> 
> On 17/07/2015 06:44, Paolo Bonzini wrote:
> > 
> > 
> > On 16/07/2015 21:05, Richard W.M. Jones wrote:
> >>
> >> Sorry to spoil things, but I'm still seeing this bug, although it is
> >> now a lot less frequent with your patch.  I would estimate it happens
> >> more often than 1 in 5 runs with qemu.git, and probably 1 in 200 runs
> >> with qemu.git + the v2 patch series.
> >>
> >> It's the exact same hang in both cases.
> >>
> >> Is it possible that this patch doesn't completely close any race?
> >>
> >> Still, it is an improvement, so there is that.
> > 
> > Would seem at first glance like a different bug.
> > 
> > Interestingly, adding some "tracing" (qemu_clock_get_ns) makes the bug
> > more likely: now it reproduces in about 10 tries.  Of course :) adding
> > other kinds of tracing instead make it go away again (>50 tries).
> > 
> > Perhaps this:
> > 
> >    i/o thread         vcpu thread                   worker thread
> >    ---------------------------------------------------------------------
> >    lock_iothread
> >    notify_me = 1
> >    ...
> >    unlock_iothread
> >                       lock_iothread
> >                       notify_me = 3
> >                       ppoll
> >                       notify_me = 1
> >                                                      bh->scheduled = 1
> >                                                      event_notifier_set
> >                       event_notifier_test_and_clear
> >    ppoll
> >     ^^ hang
> > 	
> > In the exact shape above, it doesn't seem too likely to happen, but
> > perhaps there's another simpler case.  Still, the bug exists.
> > 
> > The above is not really related to notify_me.  Here the notification is
> > not being optimized away!  So I wonder if this one has been there forever.
> > 
> > Fam suggested putting the event_notifier_test_and_clear before
> > aio_bh_poll(), but it does not work.  I'll look more close
> > 
> > However, an unconditional event_notifier_test_and_clear is pretty
> > expensive.  On one hand, obviously correctness comes first.  On the
> > other hand, an expensive operation at the wrong place can mask the race
> > very easily; I'll let the fix run for a while, but I'm not sure if a
> > successful test really says anything useful.
> 
> So it may not be useful, but still successful test is successful. :)
> The following patch, which also includes the delta between v2 and v3
> of this series, survived 674 reboots before hitting a definitely
> unrelated problem:
> 
> error: kvm run failed Function not implemented
> PC=00000000bf671210  SP=00000000c00001f0
> X00=000000000a003e70 X01=0000000000000000 X02=00000000bf680548 X03=0000000000000030
> X04=00000000bbb5fc18 X05=00000000004b7770 X06=00000000bf721930 X07=000000000000009a
> X08=00000000bf716858 X09=0000000000000090 X10=0000000000000000 X11=0000000000000046
> X12=00000000a007e03a X13=0000000000000000 X14=0000000000000000 X15=0000000000000000
> X16=00000000bf716df0 X17=0000000000000000 X18=0000000000000000 X19=00000000bf6f5f18
> X20=0000000000000000 X21=0000000000000000 X22=0000000000000000 X23=0000000000000000
> X24=0000000000000000 X25=0000000000000000 X26=0000000000000000 X27=0000000000000000
> X28=0000000000000000 X29=0000000000000000 X30=0000000000000000 PSTATE=60000305 (flags -ZC-)
> 
> For the record, this is the kvm_run struct:
> 
> $6 = {request_interrupt_window = 0 '\000', padding1 = "\000\000\000\000\000\000", exit_reason = 0, 
>   ready_for_interrupt_injection = 0 '\000', if_flag = 0 '\000', flags = 0, cr8 = 0, apic_base = 0, {hw = {
>       hardware_exit_reason = 150994968}, fail_entry = {hardware_entry_failure_reason = 150994968}, ex = {
>       exception = 150994968, error_code = 0}, io = {direction = 24 '\030', size = 0 '\000', port = 2304, 
>       count = 0, data_offset = 144}, debug = {arch = {<No data fields>}}, mmio = {phys_addr = 150994968, 
>       data = "\220\000\000\000\000\000\000", len = 4, is_write = 0 '\000'}, hypercall = {nr = 150994968, 
>       args = {144, 4, 0, 0, 0, 0}, ret = 0, longmode = 0, pad = 0}, tpr_access = {rip = 150994968, 
>       is_write = 144, pad = 0}, s390_sieic = {icptcode = 24 '\030', ipa = 2304, ipb = 0}, 
>     s390_reset_flags = 150994968, s390_ucontrol = {trans_exc_code = 150994968, pgm_code = 144}, dcr = {
>       dcrn = 150994968, data = 0, is_write = 144 '\220'}, internal = {suberror = 150994968, ndata = 0, 
>       data = {144, 4, 0 <repeats 14 times>}}, osi = {gprs = {150994968, 144, 4, 0 <repeats 29 times>}}, 
>     papr_hcall = {nr = 150994968, ret = 144, args = {4, 0, 0, 0, 0, 0, 0, 0, 0}}, s390_tsch = {
>       subchannel_id = 24, subchannel_nr = 2304, io_int_parm = 0, io_int_word = 144, ipb = 0, 
>       dequeued = 4 '\004'}, epr = {epr = 150994968}, system_event = {type = 150994968, flags = 144}, 
>     s390_stsi = {addr = 150994968, ar = 144 '\220', reserved = 0 '\000', fc = 0 '\000', sel1 = 0 '\000', 
>       sel2 = 0}, 
>     padding = "\030\000\000\t\000\000\000\000\220\000\000\000\000\000\000\000\004", '\000' <repeats 238 times>}, kvm_valid_regs = 0, kvm_dirty_regs = 0, s = {regs = {<No data fields>}, 
>     padding = '\000' <repeats 2047 times>}}
> 
> Marc, does it ring any bell?

Well, this is an example of a guest accessing non-memory using an
instruction that we cannot safely emulate - not an IO accessor (load
multiple, for example).

In this case, we kill the guest (we could as well inject a fault).

This vcpu seems to be accessing 0x9000018 (the mmio structure points
there), but I can't immediately relate it to the content of the
registers.

What looks a bit weird is that all the registers are clamped to 32bit,
but the PSTATE indicates it is running in 64bit (EL1h, which makes the
PC being utterly wrong).

What are you running there?

Thanks,

	M.

> Paolo
> 
> diff --git a/aio-posix.c b/aio-posix.c
> index 268d14d..d2011d0 100644
> --- a/aio-posix.c
> +++ b/aio-posix.c
> @@ -273,6 +273,13 @@ bool aio_poll(AioContext *ctx, bool blocking)
>          aio_context_acquire(ctx);
>      }
>  
> +    /* This should be optimized... */
> +    event_notifier_test_and_clear(&ctx->notifier);
> +
> +    if (blocking) {
> +        atomic_sub(&ctx->notify_me, 2);
> +    }
> +
>      /* if we have any readable fds, dispatch event */
>      if (ret > 0) {
>          for (i = 0; i < npfd; i++) {
> @@ -283,10 +290,6 @@ bool aio_poll(AioContext *ctx, bool blocking)
>      npfd = 0;
>      ctx->walking_handlers--;
>  
> -    if (blocking) {
> -        atomic_sub(&ctx->notify_me, 2);
> -    }
> -
>      /* Run dispatch even if there were no readable fds to run timers */
>      if (aio_dispatch(ctx)) {
>          progress = true;
> diff --git a/aio-win32.c b/aio-win32.c
> index 2bfd5f8..33809fd 100644
> --- a/aio-win32.c
> +++ b/aio-win32.c
> @@ -326,6 +326,10 @@ bool aio_poll(AioContext *ctx, bool blocking)
>          if (timeout) {
>              aio_context_acquire(ctx);
>          }
> +
> +        /* This should be optimized... */
> +        event_notifier_test_and_clear(&ctx->notifier);
> +
>          if (blocking) {
>              assert(first);
>              atomic_sub(&ctx->notify_me, 2);
> diff --git a/async.c b/async.c
> index 9204907..120e183 100644
> --- a/async.c
> +++ b/async.c
> @@ -202,6 +202,9 @@ aio_ctx_check(GSource *source)
>      AioContext *ctx = (AioContext *) source;
>      QEMUBH *bh;
>  
> +    /* This should be optimized... */
> +    event_notifier_test_and_clear(&ctx->notifier);
> +
>      atomic_and(&ctx->notify_me, ~1);
>      for (bh = ctx->first_bh; bh; bh = bh->next) {
>          if (!bh->deleted && bh->scheduled) {
> @@ -280,6 +280,10 @@ static void aio_rfifolock_cb(void *opaque)
>      aio_notify(opaque);
>  }
>  
> +static void event_notifier_dummy_cb(EventNotifier *e)
> +{
> +}
> +
>  AioContext *aio_context_new(Error **errp)
>  {
>      int ret;
> @@ -292,7 +296,7 @@ AioContext *aio_context_new(Error **errp)
>          return NULL;
>      }
>      g_source_set_can_recurse(&ctx->source, true);
> -    aio_set_event_notifier(ctx, &ctx->notifier, NULL);
> +    aio_set_event_notifier(ctx, &ctx->notifier, event_notifier_dummy_cb);
>      ctx->thread_pool = NULL;
>      qemu_mutex_init(&ctx->bh_lock);
>      rfifolock_init(&ctx->lock, aio_rfifolock_cb, ctx);
> 



-- 
Jazz is not dead. It just smells funny.

Re: [Qemu-devel] [PATCH v2 0/3] AioContext: ctx->dispatching is dead, all hail ctx->notify_me

[Laszlo Ersek]

On 07/17/15 15:28, Marc Zyngier wrote:
> On Fri, 17 Jul 2015 10:30:38 +0100
> Paolo Bonzini <pbonzini@redhat.com> wrote:
> 
>>
>>
>> On 17/07/2015 06:44, Paolo Bonzini wrote:
>>>
>>>
>>> On 16/07/2015 21:05, Richard W.M. Jones wrote:
>>>>
>>>> Sorry to spoil things, but I'm still seeing this bug, although it is
>>>> now a lot less frequent with your patch.  I would estimate it happens
>>>> more often than 1 in 5 runs with qemu.git, and probably 1 in 200 runs
>>>> with qemu.git + the v2 patch series.
>>>>
>>>> It's the exact same hang in both cases.
>>>>
>>>> Is it possible that this patch doesn't completely close any race?
>>>>
>>>> Still, it is an improvement, so there is that.
>>>
>>> Would seem at first glance like a different bug.
>>>
>>> Interestingly, adding some "tracing" (qemu_clock_get_ns) makes the bug
>>> more likely: now it reproduces in about 10 tries.  Of course :) adding
>>> other kinds of tracing instead make it go away again (>50 tries).
>>>
>>> Perhaps this:
>>>
>>>    i/o thread         vcpu thread                   worker thread
>>>    ---------------------------------------------------------------------
>>>    lock_iothread
>>>    notify_me = 1
>>>    ...
>>>    unlock_iothread
>>>                       lock_iothread
>>>                       notify_me = 3
>>>                       ppoll
>>>                       notify_me = 1
>>>                                                      bh->scheduled = 1
>>>                                                      event_notifier_set
>>>                       event_notifier_test_and_clear
>>>    ppoll
>>>     ^^ hang
>>> 	
>>> In the exact shape above, it doesn't seem too likely to happen, but
>>> perhaps there's another simpler case.  Still, the bug exists.
>>>
>>> The above is not really related to notify_me.  Here the notification is
>>> not being optimized away!  So I wonder if this one has been there forever.
>>>
>>> Fam suggested putting the event_notifier_test_and_clear before
>>> aio_bh_poll(), but it does not work.  I'll look more close
>>>
>>> However, an unconditional event_notifier_test_and_clear is pretty
>>> expensive.  On one hand, obviously correctness comes first.  On the
>>> other hand, an expensive operation at the wrong place can mask the race
>>> very easily; I'll let the fix run for a while, but I'm not sure if a
>>> successful test really says anything useful.
>>
>> So it may not be useful, but still successful test is successful. :)
>> The following patch, which also includes the delta between v2 and v3
>> of this series, survived 674 reboots before hitting a definitely
>> unrelated problem:
>>
>> error: kvm run failed Function not implemented
>> PC=00000000bf671210  SP=00000000c00001f0
>> X00=000000000a003e70 X01=0000000000000000 X02=00000000bf680548 X03=0000000000000030
>> X04=00000000bbb5fc18 X05=00000000004b7770 X06=00000000bf721930 X07=000000000000009a
>> X08=00000000bf716858 X09=0000000000000090 X10=0000000000000000 X11=0000000000000046
>> X12=00000000a007e03a X13=0000000000000000 X14=0000000000000000 X15=0000000000000000
>> X16=00000000bf716df0 X17=0000000000000000 X18=0000000000000000 X19=00000000bf6f5f18
>> X20=0000000000000000 X21=0000000000000000 X22=0000000000000000 X23=0000000000000000
>> X24=0000000000000000 X25=0000000000000000 X26=0000000000000000 X27=0000000000000000
>> X28=0000000000000000 X29=0000000000000000 X30=0000000000000000 PSTATE=60000305 (flags -ZC-)
>>
>> For the record, this is the kvm_run struct:
>>
>> $6 = {request_interrupt_window = 0 '\000', padding1 = "\000\000\000\000\000\000", exit_reason = 0, 
>>   ready_for_interrupt_injection = 0 '\000', if_flag = 0 '\000', flags = 0, cr8 = 0, apic_base = 0, {hw = {
>>       hardware_exit_reason = 150994968}, fail_entry = {hardware_entry_failure_reason = 150994968}, ex = {
>>       exception = 150994968, error_code = 0}, io = {direction = 24 '\030', size = 0 '\000', port = 2304, 
>>       count = 0, data_offset = 144}, debug = {arch = {<No data fields>}}, mmio = {phys_addr = 150994968, 
>>       data = "\220\000\000\000\000\000\000", len = 4, is_write = 0 '\000'}, hypercall = {nr = 150994968, 
>>       args = {144, 4, 0, 0, 0, 0}, ret = 0, longmode = 0, pad = 0}, tpr_access = {rip = 150994968, 
>>       is_write = 144, pad = 0}, s390_sieic = {icptcode = 24 '\030', ipa = 2304, ipb = 0}, 
>>     s390_reset_flags = 150994968, s390_ucontrol = {trans_exc_code = 150994968, pgm_code = 144}, dcr = {
>>       dcrn = 150994968, data = 0, is_write = 144 '\220'}, internal = {suberror = 150994968, ndata = 0, 
>>       data = {144, 4, 0 <repeats 14 times>}}, osi = {gprs = {150994968, 144, 4, 0 <repeats 29 times>}}, 
>>     papr_hcall = {nr = 150994968, ret = 144, args = {4, 0, 0, 0, 0, 0, 0, 0, 0}}, s390_tsch = {
>>       subchannel_id = 24, subchannel_nr = 2304, io_int_parm = 0, io_int_word = 144, ipb = 0, 
>>       dequeued = 4 '\004'}, epr = {epr = 150994968}, system_event = {type = 150994968, flags = 144}, 
>>     s390_stsi = {addr = 150994968, ar = 144 '\220', reserved = 0 '\000', fc = 0 '\000', sel1 = 0 '\000', 
>>       sel2 = 0}, 
>>     padding = "\030\000\000\t\000\000\000\000\220\000\000\000\000\000\000\000\004", '\000' <repeats 238 times>}, kvm_valid_regs = 0, kvm_dirty_regs = 0, s = {regs = {<No data fields>}, 
>>     padding = '\000' <repeats 2047 times>}}
>>
>> Marc, does it ring any bell?
> 
> Well, this is an example of a guest accessing non-memory using an
> instruction that we cannot safely emulate - not an IO accessor (load
> multiple, for example).
> 
> In this case, we kill the guest (we could as well inject a fault).
> 
> This vcpu seems to be accessing 0x9000018 (the mmio structure points
> there), but I can't immediately relate it to the content of the
> registers.

    [VIRT_UART] =               { 0x09000000, 0x00001000 },

Thanks
Laszlo

> 
> What looks a bit weird is that all the registers are clamped to 32bit,
> but the PSTATE indicates it is running in 64bit (EL1h, which makes the
> PC being utterly wrong).
> 
> What are you running there?
> 
> Thanks,
> 
> 	M.
> 
>> Paolo
>>
>> diff --git a/aio-posix.c b/aio-posix.c
>> index 268d14d..d2011d0 100644
>> --- a/aio-posix.c
>> +++ b/aio-posix.c
>> @@ -273,6 +273,13 @@ bool aio_poll(AioContext *ctx, bool blocking)
>>          aio_context_acquire(ctx);
>>      }
>>  
>> +    /* This should be optimized... */
>> +    event_notifier_test_and_clear(&ctx->notifier);
>> +
>> +    if (blocking) {
>> +        atomic_sub(&ctx->notify_me, 2);
>> +    }
>> +
>>      /* if we have any readable fds, dispatch event */
>>      if (ret > 0) {
>>          for (i = 0; i < npfd; i++) {
>> @@ -283,10 +290,6 @@ bool aio_poll(AioContext *ctx, bool blocking)
>>      npfd = 0;
>>      ctx->walking_handlers--;
>>  
>> -    if (blocking) {
>> -        atomic_sub(&ctx->notify_me, 2);
>> -    }
>> -
>>      /* Run dispatch even if there were no readable fds to run timers */
>>      if (aio_dispatch(ctx)) {
>>          progress = true;
>> diff --git a/aio-win32.c b/aio-win32.c
>> index 2bfd5f8..33809fd 100644
>> --- a/aio-win32.c
>> +++ b/aio-win32.c
>> @@ -326,6 +326,10 @@ bool aio_poll(AioContext *ctx, bool blocking)
>>          if (timeout) {
>>              aio_context_acquire(ctx);
>>          }
>> +
>> +        /* This should be optimized... */
>> +        event_notifier_test_and_clear(&ctx->notifier);
>> +
>>          if (blocking) {
>>              assert(first);
>>              atomic_sub(&ctx->notify_me, 2);
>> diff --git a/async.c b/async.c
>> index 9204907..120e183 100644
>> --- a/async.c
>> +++ b/async.c
>> @@ -202,6 +202,9 @@ aio_ctx_check(GSource *source)
>>      AioContext *ctx = (AioContext *) source;
>>      QEMUBH *bh;
>>  
>> +    /* This should be optimized... */
>> +    event_notifier_test_and_clear(&ctx->notifier);
>> +
>>      atomic_and(&ctx->notify_me, ~1);
>>      for (bh = ctx->first_bh; bh; bh = bh->next) {
>>          if (!bh->deleted && bh->scheduled) {
>> @@ -280,6 +280,10 @@ static void aio_rfifolock_cb(void *opaque)
>>      aio_notify(opaque);
>>  }
>>  
>> +static void event_notifier_dummy_cb(EventNotifier *e)
>> +{
>> +}
>> +
>>  AioContext *aio_context_new(Error **errp)
>>  {
>>      int ret;
>> @@ -292,7 +296,7 @@ AioContext *aio_context_new(Error **errp)
>>          return NULL;
>>      }
>>      g_source_set_can_recurse(&ctx->source, true);
>> -    aio_set_event_notifier(ctx, &ctx->notifier, NULL);
>> +    aio_set_event_notifier(ctx, &ctx->notifier, event_notifier_dummy_cb);
>>      ctx->thread_pool = NULL;
>>      qemu_mutex_init(&ctx->bh_lock);
>>      rfifolock_init(&ctx->lock, aio_rfifolock_cb, ctx);
>>
> 
> 
> 

Re: [Qemu-devel] [PATCH v2 0/3] AioContext: ctx->dispatching is dead, all hail ctx->notify_me

[Marc Zyngier]

On Fri, 17 Jul 2015 14:39:55 +0100
Laszlo Ersek <lersek@redhat.com> wrote:

> On 07/17/15 15:28, Marc Zyngier wrote:
> > On Fri, 17 Jul 2015 10:30:38 +0100
> > Paolo Bonzini <pbonzini@redhat.com> wrote:
> > 
> >>
> >>
> >> On 17/07/2015 06:44, Paolo Bonzini wrote:
> >>>
> >>>
> >>> On 16/07/2015 21:05, Richard W.M. Jones wrote:
> >>>>
> >>>> Sorry to spoil things, but I'm still seeing this bug, although it is
> >>>> now a lot less frequent with your patch.  I would estimate it happens
> >>>> more often than 1 in 5 runs with qemu.git, and probably 1 in 200 runs
> >>>> with qemu.git + the v2 patch series.
> >>>>
> >>>> It's the exact same hang in both cases.
> >>>>
> >>>> Is it possible that this patch doesn't completely close any race?
> >>>>
> >>>> Still, it is an improvement, so there is that.
> >>>
> >>> Would seem at first glance like a different bug.
> >>>
> >>> Interestingly, adding some "tracing" (qemu_clock_get_ns) makes the bug
> >>> more likely: now it reproduces in about 10 tries.  Of course :) adding
> >>> other kinds of tracing instead make it go away again (>50 tries).
> >>>
> >>> Perhaps this:
> >>>
> >>>    i/o thread         vcpu thread                   worker thread
> >>>    ---------------------------------------------------------------------
> >>>    lock_iothread
> >>>    notify_me = 1
> >>>    ...
> >>>    unlock_iothread
> >>>                       lock_iothread
> >>>                       notify_me = 3
> >>>                       ppoll
> >>>                       notify_me = 1
> >>>                                                      bh->scheduled = 1
> >>>                                                      event_notifier_set
> >>>                       event_notifier_test_and_clear
> >>>    ppoll
> >>>     ^^ hang
> >>> 	
> >>> In the exact shape above, it doesn't seem too likely to happen, but
> >>> perhaps there's another simpler case.  Still, the bug exists.
> >>>
> >>> The above is not really related to notify_me.  Here the notification is
> >>> not being optimized away!  So I wonder if this one has been there forever.
> >>>
> >>> Fam suggested putting the event_notifier_test_and_clear before
> >>> aio_bh_poll(), but it does not work.  I'll look more close
> >>>
> >>> However, an unconditional event_notifier_test_and_clear is pretty
> >>> expensive.  On one hand, obviously correctness comes first.  On the
> >>> other hand, an expensive operation at the wrong place can mask the race
> >>> very easily; I'll let the fix run for a while, but I'm not sure if a
> >>> successful test really says anything useful.
> >>
> >> So it may not be useful, but still successful test is successful. :)
> >> The following patch, which also includes the delta between v2 and v3
> >> of this series, survived 674 reboots before hitting a definitely
> >> unrelated problem:
> >>
> >> error: kvm run failed Function not implemented
> >> PC=00000000bf671210  SP=00000000c00001f0
> >> X00=000000000a003e70 X01=0000000000000000 X02=00000000bf680548 X03=0000000000000030
> >> X04=00000000bbb5fc18 X05=00000000004b7770 X06=00000000bf721930 X07=000000000000009a
> >> X08=00000000bf716858 X09=0000000000000090 X10=0000000000000000 X11=0000000000000046
> >> X12=00000000a007e03a X13=0000000000000000 X14=0000000000000000 X15=0000000000000000
> >> X16=00000000bf716df0 X17=0000000000000000 X18=0000000000000000 X19=00000000bf6f5f18
> >> X20=0000000000000000 X21=0000000000000000 X22=0000000000000000 X23=0000000000000000
> >> X24=0000000000000000 X25=0000000000000000 X26=0000000000000000 X27=0000000000000000
> >> X28=0000000000000000 X29=0000000000000000 X30=0000000000000000 PSTATE=60000305 (flags -ZC-)
> >>
> >> For the record, this is the kvm_run struct:
> >>
> >> $6 = {request_interrupt_window = 0 '\000', padding1 = "\000\000\000\000\000\000", exit_reason = 0, 
> >>   ready_for_interrupt_injection = 0 '\000', if_flag = 0 '\000', flags = 0, cr8 = 0, apic_base = 0, {hw = {
> >>       hardware_exit_reason = 150994968}, fail_entry = {hardware_entry_failure_reason = 150994968}, ex = {
> >>       exception = 150994968, error_code = 0}, io = {direction = 24 '\030', size = 0 '\000', port = 2304, 
> >>       count = 0, data_offset = 144}, debug = {arch = {<No data fields>}}, mmio = {phys_addr = 150994968, 
> >>       data = "\220\000\000\000\000\000\000", len = 4, is_write = 0 '\000'}, hypercall = {nr = 150994968, 
> >>       args = {144, 4, 0, 0, 0, 0}, ret = 0, longmode = 0, pad = 0}, tpr_access = {rip = 150994968, 
> >>       is_write = 144, pad = 0}, s390_sieic = {icptcode = 24 '\030', ipa = 2304, ipb = 0}, 
> >>     s390_reset_flags = 150994968, s390_ucontrol = {trans_exc_code = 150994968, pgm_code = 144}, dcr = {
> >>       dcrn = 150994968, data = 0, is_write = 144 '\220'}, internal = {suberror = 150994968, ndata = 0, 
> >>       data = {144, 4, 0 <repeats 14 times>}}, osi = {gprs = {150994968, 144, 4, 0 <repeats 29 times>}}, 
> >>     papr_hcall = {nr = 150994968, ret = 144, args = {4, 0, 0, 0, 0, 0, 0, 0, 0}}, s390_tsch = {
> >>       subchannel_id = 24, subchannel_nr = 2304, io_int_parm = 0, io_int_word = 144, ipb = 0, 
> >>       dequeued = 4 '\004'}, epr = {epr = 150994968}, system_event = {type = 150994968, flags = 144}, 
> >>     s390_stsi = {addr = 150994968, ar = 144 '\220', reserved = 0 '\000', fc = 0 '\000', sel1 = 0 '\000', 
> >>       sel2 = 0}, 
> >>     padding = "\030\000\000\t\000\000\000\000\220\000\000\000\000\000\000\000\004", '\000' <repeats 238 times>}, kvm_valid_regs = 0, kvm_dirty_regs = 0, s = {regs = {<No data fields>}, 
> >>     padding = '\000' <repeats 2047 times>}}
> >>
> >> Marc, does it ring any bell?
> > 
> > Well, this is an example of a guest accessing non-memory using an
> > instruction that we cannot safely emulate - not an IO accessor (load
> > multiple, for example).
> > 
> > In this case, we kill the guest (we could as well inject a fault).
> > 
> > This vcpu seems to be accessing 0x9000018 (the mmio structure points
> > there), but I can't immediately relate it to the content of the
> > registers.
> 
>     [VIRT_UART] =               { 0x09000000, 0x00001000 },
> 

Still: there is nothing in the registers that remotely points to that
area. X0 is the closest, but it'd take a big negative offset to get
there.

Is that a Linux kernel? or something else?

	M.
-- 
Jazz is not dead. It just smells funny.

Re: [Qemu-devel] [PATCH v2 0/3] AioContext: ctx->dispatching is dead, all hail ctx->notify_me

[Richard W.M. Jones]

On Fri, Jul 17, 2015 at 02:48:40PM +0100, Marc Zyngier wrote:
> Still: there is nothing in the registers that remotely points to that
> area. X0 is the closest, but it'd take a big negative offset to get
> there.
> 
> Is that a Linux kernel? or something else?

You're sure it's not this one?
https://bugzilla.redhat.com/show_bug.cgi?id=1194366
That was caused by ftrace screwing up guest memory, so it was
effectively running random code.  It is also fixed (by you in fact).

Rich.

-- 
Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones
Read my programming and virtualization blog: http://rwmj.wordpress.com
virt-top is 'top' for virtual machines.  Tiny program with many
powerful monitoring features, net stats, disk stats, logging, etc.
http://people.redhat.com/~rjones/virt-top

Re: [Qemu-devel] [PATCH v2 0/3] AioContext: ctx->dispatching is dead, all hail ctx->notify_me

[Laszlo Ersek]

On 07/17/15 15:48, Marc Zyngier wrote:
> On Fri, 17 Jul 2015 14:39:55 +0100
> Laszlo Ersek <lersek@redhat.com> wrote:
> 
>> On 07/17/15 15:28, Marc Zyngier wrote:
>>> On Fri, 17 Jul 2015 10:30:38 +0100
>>> Paolo Bonzini <pbonzini@redhat.com> wrote:
>>>
>>>>
>>>>
>>>> On 17/07/2015 06:44, Paolo Bonzini wrote:
>>>>>
>>>>>
>>>>> On 16/07/2015 21:05, Richard W.M. Jones wrote:
>>>>>>
>>>>>> Sorry to spoil things, but I'm still seeing this bug, although it is
>>>>>> now a lot less frequent with your patch.  I would estimate it happens
>>>>>> more often than 1 in 5 runs with qemu.git, and probably 1 in 200 runs
>>>>>> with qemu.git + the v2 patch series.
>>>>>>
>>>>>> It's the exact same hang in both cases.
>>>>>>
>>>>>> Is it possible that this patch doesn't completely close any race?
>>>>>>
>>>>>> Still, it is an improvement, so there is that.
>>>>>
>>>>> Would seem at first glance like a different bug.
>>>>>
>>>>> Interestingly, adding some "tracing" (qemu_clock_get_ns) makes the bug
>>>>> more likely: now it reproduces in about 10 tries.  Of course :) adding
>>>>> other kinds of tracing instead make it go away again (>50 tries).
>>>>>
>>>>> Perhaps this:
>>>>>
>>>>>    i/o thread         vcpu thread                   worker thread
>>>>>    ---------------------------------------------------------------------
>>>>>    lock_iothread
>>>>>    notify_me = 1
>>>>>    ...
>>>>>    unlock_iothread
>>>>>                       lock_iothread
>>>>>                       notify_me = 3
>>>>>                       ppoll
>>>>>                       notify_me = 1
>>>>>                                                      bh->scheduled = 1
>>>>>                                                      event_notifier_set
>>>>>                       event_notifier_test_and_clear
>>>>>    ppoll
>>>>>     ^^ hang
>>>>> 	
>>>>> In the exact shape above, it doesn't seem too likely to happen, but
>>>>> perhaps there's another simpler case.  Still, the bug exists.
>>>>>
>>>>> The above is not really related to notify_me.  Here the notification is
>>>>> not being optimized away!  So I wonder if this one has been there forever.
>>>>>
>>>>> Fam suggested putting the event_notifier_test_and_clear before
>>>>> aio_bh_poll(), but it does not work.  I'll look more close
>>>>>
>>>>> However, an unconditional event_notifier_test_and_clear is pretty
>>>>> expensive.  On one hand, obviously correctness comes first.  On the
>>>>> other hand, an expensive operation at the wrong place can mask the race
>>>>> very easily; I'll let the fix run for a while, but I'm not sure if a
>>>>> successful test really says anything useful.
>>>>
>>>> So it may not be useful, but still successful test is successful. :)
>>>> The following patch, which also includes the delta between v2 and v3
>>>> of this series, survived 674 reboots before hitting a definitely
>>>> unrelated problem:
>>>>
>>>> error: kvm run failed Function not implemented
>>>> PC=00000000bf671210  SP=00000000c00001f0
>>>> X00=000000000a003e70 X01=0000000000000000 X02=00000000bf680548 X03=0000000000000030
>>>> X04=00000000bbb5fc18 X05=00000000004b7770 X06=00000000bf721930 X07=000000000000009a
>>>> X08=00000000bf716858 X09=0000000000000090 X10=0000000000000000 X11=0000000000000046
>>>> X12=00000000a007e03a X13=0000000000000000 X14=0000000000000000 X15=0000000000000000
>>>> X16=00000000bf716df0 X17=0000000000000000 X18=0000000000000000 X19=00000000bf6f5f18
>>>> X20=0000000000000000 X21=0000000000000000 X22=0000000000000000 X23=0000000000000000
>>>> X24=0000000000000000 X25=0000000000000000 X26=0000000000000000 X27=0000000000000000
>>>> X28=0000000000000000 X29=0000000000000000 X30=0000000000000000 PSTATE=60000305 (flags -ZC-)
>>>>
>>>> For the record, this is the kvm_run struct:
>>>>
>>>> $6 = {request_interrupt_window = 0 '\000', padding1 = "\000\000\000\000\000\000", exit_reason = 0, 
>>>>   ready_for_interrupt_injection = 0 '\000', if_flag = 0 '\000', flags = 0, cr8 = 0, apic_base = 0, {hw = {
>>>>       hardware_exit_reason = 150994968}, fail_entry = {hardware_entry_failure_reason = 150994968}, ex = {
>>>>       exception = 150994968, error_code = 0}, io = {direction = 24 '\030', size = 0 '\000', port = 2304, 
>>>>       count = 0, data_offset = 144}, debug = {arch = {<No data fields>}}, mmio = {phys_addr = 150994968, 
>>>>       data = "\220\000\000\000\000\000\000", len = 4, is_write = 0 '\000'}, hypercall = {nr = 150994968, 
>>>>       args = {144, 4, 0, 0, 0, 0}, ret = 0, longmode = 0, pad = 0}, tpr_access = {rip = 150994968, 
>>>>       is_write = 144, pad = 0}, s390_sieic = {icptcode = 24 '\030', ipa = 2304, ipb = 0}, 
>>>>     s390_reset_flags = 150994968, s390_ucontrol = {trans_exc_code = 150994968, pgm_code = 144}, dcr = {
>>>>       dcrn = 150994968, data = 0, is_write = 144 '\220'}, internal = {suberror = 150994968, ndata = 0, 
>>>>       data = {144, 4, 0 <repeats 14 times>}}, osi = {gprs = {150994968, 144, 4, 0 <repeats 29 times>}}, 
>>>>     papr_hcall = {nr = 150994968, ret = 144, args = {4, 0, 0, 0, 0, 0, 0, 0, 0}}, s390_tsch = {
>>>>       subchannel_id = 24, subchannel_nr = 2304, io_int_parm = 0, io_int_word = 144, ipb = 0, 
>>>>       dequeued = 4 '\004'}, epr = {epr = 150994968}, system_event = {type = 150994968, flags = 144}, 
>>>>     s390_stsi = {addr = 150994968, ar = 144 '\220', reserved = 0 '\000', fc = 0 '\000', sel1 = 0 '\000', 
>>>>       sel2 = 0}, 
>>>>     padding = "\030\000\000\t\000\000\000\000\220\000\000\000\000\000\000\000\004", '\000' <repeats 238 times>}, kvm_valid_regs = 0, kvm_dirty_regs = 0, s = {regs = {<No data fields>}, 
>>>>     padding = '\000' <repeats 2047 times>}}
>>>>
>>>> Marc, does it ring any bell?
>>>
>>> Well, this is an example of a guest accessing non-memory using an
>>> instruction that we cannot safely emulate - not an IO accessor (load
>>> multiple, for example).
>>>
>>> In this case, we kill the guest (we could as well inject a fault).
>>>
>>> This vcpu seems to be accessing 0x9000018 (the mmio structure points
>>> there), but I can't immediately relate it to the content of the
>>> registers.
>>
>>     [VIRT_UART] =               { 0x09000000, 0x00001000 },
>>
> 
> Still: there is nothing in the registers that remotely points to that
> area. X0 is the closest, but it'd take a big negative offset to get
> there.
> 
> Is that a Linux kernel? or something else?

Assuming I managed to decipher the nesting of the contexts, the register
dump was pasted by Paolo. IIRC Paolo has been using the guest firmware
(the ArmVirtPkg/ArmVirtQemu.dsc platform build in edk2, also known as
"AAVMF" sometimes) to reproduce the issue.

Thanks
Laszlo

Re: [Qemu-devel] [PATCH v2 0/3] AioContext: ctx->dispatching is dead, all hail ctx->notify_me

[Marc Zyngier]

On Fri, 17 Jul 2015 14:53:06 +0100
"Richard W.M. Jones" <rjones@redhat.com> wrote:

> On Fri, Jul 17, 2015 at 02:48:40PM +0100, Marc Zyngier wrote:
> > Still: there is nothing in the registers that remotely points to that
> > area. X0 is the closest, but it'd take a big negative offset to get
> > there.
> > 
> > Is that a Linux kernel? or something else?
> 
> You're sure it's not this one?
> https://bugzilla.redhat.com/show_bug.cgi?id=1194366
> That was caused by ftrace screwing up guest memory, so it was
> effectively running random code.  It is also fixed (by you in fact).

Don't think so. The bug you quote was the guest kernel being buggy, and
touching non-memory space.

This new issue seems different - this is not a Linux kernel, by the
look of it.

	M.
-- 
Jazz is not dead. It just smells funny.

Re: [Qemu-devel] [PATCH v2 0/3] AioContext: ctx->dispatching is dead, all hail ctx->notify_me

[Paolo Bonzini]

On 17/07/2015 15:28, Marc Zyngier wrote:
> > 
> > Marc, does it ring any bell?
> Well, this is an example of a guest accessing non-memory using an
> instruction that we cannot safely emulate - not an IO accessor (load
> multiple, for example).
> 
> In this case, we kill the guest (we could as well inject a fault).

Yup, I later found this in the dmesg:

[1875219.903969] kvm [14843]: load/store instruction decoding not implemented

> This vcpu seems to be accessing 0x9000018 (the mmio structure points
> there), but I can't immediately relate it to the content of the
> registers.

0x9000018 is the pl011, which makes some sense.

Have you ever seen a corrupted register dump?  The guest RAM goes
from 0x40000000 to 0xbfffffff, so SP is pointing outside memory.

> > PC=00000000bf671210  SP=00000000c00001f0
> > X00=000000000a003e70 X01=0000000000000000 X02=00000000bf680548 X03=0000000000000030
> > X04=00000000bbb5fc18 X05=00000000004b7770 X06=00000000bf721930 X07=000000000000009a
> > X08=00000000bf716858 X09=0000000000000090 X10=0000000000000000 X11=0000000000000046
> > X12=00000000a007e03a X13=0000000000000000 X14=0000000000000000 X15=0000000000000000
> > X16=00000000bf716df0 X17=0000000000000000 X18=0000000000000000 X19=00000000bf6f5f18
> > X20=0000000000000000 X21=0000000000000000 X22=0000000000000000 X23=0000000000000000
> > X24=0000000000000000 X25=0000000000000000 X26=0000000000000000 X27=0000000000000000
> > X28=0000000000000000 X29=0000000000000000 X30=0000000000000000 PSTATE=60000305 (flags -ZC-)

If the register dump is not corrupted, execution went in the weeds...
I don't have the guest anymore but it's just firmware so the memory
contents are well reproducible:

0x00000000bf671200:  a97d6ffa      ldmdbge	sp!, {r1, r3, r4, r5, r6, r7, r8, r9, sl, fp, sp, lr}^
0x00000000bf671204:  a97e77fc      ldmdbge	lr!, {r2, r3, r4, r5, r6, r7, r8, r9, sl, ip, sp, lr}^
0x00000000bf671208:  f85f03fe      undefined instruction 0xf85f03fe
0x00000000bf67120c:  910803ff      strdls	r0, [r8, -pc]
0x00000000bf671210:  ad7007e0      ldclge	7, cr0, [r0, #-896]!
0x00000000bf671214:  ad710fe2      ldclge	15, cr0, [r1, #-904]!
0x00000000bf671218:  ad7217e4      ldclge	7, cr1, [r2, #-912]!
0x00000000bf67121c:  ad731fe6      ldclge	15, cr1, [r3, #-920]!
0x00000000bf671220:  ad7427e8      ldclge	7, cr2, [r4, #-928]!
0x00000000bf671224:  ad752fea      ldclge	15, cr2, [r5, #-936]!

> What looks a bit weird is that all the registers are clamped to 32bit,
> but the PSTATE indicates it is running in 64bit (EL1h, which makes the
> PC being utterly wrong).

The PC can be okay since UEFI code doesn't really use virtual addressing,
but the other registers are weird indeed.

> What are you running there?

Just firmware.  It's a UEFI reboot loop (as soon as you get to the
UEFI shell QEMU exits and the script starts a new one).

The kernel is an old 3.19 one, I'll upgrade and retest.

Paolo

Re: [Qemu-devel] [PATCH v2 0/3] AioContext: ctx->dispatching is dead, all hail ctx->notify_me

[Marc Zyngier]

On Fri, 17 Jul 2015 15:04:27 +0100
Paolo Bonzini <pbonzini@redhat.com> wrote:

> 
> 
> On 17/07/2015 15:28, Marc Zyngier wrote:
> > > 
> > > Marc, does it ring any bell?
> > Well, this is an example of a guest accessing non-memory using an
> > instruction that we cannot safely emulate - not an IO accessor (load
> > multiple, for example).
> > 
> > In this case, we kill the guest (we could as well inject a fault).
> 
> Yup, I later found this in the dmesg:
> 
> [1875219.903969] kvm [14843]: load/store instruction decoding not implemented
> 
> > This vcpu seems to be accessing 0x9000018 (the mmio structure points
> > there), but I can't immediately relate it to the content of the
> > registers.
> 
> 0x9000018 is the pl011, which makes some sense.
> 
> Have you ever seen a corrupted register dump?  The guest RAM goes
> from 0x40000000 to 0xbfffffff, so SP is pointing outside memory.

I've never seen such a corruption - so far.

> > > PC=00000000bf671210  SP=00000000c00001f0
> > > X00=000000000a003e70 X01=0000000000000000 X02=00000000bf680548 X03=0000000000000030
> > > X04=00000000bbb5fc18 X05=00000000004b7770 X06=00000000bf721930 X07=000000000000009a
> > > X08=00000000bf716858 X09=0000000000000090 X10=0000000000000000 X11=0000000000000046
> > > X12=00000000a007e03a X13=0000000000000000 X14=0000000000000000 X15=0000000000000000
> > > X16=00000000bf716df0 X17=0000000000000000 X18=0000000000000000 X19=00000000bf6f5f18
> > > X20=0000000000000000 X21=0000000000000000 X22=0000000000000000 X23=0000000000000000
> > > X24=0000000000000000 X25=0000000000000000 X26=0000000000000000 X27=0000000000000000
> > > X28=0000000000000000 X29=0000000000000000 X30=0000000000000000 PSTATE=60000305 (flags -ZC-)
> 
> If the register dump is not corrupted, execution went in the weeds...
> I don't have the guest anymore but it's just firmware so the memory
> contents are well reproducible:
> 
> 0x00000000bf671200:  a97d6ffa      ldmdbge	sp!, {r1, r3, r4, r5, r6, r7, r8, r9, sl, fp, sp, lr}^
> 0x00000000bf671204:  a97e77fc      ldmdbge	lr!, {r2, r3, r4, r5, r6, r7, r8, r9, sl, ip, sp, lr}^
> 0x00000000bf671208:  f85f03fe      undefined instruction 0xf85f03fe
> 0x00000000bf67120c:  910803ff      strdls	r0, [r8, -pc]
> 0x00000000bf671210:  ad7007e0      ldclge	7, cr0, [r0, #-896]!
> 0x00000000bf671214:  ad710fe2      ldclge	15, cr0, [r1, #-904]!
> 0x00000000bf671218:  ad7217e4      ldclge	7, cr1, [r2, #-912]!
> 0x00000000bf67121c:  ad731fe6      ldclge	15, cr1, [r3, #-920]!
> 0x00000000bf671220:  ad7427e8      ldclge	7, cr2, [r4, #-928]!
> 0x00000000bf671224:  ad752fea      ldclge	15, cr2, [r5, #-936]!

But that's all 32bit code, and your guest was running in 64bit. What
does it look like as A64?

> > What looks a bit weird is that all the registers are clamped to 32bit,
> > but the PSTATE indicates it is running in 64bit (EL1h, which makes the
> > PC being utterly wrong).
> 
> The PC can be okay since UEFI code doesn't really use virtual addressing,
> but the other registers are weird indeed.

It definitely looks like something tramped on your register file. KVM
doesn't do that at all (we use the whole AArch64 register file
irrespective of the execution state).

Is your UEFI guest 32 or 64bit?

	M.
-- 
Jazz is not dead. It just smells funny.

Re: [Qemu-devel] [PATCH v2 0/3] AioContext: ctx->dispatching is dead, all hail ctx->notify_me

[Stefan Hajnoczi]

[-- Attachment #1: Type: text/plain, Size: 1095 bytes --]

On Sat, Jul 18, 2015 at 10:21:28PM +0200, Paolo Bonzini wrote:
> The change from v2 is very small, notify_me is decremented as soon
> as ppoll returns.
> 
> Paolo
> 
> v1->v2
>         Split some changes to the tests to a separate patch
>         Fix commit message [Laszlo]
>         Clarify do...while loop in aio-win32.c [Kevin]
> 
> v2->v3
>         Decrement notify_me a little earlier in aio-posix.c.
> 
> Paolo Bonzini (3):
>   tests: remove irrelevant assertions from test-aio
>   aio-win32: reorganize polling loop
>   AioContext: fix broken ctx->dispatching optimization
> 
>  aio-posix.c             | 18 +++++-------
>  aio-win32.c             | 41 ++++++++++++++------------
>  async.c                 | 21 +++++---------
>  docs/aio_notify.promela | 77 +++++++++++++++++++++----------------------------
>  include/block/aio.h     | 29 +++++++++++++++----
>  tests/test-aio.c        | 26 +++--------------
>  6 files changed, 97 insertions(+), 115 deletions(-)

Thanks, applied to my block tree:
https://github.com/stefanha/qemu/commits/block

Stefan

[-- Attachment #2: Type: application/pgp-signature, Size: 473 bytes --]

Re: [Qemu-devel] [PATCH v2 0/3] AioContext: ctx->dispatching is dead, all hail ctx->notify_me

[Richard W.M. Jones]

I tested this patch series, plus 'AioContext: fix missing wakeups due
to event_notifier_test_and_clear' overnight, and there were no
failures after something like 2500 iterations.  So:

  Tested-by: Richard W.M. Jones <rjones@redhat.com>

Rich.

-- 
Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones
Read my programming and virtualization blog: http://rwmj.wordpress.com
virt-df lists disk usage of guests without needing to install any
software inside the virtual machine.  Supports Linux and Windows.
http://people.redhat.com/~rjones/virt-df/

[Qemu-devel] [PATCH v2 0/3] AioContext: ctx->dispatching is dead, all hail ctx->notify_me

[Paolo Bonzini]

The change from v2 is very small, notify_me is decremented as soon
as ppoll returns.

Paolo

v1->v2
        Split some changes to the tests to a separate patch
        Fix commit message [Laszlo]
        Clarify do...while loop in aio-win32.c [Kevin]

v2->v3
        Decrement notify_me a little earlier in aio-posix.c.

Paolo Bonzini (3):
  tests: remove irrelevant assertions from test-aio
  aio-win32: reorganize polling loop
  AioContext: fix broken ctx->dispatching optimization

 aio-posix.c             | 18 +++++-------
 aio-win32.c             | 41 ++++++++++++++------------
 async.c                 | 21 +++++---------
 docs/aio_notify.promela | 77 +++++++++++++++++++++----------------------------
 include/block/aio.h     | 29 +++++++++++++++----
 tests/test-aio.c        | 26 +++--------------
 6 files changed, 97 insertions(+), 115 deletions(-)

-- 
2.4.3