| Demonstrations of softirqs, the Linux eBPF/bcc version. |
| |
| |
| This program traces soft interrupts (irqs), and stores timing statistics |
| in-kernel for efficiency. For example: |
| |
| # ./softirqs |
| Tracing soft irq event time... Hit Ctrl-C to end. |
| ^C |
| SOFTIRQ TOTAL_usecs |
| rcu_process_callbacks 974 |
| run_rebalance_domains 1809 |
| run_timer_softirq 2615 |
| net_tx_action 14605 |
| tasklet_action 38692 |
| net_rx_action 88188 |
| |
| The SOFTIRQ column prints the interrupt action function name. While tracing, |
| the net_rx_action() soft interrupt ran for 20199 microseconds (20 milliseconds) |
| in total. |
| |
| This tool works by dynamic tracing the individual softirq functions, and will |
| need to be adjusted to match kernel/module changes. Future versions should |
| use the softirq tracepoints instead. |
| |
| |
| An interval can be provided, and also optionally a count. Eg, printing output |
| every 1 second, and including timestamps (-T): |
| |
| # ./softirqs -T 1 3 |
| Tracing soft irq event time... Hit Ctrl-C to end. |
| |
| 22:29:16 |
| SOFTIRQ TOTAL_usecs |
| rcu_process_callbacks 456 |
| run_rebalance_domains 1005 |
| run_timer_softirq 1196 |
| net_tx_action 2796 |
| tasklet_action 5534 |
| net_rx_action 15075 |
| |
| 22:29:17 |
| SOFTIRQ TOTAL_usecs |
| rcu_process_callbacks 456 |
| run_rebalance_domains 839 |
| run_timer_softirq 1142 |
| net_tx_action 1912 |
| tasklet_action 4428 |
| net_rx_action 14652 |
| |
| 22:29:18 |
| SOFTIRQ TOTAL_usecs |
| rcu_process_callbacks 502 |
| run_rebalance_domains 840 |
| run_timer_softirq 1192 |
| net_tx_action 2341 |
| tasklet_action 5496 |
| net_rx_action 15656 |
| |
| This can be useful for quantifying where CPU cycles are spent among the soft |
| interrupts (summarized as the %softirq column from mpstat(1), and shown as |
| event counts in /proc/softirqs). The output above shows that most time was spent |
| processing net_rx_action(), which was around 15 milleconds per second (total |
| time across all CPUs). |
| |
| |
| The distribution of interrupt run time can be printed as a histogram with the -d |
| option. Eg: |
| |
| # ./softirqs -d |
| Tracing soft irq event time... Hit Ctrl-C to end. |
| ^C |
| |
| softirq = net_tx_action |
| 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 : 440 | | |
| 512 -> 1023 : 27613 |****************************************| |
| 1024 -> 2047 : 5728 |******** | |
| 2048 -> 4095 : 439 | | |
| 4096 -> 8191 : 53 | | |
| 8192 -> 16383 : 2 | | |
| |
| softirq = net_rx_action |
| 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 : 6 | | |
| 1024 -> 2047 : 35 | | |
| 2048 -> 4095 : 3562 |**************** | |
| 4096 -> 8191 : 7023 |******************************** | |
| 8192 -> 16383 : 8770 |****************************************| |
| 16384 -> 32767 : 1780 |******** | |
| 32768 -> 65535 : 216 | | |
| 65536 -> 131071 : 4 | | |
| |
| softirq = tasklet_action |
| 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 : 95 | | |
| 512 -> 1023 : 12521 |****************************************| |
| 1024 -> 2047 : 1068 |*** | |
| 2048 -> 4095 : 1077 |*** | |
| 4096 -> 8191 : 12349 |*************************************** | |
| 8192 -> 16383 : 464 |* | |
| 16384 -> 32767 : 1 | | |
| |
| softirq = rcu_process_callbacks |
| 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 : 708 |****************************************| |
| 1024 -> 2047 : 495 |*************************** | |
| 2048 -> 4095 : 98 |***** | |
| 4096 -> 8191 : 62 |*** | |
| 8192 -> 16383 : 4 | | |
| |
| softirq = run_timer_softirq |
| 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 : 2 | | |
| 512 -> 1023 : 366 |********* | |
| 1024 -> 2047 : 1525 |****************************************| |
| 2048 -> 4095 : 629 |**************** | |
| 4096 -> 8191 : 87 |** | |
| 8192 -> 16383 : 1 | | |
| |
| softirq = run_rebalance_domains |
| 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 : 3 | | |
| 512 -> 1023 : 18 |* | |
| 1024 -> 2047 : 80 |******** | |
| 2048 -> 4095 : 374 |****************************************| |
| 4096 -> 8191 : 257 |*************************** | |
| 8192 -> 16383 : 50 |***** | |
| 16384 -> 32767 : 24 |** | |
| |
| |
| USAGE message: |
| |
| # ./softirqs -h |
| usage: softirqs [-h] [-T] [-N] [-d] [interval] [count] |
| |
| Summarize soft irq event time as histograms |
| |
| positional arguments: |
| interval output interval, in seconds |
| count number of outputs |
| |
| optional arguments: |
| -h, --help show this help message and exit |
| -T, --timestamp include timestamp on output |
| -N, --nanoseconds output in nanoseconds |
| -d, --dist show distributions as histograms |
| |
| examples: |
| ./softirqs # sum soft irq event time |
| ./softirqs -d # show soft irq event time as histograms |
| ./softirqs 1 10 # print 1 second summaries, 10 times |
| ./softirqs -NT 1 # 1s summaries, nanoseconds, and timestamps |