| 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 |
