[Qemu-devel] [PATCH 3/3] qsp: track BQL callers directly

[Emilio G. Cota]

The BQL is acquired via qemu_mutex_lock_iothread(), which makes
the profiler assign the associated wait time (i.e. most of
BQL wait time) entirely to that function. This loses the original
call site information, which does not help diagnose BQL contention.
Fix it by tracking the callers directly when the lock profiler is
enabled. While at it, add a QSP type specific to it, so that the
BQL is reported as "BQL mutex".

- Before:
Type               Object  Call site          Wait Time (s)         Count  
Average (us)
---------------------------------------------------------------------------------------
condvar    0x557ee3090e80  cpus.c:1084              1.69207          2916       
 580.27
condvar    0x557ee30ceb10  cpus.c:1084              1.43442          2404       
 596.68
mutex      0x557ee2503540  cpus.c:1583              0.30300        636558       
   0.48
condvar    0x557ee2534460  cpus-common.c:216        0.13549         15513       
   8.73
condvar    0x557ee2534420  cpus-common.c:186        0.08927         15747       
   5.67
mutex      0x557ee3090a40  tcg/tcg.c:378            0.00823        120034       
   0.07
mutex      0x557ee3090a00  tcg/tcg.c:378            0.00820        117890       
   0.07
mutex      0x557ee3090ac0  tcg/tcg.c:378            0.00764        115954       
   0.07
mutex      0x557ee3090a80  tcg/tcg.c:378            0.00762        116573       
   0.07
mutex      0x557ee3090b00  tcg/tcg.c:378            0.00560         82547       
   0.07
---------------------------------------------------------------------------------------

- After:
Type               Object  Call site                   Wait Time (s)         
Count  Average (us)
------------------------------------------------------------------------------------------------
condvar    0x555d4b37bb10  cpus.c:1084                       1.82472          
1245       1465.64
condvar    0x555d4b33de80  cpus.c:1084                       1.22456          
3105        394.38
condvar    0x555d48ee3460  cpus-common.c:216                 0.15380         
18510          8.31
condvar    0x555d48ee3420  cpus-common.c:186                 0.10400         
18303          5.68
BQL mutex  0x555d48eb2540  cpus.c:1272                       0.06565         
77751          0.84
BQL mutex  0x555d48eb2540  target/arm/op_helper.c:837        0.04077         
28317          1.44
BQL mutex  0x555d48eb2540  accel/tcg/cpu-exec.c:502          0.03935        
149975          0.26
BQL mutex  0x555d48eb2540  target/arm/op_helper.c:851        0.03917         
85698          0.46
BQL mutex  0x555d48eb2540  util/rcu.c:257                    0.03059            
 9       3399.36
BQL mutex  0x555d48eb2540  cpus-common.c:352                 0.02717         
29992          0.91
------------------------------------------------------------------------------------------------

Signed-off-by: Emilio G. Cota <address@hidden>
---
 include/qemu/main-loop.h | 10 +++++++++-
 include/qemu/qsp.h       |  2 ++
 cpus.c                   | 15 ++++++++++++++-
 stubs/iothread-lock.c    |  8 +++++++-
 util/qsp.c               |  4 ++++
 5 files changed, 36 insertions(+), 3 deletions(-)

diff --git a/include/qemu/main-loop.h b/include/qemu/main-loop.h
index 721aa2416a..dc64731009 100644
--- a/include/qemu/main-loop.h
+++ b/include/qemu/main-loop.h
@@ -276,7 +276,15 @@ bool qemu_mutex_iothread_locked(void);
  * NOTE: tools currently are single-threaded and qemu_mutex_lock_iothread
  * is a no-op there.
  */
-void qemu_mutex_lock_iothread(void);
+#ifdef CONFIG_SYNC_PROFILER
+void do_qemu_mutex_lock_iothread(const char *file, int line);
+#define qemu_mutex_lock_iothread()                      \
+    do_qemu_mutex_lock_iothread(__FILE__, __LINE__)
+#else
+void do_qemu_mutex_lock_iothread(void);
+#define qemu_mutex_lock_iothread()              \
+    do_qemu_mutex_lock_iothread()
+#endif
 
 /**
  * qemu_mutex_unlock_iothread: Unlock the main loop mutex.
diff --git a/include/qemu/qsp.h b/include/qemu/qsp.h
index e36f94ab1d..96a1fff1bb 100644
--- a/include/qemu/qsp.h
+++ b/include/qemu/qsp.h
@@ -18,6 +18,8 @@
 void qsp_mutex_lock(QemuMutex *mutex, const char *file, unsigned line);
 int qsp_mutex_trylock(QemuMutex *mutex, const char *file, unsigned line);
 
+void qsp_bql_mutex_lock(QemuMutex *mutex, const char *file, unsigned line);
+
 void qsp_rec_mutex_lock(QemuRecMutex *mutex, const char *file, unsigned line);
 int qsp_rec_mutex_trylock(QemuRecMutex *mutex, const char *file, unsigned 
line);
 
diff --git a/cpus.c b/cpus.c
index b5844b7103..8ec034954b 100644
--- a/cpus.c
+++ b/cpus.c
@@ -1762,12 +1762,25 @@ bool qemu_mutex_iothread_locked(void)
     return iothread_locked;
 }
 
-void qemu_mutex_lock_iothread(void)
+/*
+ * The BQL is taken from so many places that it is worth tracking the
+ * callers directly, instead of funneling them all through a single function.
+ */
+#ifdef CONFIG_SYNC_PROFILER
+void do_qemu_mutex_lock_iothread(const char *file, int line)
+{
+    g_assert(!qemu_mutex_iothread_locked());
+    qsp_bql_mutex_lock(&qemu_global_mutex, file, line);
+    iothread_locked = true;
+}
+#else
+void do_qemu_mutex_lock_iothread(void)
 {
     g_assert(!qemu_mutex_iothread_locked());
     qemu_mutex_lock(&qemu_global_mutex);
     iothread_locked = true;
 }
+#endif /* CONFIG_SYNC_PROFILER */
 
 void qemu_mutex_unlock_iothread(void)
 {
diff --git a/stubs/iothread-lock.c b/stubs/iothread-lock.c
index 9b6db2e740..3d129f367c 100644
--- a/stubs/iothread-lock.c
+++ b/stubs/iothread-lock.c
@@ -7,9 +7,15 @@ bool qemu_mutex_iothread_locked(void)
     return true;
 }
 
-void qemu_mutex_lock_iothread(void)
+#ifdef CONFIG_SYNC_PROFILER
+void do_qemu_mutex_lock_iothread(const char *file, int line)
 {
 }
+#else
+void do_qemu_mutex_lock_iothread(void)
+{
+}
+#endif
 
 void qemu_mutex_unlock_iothread(void)
 {
diff --git a/util/qsp.c b/util/qsp.c
index 908e99cccf..9f12762d36 100644
--- a/util/qsp.c
+++ b/util/qsp.c
@@ -61,6 +61,7 @@
 
 enum qsp_type {
     QSP_MUTEX,
+    QSP_BQL_MUTEX,
     QSP_REC_MUTEX,
     QSP_CONDVAR,
 };
@@ -102,6 +103,7 @@ static bool qsp_initialized, qsp_initializing;
 
 static const char * const qsp_typenames[] = {
     [QSP_MUTEX]     = "mutex",
+    [QSP_BQL_MUTEX] = "BQL mutex",
     [QSP_REC_MUTEX] = "rec_mutex",
     [QSP_CONDVAR]   = "condvar",
 };
@@ -316,6 +318,8 @@ static struct qsp_entry *qsp_entry_get(const void *obj, 
const char *file,
 QSP_GEN_VOID(QemuMutex, QSP_MUTEX, qsp_mutex_lock, qemu_mutex_lock_impl)
 QSP_GEN_RET1(QemuMutex, QSP_MUTEX, qsp_mutex_trylock, qemu_mutex_trylock_impl)
 
+QSP_GEN_VOID(QemuMutex, QSP_BQL_MUTEX, qsp_bql_mutex_lock, 
qemu_mutex_lock_impl)
+
 QSP_GEN_VOID(QemuRecMutex, QSP_REC_MUTEX, qsp_rec_mutex_lock,
              qemu_rec_mutex_lock_impl)
 QSP_GEN_RET1(QemuRecMutex, QSP_REC_MUTEX, qsp_rec_mutex_trylock,
-- 
2.17.1