1 Demonstrations of softirqs, the Linux eBPF/bcc version. 2 3 4 This program traces soft interrupts (irqs), and stores timing statistics 5 in-kernel for efficiency. For example: 6 7 # ./softirqs 8 Tracing soft irq event time... Hit Ctrl-C to end. 9 ^C 10 SOFTIRQ TOTAL_usecs 11 rcu_process_callbacks 974 12 run_rebalance_domains 1809 13 run_timer_softirq 2615 14 net_tx_action 14605 15 tasklet_action 38692 16 net_rx_action 88188 17 18 The SOFTIRQ column prints the interrupt action function name. While tracing, 19 the net_rx_action() soft interrupt ran for 20199 microseconds (20 milliseconds) 20 in total. 21 22 This tool works by dynamic tracing the individual softirq functions, and will 23 need to be adjusted to match kernel/module changes. Future versions should 24 use the softirq tracepoints instead. 25 26 27 An interval can be provided, and also optionally a count. Eg, printing output 28 every 1 second, and including timestamps (-T): 29 30 # ./softirqs -T 1 3 31 Tracing soft irq event time... Hit Ctrl-C to end. 32 33 22:29:16 34 SOFTIRQ TOTAL_usecs 35 rcu_process_callbacks 456 36 run_rebalance_domains 1005 37 run_timer_softirq 1196 38 net_tx_action 2796 39 tasklet_action 5534 40 net_rx_action 15075 41 42 22:29:17 43 SOFTIRQ TOTAL_usecs 44 rcu_process_callbacks 456 45 run_rebalance_domains 839 46 run_timer_softirq 1142 47 net_tx_action 1912 48 tasklet_action 4428 49 net_rx_action 14652 50 51 22:29:18 52 SOFTIRQ TOTAL_usecs 53 rcu_process_callbacks 502 54 run_rebalance_domains 840 55 run_timer_softirq 1192 56 net_tx_action 2341 57 tasklet_action 5496 58 net_rx_action 15656 59 60 This can be useful for quantifying where CPU cycles are spent among the soft 61 interrupts (summarized as the %softirq column from mpstat(1), and shown as 62 event counts in /proc/softirqs). The output above shows that most time was spent 63 processing net_rx_action(), which was around 15 milliseconds per second (total 64 time across all CPUs). 65 66 67 The distribution of interrupt run time can be printed as a histogram with the -d 68 option. Eg: 69 70 # ./softirqs -d 71 Tracing soft irq event time... Hit Ctrl-C to end. 72 ^C 73 74 softirq = 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 91 softirq = 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 111 softirq = 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 129 softirq = 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 146 softirq = 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 163 softirq = 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 182 USAGE message: 183 184 # ./softirqs -h 185 usage: softirqs [-h] [-T] [-N] [-d] [interval] [count] 186 187 Summarize soft irq event time as histograms 188 189 positional arguments: 190 interval output interval, in seconds 191 count number of outputs 192 193 optional 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 199 examples: 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
