From fb62cc3f5e39ed5b3feda8d20858652042890de5 Mon Sep 17 00:00:00 2001 From: Bojun Seo Date: Sat, 23 Nov 2024 04:54:33 +0900 Subject: [PATCH] tools/hardirqs: Print results in descending order (#5148) Users are usually interested in events that happen frequently and consume more time. So, print the results in descending order. --- tools/hardirqs.py | 2 +- tools/hardirqs_example.txt | 302 ++++++++++++++++++------------------- 2 files changed, 152 insertions(+), 152 deletions(-) diff --git a/tools/hardirqs.py b/tools/hardirqs.py index b9f15accfaf0..aa15bb87d2fd 100755 --- a/tools/hardirqs.py +++ b/tools/hardirqs.py @@ -245,7 +245,7 @@ dist.print_log2_hist(label, "hardirq", section_print_fn=bytes.decode) else: print("%-26s %11s" % ("HARDIRQ", "TOTAL_" + label)) - for k, v in sorted(dist.items(), key=lambda dist: dist[1].value): + for k, v in sorted(dist.items(), key=lambda dist: -dist[1].value): print("%-26s %11d" % (k.name.decode('utf-8', 'replace'), v.value / factor)) dist.clear() diff --git a/tools/hardirqs_example.txt b/tools/hardirqs_example.txt index d7dcc9cb8d09..2dfbd299a50f 100644 --- a/tools/hardirqs_example.txt +++ b/tools/hardirqs_example.txt @@ -8,28 +8,28 @@ in-kernel for efficiency. For example: Tracing hard irq event time... Hit Ctrl-C to end. ^C HARDIRQ TOTAL_usecs -callfuncsingle0 2 -callfuncsingle5 5 -callfuncsingle6 5 -callfuncsingle7 21 -blkif 66 -timer7 84 -resched5 94 -resched0 97 -resched3 102 -resched7 111 -resched6 255 -timer3 362 -resched4 367 -timer5 474 -timer1 529 -timer6 679 -timer2 746 -timer4 943 -resched1 1048 -timer0 1558 -resched2 1750 eth0 11441 +resched2 1750 +timer0 1558 +resched1 1048 +timer4 943 +timer2 746 +timer6 679 +timer1 529 +timer5 474 +resched4 367 +timer3 362 +resched6 255 +resched7 111 +resched3 102 +resched0 97 +resched5 94 +timer7 84 +blkif 66 +callfuncsingle7 21 +callfuncsingle6 5 +callfuncsingle5 5 +callfuncsingle0 2 The HARDIRQ column prints the interrupt action name. While tracing, the eth0 hard irq action ran for 11441 microseconds (11 milliseconds) in total. @@ -47,80 +47,80 @@ Tracing hard irq event time... Hit Ctrl-C to end. 22:16:14 HARDIRQ TOTAL_usecs -callfuncsingle0 2 -callfuncsingle7 5 -callfuncsingle3 5 -callfuncsingle2 5 -callfuncsingle6 6 -callfuncsingle1 11 -resched0 32 -blkif 51 -resched5 71 -resched7 71 -resched4 72 -resched6 82 -timer7 172 -resched1 187 -resched2 236 -timer3 252 -resched3 282 -timer1 320 -timer2 374 -timer6 396 -timer5 427 -timer4 470 -timer0 1430 eth0 7498 +timer0 1430 +timer4 470 +timer5 427 +timer6 396 +timer2 374 +timer1 320 +resched3 282 +timer3 252 +resched2 236 +resched1 187 +timer7 172 +resched6 82 +resched4 72 +resched7 71 +resched5 71 +blkif 51 +resched0 32 +callfuncsingle1 11 +callfuncsingle6 6 +callfuncsingle2 5 +callfuncsingle3 5 +callfuncsingle7 5 +callfuncsingle0 2 22:16:15 HARDIRQ TOTAL_usecs -callfuncsingle7 6 -callfuncsingle5 11 -callfuncsingle4 13 -timer2 17 -callfuncsingle6 18 -resched0 21 -blkif 33 -resched3 40 -resched5 60 -resched4 69 -resched6 70 -resched7 74 -timer7 86 -resched2 91 -timer3 134 -resched1 293 -timer5 354 -timer1 433 -timer6 497 -timer4 1112 -timer0 1768 eth0 6972 +timer0 1768 +timer4 1112 +timer6 497 +timer1 433 +timer5 354 +resched1 293 +timer3 134 +resched2 91 +timer7 86 +resched7 74 +resched6 70 +resched4 69 +resched5 60 +resched3 40 +blkif 33 +resched0 21 +callfuncsingle6 18 +timer2 17 +callfuncsingle4 13 +callfuncsingle5 11 +callfuncsingle7 6 22:16:16 HARDIRQ TOTAL_usecs -callfuncsingle7 5 -callfuncsingle3 5 -callfuncsingle2 6 -timer3 10 -resched0 18 -callfuncsingle4 22 -resched5 27 -resched6 44 -blkif 45 -resched7 65 -resched4 69 -timer4 77 -resched2 97 -timer7 98 -resched3 103 -timer2 169 -resched1 226 -timer5 525 -timer1 691 -timer6 697 -timer0 1415 eth0 7152 +timer0 1415 +timer6 697 +timer1 691 +timer5 525 +resched1 226 +timer2 169 +resched3 103 +timer7 98 +resched2 97 +timer4 77 +resched4 69 +resched7 65 +blkif 45 +resched6 44 +resched5 27 +callfuncsingle4 22 +resched0 18 +timer3 10 +callfuncsingle2 6 +callfuncsingle3 5 +callfuncsingle7 5 This can be useful for quantifying where CPU cycles are spent among the hard interrupts (summarized as the %irq column from mpstat(1)). The output above @@ -133,29 +133,29 @@ perf tool is performing a 999 Hertz CPU profile ("perf record -F 999 -a ..."): 22:13:59 HARDIRQ TOTAL_usecs -callfuncsingle7 5 -callfuncsingle5 5 -callfuncsingle3 6 -callfuncsingle4 7 -callfuncsingle6 19 -blkif 66 -resched0 66 -resched2 82 -resched7 87 -resched3 96 -resched4 118 -resched5 120 -resched6 130 -resched1 230 -timer3 946 -timer1 1981 -timer7 2618 -timer5 3063 -timer6 3141 -timer4 3511 -timer2 3554 -timer0 5044 eth0 16015 +timer0 5044 +timer2 3554 +timer4 3511 +timer6 3141 +timer5 3063 +timer7 2618 +timer1 1981 +timer3 946 +resched1 230 +resched6 130 +resched5 120 +resched4 118 +resched3 96 +resched7 87 +resched2 82 +resched0 66 +blkif 66 +callfuncsingle6 19 +callfuncsingle4 7 +callfuncsingle3 6 +callfuncsingle5 5 +callfuncsingle7 5 This sheds some light into the CPU overhead of the perf profiler, which cost around 3 milliseconds per second. Note that I'm usually profiling at a much @@ -163,27 +163,27 @@ lower rate, 99 Hertz, which looks like this: 22:22:12 HARDIRQ TOTAL_usecs -callfuncsingle3 5 -callfuncsingle6 5 -callfuncsingle5 22 -blkif 46 -resched6 47 -resched5 57 -resched4 66 -resched7 78 -resched2 97 -resched0 214 -timer2 326 -timer0 498 -timer5 536 -timer6 576 -timer1 600 -timer4 982 -resched1 1315 -timer7 1364 -timer3 1825 -resched3 5708 eth0 9743 +resched3 5708 +timer3 1825 +timer7 1364 +resched1 1315 +timer4 982 +timer1 600 +timer6 576 +timer5 536 +timer0 498 +timer2 326 +resched0 214 +resched2 97 +resched7 78 +resched4 66 +resched5 57 +resched6 47 +blkif 46 +callfuncsingle5 22 +callfuncsingle6 5 +callfuncsingle3 5 Much lower (and remember to compare this to the baseline). Note that perf has other overheads (non-irq CPU cycles, file system storage). @@ -621,30 +621,30 @@ of times. You can use the -C or --count option: Tracing hard irq events... Hit Ctrl-C to end. ^C HARDIRQ TOTAL_count -blkif 2 -callfuncsingle3 8 -callfuncsingle2 10 -callfuncsingle1 18 -resched7 25 -callfuncsingle6 25 -callfuncsingle5 27 -callfuncsingle0 27 -eth0 34 -resched2 40 -resched1 66 -timer7 70 -resched6 71 -resched0 73 -resched5 79 -resched4 90 -timer6 95 -timer4 100 -timer1 109 -timer2 115 -timer0 117 -timer3 123 -resched3 140 timer5 288 +resched3 140 +timer3 123 +timer0 117 +timer2 115 +timer1 109 +timer4 100 +timer6 95 +resched4 90 +resched5 79 +resched0 73 +resched6 71 +timer7 70 +resched1 66 +resched2 40 +eth0 34 +callfuncsingle0 27 +callfuncsingle5 27 +callfuncsingle6 25 +resched7 25 +callfuncsingle1 18 +callfuncsingle2 10 +callfuncsingle3 8 +blkif 2 USAGE message: