Demonstrations of hardirqs, the Linux eBPF/bcc version.
|
|
|
This program traces hard interrupts (irqs), and stores timing statistics
|
in-kernel for efficiency. For example:
|
|
# ./hardirqs
|
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
|
|
The HARDIRQ column prints the interrupt action name. While tracing, the eth0
|
hard irq action ran for 11441 microseconds (11 milliseconds) in total.
|
|
Many other interrupts are visible in the output: this is an 8 CPU system, and
|
some of these interrupts have a separate action per-CPU (eg, "timer",
|
"resched").
|
|
|
An interval can be provided, and also optionally a count. Eg, printing output
|
every 1 second, and including timestamps (-T):
|
|
# ./hardirqs -T 1 3
|
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
|
|
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
|
|
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
|
|
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
|
shows that most time was spent processing for eth0 (network interface), which
|
was around 7 milliseconds per second (total across all CPUs).
|
|
Note that the time spent among the "timer" interrupts was low, and usually less
|
than one microsecond per second. Here's the hardirq per-second output when the
|
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
|
|
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
|
|
Much lower (and remember to compare this to the baseline). Note that perf has
|
other overheads (non-irq CPU cycles, file system storage).
|
|
|
The distribution of interrupt run time can be printed as a histogram with the -d
|
option. Eg:
|
|
# ./hardirqs -d
|
Tracing hard irq event time... Hit Ctrl-C to end.
|
^C
|
|
hardirq = 'callfuncsingle1'
|
usecs : count distribution
|
0 -> 1 : 0 | |
|
2 -> 3 : 0 | |
|
4 -> 7 : 0 | |
|
8 -> 15 : 0 | |
|
16 -> 31 : 0 | |
|
32 -> 63 : 0 | |
|
64 -> 127 : 0 | |
|
128 -> 255 : 0 | |
|
256 -> 511 : 0 | |
|
512 -> 1023 : 0 | |
|
1024 -> 2047 : 0 | |
|
2048 -> 4095 : 0 | |
|
4096 -> 8191 : 0 | |
|
8192 -> 16383 : 1 |****************************************|
|
|
hardirq = 'callfuncsingle0'
|
usecs : count distribution
|
0 -> 1 : 0 | |
|
2 -> 3 : 0 | |
|
4 -> 7 : 0 | |
|
8 -> 15 : 0 | |
|
16 -> 31 : 0 | |
|
32 -> 63 : 0 | |
|
64 -> 127 : 0 | |
|
128 -> 255 : 0 | |
|
256 -> 511 : 0 | |
|
512 -> 1023 : 0 | |
|
1024 -> 2047 : 0 | |
|
2048 -> 4095 : 1 |****************************************|
|
|
hardirq = 'callfuncsingle3'
|
usecs : count distribution
|
0 -> 1 : 0 | |
|
2 -> 3 : 0 | |
|
4 -> 7 : 0 | |
|
8 -> 15 : 0 | |
|
16 -> 31 : 0 | |
|
32 -> 63 : 0 | |
|
64 -> 127 : 0 | |
|
128 -> 255 : 0 | |
|
256 -> 511 : 0 | |
|
512 -> 1023 : 0 | |
|
1024 -> 2047 : 0 | |
|
2048 -> 4095 : 0 | |
|
4096 -> 8191 : 3 |****************************************|
|
|
hardirq = 'callfuncsingle2'
|
usecs : count distribution
|
0 -> 1 : 0 | |
|
2 -> 3 : 0 | |
|
4 -> 7 : 0 | |
|
8 -> 15 : 0 | |
|
16 -> 31 : 0 | |
|
32 -> 63 : 0 | |
|
64 -> 127 : 0 | |
|
128 -> 255 : 0 | |
|
256 -> 511 : 0 | |
|
512 -> 1023 : 0 | |
|
1024 -> 2047 : 0 | |
|
2048 -> 4095 : 0 | |
|
4096 -> 8191 : 2 |****************************************|
|
|
hardirq = 'callfuncsingle5'
|
usecs : count distribution
|
0 -> 1 : 0 | |
|
2 -> 3 : 0 | |
|
4 -> 7 : 0 | |
|
8 -> 15 : 0 | |
|
16 -> 31 : 0 | |
|
32 -> 63 : 0 | |
|
64 -> 127 : 0 | |
|
128 -> 255 : 0 | |
|
256 -> 511 : 0 | |
|
512 -> 1023 : 0 | |
|
1024 -> 2047 : 0 | |
|
2048 -> 4095 : 0 | |
|
4096 -> 8191 : 5 |****************************************|
|
|
hardirq = 'callfuncsingle4'
|
usecs : count distribution
|
0 -> 1 : 0 | |
|
2 -> 3 : 0 | |
|
4 -> 7 : 0 | |
|
8 -> 15 : 0 | |
|
16 -> 31 : 0 | |
|
32 -> 63 : 0 | |
|
64 -> 127 : 0 | |
|
128 -> 255 : 0 | |
|
256 -> 511 : 0 | |
|
512 -> 1023 : 0 | |
|
1024 -> 2047 : 0 | |
|
2048 -> 4095 : 0 | |
|
4096 -> 8191 : 6 |****************************************|
|
|
hardirq = 'callfuncsingle7'
|
usecs : count distribution
|
0 -> 1 : 0 | |
|
2 -> 3 : 0 | |
|
4 -> 7 : 0 | |
|
8 -> 15 : 0 | |
|
16 -> 31 : 0 | |
|
32 -> 63 : 0 | |
|
64 -> 127 : 0 | |
|
128 -> 255 : 0 | |
|
256 -> 511 : 0 | |
|
512 -> 1023 : 0 | |
|
1024 -> 2047 : 0 | |
|
2048 -> 4095 : 0 | |
|
4096 -> 8191 : 4 |****************************************|
|
|
hardirq = 'callfuncsingle6'
|
usecs : count distribution
|
0 -> 1 : 0 | |
|
2 -> 3 : 0 | |
|
4 -> 7 : 0 | |
|
8 -> 15 : 0 | |
|
16 -> 31 : 0 | |
|
32 -> 63 : 0 | |
|
64 -> 127 : 0 | |
|
128 -> 255 : 0 | |
|
256 -> 511 : 0 | |
|
512 -> 1023 : 0 | |
|
1024 -> 2047 : 0 | |
|
2048 -> 4095 : 0 | |
|
4096 -> 8191 : 4 |****************************************|
|
|
hardirq = 'eth0'
|
usecs : count distribution
|
0 -> 1 : 0 | |
|
2 -> 3 : 0 | |
|
4 -> 7 : 0 | |
|
8 -> 15 : 0 | |
|
16 -> 31 : 0 | |
|
32 -> 63 : 0 | |
|
64 -> 127 : 0 | |
|
128 -> 255 : 0 | |
|
256 -> 511 : 0 | |
|
512 -> 1023 : 5102 |********* |
|
1024 -> 2047 : 20617 |****************************************|
|
2048 -> 4095 : 4832 |********* |
|
4096 -> 8191 : 12 | |
|
|
hardirq = 'timer7'
|
usecs : count distribution
|
0 -> 1 : 0 | |
|
2 -> 3 : 0 | |
|
4 -> 7 : 0 | |
|
8 -> 15 : 0 | |
|
16 -> 31 : 0 | |
|
32 -> 63 : 0 | |
|
64 -> 127 : 0 | |
|
128 -> 255 : 0 | |
|
256 -> 511 : 0 | |
|
512 -> 1023 : 0 | |
|
1024 -> 2047 : 9 |*** |
|
2048 -> 4095 : 70 |***************************** |
|
4096 -> 8191 : 94 |****************************************|
|
|
hardirq = 'timer6'
|
usecs : count distribution
|
0 -> 1 : 0 | |
|
2 -> 3 : 0 | |
|
4 -> 7 : 0 | |
|
8 -> 15 : 0 | |
|
16 -> 31 : 0 | |
|
32 -> 63 : 0 | |
|
64 -> 127 : 0 | |
|
128 -> 255 : 0 | |
|
256 -> 511 : 0 | |
|
512 -> 1023 : 0 | |
|
1024 -> 2047 : 1 | |
|
2048 -> 4095 : 86 |*********** |
|
4096 -> 8191 : 295 |****************************************|
|
8192 -> 16383 : 28 |*** |
|
|
hardirq = 'timer5'
|
usecs : count distribution
|
0 -> 1 : 0 | |
|
2 -> 3 : 0 | |
|
4 -> 7 : 0 | |
|
8 -> 15 : 0 | |
|
16 -> 31 : 0 | |
|
32 -> 63 : 0 | |
|
64 -> 127 : 0 | |
|
128 -> 255 : 0 | |
|
256 -> 511 : 0 | |
|
512 -> 1023 : 1 | |
|
1024 -> 2047 : 0 | |
|
2048 -> 4095 : 137 |****************************************|
|
4096 -> 8191 : 123 |*********************************** |
|
8192 -> 16383 : 8 |** |
|
|
hardirq = 'timer4'
|
usecs : count distribution
|
0 -> 1 : 0 | |
|
2 -> 3 : 0 | |
|
4 -> 7 : 0 | |
|
8 -> 15 : 0 | |
|
16 -> 31 : 0 | |
|
32 -> 63 : 0 | |
|
64 -> 127 : 0 | |
|
128 -> 255 : 0 | |
|
256 -> 511 : 0 | |
|
512 -> 1023 : 0 | |
|
1024 -> 2047 : 0 | |
|
2048 -> 4095 : 46 |********* |
|
4096 -> 8191 : 198 |****************************************|
|
8192 -> 16383 : 49 |********* |
|
|
hardirq = 'timer3'
|
usecs : count distribution
|
0 -> 1 : 0 | |
|
2 -> 3 : 0 | |
|
4 -> 7 : 0 | |
|
8 -> 15 : 0 | |
|
16 -> 31 : 0 | |
|
32 -> 63 : 0 | |
|
64 -> 127 : 0 | |
|
128 -> 255 : 0 | |
|
256 -> 511 : 0 | |
|
512 -> 1023 : 0 | |
|
1024 -> 2047 : 4 | |
|
2048 -> 4095 : 210 |****************************************|
|
4096 -> 8191 : 186 |*********************************** |
|
|
hardirq = 'timer2'
|
usecs : count distribution
|
0 -> 1 : 0 | |
|
2 -> 3 : 0 | |
|
4 -> 7 : 0 | |
|
8 -> 15 : 0 | |
|
16 -> 31 : 0 | |
|
32 -> 63 : 0 | |
|
64 -> 127 : 0 | |
|
128 -> 255 : 0 | |
|
256 -> 511 : 0 | |
|
512 -> 1023 : 0 | |
|
1024 -> 2047 : 0 | |
|
2048 -> 4095 : 245 |****************************************|
|
4096 -> 8191 : 227 |************************************* |
|
8192 -> 16383 : 6 | |
|
|
hardirq = 'timer1'
|
usecs : count distribution
|
0 -> 1 : 0 | |
|
2 -> 3 : 0 | |
|
4 -> 7 : 0 | |
|
8 -> 15 : 0 | |
|
16 -> 31 : 0 | |
|
32 -> 63 : 0 | |
|
64 -> 127 : 0 | |
|
128 -> 255 : 0 | |
|
256 -> 511 : 0 | |
|
512 -> 1023 : 0 | |
|
1024 -> 2047 : 6 |* |
|
2048 -> 4095 : 112 |************************ |
|
4096 -> 8191 : 181 |****************************************|
|
8192 -> 16383 : 7 |* |
|
|
hardirq = 'timer0'
|
usecs : count distribution
|
0 -> 1 : 0 | |
|
2 -> 3 : 0 | |
|
4 -> 7 : 0 | |
|
8 -> 15 : 0 | |
|
16 -> 31 : 0 | |
|
32 -> 63 : 0 | |
|
64 -> 127 : 0 | |
|
128 -> 255 : 0 | |
|
256 -> 511 : 0 | |
|
512 -> 1023 : 0 | |
|
1024 -> 2047 : 0 | |
|
2048 -> 4095 : 0 | |
|
4096 -> 8191 : 887 |****************************************|
|
8192 -> 16383 : 92 |**** |
|
|
hardirq = 'blkif'
|
usecs : count distribution
|
0 -> 1 : 0 | |
|
2 -> 3 : 0 | |
|
4 -> 7 : 0 | |
|
8 -> 15 : 0 | |
|
16 -> 31 : 0 | |
|
32 -> 63 : 0 | |
|
64 -> 127 : 0 | |
|
128 -> 255 : 0 | |
|
256 -> 511 : 0 | |
|
512 -> 1023 : 0 | |
|
1024 -> 2047 : 0 | |
|
2048 -> 4095 : 0 | |
|
4096 -> 8191 : 9 |****************************************|
|
8192 -> 16383 : 7 |******************************* |
|
16384 -> 32767 : 2 |******** |
|
|
hardirq = 'resched4'
|
usecs : count distribution
|
0 -> 1 : 0 | |
|
2 -> 3 : 0 | |
|
4 -> 7 : 0 | |
|
8 -> 15 : 0 | |
|
16 -> 31 : 0 | |
|
32 -> 63 : 0 | |
|
64 -> 127 : 0 | |
|
128 -> 255 : 0 | |
|
256 -> 511 : 0 | |
|
512 -> 1023 : 0 | |
|
1024 -> 2047 : 104 |****************************************|
|
2048 -> 4095 : 80 |****************************** |
|
|
hardirq = 'resched5'
|
usecs : count distribution
|
0 -> 1 : 0 | |
|
2 -> 3 : 0 | |
|
4 -> 7 : 0 | |
|
8 -> 15 : 0 | |
|
16 -> 31 : 0 | |
|
32 -> 63 : 0 | |
|
64 -> 127 : 0 | |
|
128 -> 255 : 0 | |
|
256 -> 511 : 0 | |
|
512 -> 1023 : 27 |***** |
|
1024 -> 2047 : 216 |****************************************|
|
2048 -> 4095 : 27 |***** |
|
4096 -> 8191 : 1 | |
|
|
hardirq = 'resched6'
|
usecs : count distribution
|
0 -> 1 : 0 | |
|
2 -> 3 : 0 | |
|
4 -> 7 : 0 | |
|
8 -> 15 : 0 | |
|
16 -> 31 : 0 | |
|
32 -> 63 : 0 | |
|
64 -> 127 : 0 | |
|
128 -> 255 : 0 | |
|
256 -> 511 : 0 | |
|
512 -> 1023 : 480 |******************* |
|
1024 -> 2047 : 1003 |****************************************|
|
2048 -> 4095 : 64 |** |
|
|
hardirq = 'resched7'
|
usecs : count distribution
|
0 -> 1 : 0 | |
|
2 -> 3 : 0 | |
|
4 -> 7 : 0 | |
|
8 -> 15 : 0 | |
|
16 -> 31 : 0 | |
|
32 -> 63 : 0 | |
|
64 -> 127 : 0 | |
|
128 -> 255 : 0 | |
|
256 -> 511 : 0 | |
|
512 -> 1023 : 46 |********* |
|
1024 -> 2047 : 190 |****************************************|
|
2048 -> 4095 : 42 |******** |
|
|
hardirq = 'resched0'
|
usecs : count distribution
|
0 -> 1 : 0 | |
|
2 -> 3 : 0 | |
|
4 -> 7 : 0 | |
|
8 -> 15 : 0 | |
|
16 -> 31 : 0 | |
|
32 -> 63 : 0 | |
|
64 -> 127 : 0 | |
|
128 -> 255 : 0 | |
|
256 -> 511 : 0 | |
|
512 -> 1023 : 11 |**** |
|
1024 -> 2047 : 100 |****************************************|
|
2048 -> 4095 : 23 |********* |
|
|
hardirq = 'resched1'
|
usecs : count distribution
|
0 -> 1 : 0 | |
|
2 -> 3 : 0 | |
|
4 -> 7 : 0 | |
|
8 -> 15 : 0 | |
|
16 -> 31 : 0 | |
|
32 -> 63 : 0 | |
|
64 -> 127 : 0 | |
|
128 -> 255 : 0 | |
|
256 -> 511 : 0 | |
|
512 -> 1023 : 96 |******** |
|
1024 -> 2047 : 462 |****************************************|
|
2048 -> 4095 : 36 |*** |
|
|
hardirq = 'resched2'
|
usecs : count distribution
|
0 -> 1 : 0 | |
|
2 -> 3 : 0 | |
|
4 -> 7 : 0 | |
|
8 -> 15 : 0 | |
|
16 -> 31 : 0 | |
|
32 -> 63 : 0 | |
|
64 -> 127 : 0 | |
|
128 -> 255 : 0 | |
|
256 -> 511 : 0 | |
|
512 -> 1023 : 120 |************************** |
|
1024 -> 2047 : 183 |****************************************|
|
2048 -> 4095 : 41 |******** |
|
|
hardirq = 'resched3'
|
usecs : count distribution
|
0 -> 1 : 0 | |
|
2 -> 3 : 0 | |
|
4 -> 7 : 0 | |
|
8 -> 15 : 0 | |
|
16 -> 31 : 0 | |
|
32 -> 63 : 0 | |
|
64 -> 127 : 0 | |
|
128 -> 255 : 0 | |
|
256 -> 511 : 0 | |
|
512 -> 1023 : 0 | |
|
1024 -> 2047 : 789 |****************************************|
|
2048 -> 4095 : 39 |* |
|
|
|
Sometimes you just want counts of events, and don't need the distribution
|
of times. You can use the -C or --count option:
|
|
# ./hardirqs.py -C
|
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
|
|
|
USAGE message:
|
|
# ./hardirqs -h
|
usage: hardirqs [-h] [-T] [-N] [-C] [-d] [interval] [outputs]
|
|
Summarize hard irq event time as histograms
|
|
positional arguments:
|
interval output interval, in seconds
|
outputs number of outputs
|
|
optional arguments:
|
-h, --help show this help message and exit
|
-T, --timestamp include timestamp on output
|
-N, --nanoseconds output in nanoseconds
|
-C, --count show event counts instead of timing
|
-d, --dist show distributions as histograms
|
|
examples:
|
./hardirqs # sum hard irq event time
|
./hardirqs -d # show hard irq event time as histograms
|
./hardirqs 1 10 # print 1 second summaries, 10 times
|
./hardirqs -NT 1 # 1s summaries, nanoseconds, and timestamps
|
