Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

tools/hardirqs: Print results in descending order #5148

Merged
merged 1 commit into from
Nov 22, 2024
Merged

tools/hardirqs: Print results in descending order #5148

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 1 addition & 1 deletion tools/hardirqs.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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()

Expand Down
302 changes: 151 additions & 151 deletions tools/hardirqs_example.txt
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand All @@ -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
Expand All @@ -133,57 +133,57 @@ 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
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).
Expand Down Expand Up @@ -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:
Expand Down