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 milliseconds 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 |** | Sometimes you just want counts of events, and don't need the distribution of times. You can use the -C or --events option: # ./softirqs.py -C Tracing soft irq events... Hit Ctrl-C to end. ^C SOFTIRQ TOTAL_count block 5 tasklet 6 net_rx 402 sched 5251 rcu 5748 timer 9530 USAGE message: # ./softirqs -h usage: softirqs [-h] [-T] [-N] [-C] [-d] [-c CPU] [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 -C, --events show the number of soft irq events -d, --dist show distributions as histograms -c CPU, --cpu CPU trace this CPU only examples: ./softirqs # sum soft irq event time ./softirqs -C # show the number of soft irq events ./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 ./softirqs -c 1 # sum soft irq event time on CPU 1 only