Brendan Gregg | 860b649 | 2015-10-20 15:52:23 -0700 | [diff] [blame] | 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 | |
Alexei Starovoitov | bdf0773 | 2016-01-14 10:09:20 -0800 | [diff] [blame] | 7 | # ./softirqs |
Brendan Gregg | 860b649 | 2015-10-20 15:52:23 -0700 | [diff] [blame] | 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 |
Alex Bagehot | 3b9679a | 2016-02-06 16:01:02 +0000 | [diff] [blame] | 63 | processing net_rx_action(), which was around 15 milliseconds per second (total |
Brendan Gregg | 860b649 | 2015-10-20 15:52:23 -0700 | [diff] [blame] | 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 |