Gitiles
Code Review Sign In
gerrit-public.fairphone.software / platform / external / bcc / refs/heads/odm/dev/qssi/13/fp5 / . / tools / softirqs_example.txt
blob: a9141431d255c21f7b44d667dccf57cf4b94d702 [file] [log] [blame]
Brendan Gregg860b6492015-10-20 15:52:23 -0700[diff] [blame]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
Alexei Starovoitovbdf07732016-01-14 10:09:20 -0800[diff] [blame]7# ./softirqs
Brendan Gregg860b6492015-10-20 15:52:23 -0700[diff] [blame]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
Alex Bagehot3b9679a2016-02-06 16:01:02 +0000[diff] [blame]63processing net_rx_action(), which was around 15 milliseconds per second (total
Brendan Gregg860b6492015-10-20 15:52:23 -0700[diff] [blame]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
xingfeng251015ed9972022-03-24 21:10:28 +0800[diff] [blame]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
Brendan Gregg860b6492015-10-20 15:52:23 -0700[diff] [blame]197USAGE message:
198
199# ./softirqs -h
xingfeng251015ed9972022-03-24 21:10:28 +0800[diff] [blame]200usage: softirqs [-h] [-T] [-N] [-C] [-d] [-c CPU] [interval] [count]
Brendan Gregg860b6492015-10-20 15:52:23 -0700[diff] [blame]201
xingfeng251015ed9972022-03-24 21:10:28 +0800[diff] [blame]202Summarize soft irq event time as histograms.
Brendan Gregg860b6492015-10-20 15:52:23 -0700[diff] [blame]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
xingfeng251015ed9972022-03-24 21:10:28 +0800[diff] [blame]212 -C, --events show the number of soft irq events
Brendan Gregg860b6492015-10-20 15:52:23 -0700[diff] [blame]213 -d, --dist show distributions as histograms
xingfeng251015ed9972022-03-24 21:10:28 +0800[diff] [blame]214 -c CPU, --cpu CPU trace this CPU only
Brendan Gregg860b6492015-10-20 15:52:23 -0700[diff] [blame]215
216examples:
217 ./softirqs # sum soft irq event time
xingfeng251015ed9972022-03-24 21:10:28 +0800[diff] [blame]218 ./softirqs -C # show the number of soft irq events
Brendan Gregg860b6492015-10-20 15:52:23 -0700[diff] [blame]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
xingfeng251015ed9972022-03-24 21:10:28 +0800[diff] [blame]222 ./softirqs -c 1 # sum soft irq event time on CPU 1 only
223