1Demonstrations of softirqs, the Linux eBPF/bcc version. 2 3 4This program traces soft interrupts (irqs), and stores timing statistics 5in-kernel for efficiency. For example: 6 7# ./softirqs 8Tracing soft irq event time... Hit Ctrl-C to end. 9^C 10SOFTIRQ TOTAL_usecs 11rcu_process_callbacks 974 12run_rebalance_domains 1809 13run_timer_softirq 2615 14net_tx_action 14605 15tasklet_action 38692 16net_rx_action 88188 17 18The SOFTIRQ column prints the interrupt action function name. While tracing, 19the net_rx_action() soft interrupt ran for 20199 microseconds (20 milliseconds) 20in total. 21 22This tool works by dynamic tracing the individual softirq functions, and will 23need to be adjusted to match kernel/module changes. Future versions should 24use the softirq tracepoints instead. 25 26 27An interval can be provided, and also optionally a count. Eg, printing output 28every 1 second, and including timestamps (-T): 29 30# ./softirqs -T 1 3 31Tracing soft irq event time... Hit Ctrl-C to end. 32 3322:29:16 34SOFTIRQ TOTAL_usecs 35rcu_process_callbacks 456 36run_rebalance_domains 1005 37run_timer_softirq 1196 38net_tx_action 2796 39tasklet_action 5534 40net_rx_action 15075 41 4222:29:17 43SOFTIRQ TOTAL_usecs 44rcu_process_callbacks 456 45run_rebalance_domains 839 46run_timer_softirq 1142 47net_tx_action 1912 48tasklet_action 4428 49net_rx_action 14652 50 5122:29:18 52SOFTIRQ TOTAL_usecs 53rcu_process_callbacks 502 54run_rebalance_domains 840 55run_timer_softirq 1192 56net_tx_action 2341 57tasklet_action 5496 58net_rx_action 15656 59 60This can be useful for quantifying where CPU cycles are spent among the soft 61interrupts (summarized as the %softirq column from mpstat(1), and shown as 62event counts in /proc/softirqs). The output above shows that most time was spent 63processing net_rx_action(), which was around 15 milliseconds per second (total 64time across all CPUs). 65 66 67The distribution of interrupt run time can be printed as a histogram with the -d 68option. Eg: 69 70# ./softirqs -d 71Tracing soft irq event time... Hit Ctrl-C to end. 72^C 73 74softirq = net_tx_action 75 usecs : count distribution 76 0 -> 1 : 0 | | 77 2 -> 3 : 0 | | 78 4 -> 7 : 0 | | 79 8 -> 15 : 0 | | 80 16 -> 31 : 0 | | 81 32 -> 63 : 0 | | 82 64 -> 127 : 0 | | 83 128 -> 255 : 0 | | 84 256 -> 511 : 440 | | 85 512 -> 1023 : 27613 |****************************************| 86 1024 -> 2047 : 5728 |******** | 87 2048 -> 4095 : 439 | | 88 4096 -> 8191 : 53 | | 89 8192 -> 16383 : 2 | | 90 91softirq = net_rx_action 92 usecs : count distribution 93 0 -> 1 : 0 | | 94 2 -> 3 : 0 | | 95 4 -> 7 : 0 | | 96 8 -> 15 : 0 | | 97 16 -> 31 : 0 | | 98 32 -> 63 : 0 | | 99 64 -> 127 : 0 | | 100 128 -> 255 : 0 | | 101 256 -> 511 : 0 | | 102 512 -> 1023 : 6 | | 103 1024 -> 2047 : 35 | | 104 2048 -> 4095 : 3562 |**************** | 105 4096 -> 8191 : 7023 |******************************** | 106 8192 -> 16383 : 8770 |****************************************| 107 16384 -> 32767 : 1780 |******** | 108 32768 -> 65535 : 216 | | 109 65536 -> 131071 : 4 | | 110 111softirq = tasklet_action 112 usecs : count distribution 113 0 -> 1 : 0 | | 114 2 -> 3 : 0 | | 115 4 -> 7 : 0 | | 116 8 -> 15 : 0 | | 117 16 -> 31 : 0 | | 118 32 -> 63 : 0 | | 119 64 -> 127 : 0 | | 120 128 -> 255 : 0 | | 121 256 -> 511 : 95 | | 122 512 -> 1023 : 12521 |****************************************| 123 1024 -> 2047 : 1068 |*** | 124 2048 -> 4095 : 1077 |*** | 125 4096 -> 8191 : 12349 |*************************************** | 126 8192 -> 16383 : 464 |* | 127 16384 -> 32767 : 1 | | 128 129softirq = rcu_process_callbacks 130 usecs : count distribution 131 0 -> 1 : 0 | | 132 2 -> 3 : 0 | | 133 4 -> 7 : 0 | | 134 8 -> 15 : 0 | | 135 16 -> 31 : 0 | | 136 32 -> 63 : 0 | | 137 64 -> 127 : 0 | | 138 128 -> 255 : 0 | | 139 256 -> 511 : 0 | | 140 512 -> 1023 : 708 |****************************************| 141 1024 -> 2047 : 495 |*************************** | 142 2048 -> 4095 : 98 |***** | 143 4096 -> 8191 : 62 |*** | 144 8192 -> 16383 : 4 | | 145 146softirq = run_timer_softirq 147 usecs : count distribution 148 0 -> 1 : 0 | | 149 2 -> 3 : 0 | | 150 4 -> 7 : 0 | | 151 8 -> 15 : 0 | | 152 16 -> 31 : 0 | | 153 32 -> 63 : 0 | | 154 64 -> 127 : 0 | | 155 128 -> 255 : 0 | | 156 256 -> 511 : 2 | | 157 512 -> 1023 : 366 |********* | 158 1024 -> 2047 : 1525 |****************************************| 159 2048 -> 4095 : 629 |**************** | 160 4096 -> 8191 : 87 |** | 161 8192 -> 16383 : 1 | | 162 163softirq = run_rebalance_domains 164 usecs : count distribution 165 0 -> 1 : 0 | | 166 2 -> 3 : 0 | | 167 4 -> 7 : 0 | | 168 8 -> 15 : 0 | | 169 16 -> 31 : 0 | | 170 32 -> 63 : 0 | | 171 64 -> 127 : 0 | | 172 128 -> 255 : 0 | | 173 256 -> 511 : 3 | | 174 512 -> 1023 : 18 |* | 175 1024 -> 2047 : 80 |******** | 176 2048 -> 4095 : 374 |****************************************| 177 4096 -> 8191 : 257 |*************************** | 178 8192 -> 16383 : 50 |***** | 179 16384 -> 32767 : 24 |** | 180 181 182Sometimes you just want counts of events, and don't need the distribution 183of times. You can use the -C or --events option: 184 185# ./softirqs.py -C 186Tracing soft irq events... Hit Ctrl-C to end. 187^C 188SOFTIRQ TOTAL_count 189block 5 190tasklet 6 191net_rx 402 192sched 5251 193rcu 5748 194timer 9530 195 196 197USAGE message: 198 199# ./softirqs -h 200usage: softirqs [-h] [-T] [-N] [-C] [-d] [-c CPU] [interval] [count] 201 202Summarize soft irq event time as histograms. 203 204positional arguments: 205 interval output interval, in seconds 206 count number of outputs 207 208optional arguments: 209 -h, --help show this help message and exit 210 -T, --timestamp include timestamp on output 211 -N, --nanoseconds output in nanoseconds 212 -C, --events show the number of soft irq events 213 -d, --dist show distributions as histograms 214 -c CPU, --cpu CPU trace this CPU only 215 216examples: 217 ./softirqs # sum soft irq event time 218 ./softirqs -C # show the number of soft irq events 219 ./softirqs -d # show soft irq event time as histograms 220 ./softirqs 1 10 # print 1 second summaries, 10 times 221 ./softirqs -NT 1 # 1s summaries, nanoseconds, and timestamps 222 ./softirqs -c 1 # sum soft irq event time on CPU 1 only 223 224