[PATCH hci-8.0 09/12] system/cpus: report a BQL held past a deadline #VSTOR-144507

["Denis V. Lunev" <den@openvz.org>]

From: Denis V. Lunev <den@openvz.org>

A vCPU thread reacquires the BQL on every exit that needs userspace, so
a lock held for tens of seconds stops those vCPUs dead and the guest
reports its own soft lockup. Nothing in qemu records that this
happened, which leaves a guest panic as the only evidence and no way to
tell a stuck holder from a guest that wedged on its own.

Add a BQL watchdog. A thread of its own samples a counter advanced on
every acquire and every release, so it is odd while the lock is held.
One odd value seen throughout the window means a single owner held the
lock for the whole window, because any handover would have advanced the
counter twice.

Advance it in bql_update_status(), which the mutex hooks already call
for exactly those two transitions, so a cond-wait that drops and
retakes the lock is covered without the wrappers knowing, and so is any
caller that reaches the BQL through the plain mutex API. Record the
holder's tid beside it, under the same lock, because the thread listing
alone cannot tell a thread parked on its own condvar from one blocked
on the BQL. Cache the tid per thread, since gettid is a syscall and
this is the lock path.

On expiry, name the holder and list every thread's state. The listing
separates a thread blocked on the BQL, which waits in a futex, from one
idle inside KVM, which waits in kvm_vcpu_block, and names the syscall a
wedged holder is stuck in. Report once per episode, or a lock held for
a minute buries the log in copies of one answer. Put the time on the
line unless -msg timestamp=on already does: a hold is only worth
reporting if it can be lined up against what the guest saw, and that
option has to be asked for in advance.

The deadline has to clear the longest legitimate hold, and migration
setup can hold the BQL for a while, so the watchdog stays off unless
asked for. The bql-watchdog-ms machine property is the whole interface:
it sets the deadline, on the command line or over qom-set at any time,
and 0 turns the watchdog off. Reject a deadline above a minute: a hold
that long has already shown up as a soft lockup inside the guest.

Cc: Paolo Bonzini <pbonzini@redhat.com>
Cc: Richard Henderson <richard.henderson@linaro.org>
Cc: Philippe Mathieu-Daudé <philmd@oss.qualcomm.com>
Cc: Zhao Liu <zhao1.liu@intel.com>
Signed-off-by: Denis V. Lunev <den@openvz.org>
---
 hw/core/machine.c     |  27 ++++++++++
 include/system/cpus.h |   4 ++
 qemu-options.hx       |   6 +++
 system/cpus.c         | 120 ++++++++++++++++++++++++++++++++++++++++++
 4 files changed, 157 insertions(+)

diff --git a/hw/core/machine.c b/hw/core/machine.c
index bd61aa69ccc..d5bb047744d 100644
--- a/hw/core/machine.c
+++ b/hw/core/machine.c
@@ -923,6 +923,27 @@ static void machine_set_dump_guest_core(Object *obj, bool value, Error **errp)
     ms->dump_guest_core = value;
 }
 
+static void machine_get_bql_watchdog_ms(Object *obj, Visitor *v,
+                                        const char *name, void *opaque,
+                                        Error **errp)
+{
+    uint64_t value = bql_watchdog_get_timeout_ms();
+
+    visit_type_uint64(v, name, &value, errp);
+}
+
+static void machine_set_bql_watchdog_ms(Object *obj, Visitor *v,
+                                        const char *name, void *opaque,
+                                        Error **errp)
+{
+    uint64_t value;
+
+    if (!visit_type_uint64(v, name, &value, errp)) {
+        return;
+    }
+    bql_watchdog_set_timeout_ms(value, errp);
+}
+
 static bool machine_get_mem_merge(Object *obj, Error **errp)
 {
     MachineState *ms = MACHINE(obj);
@@ -1671,6 +1692,12 @@ static void machine_class_init(ObjectClass *oc, const void *data)
     object_class_property_set_description(oc, "dump-guest-core",
         "Include guest memory in a core dump");
 
+    object_class_property_add(oc, "bql-watchdog-ms", "uint64",
+        machine_get_bql_watchdog_ms, machine_set_bql_watchdog_ms, NULL, NULL);
+    object_class_property_set_description(oc, "bql-watchdog-ms",
+        "Watchdog deadline for a Big QEMU Lock hold, in ms. "
+        "Default: 0 (disabled)");
+
     object_class_property_add_bool(oc, "mem-merge",
         machine_get_mem_merge, machine_set_mem_merge);
     object_class_property_set_description(oc, "mem-merge",
diff --git a/include/system/cpus.h b/include/system/cpus.h
index 4aebec48705..45adcacdc38 100644
--- a/include/system/cpus.h
+++ b/include/system/cpus.h
@@ -41,4 +41,8 @@ void cpu_synchronize_all_post_reset(void);
 void cpu_synchronize_all_post_init(void);
 void cpu_synchronize_all_pre_loadvm(void);
 
+/* Watchdog deadline for a BQL hold. 0 disables the watchdog. */
+bool bql_watchdog_set_timeout_ms(uint64_t ms, Error **errp);
+uint64_t bql_watchdog_get_timeout_ms(void);
+
 #endif
diff --git a/qemu-options.hx b/qemu-options.hx
index aae51823d70..2809fe42fb9 100644
--- a/qemu-options.hx
+++ b/qemu-options.hx
@@ -32,6 +32,7 @@ DEF("machine", HAS_ARG, QEMU_OPTION_machine, \
     "                vmport=on|off|auto controls emulation of vmport (default: auto)\n"
     "                dump-guest-core=on|off include guest memory in a core dump (default=on)\n"
     "                mem-merge=on|off controls memory merge support (default: on)\n"
+    "                bql-watchdog-ms=ms report a Big QEMU Lock held longer than ms (default: 0, off)\n"
     "                aes-key-wrap=on|off controls support for AES key wrapping (default=on)\n"
     "                dea-key-wrap=on|off controls support for DEA key wrapping (default=on)\n"
     "                suppress-vmdesc=on|off disables self-describing migration (default=off)\n"
@@ -84,6 +85,11 @@ SRST
         supported by the host, de-duplicates identical memory pages
         among VMs instances (enabled by default).
 
+    ``bql-watchdog-ms=ms``
+        Report when the Big QEMU Lock has been held for more than ``ms``
+        milliseconds, up to a minute. The default is 0, which disables the
+        watchdog.
+
     ``aes-key-wrap=on|off``
         Enables or disables AES key wrapping support on s390-ccw hosts.
         This feature controls whether AES wrapping keys will be created
diff --git a/system/cpus.c b/system/cpus.c
index 5c2bdc3f3d0..fe7f47ab1c3 100644
--- a/system/cpus.c
+++ b/system/cpus.c
@@ -36,6 +36,7 @@
 #include "exec/cpu-common.h"
 #include "qemu/thread.h"
 #include "qemu/main-loop.h"
+#include "qemu/error-report.h"
 #include "qemu/plugin.h"
 #include "system/cpus.h"
 #include "qemu/guest-random.h"
@@ -419,12 +420,129 @@ static QemuCond qemu_cpu_cond;
 /* system init */
 static QemuCond qemu_pause_cond;
 
+/*
+ * Advanced by bql_update_status() below, so odd while the BQL is held and
+ * even while it is free. A sampler that sees one odd value throughout its
+ * window knows a single owner held the lock for the whole window: any
+ * handover would have advanced it twice.
+ */
+static unsigned int bql_seq;
+
+/* Who advanced bql_seq to its current odd value, 0 while the BQL is free */
+static int bql_owner_tid;
+
+static int bql_this_tid(void)
+{
+    static __thread int tid;
+
+    if (tid) {
+        return tid;
+    }
+    tid = qemu_get_thread_id();
+    return tid;
+}
+
+/* Poll this many times per timeout, to bound how late the watchdog reacts */
+#define BQL_WATCHDOG_POLLS 4
+
+#define BQL_WATCHDOG_MAX_MS (60 * 1000)
+
+static QemuThread bql_watchdog_thread;
+static QemuSemaphore bql_watchdog_sem;
+static uint64_t bql_watchdog_timeout_ms;
+
+static void bql_report_thread_states(void)
+{
+    g_autofree char *states = qemu_thread_states();
+
+    if (!states) {
+        return;
+    }
+    qemu_flockfile(stderr);
+    fputs(states, stderr);
+    qemu_funlockfile(stderr);
+}
+
+static void *bql_watchdog_fn(void *opaque)
+{
+    unsigned int last = qatomic_read(&bql_seq);
+    unsigned int reported = 0;
+    int stuck_polls = 0;
+
+    for (;;) {
+        uint64_t timeout_ms = qatomic_read(&bql_watchdog_timeout_ms);
+        g_autofree char *when = NULL;
+        unsigned int seq;
+
+        if (!timeout_ms) {
+            /* Park rather than exit, so re-arming needs no new thread */
+            qemu_sem_wait(&bql_watchdog_sem);
+            last = qatomic_read(&bql_seq);
+            stuck_polls = 0;
+            continue;
+        }
+        qemu_sem_timedwait(&bql_watchdog_sem,
+                           MAX(timeout_ms / BQL_WATCHDOG_POLLS, 1));
+
+        seq = qatomic_read(&bql_seq);
+        if (seq != last || !(seq & 1)) {
+            last = seq;
+            stuck_polls = 0;
+            continue;
+        }
+        if (++stuck_polls < BQL_WATCHDOG_POLLS) {
+            continue;
+        }
+        if (seq == reported) {
+            continue;
+        }
+        reported = seq;
+        if (!message_with_timestamp) {
+            when = real_time_iso8601();
+        }
+        error_report("%s%sBQL held for more than %" PRIu64 " ms by thread %d",
+                     when ?: "", when ? " " : "", timeout_ms,
+                     qatomic_read(&bql_owner_tid));
+        bql_report_thread_states();
+    }
+}
+
+uint64_t bql_watchdog_get_timeout_ms(void)
+{
+    return qatomic_read(&bql_watchdog_timeout_ms);
+}
+
+bool bql_watchdog_set_timeout_ms(uint64_t ms, Error **errp)
+{
+    static bool started;
+
+    assert(bql_locked());
+    if (ms > BQL_WATCHDOG_MAX_MS) {
+        error_setg(errp, "BQL watchdog deadline must not exceed %d ms",
+                   BQL_WATCHDOG_MAX_MS);
+        return false;
+    }
+    qatomic_set(&bql_watchdog_timeout_ms, ms);
+    if (!ms) {
+        return true;
+    }
+    if (!started) {
+        started = true;
+        qemu_thread_create(&bql_watchdog_thread, "bql-watchdog",
+                           bql_watchdog_fn, NULL, QEMU_THREAD_DETACHED);
+    } else {
+        qemu_sem_post(&bql_watchdog_sem);
+    }
+    return true;
+}
+
 void qemu_init_cpu_loop(void)
 {
     qemu_init_sigbus();
     qemu_cond_init(&qemu_cpu_cond);
     qemu_cond_init(&qemu_pause_cond);
     qemu_mutex_init(&bql);
+    qemu_sem_init(&bql_watchdog_sem, 0);
 
     qemu_thread_get_self(&io_thread);
 }
@@ -528,6 +646,8 @@ void bql_update_status(bool locked)
     /* This function should only be used when an update happened.. */
     assert(bql_locked() != locked);
     set_bql_locked(locked);
+    qatomic_set(&bql_owner_tid, locked ? bql_this_tid() : 0);
+    qatomic_set(&bql_seq, qatomic_read(&bql_seq) + 1);
 }
 
 static uint32_t bql_unlock_blocked;
-- 
2.53.0