[Qemu-devel] [PULL 26/74] hmp-commands-info: add sync-profile

[Paolo Bonzini]

From: "Emilio G. Cota" <address@hidden>

The command introduced here is just for developers. This means that:

- the info displayed and the output format could change in the future
- the command is only meant to be used from HMP, not from QMP

Sample output:

(qemu) sync-profile
sync-profile is off
(qemu) info sync-profile
Type               Object  Call site  Wait Time (s)         Count  Average (us)
-------------------------------------------------------------------------------
-------------------------------------------------------------------------------
(qemu) sync-profile on
(qemu) sync-profile
sync-profile is on
(qemu) info sync-profile 15
Type               Object  Call site                 Wait Time (s)         
Count  Average (us)
----------------------------------------------------------------------------------------------
condvar    0x55a01813ced0  cpus.c:1165                    91.38235          
2842      32154.24
BQL mutex  0x55a0171b7140  cpus.c:1434                    12.56490          
5787       2171.23
BQL mutex  0x55a0171b7140  accel/tcg/cpu-exec.c:432        7.75846          
2844       2728.01
BQL mutex  0x55a0171b7140  accel/tcg/cputlb.c:870          5.09889          
2884       1767.99
BQL mutex  0x55a0171b7140  accel/tcg/cpu-exec.c:529        3.46140          
3254       1063.74
BQL mutex  0x55a0171b7140  accel/tcg/cputlb.c:804          0.76333          
8655         88.20
BQL mutex  0x55a0171b7140  cpus.c:1466                     0.60893          
2941        207.05
BQL mutex  0x55a0171b7140  util/main-loop.c:236            0.00894          
6425          1.39
mutex      [           3]  util/qemu-timer.c:520           0.00342         
50611          0.07
mutex      [           2]  util/qemu-timer.c:426           0.00254         
31336          0.08
mutex      [           3]  util/qemu-timer.c:234           0.00107         
19275          0.06
mutex      0x55a0171d9960  vl.c:763                        0.00043          
6425          0.07
mutex      0x55a0180d1bb0  monitor.c:458                   0.00015          
1603          0.09
mutex      0x55a0180e4c78  chardev/char.c:109              0.00002           
217          0.08
mutex      0x55a0180d1bb0  monitor.c:448                   0.00001           
162          0.08
----------------------------------------------------------------------------------------------
(qemu) info sync-profile -m 15
Type               Object  Call site                 Wait Time (s)         
Count  Average (us)
----------------------------------------------------------------------------------------------
condvar    0x55a01813ced0  cpus.c:1165                    95.11196          
3051      31174.03
BQL mutex  0x55a0171b7140  accel/tcg/cpu-exec.c:432        7.92108          
3052       2595.37
BQL mutex  0x55a0171b7140  cpus.c:1434                    13.38253          
6210       2155.00
BQL mutex  0x55a0171b7140  accel/tcg/cputlb.c:870          5.09901          
3093       1648.57
BQL mutex  0x55a0171b7140  accel/tcg/cpu-exec.c:529        4.21123          
3468       1214.31
BQL mutex  0x55a0171b7140  cpus.c:1466                     0.60895          
3156        192.95
BQL mutex  0x55a0171b7140  accel/tcg/cputlb.c:804          0.76337          
9282         82.24
BQL mutex  0x55a0171b7140  util/main-loop.c:236            0.00944          
6889          1.37
mutex      0x55a01813ce80  tcg/tcg.c:397                   0.00000            
24          0.15
mutex      0x55a0180d1bb0  monitor.c:458                   0.00018          
1922          0.09
mutex      [           2]  util/qemu-timer.c:426           0.00266         
32710          0.08
mutex      0x55a0180e4c78  chardev/char.c:109              0.00002           
260          0.08
mutex      0x55a0180d1bb0  monitor.c:448                   0.00001           
187          0.08
mutex      0x55a0171d9960  vl.c:763                        0.00047          
6889          0.07
mutex      [           3]  util/qemu-timer.c:520           0.00362         
53377          0.07
----------------------------------------------------------------------------------------------
(qemu) info sync-profile -m -n 15
Type               Object  Call site                 Wait Time (s)         
Count  Average (us)
----------------------------------------------------------------------------------------------
condvar    0x55a01813ced0  cpus.c:1165                   101.39331          
3398      29839.12
BQL mutex  0x55a0171b7140  accel/tcg/cpu-exec.c:432        7.92112          
3399       2330.43
BQL mutex  0x55a0171b7140  cpus.c:1434                    14.28280          
6922       2063.39
BQL mutex  0x55a0171b7140  accel/tcg/cputlb.c:870          5.77505          
3445       1676.36
BQL mutex  0x55a0171b7140  accel/tcg/cpu-exec.c:529        5.66139          
3883       1457.99
BQL mutex  0x55a0171b7140  cpus.c:1466                     0.60901          
3519        173.06
BQL mutex  0x55a0171b7140  accel/tcg/cputlb.c:804          0.76351         
10338         73.85
BQL mutex  0x55a0171b7140  util/main-loop.c:236            0.01032          
7664          1.35
mutex      0x55a0180e4f08  util/qemu-timer.c:426           0.00041           
901          0.45
mutex      0x55a01813ce80  tcg/tcg.c:397                   0.00000            
24          0.15
mutex      0x55a0180d1bb0  monitor.c:458                   0.00022          
2319          0.09
mutex      0x55a0180e4c78  chardev/char.c:109              0.00003           
306          0.08
mutex      0x55a0180e4f08  util/qemu-timer.c:520           0.00068          
8565          0.08
mutex      0x55a0180d1bb0  monitor.c:448                   0.00002           
215          0.08
mutex      0x55a0180e4f78  util/qemu-timer.c:426           0.00247         
34224          0.07
----------------------------------------------------------------------------------------------
(qemu) sync-profile reset
(qemu) info sync-profile -m 2
Type               Object  Call site               Wait Time (s)         Count  
Average (us)
--------------------------------------------------------------------------------------------
condvar    0x55a01813ced0  cpus.c:1165                   2.78756            99  
    28157.12
BQL mutex  0x55a0171b7140  accel/tcg/cputlb.c:870        0.33054           102  
     3240.55
--------------------------------------------------------------------------------------------
(qemu) sync-profile off
(qemu) sync-profile
sync-profile is off
(qemu) sync-profile reset
(qemu) info sync-profile
Type               Object  Call site  Wait Time (s)         Count  Average (us)
-------------------------------------------------------------------------------
-------------------------------------------------------------------------------

Reviewed-by: Dr. David Alan Gilbert <address@hidden>
Signed-off-by: Emilio G. Cota <address@hidden>
Signed-off-by: Paolo Bonzini <address@hidden>
---
 hmp-commands-info.hx | 22 ++++++++++++++++++++++
 monitor.c            | 11 +++++++++++
 2 files changed, 33 insertions(+)

diff --git a/hmp-commands-info.hx b/hmp-commands-info.hx
index 70639f6..cbee8b9 100644
--- a/hmp-commands-info.hx
+++ b/hmp-commands-info.hx
@@ -300,6 +300,28 @@ Show dynamic compiler opcode counters
 ETEXI
 
     {
+        .name       = "sync-profile",
+        .args_type  = "mean:-m,no_coalesce:-n,max:i?",
+        .params     = "[-m] [-n] [max]",
+        .help       = "show synchronization profiling info, up to max entries "
+                      "(default: 10), sorted by total wait time. (-m: sort by "
+                      "mean wait time; -n: do not coalesce objects with the "
+                      "same call site)",
+        .cmd        = hmp_info_sync_profile,
+    },
+
+STEXI
address@hidden info sync-profile [-m|-n] address@hidden
address@hidden info sync-profile
+Show synchronization profiling info, up to @var{max} entries (default: 10),
+sorted by total wait time.
+        -m: sort by mean wait time
+        -n: do not coalesce objects with the same call site
+When different objects that share the same call site are coalesced, the 
"Object"
+field shows---enclosed in brackets---the number of objects being coalesced.
+ETEXI
+
+    {
         .name       = "kvm",
         .args_type  = "",
         .params     = "",
diff --git a/monitor.c b/monitor.c
index a1999e3..94f6735 100644
--- a/monitor.c
+++ b/monitor.c
@@ -1454,6 +1454,17 @@ static void hmp_info_opcount(Monitor *mon, const QDict 
*qdict)
 }
 #endif
 
+static void hmp_info_sync_profile(Monitor *mon, const QDict *qdict)
+{
+    int64_t max = qdict_get_try_int(qdict, "max", 10);
+    bool mean = qdict_get_try_bool(qdict, "mean", false);
+    bool coalesce = !qdict_get_try_bool(qdict, "no_coalesce", false);
+    enum QSPSortBy sort_by;
+
+    sort_by = mean ? QSP_SORT_BY_AVG_WAIT_TIME : QSP_SORT_BY_TOTAL_WAIT_TIME;
+    qsp_report((FILE *)mon, monitor_fprintf, max, sort_by, coalesce);
+}
+
 static void hmp_info_history(Monitor *mon, const QDict *qdict)
 {
     int i;
-- 
1.8.3.1