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 182USAGE message: 183 184# ./softirqs -h 185usage: softirqs [-h] [-T] [-N] [-d] [interval] [count] 186 187Summarize soft irq event time as histograms 188 189positional arguments: 190 interval output interval, in seconds 191 count number of outputs 192 193optional arguments: 194 -h, --help show this help message and exit 195 -T, --timestamp include timestamp on output 196 -N, --nanoseconds output in nanoseconds 197 -d, --dist show distributions as histograms 198 199examples: 200 ./softirqs # sum soft irq event time 201 ./softirqs -d # show soft irq event time as histograms 202 ./softirqs 1 10 # print 1 second summaries, 10 times 203 ./softirqs -NT 1 # 1s summaries, nanoseconds, and timestamps 204