* [Qemu-devel] [PATCH 0/3] synchronization profiler
@ 2018-08-13 17:11 Emilio G. Cota
2018-08-13 17:11 ` [Qemu-devel] [PATCH 1/3] qsp: QEMU's Synchronization Profiler Emilio G. Cota
` (3 more replies)
0 siblings, 4 replies; 20+ messages in thread
From: Emilio G. Cota @ 2018-08-13 17:11 UTC (permalink / raw)
To: qemu-devel
Cc: Paolo Bonzini, Peter Crosthwaite, Richard Henderson,
Dr. David Alan Gilbert, Stefan Weil, Markus Armbruster, Peter Xu
This series adds a synchronization profiler, similar to the one
described in
https://www.usenix.org/system/files/conference/atc12/atc12-final237.pdf
, although without using perf counters.
The profiler allows us to identify what wait times in locks/condvars are,
and where they are coming from. This info is very useful to
identify scalability bottlenecks imposed by locks, particularly
the BQL. I have patches (currently out of tree) to switch the
BQL for per-CPU locks to keep track of CPU state; the profiler was
really useful when doing that work.
The profiler is disabled by default, and can be enabled by configuring
with --enable-sync-profiler. Overhead is pretty low though, see
patch 1's commit log.
You can fetch the patches from:
https://github.com/cota/qemu/tree/sync-profiler
Note that checkpatch gives some warnings, but they are false positives.
Thanks,
Emilio
^ permalink raw reply [flat|nested] 20+ messages in thread* [Qemu-devel] [PATCH 1/3] qsp: QEMU's Synchronization Profiler 2018-08-13 17:11 [Qemu-devel] [PATCH 0/3] synchronization profiler Emilio G. Cota @ 2018-08-13 17:11 ` Emilio G. Cota 2018-08-14 8:13 ` Paolo Bonzini 2018-08-15 3:09 ` Fam Zheng 2018-08-13 17:11 ` [Qemu-devel] [PATCH 2/3] monitor: show sync profiling info with 'info sync' Emilio G. Cota ` (2 subsequent siblings) 3 siblings, 2 replies; 20+ messages in thread From: Emilio G. Cota @ 2018-08-13 17:11 UTC (permalink / raw) To: qemu-devel Cc: Paolo Bonzini, Peter Crosthwaite, Richard Henderson, Dr. David Alan Gilbert, Stefan Weil, Markus Armbruster, Peter Xu The goal of this module is to profile synchronization primitives (i.e. mutexes, recursive mutexes and condition variables) so that scalability issues can be quickly diagnosed. Sync primitives are profiled by QSP based on the vaddr of the object accessed as well as the call site (file:line_nr). That means the same object called from two different call sites will be tracked in separate entries, and in the report (see below) they will show up in different rows. See the comments at the top of qsp.c for further info on this decision and the overall design of QSP. A report shows info about the tracked entries, sorted in descending order of total wait time. Sample output: 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 --------------------------------------------------------------------------------------- Some perf numbers: - Double-check that profiling disabled does not affect performance with `taskset -c 0 tests/atomic_add-bench -d 5 -m'. Host: AMD Opteron 6376. - Before: 14.25 Mops/s - After: 14.27 Mops/s (within noise range) - Profiling overhead for `taskset -c 0 atomic_add-bench -d 5 -m' on AMD Opteron 6376: - No profiling: 14.27 Mops/s - W/ profiling: 3.05 Mops/s - W/o get_clock: 6.73 Mops/s That is, a 4.67X slowdown for mutex_lock. The third result is the performance measured for an instrumented mutex_lock that does not call get_clock and instead just increments the number of acquisitions for each entry. With this we measure the overhead of just the instrumentation + the hash table lookup. - `taskset -c 0 tests/atomic_add-bench -d 5 -m' on Intel Xeon E5-2690: - W/o profiling: 33.95 Mops/s - W/ profiling: 8.08 Mops/s - W/o get_clock: 14.19 Mops/s That is, a 4.20X slowdown for mutex_lock. Synchronization primitives are not called very often during a regular QEMU run, so the overall performance impact of the profiler is quite tolerable, as the following results show. - Boot + shut down of debian-aarch64, on Intel Xeon E5-2690, 3 runs: -smp 1: - W/o profiling: 16448.021211 task-clock (msec) # 1.000 CPUs utilized ( +- 0.27% ) 35,383 context-switches # 0.002 M/sec ( +- 0.17% ) 1 cpu-migrations # 0.000 K/sec 13,410 page-faults # 0.815 K/sec ( +- 1.79% ) 47,526,630,360 cycles # 2.890 GHz ( +- 0.18% ) (83.33%) 22,943,171,724 stalled-cycles-frontend # 48.27% frontend cycles idle ( +- 0.18% ) (83.35%) 16,585,410,756 stalled-cycles-backend # 34.90% backend cycles idle ( +- 0.32% ) (66.68%) 60,962,863,668 instructions # 1.28 insns per cycle # 0.38 stalled cycles per insn ( +- 0.06% ) (83.33%) 10,910,210,349 branches # 663.314 M/sec ( +- 0.08% ) (83.33%) 240,046,904 branch-misses # 2.20% of all branches ( +- 0.29% ) (83.33%) 16.452269799 seconds time elapsed ( +- 0.27% ) - W/ profiling: 16678.033593 task-clock (msec) # 1.000 CPUs utilized ( +- 0.09% ) 35,740 context-switches # 0.002 M/sec ( +- 0.12% ) 1 cpu-migrations # 0.000 K/sec 13,283 page-faults # 0.796 K/sec ( +- 1.79% ) 48,208,446,365 cycles # 2.891 GHz ( +- 0.15% ) (83.34%) 23,237,819,053 stalled-cycles-frontend # 48.20% frontend cycles idle ( +- 0.22% ) (83.34%) 16,926,585,765 stalled-cycles-backend # 35.11% backend cycles idle ( +- 0.30% ) (66.68%) 61,620,102,560 instructions # 1.28 insns per cycle # 0.38 stalled cycles per insn ( +- 0.20% ) (83.34%) 11,015,082,852 branches # 660.455 M/sec ( +- 0.22% ) (83.32%) 243,335,050 branch-misses # 2.21% of all branches ( +- 0.47% ) (83.33%) 16.685661370 seconds time elapsed ( +- 0.08% ) That is, a 1.3% slowdown. -smp 8: - W/o profiling: 21591.674202 task-clock (msec) # 2.512 CPUs utilized ( +- 0.04% ) 428,423 context-switches # 0.020 M/sec ( +- 0.38% ) 8,474 cpu-migrations # 0.392 K/sec ( +- 1.64% ) 27,668 page-faults # 0.001 M/sec ( +- 4.56% ) 58,611,751,157 cycles # 2.715 GHz ( +- 0.27% ) (83.40%) 31,033,543,440 stalled-cycles-frontend # 52.95% frontend cycles idle ( +- 0.45% ) (82.98%) 22,983,788,382 stalled-cycles-backend # 39.21% backend cycles idle ( +- 0.50% ) (66.80%) 67,020,810,260 instructions # 1.14 insns per cycle # 0.46 stalled cycles per insn ( +- 0.21% ) (83.45%) 12,050,905,600 branches # 558.127 M/sec ( +- 0.16% ) (83.40%) 271,074,726 branch-misses # 2.25% of all branches ( +- 0.33% ) (83.42%) 8.595004141 seconds time elapsed ( +- 0.65% ) - W/ profiling: 22227.582945 task-clock (msec) # 2.516 CPUs utilized ( +- 0.71% ) 487,009 context-switches # 0.022 M/sec ( +- 1.43% ) 9,049 cpu-migrations # 0.407 K/sec ( +- 0.99% ) 25,963 page-faults # 0.001 M/sec ( +- 1.70% ) 60,705,049,201 cycles # 2.731 GHz ( +- 0.52% ) (83.33%) 32,225,054,360 stalled-cycles-frontend # 53.08% frontend cycles idle ( +- 0.39% ) (83.50%) 23,943,332,206 stalled-cycles-backend # 39.44% backend cycles idle ( +- 0.40% ) (66.79%) 68,775,229,321 instructions # 1.13 insns per cycle # 0.47 stalled cycles per insn ( +- 0.45% ) (83.38%) 12,361,594,986 branches # 556.138 M/sec ( +- 0.36% ) (83.46%) 281,775,777 branch-misses # 2.28% of all branches ( +- 1.16% ) (82.93%) 8.836031859 seconds time elapsed ( +- 1.07% ) That is, a 2.7% slowdown. - Boot + shut down of debian-aarch64, on AMD Opteron 6376, 3 runs: -smp 1: - W/o profiling: 27601.373288 task-clock (msec) # 0.999 CPUs utilized ( +- 0.74% ) 51,532 context-switches # 0.002 M/sec ( +- 0.49% ) 1 cpu-migrations # 0.000 K/sec 22,085 page-faults # 0.800 K/sec ( +- 1.94% ) 63,051,935,104 cycles # 2.284 GHz ( +- 0.59% ) (83.32%) 15,210,275,327 stalled-cycles-frontend # 24.12% frontend cycles idle ( +- 1.57% ) (83.33%) 12,701,776,029 stalled-cycles-backend # 20.14% backend cycles idle ( +- 0.65% ) (33.35%) 64,895,509,291 instructions # 1.03 insns per cycle # 0.23 stalled cycles per insn ( +- 0.15% ) (50.03%) 11,598,175,695 branches # 420.203 M/sec ( +- 0.12% ) (66.69%) 424,964,774 branch-misses # 3.66% of all branches ( +- 2.44% ) (83.34%) 27.634390949 seconds time elapsed ( +- 0.73% ) - W/ profiling: 28539.459861 task-clock (msec) # 0.999 CPUs utilized ( +- 0.90% ) 52,971 context-switches # 0.002 M/sec ( +- 0.62% ) 1 cpu-migrations # 0.000 K/sec 22,828 page-faults # 0.800 K/sec ( +- 2.19% ) 65,196,667,837 cycles # 2.284 GHz ( +- 0.76% ) (83.32%) 16,438,749,522 stalled-cycles-frontend # 25.21% frontend cycles idle ( +- 2.44% ) (83.34%) 13,080,610,434 stalled-cycles-backend # 20.06% backend cycles idle ( +- 1.22% ) (33.35%) 65,744,290,786 instructions # 1.01 insns per cycle # 0.25 stalled cycles per insn ( +- 0.17% ) (50.05%) 11,760,663,051 branches # 412.084 M/sec ( +- 0.11% ) (66.69%) 433,815,865 branch-misses # 3.69% of all branches ( +- 2.27% ) (83.34%) 28.558462655 seconds time elapsed ( +- 0.90% ) That is, a 3.5% slowdown. -smp 8: - W/o profiling: 67084.039812 task-clock (msec) # 3.075 CPUs utilized ( +- 0.57% ) 448,562 context-switches # 0.007 M/sec ( +- 1.30% ) 13,417 cpu-migrations # 0.200 K/sec ( +- 1.67% ) 38,428 page-faults # 0.573 K/sec ( +- 2.60% ) 92,018,881,848 cycles # 1.372 GHz ( +- 0.51% ) (83.27%) 24,887,145,043 stalled-cycles-frontend # 27.05% frontend cycles idle ( +- 0.97% ) (83.31%) 10,843,517,286 stalled-cycles-backend # 11.78% backend cycles idle ( +- 0.84% ) (33.45%) 72,663,707,013 instructions # 0.79 insns per cycle # 0.34 stalled cycles per insn ( +- 0.34% ) (50.14%) 13,148,472,626 branches # 196.000 M/sec ( +- 0.26% ) (66.68%) 524,683,844 branch-misses # 3.99% of all branches ( +- 0.31% ) (83.34%) 21.816863743 seconds time elapsed ( +- 1.37% ) - W/ profiling: 72646.052577 task-clock (msec) # 3.088 CPUs utilized ( +- 0.52% ) 558,334 context-switches # 0.008 M/sec ( +- 0.35% ) 16,471 cpu-migrations # 0.227 K/sec ( +- 1.35% ) 40,420 page-faults # 0.556 K/sec ( +- 2.31% ) 99,025,850,252 cycles # 1.363 GHz ( +- 0.19% ) (83.14%) 28,317,752,389 stalled-cycles-frontend # 28.60% frontend cycles idle ( +- 0.21% ) (83.29%) 11,370,442,683 stalled-cycles-backend # 11.48% backend cycles idle ( +- 0.78% ) (33.59%) 75,859,240,699 instructions # 0.77 insns per cycle # 0.37 stalled cycles per insn ( +- 0.11% ) (50.25%) 13,774,590,759 branches # 189.612 M/sec ( +- 0.10% ) (66.87%) 541,354,013 branch-misses # 3.93% of all branches ( +- 0.13% ) (83.50%) 23.525659377 seconds time elapsed ( +- 0.90% ) That is, a 7.8% slowdown. Note that as -smp increases the memory footprint of the profiling data grows as well, which explains the slowdown increase as we add more guest CPUs. Signed-off-by: Emilio G. Cota <cota@braap.org> --- configure | 8 + include/qemu/qht.h | 1 + include/qemu/qsp.h | 38 +++ include/qemu/thread-posix.h | 4 +- include/qemu/thread-win32.h | 5 +- include/qemu/thread.h | 41 ++- util/qemu-thread-win32.c | 4 +- util/qht.c | 47 +++- util/qsp.c | 545 ++++++++++++++++++++++++++++++++++++ util/Makefile.objs | 1 + 10 files changed, 671 insertions(+), 23 deletions(-) create mode 100644 include/qemu/qsp.h create mode 100644 util/qsp.c diff --git a/configure b/configure index 2a7796ea80..d7fead7c85 100755 --- a/configure +++ b/configure @@ -408,6 +408,7 @@ bsd="no" linux="no" solaris="no" profiler="no" +sync_profiler="no" cocoa="no" softmmu="yes" linux_user="no" @@ -1163,6 +1164,8 @@ for opt do ;; --enable-profiler) profiler="yes" ;; + --enable-sync-profiler) sync_profiler="yes" + ;; --disable-cocoa) cocoa="no" ;; --enable-cocoa) @@ -1621,6 +1624,7 @@ Advanced options (experts only): --tls-priority default TLS protocol/cipher priority string --enable-gprof QEMU profiling with gprof --enable-profiler profiler support + --enable-sync-profiler support profiling of synchronization primitives --enable-xen-pv-domain-build xen pv domain builder --enable-debug-stack-usage @@ -5893,6 +5897,7 @@ echo "gprof enabled $gprof" echo "sparse enabled $sparse" echo "strip binaries $strip_opt" echo "profiler $profiler" +echo "sync profiler $sync_profiler" echo "static build $static" if test "$darwin" = "yes" ; then echo "Cocoa support $cocoa" @@ -6146,6 +6151,9 @@ fi if test "$profiler" = "yes" ; then echo "CONFIG_PROFILER=y" >> $config_host_mak fi +if test "$sync_profiler" = "yes" ; then + echo "CONFIG_SYNC_PROFILER=y" >> $config_host_mak +fi if test "$slirp" = "yes" ; then echo "CONFIG_SLIRP=y" >> $config_host_mak echo "CONFIG_SMBD_COMMAND=\"$smbd\"" >> $config_host_mak diff --git a/include/qemu/qht.h b/include/qemu/qht.h index 1fb9116fa0..c9a11cc29a 100644 --- a/include/qemu/qht.h +++ b/include/qemu/qht.h @@ -46,6 +46,7 @@ typedef bool (*qht_lookup_func_t)(const void *obj, const void *userp); typedef void (*qht_iter_func_t)(struct qht *ht, void *p, uint32_t h, void *up); #define QHT_MODE_AUTO_RESIZE 0x1 /* auto-resize when heavily loaded */ +#define QHT_MODE_RAW_MUTEXES 0x2 /* bypass the profiler (QSP) */ /** * qht_init - Initialize a QHT diff --git a/include/qemu/qsp.h b/include/qemu/qsp.h new file mode 100644 index 0000000000..e36f94ab1d --- /dev/null +++ b/include/qemu/qsp.h @@ -0,0 +1,38 @@ +/* + * qsp.c - QEMU Synchronization Profiler + * + * Copyright (C) 2017, Emilio G. Cota <cota@braap.org> + * + * License: GNU GPL, version 2 or later. + * See the COPYING file in the top-level directory. + * + * Note: this header file can *only* be included from thread.h. + */ +#ifndef QEMU_QSP_H +#define QEMU_QSP_H + +#include "qemu/fprintf-fn.h" + +#ifdef CONFIG_SYNC_PROFILER + +void qsp_mutex_lock(QemuMutex *mutex, const char *file, unsigned line); +int qsp_mutex_trylock(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); + +void qsp_cond_wait(QemuCond *cond, QemuMutex *mutex, const char *file, + unsigned line); + +void qsp_report(FILE *f, fprintf_function cpu_fprintf, size_t max); + +#else /* !CONF_SYNC_PROFILER */ + +static inline void qsp_report(FILE *f, fprintf_function cpu_fprintf, size_t max) +{ + cpu_fprintf(f, "[Sync profiler not compiled]\n"); +} + +#endif /* !CONF_SYNC_PROFILER */ + +#endif /* QEMU_QSP_H */ diff --git a/include/qemu/thread-posix.h b/include/qemu/thread-posix.h index fd27b34128..c903525062 100644 --- a/include/qemu/thread-posix.h +++ b/include/qemu/thread-posix.h @@ -6,8 +6,8 @@ typedef QemuMutex QemuRecMutex; #define qemu_rec_mutex_destroy qemu_mutex_destroy -#define qemu_rec_mutex_lock qemu_mutex_lock -#define qemu_rec_mutex_trylock qemu_mutex_trylock +#define qemu_rec_mutex_lock_impl qemu_mutex_lock_impl +#define qemu_rec_mutex_trylock_impl qemu_mutex_trylock_impl #define qemu_rec_mutex_unlock qemu_mutex_unlock struct QemuMutex { diff --git a/include/qemu/thread-win32.h b/include/qemu/thread-win32.h index d668d789b4..50af5dd7ab 100644 --- a/include/qemu/thread-win32.h +++ b/include/qemu/thread-win32.h @@ -19,8 +19,9 @@ struct QemuRecMutex { }; void qemu_rec_mutex_destroy(QemuRecMutex *mutex); -void qemu_rec_mutex_lock(QemuRecMutex *mutex); -int qemu_rec_mutex_trylock(QemuRecMutex *mutex); +void qemu_rec_mutex_lock_impl(QemuRecMutex *mutex, const char *file, int line); +int qemu_rec_mutex_trylock_impl(QemuRecMutex *mutex, const char *file, + int line); void qemu_rec_mutex_unlock(QemuRecMutex *mutex); struct QemuCond { diff --git a/include/qemu/thread.h b/include/qemu/thread.h index ef7bd16123..55009bbf26 100644 --- a/include/qemu/thread.h +++ b/include/qemu/thread.h @@ -16,6 +16,9 @@ typedef struct QemuThread QemuThread; #include "qemu/thread-posix.h" #endif +/* include QSP header once QemuMutex, QemuCond etc. are defined */ +#include "qemu/qsp.h" + #define QEMU_THREAD_JOINABLE 0 #define QEMU_THREAD_DETACHED 1 @@ -25,10 +28,27 @@ int qemu_mutex_trylock_impl(QemuMutex *mutex, const char *file, const int line); void qemu_mutex_lock_impl(QemuMutex *mutex, const char *file, const int line); void qemu_mutex_unlock_impl(QemuMutex *mutex, const char *file, const int line); -#define qemu_mutex_lock(mutex) \ - qemu_mutex_lock_impl(mutex, __FILE__, __LINE__) -#define qemu_mutex_trylock(mutex) \ - qemu_mutex_trylock_impl(mutex, __FILE__, __LINE__) +/* convenience macros to bypass the profiler */ +#define qemu_mutex_lock__raw(m) \ + qemu_mutex_lock_impl(m, __FILE__, __LINE__) +#define qemu_mutex_trylock__raw(m) \ + qemu_mutex_trylock_impl(m, __FILE__, __LINE__) + +#ifdef CONFIG_SYNC_PROFILER +# define qemu_mutex_lock(m) qsp_mutex_lock(m, __FILE__, __LINE__) +# define qemu_mutex_trylock(m) qsp_mutex_trylock(m, __FILE__, __LINE__) +# define qemu_rec_mutex_lock(m) qsp_rec_mutex_lock(m, __FILE__, __LINE__) +# define qemu_rec_mutex_trylock(m) qsp_rec_mutex_trylock(m, __FILE__, __LINE__) +# define qemu_cond_wait(c, m) qsp_cond_wait(c, m, __FILE__, __LINE__) +#else +# define qemu_mutex_lock(m) qemu_mutex_lock_impl(m, __FILE__, __LINE__) +# define qemu_mutex_trylock(m) qemu_mutex_trylock_impl(m, __FILE__, __LINE__) +# define qemu_rec_mutex_lock(m) qemu_rec_mutex_lock_impl(m, __FILE__, __LINE__) +# define qemu_rec_mutex_trylock(m) \ + qemu_rec_mutex_trylock_impl(m, __FILE__, __LINE__) +# define qemu_cond_wait(c, m) qemu_cond_wait_impl(c, m, __FILE__, __LINE__) +#endif /* !CONFIG_SYNC_PROFILER */ + #define qemu_mutex_unlock(mutex) \ qemu_mutex_unlock_impl(mutex, __FILE__, __LINE__) @@ -47,6 +67,16 @@ static inline void (qemu_mutex_unlock)(QemuMutex *mutex) qemu_mutex_unlock(mutex); } +static inline void (qemu_rec_mutex_lock)(QemuRecMutex *mutex) +{ + qemu_rec_mutex_lock(mutex); +} + +static inline int (qemu_rec_mutex_trylock)(QemuRecMutex *mutex) +{ + return qemu_rec_mutex_trylock(mutex); +} + /* Prototypes for other functions are in thread-posix.h/thread-win32.h. */ void qemu_rec_mutex_init(QemuRecMutex *mutex); @@ -63,9 +93,6 @@ void qemu_cond_broadcast(QemuCond *cond); void qemu_cond_wait_impl(QemuCond *cond, QemuMutex *mutex, const char *file, const int line); -#define qemu_cond_wait(cond, mutex) \ - qemu_cond_wait_impl(cond, mutex, __FILE__, __LINE__) - static inline void (qemu_cond_wait)(QemuCond *cond, QemuMutex *mutex) { qemu_cond_wait(cond, mutex); diff --git a/util/qemu-thread-win32.c b/util/qemu-thread-win32.c index b303188a36..4a363ca675 100644 --- a/util/qemu-thread-win32.c +++ b/util/qemu-thread-win32.c @@ -97,13 +97,13 @@ void qemu_rec_mutex_destroy(QemuRecMutex *mutex) DeleteCriticalSection(&mutex->lock); } -void qemu_rec_mutex_lock(QemuRecMutex *mutex) +void qemu_rec_mutex_lock_impl(QemuRecMutex *mutex, const char *file, int line) { assert(mutex->initialized); EnterCriticalSection(&mutex->lock); } -int qemu_rec_mutex_trylock(QemuRecMutex *mutex) +int qemu_rec_mutex_trylock_impl(QemuRecMutex *mutex, const char *file, int line) { assert(mutex->initialized); return !TryEnterCriticalSection(&mutex->lock); diff --git a/util/qht.c b/util/qht.c index c138777a9c..1e3a072e25 100644 --- a/util/qht.c +++ b/util/qht.c @@ -89,6 +89,33 @@ #define QHT_BUCKET_ENTRIES 4 #endif +/* + * Do _not_ use qemu_mutex_[try]lock directly! Use these macros, otherwise + * the profiler (QSP) will deadlock. + */ +static inline void qht_lock(struct qht *ht) +{ + if (ht->mode & QHT_MODE_RAW_MUTEXES) { + qemu_mutex_lock__raw(&ht->lock); + } else { + qemu_mutex_lock(&ht->lock); + } +} + +static inline int qht_trylock(struct qht *ht) +{ + if (ht->mode & QHT_MODE_RAW_MUTEXES) { + return qemu_mutex_trylock__raw(&(ht)->lock); + } + return qemu_mutex_trylock(&(ht)->lock); +} + +/* this inline is not really necessary, but it helps keep code consistent */ +static inline void qht_unlock(struct qht *ht) +{ + qemu_mutex_unlock(&ht->lock); +} + /* * Note: reading partially-updated pointers in @pointers could lead to * segfaults. We thus access them with atomic_read/set; this guarantees @@ -254,10 +281,10 @@ void qht_map_lock_buckets__no_stale(struct qht *ht, struct qht_map **pmap) qht_map_unlock_buckets(map); /* we raced with a resize; acquire ht->lock to see the updated ht->map */ - qemu_mutex_lock(&ht->lock); + qht_lock(ht); map = ht->map; qht_map_lock_buckets(map); - qemu_mutex_unlock(&ht->lock); + qht_unlock(ht); *pmap = map; return; } @@ -288,11 +315,11 @@ struct qht_bucket *qht_bucket_lock__no_stale(struct qht *ht, uint32_t hash, qemu_spin_unlock(&b->lock); /* we raced with a resize; acquire ht->lock to see the updated ht->map */ - qemu_mutex_lock(&ht->lock); + qht_lock(ht); map = ht->map; b = qht_map_to_bucket(map, hash); qemu_spin_lock(&b->lock); - qemu_mutex_unlock(&ht->lock); + qht_unlock(ht); *pmap = map; return b; } @@ -430,13 +457,13 @@ bool qht_reset_size(struct qht *ht, size_t n_elems) n_buckets = qht_elems_to_buckets(n_elems); - qemu_mutex_lock(&ht->lock); + qht_lock(ht); map = ht->map; if (n_buckets != map->n_buckets) { new = qht_map_create(n_buckets); } qht_do_resize_and_reset(ht, new); - qemu_mutex_unlock(&ht->lock); + qht_unlock(ht); return !!new; } @@ -565,7 +592,7 @@ static __attribute__((noinline)) void qht_grow_maybe(struct qht *ht) * If the lock is taken it probably means there's an ongoing resize, * so bail out. */ - if (qemu_mutex_trylock(&ht->lock)) { + if (qht_trylock(ht)) { return; } map = ht->map; @@ -575,7 +602,7 @@ static __attribute__((noinline)) void qht_grow_maybe(struct qht *ht) qht_do_resize(ht, new); } - qemu_mutex_unlock(&ht->lock); + qht_unlock(ht); } bool qht_insert(struct qht *ht, void *p, uint32_t hash, void **existing) @@ -788,7 +815,7 @@ bool qht_resize(struct qht *ht, size_t n_elems) size_t n_buckets = qht_elems_to_buckets(n_elems); size_t ret = false; - qemu_mutex_lock(&ht->lock); + qht_lock(ht); if (n_buckets != ht->map->n_buckets) { struct qht_map *new; @@ -796,7 +823,7 @@ bool qht_resize(struct qht *ht, size_t n_elems) qht_do_resize(ht, new); ret = true; } - qemu_mutex_unlock(&ht->lock); + qht_unlock(ht); return ret; } diff --git a/util/qsp.c b/util/qsp.c new file mode 100644 index 0000000000..908e99cccf --- /dev/null +++ b/util/qsp.c @@ -0,0 +1,545 @@ +/* + * qsp.c - QEMU Synchronization Profiler + * + * Copyright (C) 2017, Emilio G. Cota <cota@braap.org> + * + * License: GNU GPL, version 2 or later. + * See the COPYING file in the top-level directory. + * + * QSP profiles the time spent in synchronization primitives, which can + * help diagnose performance problems, e.g. scalability issues when + * contention is high. + * + * The primitives currently supported are mutexes, recursive mutexes and + * condition variables. Note that not all related functions are intercepted; + * instead we profile only those functions that can have a performance impact, + * either due to blocking (e.g. cond_wait, mutex_lock) or cache line + * contention (e.g. mutex_lock, mutex_trylock). + * + * QSP's design focuses on speed and scalability. This is achieved + * by having threads do their profiling entirely on thread-local data. + * The appropriate thread-local data is found via a QHT, i.e. a concurrent hash + * table. To aggregate data in order to generate a report, we iterate over + * all entries in the hash table. Depending on the number of threads and + * synchronization objects this might be expensive, but note that it is + * very rarely called -- reports are generated only when requested by users. + * + * Reports are generated as a table where each row represents a call site. A + * call site is the triplet formed by the __file__ and __LINE__ of the caller + * as well as the address of the "object" (i.e. mutex, rec. mutex or condvar) + * being operated on. Focusing on call sites instead of just on objects might + * seem puzzling. However, it is a sensible choice since otherwise dealing with + * dynamically-allocated objects becomes difficult (e.g. what to do when an + * object is destroyed, or reused?). Furthermore, the call site info is of most + * importance, since it is callers, and not objects, what cause wait time. + * + * Alternative designs considered: + * + * - Use an off-the-shelf profiler such as mutrace. This is not a viable option + * for us because QEMU has __malloc_hook set (by one of the libraries it + * uses); leaving this hook unset is required to avoid deadlock in mutrace. + * + * - Use a glib HT for each thread, protecting each HT with its own lock. + * This isn't simpler than the current design, and is 10% slower in the + * atomic_add-bench microbenchmark (-m option). + * + * - For reports, just use a binary tree as we aggregate data, instead of having + * an intermediate hash table. This would simplify the code only slightly, but + * would perform badly if there were many threads and objects to track. + * + * Related Work: + * - Lennart Poettering's mutrace: http://0pointer.de/blog/projects/mutrace.html + * - Lozi, David, Thomas, Lawall and Muller. "Remote Core Locking: Migrating + * Critical-Section Execution to Improve the Performance of Multithreaded + * Applications", USENIX ATC'12. + */ +#include "qemu/osdep.h" +#include "qemu/thread.h" +#include "qemu/timer.h" +#include "qemu/qht.h" +#include "exec/tb-hash-xx.h" + +enum qsp_type { + QSP_MUTEX, + QSP_REC_MUTEX, + QSP_CONDVAR, +}; + +struct qsp_callsite { + const void *obj; + const char *file; /* i.e. __FILE__; shortened later */ + unsigned int line; + enum qsp_type type; +}; + +struct qsp_entry { + void *thread_ptr; + const struct qsp_callsite *callsite; + uint64_t n_acqs; + uint64_t ns; +}; + +/* initial sizing for hash tables */ +#define QSP_INITIAL_SIZE 64 + +/* If this file is moved, QSP_REL_PATH should be updated accordingly */ +#define QSP_REL_PATH "util/qsp.c" + +/* this file's full path. Used to present all call sites with relative paths */ +static size_t qsp_qemu_path_len; + +/* the address of qsp_thread gives us a unique 'thread ID' */ +static __thread int qsp_thread; + +/* + * Call sites are the same for all threads, so we track them in a separate hash + * table to save memory. + */ +static struct qht qsp_callsite_ht; + +static struct qht qsp_ht; +static bool qsp_initialized, qsp_initializing; + +static const char * const qsp_typenames[] = { + [QSP_MUTEX] = "mutex", + [QSP_REC_MUTEX] = "rec_mutex", + [QSP_CONDVAR] = "condvar", +}; + +/* + * It pays off to _not_ hash callsite->file; hashing a string is slow, and + * without it we still get a pretty unique hash. + */ +static inline +uint32_t do_qsp_callsite_hash(const struct qsp_callsite *callsite, uint64_t a) +{ + uint64_t b = (uint64_t)callsite->obj; + uint32_t e = callsite->line; + uint32_t f = callsite->type; + + return tb_hash_func7(a, b, e, f, 0); +} + +static inline +uint32_t qsp_callsite_hash(const struct qsp_callsite *callsite) +{ + return do_qsp_callsite_hash(callsite, 0); +} + +static inline uint32_t do_qsp_entry_hash(const struct qsp_entry *entry, + uint64_t a) +{ + return do_qsp_callsite_hash(entry->callsite, a); +} + +static uint32_t qsp_entry_hash(const struct qsp_entry *entry) +{ + return do_qsp_entry_hash(entry, (uint64_t)entry->thread_ptr); +} + +static uint32_t qsp_entry_no_thread_hash(const struct qsp_entry *entry) +{ + return do_qsp_entry_hash(entry, 0); +} + +static bool qsp_callsite_cmp(const void *ap, const void *bp) +{ + const struct qsp_callsite *a = ap; + const struct qsp_callsite *b = bp; + + return a == b || + (a->obj == b->obj && + a->line == b->line && + a->type == b->type && + (a->file == b->file || !strcmp(a->file, b->file))); +} + +static bool qsp_entry_no_thread_cmp(const void *ap, const void *bp) +{ + const struct qsp_entry *a = ap; + const struct qsp_entry *b = bp; + + return qsp_callsite_cmp(a->callsite, b->callsite); +} + +static bool qsp_entry_cmp(const void *ap, const void *bp) +{ + const struct qsp_entry *a = ap; + const struct qsp_entry *b = bp; + + return a->thread_ptr == b->thread_ptr && + qsp_callsite_cmp(a->callsite, b->callsite); +} + +/* + * Normally we'd call this from a constructor function, but we want it to work + * via libutil as well. + */ +static void qsp_do_init(void) +{ + /* make sure this file's path in the tree is up to date with QSP_REL_PATH */ + g_assert(strstr(__FILE__, QSP_REL_PATH)); + qsp_qemu_path_len = strlen(__FILE__) - strlen(QSP_REL_PATH); + + qht_init(&qsp_ht, qsp_entry_cmp, QSP_INITIAL_SIZE, + QHT_MODE_AUTO_RESIZE | QHT_MODE_RAW_MUTEXES); + qht_init(&qsp_callsite_ht, qsp_callsite_cmp, QSP_INITIAL_SIZE, + QHT_MODE_AUTO_RESIZE | QHT_MODE_RAW_MUTEXES); +} + +static __attribute__((noinline)) void qsp_init__slowpath(void) +{ + if (atomic_cmpxchg(&qsp_initializing, false, true) == false) { + qsp_do_init(); + atomic_set(&qsp_initialized, true); + } else { + while (!atomic_read(&qsp_initialized)) { + cpu_relax(); + } + } +} + +/* qsp_init() must be called from _all_ exported functions */ +static inline void qsp_init(void) +{ + if (likely(atomic_read(&qsp_initialized))) { + return; + } + qsp_init__slowpath(); +} + +static struct qsp_callsite *qsp_callsite_find(const struct qsp_callsite *orig) +{ + struct qsp_callsite *callsite; + uint32_t hash; + + hash = qsp_callsite_hash(orig); + callsite = qht_lookup(&qsp_callsite_ht, orig, hash); + if (callsite == NULL) { + void *existing = NULL; + + callsite = g_new(struct qsp_callsite, 1); + memcpy(callsite, orig, sizeof(*callsite)); + qht_insert(&qsp_callsite_ht, callsite, hash, &existing); + if (unlikely(existing)) { + g_free(callsite); + callsite = existing; + } + } + return callsite; +} + +static struct qsp_entry *qsp_entry_create(struct qht *ht, + const struct qsp_entry *entry, + uint32_t hash) +{ + struct qsp_entry *e; + void *existing = NULL; + + e = g_new(struct qsp_entry, 1); + memcpy(e, entry, sizeof(*e)); + e->callsite = qsp_callsite_find(entry->callsite); + /* zero the counters; all other fields are constant */ + e->n_acqs = 0; + e->ns = 0; + + qht_insert(ht, e, hash, &existing); + if (unlikely(existing)) { + g_free(e); + e = existing; + } + return e; +} + +static struct qsp_entry *qsp_entry_find(struct qht *ht, + const struct qsp_entry *entry, + uint32_t hash) +{ + struct qsp_entry *e; + + e = qht_lookup(ht, entry, hash); + if (e == NULL) { + e = qsp_entry_create(ht, entry, hash); + } + return e; +} + +static struct qsp_entry *qsp_entry_get(const void *obj, const char *file, + unsigned line, enum qsp_type type) +{ + struct qsp_callsite callsite = { + .obj = obj, + .file = file, + .line = line, + .type = type, + }; + struct qsp_entry orig; + uint32_t hash; + + qsp_init(); + + orig.thread_ptr = &qsp_thread; + orig.callsite = &callsite; + + hash = qsp_entry_hash(&orig); + return qsp_entry_find(&qsp_ht, &orig, hash); +} + +#define QSP_GEN_VOID(type_, qsp_t_, func_, impl_) \ + void func_(type_ *obj, const char *file, unsigned line) \ + { \ + struct qsp_entry *e = qsp_entry_get(obj, file, line, qsp_t_); \ + int64_t t; \ + \ + t = get_clock(); \ + impl_(obj, file, line); \ + atomic_set(&e->ns, e->ns + get_clock() - t); \ + atomic_set(&e->n_acqs, e->n_acqs + 1); \ + } + +#define QSP_GEN_RET1(type_, qsp_t_, func_, impl_) \ + int func_(type_ *obj, const char *file, unsigned line) \ + { \ + struct qsp_entry *e = qsp_entry_get(obj, file, line, qsp_t_); \ + int64_t t; \ + int err; \ + \ + t = get_clock(); \ + err = impl_(obj, file, line); \ + atomic_set(&e->ns, e->ns + get_clock() - t); \ + if (!err) { \ + atomic_set(&e->n_acqs, e->n_acqs + 1); \ + } \ + return err; \ + } + +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(QemuRecMutex, QSP_REC_MUTEX, qsp_rec_mutex_lock, + qemu_rec_mutex_lock_impl) +QSP_GEN_RET1(QemuRecMutex, QSP_REC_MUTEX, qsp_rec_mutex_trylock, + qemu_rec_mutex_trylock_impl) + +void qsp_cond_wait(QemuCond *cond, QemuMutex *mutex, const char *file, + unsigned line) +{ + struct qsp_entry *e; + int64_t t; + + qsp_init(); + + e = qsp_entry_get(cond, file, line, QSP_CONDVAR); + t = get_clock(); + qemu_cond_wait_impl(cond, mutex, file, line); + atomic_set(&e->ns, e->ns + get_clock() - t); + atomic_set(&e->n_acqs, e->n_acqs + 1); +} + +static gint qsp_tree_cmp(gconstpointer ap, gconstpointer bp, gpointer up) +{ + const struct qsp_entry *a = ap; + const struct qsp_entry *b = bp; + + if (a->ns > b->ns) { + return -1; + } else if (a->ns < b->ns) { + return 1; + } else { + const struct qsp_callsite *ca = a->callsite; + const struct qsp_callsite *cb = b->callsite; + + /* same ns. Break the tie with the object's address */ + if (ca->obj < cb->obj) { + return -1; + } else if (ca->obj > cb->obj) { + return 1; + } else { + int cmp; + + /* same obj. Break the tie with the callsite's file */ + cmp = strcmp(ca->file, cb->file); + if (cmp) { + return cmp; + } + /* same callsite file. Break the tie with the callsite's line */ + g_assert(ca->line != cb->line); + if (ca->line < cb->line) { + return -1; + } else if (ca->line > cb->line) { + return 1; + } else { + /* break the tie with the callsite's type */ + return cb->type - ca->type; + } + } + } +} + +static void qsp_sort(struct qht *ht, void *p, uint32_t h, void *userp) +{ + struct qsp_entry *e = p; + GTree *tree = userp; + + g_tree_insert(tree, e, NULL); +} + +static void qsp_aggregate(struct qht *global_ht, void *p, uint32_t h, void *up) +{ + struct qht *ht = up; + const struct qsp_entry *e = p; + struct qsp_entry *agg; + uint32_t hash; + + hash = qsp_entry_no_thread_hash(e); + agg = qsp_entry_find(ht, e, hash); + agg->ns += e->ns; + agg->n_acqs += e->n_acqs; +} + +static void qsp_mktree(GTree *tree) +{ + struct qht ht; + + /* first, create a hash table to aggregate all results */ + qht_init(&ht, qsp_entry_no_thread_cmp, QSP_INITIAL_SIZE, + QHT_MODE_AUTO_RESIZE | QHT_MODE_RAW_MUTEXES); + + /* then fill in the hash table by iterating over the global hash table */ + qht_iter(&qsp_ht, qsp_aggregate, &ht); + + /* sort the hash table elements by using a tree */ + qht_iter(&ht, qsp_sort, tree); + + /* free the hash table, but keep the elements (those are in the tree now) */ + qht_destroy(&ht); +} + +/* free string with g_free */ +static char *qsp_at(const struct qsp_callsite *callsite) +{ + GString *s = g_string_new(""); + const char *shortened; + + /* remove the absolute path to qemu */ + if (unlikely(strlen(callsite->file) < qsp_qemu_path_len)) { + shortened = callsite->file; + } else { + shortened = callsite->file + qsp_qemu_path_len; + } + g_string_append_printf(s, "%s:%u", shortened, callsite->line); + return g_string_free(s, FALSE); +} + +struct qsp_report_entry { + const void *obj; + char *callsite_at; + const char *typename; + double time_s; + double ns_avg; + uint64_t n_acqs; +}; + +struct qsp_report { + struct qsp_report_entry *entries; + size_t n_entries; + size_t max_n_entries; +}; + +static gboolean qsp_tree_report(gpointer key, gpointer value, gpointer udata) +{ + const struct qsp_entry *e = key; + struct qsp_report *report = udata; + struct qsp_report_entry *entry; + + if (report->n_entries == report->max_n_entries) { + return TRUE; + } + entry = &report->entries[report->n_entries]; + report->n_entries++; + + entry->obj = e->callsite->obj; + entry->callsite_at = qsp_at(e->callsite); + entry->typename = qsp_typenames[e->callsite->type]; + entry->time_s = e->ns * 1e-9; + entry->n_acqs = e->n_acqs; + entry->ns_avg = e->n_acqs ? e->ns / e->n_acqs : 0; + return FALSE; +} + +static void +pr_report(const struct qsp_report *rep, FILE *f, fprintf_function pr) +{ + char *dashes; + size_t max_len = 0; + int callsite_len = 0; + int callsite_rspace; + int n_dashes; + size_t i; + + /* find out the maximum length of all 'callsite' fields */ + for (i = 0; i < rep->n_entries; i++) { + const struct qsp_report_entry *e = &rep->entries[i]; + size_t len = strlen(e->callsite_at); + + if (len > max_len) { + max_len = len; + } + } + + callsite_len = MAX(max_len, strlen("Call site")); + /* white space to leave to the right of "Call site" */ + callsite_rspace = callsite_len - strlen("Call site"); + + pr(f, "Type Object Call site%*s Wait Time (s) " + " Count Average (us)\n", callsite_rspace, ""); + + /* build a horizontal rule with dashes */ + n_dashes = 79 + callsite_rspace; + dashes = g_malloc(n_dashes + 1); + memset(dashes, '-', n_dashes); + dashes[n_dashes] = '\0'; + pr(f, "%s\n", dashes); + + for (i = 0; i < rep->n_entries; i++) { + const struct qsp_report_entry *e = &rep->entries[i]; + + pr(f, "%-9s %14p %s%*s %13.5f %12" PRIu64 " %12.2f\n", e->typename, + e->obj, e->callsite_at, callsite_len - (int)strlen(e->callsite_at), + "", e->time_s, e->n_acqs, e->ns_avg * 1e-3); + } + + pr(f, "%s\n", dashes); + g_free(dashes); +} + +static void report_destroy(struct qsp_report *rep) +{ + size_t i; + + for (i = 0; i < rep->n_entries; i++) { + struct qsp_report_entry *e = &rep->entries[i]; + + g_free(e->callsite_at); + } + g_free(rep->entries); +} + +void qsp_report(FILE *f, fprintf_function cpu_fprintf, size_t max) +{ + GTree *tree = g_tree_new_full(qsp_tree_cmp, NULL, g_free, NULL); + struct qsp_report rep; + + qsp_init(); + + rep.entries = g_new0(struct qsp_report_entry, max); + rep.n_entries = 0; + rep.max_n_entries = max; + + qsp_mktree(tree); + g_tree_foreach(tree, qsp_tree_report, &rep); + g_tree_destroy(tree); + + pr_report(&rep, f, cpu_fprintf); + report_destroy(&rep); +} diff --git a/util/Makefile.objs b/util/Makefile.objs index e1c3fed4dc..579faa2ca6 100644 --- a/util/Makefile.objs +++ b/util/Makefile.objs @@ -3,6 +3,7 @@ util-obj-y += bufferiszero.o util-obj-y += lockcnt.o util-obj-y += aiocb.o async.o aio-wait.o thread-pool.o qemu-timer.o util-obj-y += main-loop.o iohandler.o +util-obj-$(CONFIG_SYNC_PROFILER) += qsp.o util-obj-$(CONFIG_POSIX) += aio-posix.o util-obj-$(CONFIG_POSIX) += compatfd.o util-obj-$(CONFIG_POSIX) += event_notifier-posix.o -- 2.17.1 ^ permalink raw reply related [flat|nested] 20+ messages in thread
* Re: [Qemu-devel] [PATCH 1/3] qsp: QEMU's Synchronization Profiler 2018-08-13 17:11 ` [Qemu-devel] [PATCH 1/3] qsp: QEMU's Synchronization Profiler Emilio G. Cota @ 2018-08-14 8:13 ` Paolo Bonzini 2018-08-15 0:44 ` Emilio G. Cota 2018-08-15 3:09 ` Fam Zheng 1 sibling, 1 reply; 20+ messages in thread From: Paolo Bonzini @ 2018-08-14 8:13 UTC (permalink / raw) To: Emilio G. Cota, qemu-devel Cc: Peter Crosthwaite, Richard Henderson, Dr. David Alan Gilbert, Stefan Weil, Markus Armbruster, Peter Xu On 13/08/2018 19:11, Emilio G. Cota wrote: > + struct qsp_report rep; Don't like camelcase? But that's really all that I have to remark on this lovely series. Paolo ^ permalink raw reply [flat|nested] 20+ messages in thread
* Re: [Qemu-devel] [PATCH 1/3] qsp: QEMU's Synchronization Profiler 2018-08-14 8:13 ` Paolo Bonzini @ 2018-08-15 0:44 ` Emilio G. Cota 2018-08-15 4:29 ` Markus Armbruster 0 siblings, 1 reply; 20+ messages in thread From: Emilio G. Cota @ 2018-08-15 0:44 UTC (permalink / raw) To: Paolo Bonzini Cc: qemu-devel, Peter Crosthwaite, Richard Henderson, Dr. David Alan Gilbert, Stefan Weil, Markus Armbruster, Peter Xu On Tue, Aug 14, 2018 at 10:13:12 +0200, Paolo Bonzini wrote: > On 13/08/2018 19:11, Emilio G. Cota wrote: > > + struct qsp_report rep; > > Don't like camelcase? But that's really all that I have to remark on > this lovely series. I have a strong aversion to it :-) But if that's a deal breaker, let me know. Thanks, E. ^ permalink raw reply [flat|nested] 20+ messages in thread
* Re: [Qemu-devel] [PATCH 1/3] qsp: QEMU's Synchronization Profiler 2018-08-15 0:44 ` Emilio G. Cota @ 2018-08-15 4:29 ` Markus Armbruster 0 siblings, 0 replies; 20+ messages in thread From: Markus Armbruster @ 2018-08-15 4:29 UTC (permalink / raw) To: Emilio G. Cota Cc: Paolo Bonzini, Peter Crosthwaite, Stefan Weil, Peter Xu, qemu-devel, Dr. David Alan Gilbert, Richard Henderson "Emilio G. Cota" <cota@braap.org> writes: > On Tue, Aug 14, 2018 at 10:13:12 +0200, Paolo Bonzini wrote: >> On 13/08/2018 19:11, Emilio G. Cota wrote: >> > + struct qsp_report rep; >> >> Don't like camelcase? But that's really all that I have to remark on >> this lovely series. > > I have a strong aversion to it :-) I despise it as much as anyone, but CODING_STYLE demands CamelCase for "type names" (which I interpret as typedef names), and convention (not codified in CODING_STYLE) demands typedef for struct types. > But if that's a deal breaker, let me know. Hold your nose and go with the flow. ^ permalink raw reply [flat|nested] 20+ messages in thread
* Re: [Qemu-devel] [PATCH 1/3] qsp: QEMU's Synchronization Profiler 2018-08-13 17:11 ` [Qemu-devel] [PATCH 1/3] qsp: QEMU's Synchronization Profiler Emilio G. Cota 2018-08-14 8:13 ` Paolo Bonzini @ 2018-08-15 3:09 ` Fam Zheng 2018-08-15 4:53 ` Emilio G. Cota 1 sibling, 1 reply; 20+ messages in thread From: Fam Zheng @ 2018-08-15 3:09 UTC (permalink / raw) To: Emilio G. Cota Cc: qemu-devel, Peter Crosthwaite, Stefan Weil, Dr. David Alan Gilbert, Peter Xu, Markus Armbruster, Paolo Bonzini, Richard Henderson On Mon, 08/13 13:11, Emilio G. Cota wrote: > + --enable-sync-profiler) sync_profiler="yes" > + ;; Curious, not asking for a change: can this be made a runtime option instead of compile time, since there's no library dependencies? That should make this somewhat easier to use. > + > +#define QSP_GEN_VOID(type_, qsp_t_, func_, impl_) \ > + void func_(type_ *obj, const char *file, unsigned line) \ > + { \ > + struct qsp_entry *e = qsp_entry_get(obj, file, line, qsp_t_); \ > + int64_t t; \ > + \ No qsp_init()? > + t = get_clock(); \ > + impl_(obj, file, line); \ > + atomic_set(&e->ns, e->ns + get_clock() - t); \ > + atomic_set(&e->n_acqs, e->n_acqs + 1); \ > + } > + > +#define QSP_GEN_RET1(type_, qsp_t_, func_, impl_) \ > + int func_(type_ *obj, const char *file, unsigned line) \ > + { \ > + struct qsp_entry *e = qsp_entry_get(obj, file, line, qsp_t_); \ > + int64_t t; \ > + int err; \ > + \ Same here. > + t = get_clock(); \ > + err = impl_(obj, file, line); \ > + atomic_set(&e->ns, e->ns + get_clock() - t); \ > + if (!err) { \ > + atomic_set(&e->n_acqs, e->n_acqs + 1); \ > + } \ > + return err; \ > + } > + > +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(QemuRecMutex, QSP_REC_MUTEX, qsp_rec_mutex_lock, > + qemu_rec_mutex_lock_impl) > +QSP_GEN_RET1(QemuRecMutex, QSP_REC_MUTEX, qsp_rec_mutex_trylock, > + qemu_rec_mutex_trylock_impl) > + > +void qsp_cond_wait(QemuCond *cond, QemuMutex *mutex, const char *file, > + unsigned line) > +{ > + struct qsp_entry *e; > + int64_t t; > + > + qsp_init(); > + > + e = qsp_entry_get(cond, file, line, QSP_CONDVAR); > + t = get_clock(); > + qemu_cond_wait_impl(cond, mutex, file, line); > + atomic_set(&e->ns, e->ns + get_clock() - t); > + atomic_set(&e->n_acqs, e->n_acqs + 1); Why not atomic_add (both here and in above macros)? Because fetching e->ns and then updating it is not "atomic" this way. Fam ^ permalink raw reply [flat|nested] 20+ messages in thread
* Re: [Qemu-devel] [PATCH 1/3] qsp: QEMU's Synchronization Profiler 2018-08-15 3:09 ` Fam Zheng @ 2018-08-15 4:53 ` Emilio G. Cota 2018-08-15 7:04 ` Fam Zheng 2018-08-15 23:55 ` Emilio G. Cota 0 siblings, 2 replies; 20+ messages in thread From: Emilio G. Cota @ 2018-08-15 4:53 UTC (permalink / raw) To: Fam Zheng Cc: qemu-devel, Peter Crosthwaite, Stefan Weil, Dr. David Alan Gilbert, Peter Xu, Markus Armbruster, Paolo Bonzini, Richard Henderson On Wed, Aug 15, 2018 at 11:09:42 +0800, Fam Zheng wrote: > On Mon, 08/13 13:11, Emilio G. Cota wrote: > > + --enable-sync-profiler) sync_profiler="yes" > > + ;; > > Curious, not asking for a change: can this be made a runtime option instead of > compile time, since there's no library dependencies? That should make this > somewhat easier to use. Good point. I'll do some profiling tomorrow to see how the latency of the locking primitives could be minimized (ideally, not using the profiler should just add a well-predicted branch). > > + > > +#define QSP_GEN_VOID(type_, qsp_t_, func_, impl_) \ > > + void func_(type_ *obj, const char *file, unsigned line) \ > > + { \ > > + struct qsp_entry *e = qsp_entry_get(obj, file, line, qsp_t_); \ > > + int64_t t; \ > > + \ > > No qsp_init()? > > > + t = get_clock(); \ > > + impl_(obj, file, line); \ > > + atomic_set(&e->ns, e->ns + get_clock() - t); \ > > + atomic_set(&e->n_acqs, e->n_acqs + 1); \ > > + } > > + > > +#define QSP_GEN_RET1(type_, qsp_t_, func_, impl_) \ > > + int func_(type_ *obj, const char *file, unsigned line) \ > > + { \ > > + struct qsp_entry *e = qsp_entry_get(obj, file, line, qsp_t_); \ > > + int64_t t; \ > > + int err; \ > > + \ > > Same here. qsp_init is called by qsp_get_entry. (snip) > > +void qsp_cond_wait(QemuCond *cond, QemuMutex *mutex, const char *file, > > + unsigned line) > > +{ > > + struct qsp_entry *e; > > + int64_t t; > > + > > + qsp_init(); > > + > > + e = qsp_entry_get(cond, file, line, QSP_CONDVAR); > > + t = get_clock(); > > + qemu_cond_wait_impl(cond, mutex, file, line); > > + atomic_set(&e->ns, e->ns + get_clock() - t); > > + atomic_set(&e->n_acqs, e->n_acqs + 1); > > Why not atomic_add (both here and in above macros)? Because fetching e->ns and > then updating it is not "atomic" this way. This isn't a read-modify-write op; atomic_set is used here as "write_once". Note that struct qsp_entry is only ever modified by the current thread (thread_ptr is part of the struct; yes this uses a lot more memory but that's the price of scalability). The struct might be read anytime by other threads though, so we have to use atomic_set to avoid undefined behaviour (e.g. torn reads/writes). Thanks, Emilio ^ permalink raw reply [flat|nested] 20+ messages in thread
* Re: [Qemu-devel] [PATCH 1/3] qsp: QEMU's Synchronization Profiler 2018-08-15 4:53 ` Emilio G. Cota @ 2018-08-15 7:04 ` Fam Zheng 2018-08-15 23:55 ` Emilio G. Cota 1 sibling, 0 replies; 20+ messages in thread From: Fam Zheng @ 2018-08-15 7:04 UTC (permalink / raw) To: Emilio G. Cota Cc: qemu-devel, Peter Crosthwaite, Stefan Weil, Dr. David Alan Gilbert, Peter Xu, Markus Armbruster, Paolo Bonzini, Richard Henderson On Wed, 08/15 00:53, Emilio G. Cota wrote: > > > +#define QSP_GEN_VOID(type_, qsp_t_, func_, impl_) \ > > > + void func_(type_ *obj, const char *file, unsigned line) \ > > > + { \ > > > + struct qsp_entry *e = qsp_entry_get(obj, file, line, qsp_t_); \ > > > + int64_t t; \ > > > + \ > > > > No qsp_init()? > > > > > + t = get_clock(); \ > > > + impl_(obj, file, line); \ > > > + atomic_set(&e->ns, e->ns + get_clock() - t); \ > > > + atomic_set(&e->n_acqs, e->n_acqs + 1); \ > > > + } > > > + > > > +#define QSP_GEN_RET1(type_, qsp_t_, func_, impl_) \ > > > + int func_(type_ *obj, const char *file, unsigned line) \ > > > + { \ > > > + struct qsp_entry *e = qsp_entry_get(obj, file, line, qsp_t_); \ > > > + int64_t t; \ > > > + int err; \ > > > + \ > > > > Same here. > > qsp_init is called by qsp_get_entry. Oh yes, I missed it. Then you can remove the one in qsp_cond_wait() as well for consistency. (That's where I noticed this). Fam ^ permalink raw reply [flat|nested] 20+ messages in thread
* Re: [Qemu-devel] [PATCH 1/3] qsp: QEMU's Synchronization Profiler 2018-08-15 4:53 ` Emilio G. Cota 2018-08-15 7:04 ` Fam Zheng @ 2018-08-15 23:55 ` Emilio G. Cota 2018-08-16 4:29 ` Emilio G. Cota 1 sibling, 1 reply; 20+ messages in thread From: Emilio G. Cota @ 2018-08-15 23:55 UTC (permalink / raw) To: Fam Zheng Cc: qemu-devel, Peter Crosthwaite, Stefan Weil, Dr. David Alan Gilbert, Peter Xu, Markus Armbruster, Paolo Bonzini, Richard Henderson On Wed, Aug 15, 2018 at 00:53:23 -0400, Emilio G. Cota wrote: > On Wed, Aug 15, 2018 at 11:09:42 +0800, Fam Zheng wrote: > > On Mon, 08/13 13:11, Emilio G. Cota wrote: > > > + --enable-sync-profiler) sync_profiler="yes" > > > + ;; > > > > Curious, not asking for a change: can this be made a runtime option instead of > > compile time, since there's no library dependencies? That should make this > > somewhat easier to use. > > Good point. I'll do some profiling tomorrow to see how the latency > of the locking primitives could be minimized (ideally, not using > the profiler should just add a well-predicted branch). I reduced it to just a branch, but still, I measured a few percentage points (1-2%, depending on the machine) slowdown when this is a run-time option. (This is for a bootup+shutdown test of a guest.) So I'll keep it as a build-time option, then. Thanks, Emilio ^ permalink raw reply [flat|nested] 20+ messages in thread
* Re: [Qemu-devel] [PATCH 1/3] qsp: QEMU's Synchronization Profiler 2018-08-15 23:55 ` Emilio G. Cota @ 2018-08-16 4:29 ` Emilio G. Cota 2018-08-16 4:36 ` Fam Zheng 0 siblings, 1 reply; 20+ messages in thread From: Emilio G. Cota @ 2018-08-16 4:29 UTC (permalink / raw) To: Fam Zheng Cc: qemu-devel, Peter Crosthwaite, Stefan Weil, Dr. David Alan Gilbert, Peter Xu, Markus Armbruster, Paolo Bonzini, Richard Henderson On Wed, Aug 15, 2018 at 19:55:14 -0400, Emilio G. Cota wrote: > On Wed, Aug 15, 2018 at 00:53:23 -0400, Emilio G. Cota wrote: > > On Wed, Aug 15, 2018 at 11:09:42 +0800, Fam Zheng wrote: > > > On Mon, 08/13 13:11, Emilio G. Cota wrote: > > > > + --enable-sync-profiler) sync_profiler="yes" > > > > + ;; > > > > > > Curious, not asking for a change: can this be made a runtime option instead of > > > compile time, since there's no library dependencies? That should make this > > > somewhat easier to use. > > > > Good point. I'll do some profiling tomorrow to see how the latency > > of the locking primitives could be minimized (ideally, not using > > the profiler should just add a well-predicted branch). > > I reduced it to just a branch, but still, I measured a few percentage > points (1-2%, depending on the machine) slowdown when this is a > run-time option. (This is for a bootup+shutdown test of a guest.) > > So I'll keep it as a build-time option, then. I looked further into this. Turns out we don't need the branch at all; we can make indirect calls via function pointers, where the pointers are set by qsp_enable/disable(). Overhead of doing things this way is within noise range, since compilers and CPUs are so good at dealing with indirect calls. I'll send a v2 tomorrow. Emilio ^ permalink raw reply [flat|nested] 20+ messages in thread
* Re: [Qemu-devel] [PATCH 1/3] qsp: QEMU's Synchronization Profiler 2018-08-16 4:29 ` Emilio G. Cota @ 2018-08-16 4:36 ` Fam Zheng 0 siblings, 0 replies; 20+ messages in thread From: Fam Zheng @ 2018-08-16 4:36 UTC (permalink / raw) To: Emilio G. Cota Cc: qemu-devel, Peter Crosthwaite, Stefan Weil, Dr. David Alan Gilbert, Peter Xu, Markus Armbruster, Paolo Bonzini, Richard Henderson On Thu, 08/16 00:29, Emilio G. Cota wrote: > On Wed, Aug 15, 2018 at 19:55:14 -0400, Emilio G. Cota wrote: > > On Wed, Aug 15, 2018 at 00:53:23 -0400, Emilio G. Cota wrote: > > > On Wed, Aug 15, 2018 at 11:09:42 +0800, Fam Zheng wrote: > > > > On Mon, 08/13 13:11, Emilio G. Cota wrote: > > > > > + --enable-sync-profiler) sync_profiler="yes" > > > > > + ;; > > > > > > > > Curious, not asking for a change: can this be made a runtime option instead of > > > > compile time, since there's no library dependencies? That should make this > > > > somewhat easier to use. > > > > > > Good point. I'll do some profiling tomorrow to see how the latency > > > of the locking primitives could be minimized (ideally, not using > > > the profiler should just add a well-predicted branch). > > > > I reduced it to just a branch, but still, I measured a few percentage > > points (1-2%, depending on the machine) slowdown when this is a > > run-time option. (This is for a bootup+shutdown test of a guest.) > > > > So I'll keep it as a build-time option, then. > > I looked further into this. Turns out we don't need the branch at all; > we can make indirect calls via function pointers, where the > pointers are set by qsp_enable/disable(). > > Overhead of doing things this way is within noise range, since > compilers and CPUs are so good at dealing with indirect calls. Very nice finding! Thanks. Fam > > I'll send a v2 tomorrow. > > Emilio ^ permalink raw reply [flat|nested] 20+ messages in thread
* [Qemu-devel] [PATCH 2/3] monitor: show sync profiling info with 'info sync' 2018-08-13 17:11 [Qemu-devel] [PATCH 0/3] synchronization profiler Emilio G. Cota 2018-08-13 17:11 ` [Qemu-devel] [PATCH 1/3] qsp: QEMU's Synchronization Profiler Emilio G. Cota @ 2018-08-13 17:11 ` Emilio G. Cota 2018-08-14 8:14 ` Paolo Bonzini ` (2 more replies) 2018-08-13 17:11 ` [Qemu-devel] [PATCH 3/3] qsp: track BQL callers directly Emilio G. Cota 2018-08-15 23:30 ` [Qemu-devel] [PATCH 0/3] synchronization profiler no-reply 3 siblings, 3 replies; 20+ messages in thread From: Emilio G. Cota @ 2018-08-13 17:11 UTC (permalink / raw) To: qemu-devel Cc: Paolo Bonzini, Peter Crosthwaite, Richard Henderson, Dr. David Alan Gilbert, Stefan Weil, Markus Armbruster, Peter Xu Signed-off-by: Emilio G. Cota <cota@braap.org> --- monitor.c | 7 +++++++ hmp-commands-info.hx | 16 ++++++++++++++++ 2 files changed, 23 insertions(+) diff --git a/monitor.c b/monitor.c index 77861e96af..66d8d85b97 100644 --- a/monitor.c +++ b/monitor.c @@ -1454,6 +1454,13 @@ static void hmp_info_opcount(Monitor *mon, const QDict *qdict) } #endif +static void hmp_info_sync(Monitor *mon, const QDict *qdict) +{ + int64_t max = qdict_get_try_int(qdict, "max", 10); + + qsp_report((FILE *)mon, monitor_fprintf, max); +} + static void hmp_info_history(Monitor *mon, const QDict *qdict) { int i; diff --git a/hmp-commands-info.hx b/hmp-commands-info.hx index 70639f656a..56a3249bad 100644 --- a/hmp-commands-info.hx +++ b/hmp-commands-info.hx @@ -297,6 +297,22 @@ STEXI @item info opcount @findex info opcount Show dynamic compiler opcode counters +ETEXI + + { + .name = "sync", + .args_type = "max:i?", + .params = "[max]", + .help = "show sync profiling info for " + "up to max entries (default: 10). " + "Entries are sorted by wait time.", + .cmd = hmp_info_sync, + }, + +STEXI +@item info sync +@findex sync +Show sync profiling info. ETEXI { -- 2.17.1 ^ permalink raw reply related [flat|nested] 20+ messages in thread
* Re: [Qemu-devel] [PATCH 2/3] monitor: show sync profiling info with 'info sync' 2018-08-13 17:11 ` [Qemu-devel] [PATCH 2/3] monitor: show sync profiling info with 'info sync' Emilio G. Cota @ 2018-08-14 8:14 ` Paolo Bonzini 2018-08-15 1:26 ` Emilio G. Cota 2018-08-14 9:43 ` Dr. David Alan Gilbert 2018-08-14 16:03 ` Markus Armbruster 2 siblings, 1 reply; 20+ messages in thread From: Paolo Bonzini @ 2018-08-14 8:14 UTC (permalink / raw) To: Emilio G. Cota, qemu-devel Cc: Peter Crosthwaite, Richard Henderson, Dr. David Alan Gilbert, Stefan Weil, Markus Armbruster, Peter Xu On 13/08/2018 19:11, Emilio G. Cota wrote: > diff --git a/hmp-commands-info.hx b/hmp-commands-info.hx > index 70639f656a..56a3249bad 100644 > --- a/hmp-commands-info.hx > +++ b/hmp-commands-info.hx > @@ -297,6 +297,22 @@ STEXI > @item info opcount > @findex info opcount > Show dynamic compiler opcode counters > +ETEXI > + > + { > + .name = "sync", > + .args_type = "max:i?", > + .params = "[max]", > + .help = "show sync profiling info for " > + "up to max entries (default: 10). " > + "Entries are sorted by wait time.", > + .cmd = hmp_info_sync, > + }, > + > +STEXI Would it make sense to add a flag to sort by average wait time, and one to coalesce all mutexes for the same call site? Can be done separately of course. Paolo ^ permalink raw reply [flat|nested] 20+ messages in thread
* Re: [Qemu-devel] [PATCH 2/3] monitor: show sync profiling info with 'info sync' 2018-08-14 8:14 ` Paolo Bonzini @ 2018-08-15 1:26 ` Emilio G. Cota 2018-08-16 13:20 ` Peter Xu 0 siblings, 1 reply; 20+ messages in thread From: Emilio G. Cota @ 2018-08-15 1:26 UTC (permalink / raw) To: Paolo Bonzini Cc: qemu-devel, Peter Crosthwaite, Richard Henderson, Dr. David Alan Gilbert, Stefan Weil, Markus Armbruster, Peter Xu On Tue, Aug 14, 2018 at 10:14:01 +0200, Paolo Bonzini wrote: > On 13/08/2018 19:11, Emilio G. Cota wrote: > Would it make sense to add a flag to sort by average wait time Done: (qemu) help info sync-profile info sync-profile [-m] [max] -- show sync profiling info \ for up to max entries (default: 10). By default, entries \ are sorted by total wait time; -m sorts by mean wait time. (qemu) info sync-profile 3 Type Object Call site Wait Time (s) Count Average (us) ------------------------------------------------------------------------------------ condvar 0x560cc9909e50 cpus.c:1165 63.63428 16081 3957.11 condvar 0x560cc9909e50 cpus.c:1415 0.21074 2 105371.07 BQL mutex 0x560cc85a3fa0 util/rcu.c:269 0.20227 20 10113.60 ------------------------------------------------------------------------------------ (qemu) info sync-profile -m 3 Type Object Call site Wait Time (s) Count Average (us) ------------------------------------------------------------------------------------ condvar 0x560cc9909e50 cpus.c:1415 0.21074 2 105371.07 BQL mutex 0x560cc85a3fa0 util/rcu.c:269 0.20227 21 9632.00 condvar 0x560cc9909e50 cpus.c:1165 71.92799 18167 3959.27 ------------------------------------------------------------------------------------ >, and one to coalesce all mutexes for the same call site? I am not sure I understand. Do you mean to pass a specific call site, so that we coalesce all entries related to the call site's object? Or to keep the call sites separate, but only report entries related to that specific call site's object? Thanks, Emilio ^ permalink raw reply [flat|nested] 20+ messages in thread
* Re: [Qemu-devel] [PATCH 2/3] monitor: show sync profiling info with 'info sync' 2018-08-15 1:26 ` Emilio G. Cota @ 2018-08-16 13:20 ` Peter Xu 0 siblings, 0 replies; 20+ messages in thread From: Peter Xu @ 2018-08-16 13:20 UTC (permalink / raw) To: Emilio G. Cota Cc: Paolo Bonzini, qemu-devel, Peter Crosthwaite, Richard Henderson, Dr. David Alan Gilbert, Stefan Weil, Markus Armbruster On Tue, Aug 14, 2018 at 09:26:09PM -0400, Emilio G. Cota wrote: > On Tue, Aug 14, 2018 at 10:14:01 +0200, Paolo Bonzini wrote: > > On 13/08/2018 19:11, Emilio G. Cota wrote: > > Would it make sense to add a flag to sort by average wait time > > Done: > > (qemu) help info sync-profile > info sync-profile [-m] [max] -- show sync profiling info \ > for up to max entries (default: 10). By default, entries \ > are sorted by total wait time; -m sorts by mean wait time. > > (qemu) info sync-profile 3 > Type Object Call site Wait Time (s) Count Average (us) > ------------------------------------------------------------------------------------ > condvar 0x560cc9909e50 cpus.c:1165 63.63428 16081 3957.11 > condvar 0x560cc9909e50 cpus.c:1415 0.21074 2 105371.07 > BQL mutex 0x560cc85a3fa0 util/rcu.c:269 0.20227 20 10113.60 > ------------------------------------------------------------------------------------ > > (qemu) info sync-profile -m 3 > Type Object Call site Wait Time (s) Count Average (us) > ------------------------------------------------------------------------------------ > condvar 0x560cc9909e50 cpus.c:1415 0.21074 2 105371.07 > BQL mutex 0x560cc85a3fa0 util/rcu.c:269 0.20227 21 9632.00 > condvar 0x560cc9909e50 cpus.c:1165 71.92799 18167 3959.27 > ------------------------------------------------------------------------------------ > > >, and one to coalesce all mutexes for the same call site? > > I am not sure I understand. Do you mean to pass a specific call site, > so that we coalesce all entries related to the call site's object? > Or to keep the call sites separate, but only report entries related > to that specific call site's object? I would guess Paolo means that whether we can merge entries that have the same call site but with different object addresses. I copied one example from the commit message of your patch 1: 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 ... IMHO merging of these two entries might be helpful when e.g. the condvar used there is dynamically created/destroyed, then in this case the object pointer might not that helpful, instead the statistics of all the entries for the same call site might tell more. Regards, -- Peter Xu ^ permalink raw reply [flat|nested] 20+ messages in thread
* Re: [Qemu-devel] [PATCH 2/3] monitor: show sync profiling info with 'info sync' 2018-08-13 17:11 ` [Qemu-devel] [PATCH 2/3] monitor: show sync profiling info with 'info sync' Emilio G. Cota 2018-08-14 8:14 ` Paolo Bonzini @ 2018-08-14 9:43 ` Dr. David Alan Gilbert 2018-08-15 1:33 ` Emilio G. Cota 2018-08-14 16:03 ` Markus Armbruster 2 siblings, 1 reply; 20+ messages in thread From: Dr. David Alan Gilbert @ 2018-08-14 9:43 UTC (permalink / raw) To: Emilio G. Cota Cc: qemu-devel, Paolo Bonzini, Peter Crosthwaite, Richard Henderson, Stefan Weil, Markus Armbruster, Peter Xu * Emilio G. Cota (cota@braap.org) wrote: > Signed-off-by: Emilio G. Cota <cota@braap.org> > --- > monitor.c | 7 +++++++ > hmp-commands-info.hx | 16 ++++++++++++++++ > 2 files changed, 23 insertions(+) > > diff --git a/monitor.c b/monitor.c > index 77861e96af..66d8d85b97 100644 > --- a/monitor.c > +++ b/monitor.c > @@ -1454,6 +1454,13 @@ static void hmp_info_opcount(Monitor *mon, const QDict *qdict) > } > #endif > > +static void hmp_info_sync(Monitor *mon, const QDict *qdict) > +{ > + int64_t max = qdict_get_try_int(qdict, "max", 10); > + > + qsp_report((FILE *)mon, monitor_fprintf, max); > +} > + > static void hmp_info_history(Monitor *mon, const QDict *qdict) > { > int i; > diff --git a/hmp-commands-info.hx b/hmp-commands-info.hx > index 70639f656a..56a3249bad 100644 > --- a/hmp-commands-info.hx > +++ b/hmp-commands-info.hx > @@ -297,6 +297,22 @@ STEXI > @item info opcount > @findex info opcount > Show dynamic compiler opcode counters > +ETEXI > + > + { > + .name = "sync", > + .args_type = "max:i?", > + .params = "[max]", > + .help = "show sync profiling info for " > + "up to max entries (default: 10). " > + "Entries are sorted by wait time.", > + .cmd = hmp_info_sync, > + }, > + > +STEXI > +@item info sync > +@findex sync > +Show sync profiling info. > ETEXI > > { As long as this is just for devs I'm OK with this from the HMP side; however, if you want to automate the display or wire it to other tools then you should probably wire it up via QMP. Dave > -- > 2.17.1 > -- Dr. David Alan Gilbert / dgilbert@redhat.com / Manchester, UK ^ permalink raw reply [flat|nested] 20+ messages in thread
* Re: [Qemu-devel] [PATCH 2/3] monitor: show sync profiling info with 'info sync' 2018-08-14 9:43 ` Dr. David Alan Gilbert @ 2018-08-15 1:33 ` Emilio G. Cota 0 siblings, 0 replies; 20+ messages in thread From: Emilio G. Cota @ 2018-08-15 1:33 UTC (permalink / raw) To: Dr. David Alan Gilbert, Markus Armbruster Cc: qemu-devel, Paolo Bonzini, Peter Crosthwaite, Richard Henderson, Stefan Weil, Peter Xu On Tue, Aug 14, 2018 at 10:43:47 +0100, Dr. David Alan Gilbert wrote: > * Emilio G. Cota (cota@braap.org) wrote: > > +@item info sync > > As long as this is just for devs I'm OK with this from the HMP side; > however, if you want to automate the display or wire it to other > tools then you should probably wire it up via QMP. On Tue, Aug 14, 2018 at 18:03:32 +0200, Markus Armbruster wrote: > "Emilio G. Cota" <cota@braap.org> writes: > > +@item info sync > > Please explain briefly why you think this command is not going to be > useful in QMP. Recommend to do that right in your commit message. For > instance, you could argue that the information provided is useful only > to developers, and developers are just fine with getting it from HMP > "info sync". > > However, if we expect developers to further process the data, providing > it as JSON (via QMP) makes sense, because is saves them the trouble of > parsing your (undocumented) HMP output format. > > If we decide we want to provide the functionality in QMP, I can help you > with the necessary code changes. Thanks Dave and Markus for taking a look. This is just for developers. This means (1) the info displayed and the output format could change in the future, and (2) it is only meant to be used from HMP "info sync-profile". I'll include the above in the commit log, as Markus suggested. > > + .name = "sync", > > I think "info sync-profile" would be clearer. Done. Thanks, Emilio ^ permalink raw reply [flat|nested] 20+ messages in thread
* Re: [Qemu-devel] [PATCH 2/3] monitor: show sync profiling info with 'info sync' 2018-08-13 17:11 ` [Qemu-devel] [PATCH 2/3] monitor: show sync profiling info with 'info sync' Emilio G. Cota 2018-08-14 8:14 ` Paolo Bonzini 2018-08-14 9:43 ` Dr. David Alan Gilbert @ 2018-08-14 16:03 ` Markus Armbruster 2 siblings, 0 replies; 20+ messages in thread From: Markus Armbruster @ 2018-08-14 16:03 UTC (permalink / raw) To: Emilio G. Cota Cc: qemu-devel, Peter Crosthwaite, Stefan Weil, Dr. David Alan Gilbert, Peter Xu, Paolo Bonzini, Richard Henderson "Emilio G. Cota" <cota@braap.org> writes: > Signed-off-by: Emilio G. Cota <cota@braap.org> > --- > monitor.c | 7 +++++++ > hmp-commands-info.hx | 16 ++++++++++++++++ > 2 files changed, 23 insertions(+) > > diff --git a/monitor.c b/monitor.c > index 77861e96af..66d8d85b97 100644 > --- a/monitor.c > +++ b/monitor.c > @@ -1454,6 +1454,13 @@ static void hmp_info_opcount(Monitor *mon, const QDict *qdict) > } > #endif > > +static void hmp_info_sync(Monitor *mon, const QDict *qdict) > +{ > + int64_t max = qdict_get_try_int(qdict, "max", 10); > + > + qsp_report((FILE *)mon, monitor_fprintf, max); > +} > + > static void hmp_info_history(Monitor *mon, const QDict *qdict) > { > int i; > diff --git a/hmp-commands-info.hx b/hmp-commands-info.hx > index 70639f656a..56a3249bad 100644 > --- a/hmp-commands-info.hx > +++ b/hmp-commands-info.hx > @@ -297,6 +297,22 @@ STEXI > @item info opcount > @findex info opcount > Show dynamic compiler opcode counters > +ETEXI > + > + { > + .name = "sync", I think "info sync-profile" would be clearer. > + .args_type = "max:i?", > + .params = "[max]", > + .help = "show sync profiling info for " > + "up to max entries (default: 10). " > + "Entries are sorted by wait time.", > + .cmd = hmp_info_sync, > + }, > + > +STEXI > +@item info sync > +@findex sync > +Show sync profiling info. > ETEXI > > { Please explain briefly why you think this command is not going to be useful in QMP. Recommend to do that right in your commit message. For instance, you could argue that the information provided is useful only to developers, and developers are just fine with getting it from HMP "info sync". However, if we expect developers to further process the data, providing it as JSON (via QMP) makes sense, because is saves them the trouble of parsing your (undocumented) HMP output format. If we decide we want to provide the functionality in QMP, I can help you with the necessary code changes. ^ permalink raw reply [flat|nested] 20+ messages in thread
* [Qemu-devel] [PATCH 3/3] qsp: track BQL callers directly 2018-08-13 17:11 [Qemu-devel] [PATCH 0/3] synchronization profiler Emilio G. Cota 2018-08-13 17:11 ` [Qemu-devel] [PATCH 1/3] qsp: QEMU's Synchronization Profiler Emilio G. Cota 2018-08-13 17:11 ` [Qemu-devel] [PATCH 2/3] monitor: show sync profiling info with 'info sync' Emilio G. Cota @ 2018-08-13 17:11 ` Emilio G. Cota 2018-08-15 23:30 ` [Qemu-devel] [PATCH 0/3] synchronization profiler no-reply 3 siblings, 0 replies; 20+ messages in thread From: Emilio G. Cota @ 2018-08-13 17:11 UTC (permalink / raw) To: qemu-devel Cc: Paolo Bonzini, Peter Crosthwaite, Richard Henderson, Dr. David Alan Gilbert, Stefan Weil, Markus Armbruster, Peter Xu 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 <cota@braap.org> --- 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 ^ permalink raw reply related [flat|nested] 20+ messages in thread
* Re: [Qemu-devel] [PATCH 0/3] synchronization profiler 2018-08-13 17:11 [Qemu-devel] [PATCH 0/3] synchronization profiler Emilio G. Cota ` (2 preceding siblings ...) 2018-08-13 17:11 ` [Qemu-devel] [PATCH 3/3] qsp: track BQL callers directly Emilio G. Cota @ 2018-08-15 23:30 ` no-reply 3 siblings, 0 replies; 20+ messages in thread From: no-reply @ 2018-08-15 23:30 UTC (permalink / raw) To: cota Cc: famz, qemu-devel, crosthwaite.peter, sw, dgilbert, peterx, armbru, pbonzini, rth Hi, This series seems to have some coding style problems. See output below for more information: Type: series Message-id: 20180813171132.21939-1-cota@braap.org Subject: [Qemu-devel] [PATCH 0/3] synchronization profiler === TEST SCRIPT BEGIN === #!/bin/bash BASE=base n=1 total=$(git log --oneline $BASE.. | wc -l) failed=0 git config --local diff.renamelimit 0 git config --local diff.renames True git config --local diff.algorithm histogram commits="$(git log --format=%H --reverse $BASE..)" for c in $commits; do echo "Checking PATCH $n/$total: $(git log -n 1 --format=%s $c)..." if ! git show $c --format=email | ./scripts/checkpatch.pl --mailback -; then failed=1 echo fi n=$((n+1)) done exit $failed === TEST SCRIPT END === Updating 3c8cf5a9c21ff8782164d1def7f44bd888713384 Switched to a new branch 'test' ac8f1dcaca qsp: track BQL callers directly 6c0b389867 monitor: show sync profiling info with 'info sync' c43c6c8920 qsp: QEMU's Synchronization Profiler === OUTPUT BEGIN === Checking PATCH 1/3: qsp: QEMU's Synchronization Profiler... WARNING: added, moved or deleted file(s), does MAINTAINERS need updating? #263: new file mode 100644 ERROR: spaces required around that '*' (ctx:WxV) #853: FILE: util/qsp.c:289: + void func_(type_ *obj, const char *file, unsigned line) \ ^ ERROR: spaces required around that '*' (ctx:WxV) #865: FILE: util/qsp.c:301: + int func_(type_ *obj, const char *file, unsigned line) \ ^ ERROR: spaces required around that '-' (ctx:VxV) #1028: FILE: util/qsp.c:464: + entry->time_s = e->ns * 1e-9; ^ ERROR: spaces required around that '-' (ctx:VxV) #1073: FILE: util/qsp.c:509: + "", e->time_s, e->n_acqs, e->ns_avg * 1e-3); ^ total: 4 errors, 1 warnings, 841 lines checked Your patch has style problems, please review. If any of these errors are false positives report them to the maintainer, see CHECKPATCH in MAINTAINERS. Checking PATCH 2/3: monitor: show sync profiling info with 'info sync'... Checking PATCH 3/3: qsp: track BQL callers directly... === OUTPUT END === Test command exited with code: 1 --- Email generated automatically by Patchew [http://patchew.org/]. Please send your feedback to patchew-devel@redhat.com ^ permalink raw reply [flat|nested] 20+ messages in thread
end of thread, other threads:[~2018-08-16 13:20 UTC | newest] Thread overview: 20+ messages (download: mbox.gz follow: Atom feed -- links below jump to the message on this page -- 2018-08-13 17:11 [Qemu-devel] [PATCH 0/3] synchronization profiler Emilio G. Cota 2018-08-13 17:11 ` [Qemu-devel] [PATCH 1/3] qsp: QEMU's Synchronization Profiler Emilio G. Cota 2018-08-14 8:13 ` Paolo Bonzini 2018-08-15 0:44 ` Emilio G. Cota 2018-08-15 4:29 ` Markus Armbruster 2018-08-15 3:09 ` Fam Zheng 2018-08-15 4:53 ` Emilio G. Cota 2018-08-15 7:04 ` Fam Zheng 2018-08-15 23:55 ` Emilio G. Cota 2018-08-16 4:29 ` Emilio G. Cota 2018-08-16 4:36 ` Fam Zheng 2018-08-13 17:11 ` [Qemu-devel] [PATCH 2/3] monitor: show sync profiling info with 'info sync' Emilio G. Cota 2018-08-14 8:14 ` Paolo Bonzini 2018-08-15 1:26 ` Emilio G. Cota 2018-08-16 13:20 ` Peter Xu 2018-08-14 9:43 ` Dr. David Alan Gilbert 2018-08-15 1:33 ` Emilio G. Cota 2018-08-14 16:03 ` Markus Armbruster 2018-08-13 17:11 ` [Qemu-devel] [PATCH 3/3] qsp: track BQL callers directly Emilio G. Cota 2018-08-15 23:30 ` [Qemu-devel] [PATCH 0/3] synchronization profiler no-reply
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for NNTP newsgroup(s).