{"push_id":2801120071,"size":7,"distinct_size":7,"ref":"refs/heads/sync-profiler-v2","head":"92dfaeb03805d50ef3b44d528b3624956d7fcc21","before":"6d82e89c977017ae38dd05685290b6317d5cf3ee","commits":[{"sha":"b39a944cb843e5af7da84f33202120d6d5c31dee","author":{"name":"Emilio G. Cota","email":"201e881bfa0e9543bba00630d033ebfb953e7c40@braap.org"},"message":"qsp: QEMU's Synchronization Profiler\n\nThe goal of this module is to profile synchronization primitives (i.e.\nmutexes, recursive mutexes and condition variables) so that scalability\nissues can be quickly diagnosed.\n\nSync primitives are profiled by QSP based on the vaddr of the object accessed\nas well as the call site (file:line_nr). That means the same object called\nfrom two different call sites will be tracked in separate entries, and in the\nreport (see below) they will show up in different rows. See the comments\nat the top of qsp.c for further info on this decision and the overall\ndesign of QSP.\n\nA report shows info about the tracked entries, sorted in descending order\nof total wait time. Sample output:\n\nType               Object  Call site          Wait Time (s)         Count  Average (us)\n---------------------------------------------------------------------------------------\ncondvar    0x557ee3090e80  cpus.c:1084              1.69207          2916        580.27\ncondvar    0x557ee30ceb10  cpus.c:1084              1.43442          2404        596.68\nmutex      0x557ee2503540  cpus.c:1583              0.30300        636558          0.48\ncondvar    0x557ee2534460  cpus-common.c:216        0.13549         15513          8.73\ncondvar    0x557ee2534420  cpus-common.c:186        0.08927         15747          5.67\nmutex      0x557ee3090a40  tcg/tcg.c:378            0.00823        120034          0.07\nmutex      0x557ee3090a00  tcg/tcg.c:378            0.00820        117890          0.07\nmutex      0x557ee3090ac0  tcg/tcg.c:378            0.00764        115954          0.07\nmutex      0x557ee3090a80  tcg/tcg.c:378            0.00762        116573          0.07\nmutex      0x557ee3090b00  tcg/tcg.c:378            0.00560         82547          0.07\n---------------------------------------------------------------------------------------\n\nSome perf numbers:\n\n- Impact on mutex_lock performance when the profiler is disabled:\n  Host: Intel(R) Core(TM) i7-4790K CPU @ 4.00GHz\n  Command: taskset -c 0 tests/atomic_add-bench -d 5 -m\n  Before: 57.88 Mops/s\n  After:  57.72 Mops/s\n  That is a 0.27% slowdown. The slowdown comes from the branch added\n  to each qemu_mutex_lock call. Fortunately, the branch is easy to\n  predict for the processor, which results in negligible latency.\n\n- Profiling overhead for `taskset -c 0 atomic_add-bench -d 5 -m' on\n  AMD Opteron 6376:\n\n  - Before this patch:\t14.92 Mops/s\n  - No profiling:\t14.76 Mops/s\n  - W/ profiling:\t 2.60 Mops/s\n  - W/o rcu:\t\t 3.48 Mops/s\n  - W/o rcu+get_clock:\t 7.18 Mops/s\n\n  That is, a 5.67X slowdown for mutex_lock.\n\n  The \"w/o rcu\" result is the performance measured for an instrumented mutex_lock\n  that does not call rcu_read_lock/unlock; this is necessary to support resetting\n  the profiling info.\n  The \"w/o rcu+get_clock\" result removes the RCU calls as well as the get_clock\n  calls; with this we measure the overhead of just the instrumentation + the\n  hash table lookup.\n\nSynchronization primitives are not called very often during a regular\nQEMU run, so the overall performance impact of the profiler is quite\ntolerable, as the following results show.\n\n- Boot + shut down of debian-aarch64, on i7-4790K host, 3 runs, -smp 1:\n  -smp 1:\n    - Before this series:\n      9.092913684 seconds time elapsed ( +-  0.69% )\n\n    - W/ this series, no profiling:\n      9.183124367 seconds time elapsed ( +-  0.22% )\n\n    - W/ profiling:\n      10.017482673 seconds time elapsed ( +-  2.57% )\n\n  That is, a 1% slowdown.\n\nSigned-off-by: Emilio G. Cota <cota@braap.org>","distinct":true,"url":"https://api.github.com/repos/cota/qemu/commits/b39a944cb843e5af7da84f33202120d6d5c31dee"},{"sha":"73d22b2e6c765a928b4782fd6e37e65985c97629","author":{"name":"Emilio G. Cota","email":"201e881bfa0e9543bba00630d033ebfb953e7c40@braap.org"},"message":"tests/atomic_add-bench: add -p to enable sync profiler\n\nWhen used together with -m, this allows us to benchmark the\nprofiler's performance impact on qemu_mutex_lock.\n\nSigned-off-by: Emilio G. Cota <cota@braap.org>","distinct":true,"url":"https://api.github.com/repos/cota/qemu/commits/73d22b2e6c765a928b4782fd6e37e65985c97629"},{"sha":"f316c3822e6776799958a5b29fe1eab2fbab3af7","author":{"name":"Emilio G. Cota","email":"201e881bfa0e9543bba00630d033ebfb953e7c40@braap.org"},"message":"vl: add -enable-sync-profile\n\nSigned-off-by: Emilio G. Cota <cota@braap.org>","distinct":true,"url":"https://api.github.com/repos/cota/qemu/commits/f316c3822e6776799958a5b29fe1eab2fbab3af7"},{"sha":"d81258b6af40bbd228861b4222ffaf72fb333bd2","author":{"name":"Emilio G. Cota","email":"201e881bfa0e9543bba00630d033ebfb953e7c40@braap.org"},"message":"hmp-commands: add sync-profile\n\nThe command introduced here is just for developers. This means that:\n\n- the interface implemented here could change in the future\n- the command is only meant to be used from HMP, not from QMP\n\nSigned-off-by: Emilio G. Cota <cota@braap.org>","distinct":true,"url":"https://api.github.com/repos/cota/qemu/commits/d81258b6af40bbd228861b4222ffaf72fb333bd2"},{"sha":"5db6e3f4b61de77a6731f28368f98abc415ed0b8","author":{"name":"Emilio G. Cota","email":"201e881bfa0e9543bba00630d033ebfb953e7c40@braap.org"},"message":"hmp-commands-info: add sync-profile\n\nThe command introduced here is just for developers. This means that:\n\n- the info displayed and the output format could change in the future\n- the command is only meant to be used from HMP, not from QMP\n\nSigned-off-by: Emilio G. Cota <cota@braap.org>","distinct":true,"url":"https://api.github.com/repos/cota/qemu/commits/5db6e3f4b61de77a6731f28368f98abc415ed0b8"},{"sha":"0237dea804ebfe41d8e6835cc6a4f2933bcdbdaf","author":{"name":"Emilio G. Cota","email":"201e881bfa0e9543bba00630d033ebfb953e7c40@braap.org"},"message":"qsp: track BQL callers directly\n\nThe BQL is acquired via qemu_mutex_lock_iothread(), which makes\nthe profiler assign the associated wait time (i.e. most of\nBQL wait time) entirely to that function. This loses the original\ncall site information, which does not help diagnose BQL contention.\nFix it by tracking the callers directly when the lock profiler is\nenabled. While at it, add a QSP type specific to it, so that the\nBQL is reported as \"BQL mutex\".\n\n- Before:\nType               Object  Call site          Wait Time (s)         Count  Average (us)\n---------------------------------------------------------------------------------------\ncondvar    0x557ee3090e80  cpus.c:1084              1.69207          2916        580.27\ncondvar    0x557ee30ceb10  cpus.c:1084              1.43442          2404        596.68\nmutex      0x557ee2503540  cpus.c:1583              0.30300        636558          0.48\ncondvar    0x557ee2534460  cpus-common.c:216        0.13549         15513          8.73\ncondvar    0x557ee2534420  cpus-common.c:186        0.08927         15747          5.67\nmutex      0x557ee3090a40  tcg/tcg.c:378            0.00823        120034          0.07\nmutex      0x557ee3090a00  tcg/tcg.c:378            0.00820        117890          0.07\nmutex      0x557ee3090ac0  tcg/tcg.c:378            0.00764        115954          0.07\nmutex      0x557ee3090a80  tcg/tcg.c:378            0.00762        116573          0.07\nmutex      0x557ee3090b00  tcg/tcg.c:378            0.00560         82547          0.07\n---------------------------------------------------------------------------------------\n\n- After:\nType               Object  Call site                   Wait Time (s)         Count  Average (us)\n------------------------------------------------------------------------------------------------\ncondvar    0x555d4b37bb10  cpus.c:1084                       1.82472          1245       1465.64\ncondvar    0x555d4b33de80  cpus.c:1084                       1.22456          3105        394.38\ncondvar    0x555d48ee3460  cpus-common.c:216                 0.15380         18510          8.31\ncondvar    0x555d48ee3420  cpus-common.c:186                 0.10400         18303          5.68\nBQL mutex  0x555d48eb2540  cpus.c:1272                       0.06565         77751          0.84\nBQL mutex  0x555d48eb2540  target/arm/op_helper.c:837        0.04077         28317          1.44\nBQL mutex  0x555d48eb2540  accel/tcg/cpu-exec.c:502          0.03935        149975          0.26\nBQL mutex  0x555d48eb2540  target/arm/op_helper.c:851        0.03917         85698          0.46\nBQL mutex  0x555d48eb2540  util/rcu.c:257                    0.03059             9       3399.36\nBQL mutex  0x555d48eb2540  cpus-common.c:352                 0.02717         29992          0.91\n------------------------------------------------------------------------------------------------\n\nSigned-off-by: Emilio G. Cota <cota@braap.org>","distinct":true,"url":"https://api.github.com/repos/cota/qemu/commits/0237dea804ebfe41d8e6835cc6a4f2933bcdbdaf"},{"sha":"92dfaeb03805d50ef3b44d528b3624956d7fcc21","author":{"name":"Emilio G. Cota","email":"201e881bfa0e9543bba00630d033ebfb953e7c40@braap.org"},"message":"fptr wip\n\nSigned-off-by: Emilio G. Cota <cota@braap.org>","distinct":true,"url":"https://api.github.com/repos/cota/qemu/commits/92dfaeb03805d50ef3b44d528b3624956d7fcc21"}]}
{"actor":{"display_login":"cota"}}