From 97bfafe28ab3d1cd9336a3d6f63384ff12e3f434 Mon Sep 17 00:00:00 2001 From: "Emilio G. Cota" Date: Tue, 8 Aug 2017 13:54:42 -0400 Subject: [PATCH] hmp-commands-info: add sync-profile 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 Signed-off-by: Emilio G. Cota Signed-off-by: Paolo Bonzini --- 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 70639f656a..cbee8b944d 100644 --- a/hmp-commands-info.hx +++ b/hmp-commands-info.hx @@ -297,6 +297,28 @@ STEXI @item info opcount @findex info opcount 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 +@item info sync-profile [-m|-n] [@var{max}] +@findex 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 { diff --git a/monitor.c b/monitor.c index a1999e396c..94f673511b 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; -- 2.39.2