From 69f48c7040d3a02a7a77ac6ac77e174958786c7c Mon Sep 17 00:00:00 2001 From: Hagen Paul Pfeifer Date: Tue, 22 Sep 2020 22:09:22 +0200 Subject: [PATCH] perf script: Add min, max to futex-contention output, in addition to avg Average is quite informative, but the outliners - especially max - are also of interest. Before: mutex-locker[793299] lock 5637ec61e080 contended 3400 times, 446 avg ns mutex-locker[793301] lock 5637ec61e080 contended 3563 times, 385 avg ns mutex-locker[793300] lock 5637ec61e080 contended 3110 times, 1855 avg ns After: mutex-locker[795251] lock 55b14e6dd080 contended 3853 times, 1279 avg ns [max: 12270 ns, min 340 ns] mutex-locker[795253] lock 55b14e6dd080 contended 2911 times, 518 avg ns [max: 51660261 ns, min 347 ns] mutex-locker[795252] lock 55b14e6dd080 contended 3843 times, 385 avg ns [max: 24323998 ns, min 338 ns] Committer testing: [root@five ~]# perf script record futex-contention -a ^C[ perf record: Woken up 1 times to write data ] [ perf record: Captured and wrote 1.877 MB perf.data (923 samples) ] [root@five ~]# perf evlist syscalls:sys_enter_futex syscalls:sys_exit_futex dummy:HG # Tip: use 'perf evlist --trace-fields' to show fields for tracepoint events # Before: [root@five ~]# perf script report futex-contention JS Helper[2457] lock 55fe0cf82610 contended 4 times, 6657 avg ns ibus-daemon[2975] lock 56227f6d0210 contended 4 times, 1020 avg ns chromium-browse[1905801] lock 7ffe573f5088 contended 8 times, 108463 avg ns gnome-shell[2240] lock 55fe0cf82678 contended 1 times, 8616 avg ns gnome-shel:cs0[2292] lock 55fe0d0ab768 contended 3 times, 606016034 avg ns JS Helper[2458] lock 55fe0cf82690 contended 1 times, 1167840 avg ns chromium-browse[1905470] lock 7ffe573f5358 contended 1 times, 551504 avg ns chromium-browse[1905948] lock 7ffe573f5358 contended 1 times, 577422 avg ns gnome-shell[2240] lock 55fe0cf82660 contended 6 times, 202696 avg ns pool[2602] lock 7fd600008ef0 contended 1 times, 500046007 avg ns chromium-browse[1905801] lock 7ffe573f5128 contended 4 times, 285083 avg ns JS Helper[2460] lock 55fe0cf82690 contended 1 times, 680877 avg ns JS Helper[2459] lock 55fe0cf82610 contended 7 times, 4224 avg ns chromium-browse[1905434] lock 7ffe573f5358 contended 1 times, 697038 avg ns chromium-browse[212592] lock 7ffe573f53c8 contended 4 times, 460601 avg ns gnome-shel:cs0[2292] lock 55fe0d0ab76c contended 2 times, 601237648 avg ns JS Helper[2460] lock 55fe0cf82610 contended 4 times, 3340 avg ns JS Helper[2462] lock 55fe0cf82694 contended 1 times, 237275 avg ns chromium-browse[1905605] lock 7ffe573f5358 contended 2 times, 634555 avg ns chromium-browse[1905992] lock 7ffe573f5358 contended 1 times, 583965 avg ns chromium-browse[1905647] lock 7ffe573f5368 contended 8 times, 549800 avg ns JS Helper[2462] lock 55fe0cf82610 contended 2 times, 4694 avg ns JS Helper[2461] lock 55fe0cf82694 contended 1 times, 257793 avg ns JS Helper[2456] lock 55fe0cf82690 contended 1 times, 677771 avg ns JS Helper[2463] lock 55fe0cf82610 contended 3 times, 5139 avg ns gdbus[2980] lock 56227f6d0210 contended 2 times, 2465 avg ns gnome-shell[2240] lock 55fe0cf82664 contended 5 times, 8036 avg ns chromium-browse[1906308] lock 7ffe573f5358 contended 1 times, 210735 avg ns JS Helper[2463] lock 55fe0cf82694 contended 1 times, 251531 avg ns chromium-browse[1905801] lock 7ffe573f4f58 contended 4 times, 399927 avg ns [root@five ~]# After: [root@five ~]# perf script report futex-contention JS Helper[2457] lock 55fe0cf82610 contended 4 times, 6657 avg ns [max: 11502 ns, min 792 ns] ibus-daemon[2975] lock 56227f6d0210 contended 4 times, 1020 avg ns [max: 1813 ns, min 581 ns] chromium-browse[1905801] lock 7ffe573f5088 contended 8 times, 108463 avg ns [max: 380103 ns, min 57989 ns] gnome-shell[2240] lock 55fe0cf82678 contended 1 times, 8616 avg ns [max: 8616 ns, min 8616 ns] gnome-shel:cs0[2292] lock 55fe0d0ab768 contended 3 times, 606016034 avg ns [max: 611295960 ns, min 600191357 ns] JS Helper[2458] lock 55fe0cf82690 contended 1 times, 1167840 avg ns [max: 1167840 ns, min 1167840 ns] chromium-browse[1905470] lock 7ffe573f5358 contended 1 times, 551504 avg ns [max: 551504 ns, min 551504 ns] chromium-browse[1905948] lock 7ffe573f5358 contended 1 times, 577422 avg ns [max: 577422 ns, min 577422 ns] gnome-shell[2240] lock 55fe0cf82660 contended 6 times, 202696 avg ns [max: 398998 ns, min 5050 ns] pool[2602] lock 7fd600008ef0 contended 1 times, 500046007 avg ns [max: 500046007 ns, min 500046007 ns] chromium-browse[1905801] lock 7ffe573f5128 contended 4 times, 285083 avg ns [max: 389531 ns, min 76183 ns] JS Helper[2460] lock 55fe0cf82690 contended 1 times, 680877 avg ns [max: 680877 ns, min 680877 ns] JS Helper[2459] lock 55fe0cf82610 contended 7 times, 4224 avg ns [max: 12724 ns, min 1012 ns] chromium-browse[1905434] lock 7ffe573f5358 contended 1 times, 697038 avg ns [max: 697038 ns, min 697038 ns] chromium-browse[212592] lock 7ffe573f53c8 contended 4 times, 460601 avg ns [max: 594956 ns, min 232996 ns] gnome-shel:cs0[2292] lock 55fe0d0ab76c contended 2 times, 601237648 avg ns [max: 601255863 ns, min 601219434 ns] JS Helper[2460] lock 55fe0cf82610 contended 4 times, 3340 avg ns [max: 9168 ns, min 962 ns] JS Helper[2462] lock 55fe0cf82694 contended 1 times, 237275 avg ns [max: 237275 ns, min 237275 ns] chromium-browse[1905605] lock 7ffe573f5358 contended 2 times, 634555 avg ns [max: 1024060 ns, min 245050 ns] chromium-browse[1905992] lock 7ffe573f5358 contended 1 times, 583965 avg ns [max: 583965 ns, min 583965 ns] chromium-browse[1905647] lock 7ffe573f5368 contended 8 times, 549800 avg ns [max: 775293 ns, min 258375 ns] JS Helper[2462] lock 55fe0cf82610 contended 2 times, 4694 avg ns [max: 8556 ns, min 832 ns] JS Helper[2461] lock 55fe0cf82694 contended 1 times, 257793 avg ns [max: 257793 ns, min 257793 ns] JS Helper[2456] lock 55fe0cf82690 contended 1 times, 677771 avg ns [max: 677771 ns, min 677771 ns] JS Helper[2463] lock 55fe0cf82610 contended 3 times, 5139 avg ns [max: 6873 ns, min 931 ns] gdbus[2980] lock 56227f6d0210 contended 2 times, 2465 avg ns [max: 4188 ns, min 742 ns] gnome-shell[2240] lock 55fe0cf82664 contended 5 times, 8036 avg ns [max: 13105 ns, min 401 ns] chromium-browse[1906308] lock 7ffe573f5358 contended 1 times, 210735 avg ns [max: 210735 ns, min 210735 ns] JS Helper[2463] lock 55fe0cf82694 contended 1 times, 251531 avg ns [max: 251531 ns, min 251531 ns] chromium-browse[1905801] lock 7ffe573f4f58 contended 4 times, 399927 avg ns [max: 476904 ns, min 178495 ns] [root@five ~]# Signed-off-by: Hagen Paul Pfeifer Tested-by: Arnaldo Carvalho de Melo Link: http://lore.kernel.org/lkml/20200922200922.1306034-1-hagen@jauu.net Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/scripts/python/futex-contention.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/tools/perf/scripts/python/futex-contention.py b/tools/perf/scripts/python/futex-contention.py index c440f02..7e884d4 100644 --- a/tools/perf/scripts/python/futex-contention.py +++ b/tools/perf/scripts/python/futex-contention.py @@ -53,5 +53,5 @@ def trace_begin(): def trace_end(): for (tid, lock) in lock_waits: min, max, avg, count = lock_waits[tid, lock] - print("%s[%d] lock %x contended %d times, %d avg ns" % - (process_names[tid], tid, lock, count, avg)) + print("%s[%d] lock %x contended %d times, %d avg ns [max: %d ns, min %d ns]" % + (process_names[tid], tid, lock, count, avg, max, min)) -- 2.7.4