[Qemu-devel] [PATCH v2] trace/simple: fix hang in child after fork(2)

[Qemu-devel] [PATCH v2] trace/simple: fix hang in child after fork(2)

[Stefan Hajnoczi]

The simple trace backend spawns a write-out thread which is used to
asynchronously flush the in-memory ring buffer to disk.

fork(2) does not clone all threads, only the thread that invoked
fork(2).  As a result there is no write-out thread in the child process!

This causes a hang during shutdown when atexit(3) handler installed by
the simple trace backend waits for the non-existent write-out thread.

This patch uses pthread_atfork(3) to terminate the write-out thread
before fork and restart it in both the parent and child after fork.
This solves a hang in qemu-iotests 147 due to qemu-nbd --fork usage.

Reported-by: Cornelia Huck <cohuck@redhat.com>
Suggested-by: Paolo Bonzini <pbonzini@redhat.com>
Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
---
 trace/simple.c | 67 +++++++++++++++++++++++++++++++++++++++++++-------
 1 file changed, 58 insertions(+), 9 deletions(-)

diff --git a/trace/simple.c b/trace/simple.c
index 701dec639c..9f6ac9ef24 100644
--- a/trace/simple.c
+++ b/trace/simple.c
@@ -39,9 +39,11 @@
 static GMutex trace_lock;
 static GCond trace_available_cond;
 static GCond trace_empty_cond;
+static GThread *trace_writeout_thread;
 
 static bool trace_available;
 static bool trace_writeout_enabled;
+static bool trace_writeout_running;
 
 enum {
     TRACE_BUF_LEN = 4096 * 64,
@@ -142,15 +144,34 @@ static void flush_trace_file(bool wait)
     g_mutex_unlock(&trace_lock);
 }
 
-static void wait_for_trace_records_available(void)
+/**
+ * Wait to be kicked by flush_trace_file()
+ *
+ * Returns: true if the writeout thread should continue
+ *          false if the writeout thread should terminate
+ */
+static bool wait_for_trace_records_available(void)
 {
+    bool running;
+
     g_mutex_lock(&trace_lock);
-    while (!(trace_available && trace_writeout_enabled)) {
+    for (;;) {
+        running = trace_writeout_running;
+        if (!running) {
+            break;
+        }
+
+        if (trace_available && trace_writeout_enabled) {
+            break;
+        }
+
         g_cond_signal(&trace_empty_cond);
         g_cond_wait(&trace_available_cond, &trace_lock);
     }
     trace_available = false;
     g_mutex_unlock(&trace_lock);
+
+    return running;
 }
 
 static gpointer writeout_thread(gpointer opaque)
@@ -165,9 +186,7 @@ static gpointer writeout_thread(gpointer opaque)
     size_t unused __attribute__ ((unused));
     uint64_t type = TRACE_RECORD_TYPE_EVENT;
 
-    for (;;) {
-        wait_for_trace_records_available();
-
+    while (wait_for_trace_records_available()) {
         if (g_atomic_int_get(&dropped_events)) {
             dropped.rec.event = DROPPED_EVENT_ID,
             dropped.rec.timestamp_ns = get_clock();
@@ -398,18 +417,48 @@ static GThread *trace_thread_create(GThreadFunc fn)
     return thread;
 }
 
+#ifndef _WIN32
+static void stop_writeout_thread(void)
+{
+    g_mutex_lock(&trace_lock);
+    trace_writeout_running = false;
+    g_cond_signal(&trace_available_cond);
+    g_mutex_unlock(&trace_lock);
+
+    g_thread_join(trace_writeout_thread);
+    trace_writeout_thread = NULL;
+}
+
+static void restart_writeout_thread(void)
+{
+    trace_writeout_running = true;
+    trace_writeout_thread = trace_thread_create(writeout_thread);
+    if (!trace_writeout_thread) {
+        warn_report("unable to initialize simple trace backend");
+    }
+}
+#endif /* !_WIN32 */
+
 bool st_init(void)
 {
-    GThread *thread;
-
     trace_pid = getpid();
+    trace_writeout_running = true;
 
-    thread = trace_thread_create(writeout_thread);
-    if (!thread) {
+    trace_writeout_thread = trace_thread_create(writeout_thread);
+    if (!trace_writeout_thread) {
         warn_report("unable to initialize simple trace backend");
         return false;
     }
 
+#ifndef _WIN32
+    /* Terminate writeout thread across fork and restart it in parent and
+     * child afterwards.
+     */
+    pthread_atfork(stop_writeout_thread,
+                   restart_writeout_thread,
+                   restart_writeout_thread);
+#endif
+
     atexit(st_flush_trace_buffer);
     return true;
 }
-- 
2.17.1

Re: [Qemu-devel] [PATCH v2] trace/simple: fix hang in child after fork(2)

[Paolo Bonzini]

On 13/07/2018 20:42, Stefan Hajnoczi wrote:
> +#ifndef _WIN32
> +static void stop_writeout_thread(void)
> +{
> +    g_mutex_lock(&trace_lock);
> +    trace_writeout_running = false;
> +    g_cond_signal(&trace_available_cond);
> +    g_mutex_unlock(&trace_lock);
> +
> +    g_thread_join(trace_writeout_thread);
> +    trace_writeout_thread = NULL;
> +}

After stop_writeout_thread returns, another could start a write to the
shared data structure---and the write would never finish, because the
thread disappears after fork(2) returns.  This would leave the mutex
locked, causing a deadlock soon after the fork.  So you need to lock
trace_lock again here, and unlock it in restart_writeout_thread.

Apart from this, it looks good!

Thanks,

Paolo

> +static void restart_writeout_thread(void)
> +{
> +    trace_writeout_running = true;
> +    trace_writeout_thread = trace_thread_create(writeout_thread);
> +    if (!trace_writeout_thread) {
> +        warn_report("unable to initialize simple trace backend");
> +    }
> +}
> +#endif /* !_WIN32 */
> +
>  bool st_init(void)
>  {
> -    GThread *thread;
> -
>      trace_pid = getpid();
> +    trace_writeout_running = true;
>  
> -    thread = trace_thread_create(writeout_thread);
> -    if (!thread) {
> +    trace_writeout_thread = trace_thread_create(writeout_thread);
> +    if (!trace_writeout_thread) {
>          warn_report("unable to initialize simple trace backend");
>          return false;
>      }
>  
> +#ifndef _WIN32
> +    /* Terminate writeout thread across fork and restart it in parent and
> +     * child afterwards.
> +     */
> +    pthread_atfork(stop_writeout_thread,
> +                   restart_writeout_thread,
> +                   restart_writeout_thread);
> +#endif
> +
>      atexit(st_flush_trace_buffer);
>      return true;
>  }
> 

Re: [Qemu-devel] [PATCH v2] trace/simple: fix hang in child after fork(2)

[Cornelia Huck]

On Sun, 15 Jul 2018 14:42:23 +0200
Paolo Bonzini <pbonzini@redhat.com> wrote:

> On 13/07/2018 20:42, Stefan Hajnoczi wrote:
> > +#ifndef _WIN32
> > +static void stop_writeout_thread(void)
> > +{
> > +    g_mutex_lock(&trace_lock);
> > +    trace_writeout_running = false;
> > +    g_cond_signal(&trace_available_cond);
> > +    g_mutex_unlock(&trace_lock);
> > +
> > +    g_thread_join(trace_writeout_thread);
> > +    trace_writeout_thread = NULL;
> > +}  
> 
> After stop_writeout_thread returns, another could start a write to the
> shared data structure---and the write would never finish, because the
> thread disappears after fork(2) returns.  This would leave the mutex
> locked, causing a deadlock soon after the fork.  So you need to lock
> trace_lock again here, and unlock it in restart_writeout_thread.

So, I suppose there will be a v3, right?

> 
> Apart from this, it looks good!

Did a quick run and it fixed the problems for me.