Commit | Line | Data |
---|---|---|
359d5106 KS |
1 | # Display a process of packets and processed time. |
2 | # It helps us to investigate networking or network device. | |
3 | # | |
4 | # options | |
5 | # tx: show only tx chart | |
6 | # rx: show only rx chart | |
7 | # dev=: show only thing related to specified device | |
8 | # debug: work with debug mode. It shows buffer status. | |
9 | ||
10 | import os | |
11 | import sys | |
12 | ||
13 | sys.path.append(os.environ['PERF_EXEC_PATH'] + \ | |
14 | '/scripts/python/Perf-Trace-Util/lib/Perf/Trace') | |
15 | ||
16 | from perf_trace_context import * | |
17 | from Core import * | |
18 | from Util import * | |
19 | ||
20 | all_event_list = []; # insert all tracepoint event related with this script | |
21 | irq_dic = {}; # key is cpu and value is a list which stacks irqs | |
22 | # which raise NET_RX softirq | |
23 | net_rx_dic = {}; # key is cpu and value include time of NET_RX softirq-entry | |
24 | # and a list which stacks receive | |
25 | receive_hunk_list = []; # a list which include a sequence of receive events | |
26 | rx_skb_list = []; # received packet list for matching | |
27 | # skb_copy_datagram_iovec | |
28 | ||
29 | buffer_budget = 65536; # the budget of rx_skb_list, tx_queue_list and | |
30 | # tx_xmit_list | |
31 | of_count_rx_skb_list = 0; # overflow count | |
32 | ||
33 | tx_queue_list = []; # list of packets which pass through dev_queue_xmit | |
34 | of_count_tx_queue_list = 0; # overflow count | |
35 | ||
36 | tx_xmit_list = []; # list of packets which pass through dev_hard_start_xmit | |
37 | of_count_tx_xmit_list = 0; # overflow count | |
38 | ||
39 | tx_free_list = []; # list of packets which is freed | |
40 | ||
41 | # options | |
42 | show_tx = 0; | |
43 | show_rx = 0; | |
44 | dev = 0; # store a name of device specified by option "dev=" | |
45 | debug = 0; | |
46 | ||
47 | # indices of event_info tuple | |
48 | EINFO_IDX_NAME= 0 | |
49 | EINFO_IDX_CONTEXT=1 | |
50 | EINFO_IDX_CPU= 2 | |
51 | EINFO_IDX_TIME= 3 | |
52 | EINFO_IDX_PID= 4 | |
53 | EINFO_IDX_COMM= 5 | |
54 | ||
55 | # Calculate a time interval(msec) from src(nsec) to dst(nsec) | |
56 | def diff_msec(src, dst): | |
57 | return (dst - src) / 1000000.0 | |
58 | ||
59 | # Display a process of transmitting a packet | |
60 | def print_transmit(hunk): | |
61 | if dev != 0 and hunk['dev'].find(dev) < 0: | |
62 | return | |
63 | print "%7s %5d %6d.%06dsec %12.3fmsec %12.3fmsec" % \ | |
64 | (hunk['dev'], hunk['len'], | |
65 | nsecs_secs(hunk['queue_t']), | |
66 | nsecs_nsecs(hunk['queue_t'])/1000, | |
67 | diff_msec(hunk['queue_t'], hunk['xmit_t']), | |
68 | diff_msec(hunk['xmit_t'], hunk['free_t'])) | |
69 | ||
70 | # Format for displaying rx packet processing | |
71 | PF_IRQ_ENTRY= " irq_entry(+%.3fmsec irq=%d:%s)" | |
72 | PF_SOFT_ENTRY=" softirq_entry(+%.3fmsec)" | |
73 | PF_NAPI_POLL= " napi_poll_exit(+%.3fmsec %s)" | |
74 | PF_JOINT= " |" | |
75 | PF_WJOINT= " | |" | |
76 | PF_NET_RECV= " |---netif_receive_skb(+%.3fmsec skb=%x len=%d)" | |
77 | PF_NET_RX= " |---netif_rx(+%.3fmsec skb=%x)" | |
78 | PF_CPY_DGRAM= " | skb_copy_datagram_iovec(+%.3fmsec %d:%s)" | |
79 | PF_KFREE_SKB= " | kfree_skb(+%.3fmsec location=%x)" | |
80 | PF_CONS_SKB= " | consume_skb(+%.3fmsec)" | |
81 | ||
82 | # Display a process of received packets and interrputs associated with | |
83 | # a NET_RX softirq | |
84 | def print_receive(hunk): | |
85 | show_hunk = 0 | |
86 | irq_list = hunk['irq_list'] | |
87 | cpu = irq_list[0]['cpu'] | |
88 | base_t = irq_list[0]['irq_ent_t'] | |
89 | # check if this hunk should be showed | |
90 | if dev != 0: | |
91 | for i in range(len(irq_list)): | |
92 | if irq_list[i]['name'].find(dev) >= 0: | |
93 | show_hunk = 1 | |
94 | break | |
95 | else: | |
96 | show_hunk = 1 | |
97 | if show_hunk == 0: | |
98 | return | |
99 | ||
100 | print "%d.%06dsec cpu=%d" % \ | |
101 | (nsecs_secs(base_t), nsecs_nsecs(base_t)/1000, cpu) | |
102 | for i in range(len(irq_list)): | |
103 | print PF_IRQ_ENTRY % \ | |
104 | (diff_msec(base_t, irq_list[i]['irq_ent_t']), | |
105 | irq_list[i]['irq'], irq_list[i]['name']) | |
106 | print PF_JOINT | |
107 | irq_event_list = irq_list[i]['event_list'] | |
108 | for j in range(len(irq_event_list)): | |
109 | irq_event = irq_event_list[j] | |
110 | if irq_event['event'] == 'netif_rx': | |
111 | print PF_NET_RX % \ | |
112 | (diff_msec(base_t, irq_event['time']), | |
113 | irq_event['skbaddr']) | |
114 | print PF_JOINT | |
115 | print PF_SOFT_ENTRY % \ | |
116 | diff_msec(base_t, hunk['sirq_ent_t']) | |
117 | print PF_JOINT | |
118 | event_list = hunk['event_list'] | |
119 | for i in range(len(event_list)): | |
120 | event = event_list[i] | |
121 | if event['event_name'] == 'napi_poll': | |
122 | print PF_NAPI_POLL % \ | |
123 | (diff_msec(base_t, event['event_t']), event['dev']) | |
124 | if i == len(event_list) - 1: | |
125 | print "" | |
126 | else: | |
127 | print PF_JOINT | |
128 | else: | |
129 | print PF_NET_RECV % \ | |
130 | (diff_msec(base_t, event['event_t']), event['skbaddr'], | |
131 | event['len']) | |
132 | if 'comm' in event.keys(): | |
133 | print PF_WJOINT | |
134 | print PF_CPY_DGRAM % \ | |
135 | (diff_msec(base_t, event['comm_t']), | |
136 | event['pid'], event['comm']) | |
137 | elif 'handle' in event.keys(): | |
138 | print PF_WJOINT | |
139 | if event['handle'] == "kfree_skb": | |
140 | print PF_KFREE_SKB % \ | |
141 | (diff_msec(base_t, | |
142 | event['comm_t']), | |
143 | event['location']) | |
144 | elif event['handle'] == "consume_skb": | |
145 | print PF_CONS_SKB % \ | |
146 | diff_msec(base_t, | |
147 | event['comm_t']) | |
148 | print PF_JOINT | |
149 | ||
150 | def trace_begin(): | |
151 | global show_tx | |
152 | global show_rx | |
153 | global dev | |
154 | global debug | |
155 | ||
156 | for i in range(len(sys.argv)): | |
157 | if i == 0: | |
158 | continue | |
159 | arg = sys.argv[i] | |
160 | if arg == 'tx': | |
161 | show_tx = 1 | |
162 | elif arg =='rx': | |
163 | show_rx = 1 | |
164 | elif arg.find('dev=',0, 4) >= 0: | |
165 | dev = arg[4:] | |
166 | elif arg == 'debug': | |
167 | debug = 1 | |
168 | if show_tx == 0 and show_rx == 0: | |
169 | show_tx = 1 | |
170 | show_rx = 1 | |
171 | ||
172 | def trace_end(): | |
173 | # order all events in time | |
174 | all_event_list.sort(lambda a,b :cmp(a[EINFO_IDX_TIME], | |
175 | b[EINFO_IDX_TIME])) | |
176 | # process all events | |
177 | for i in range(len(all_event_list)): | |
178 | event_info = all_event_list[i] | |
179 | name = event_info[EINFO_IDX_NAME] | |
180 | if name == 'irq__softirq_exit': | |
181 | handle_irq_softirq_exit(event_info) | |
182 | elif name == 'irq__softirq_entry': | |
183 | handle_irq_softirq_entry(event_info) | |
184 | elif name == 'irq__softirq_raise': | |
185 | handle_irq_softirq_raise(event_info) | |
186 | elif name == 'irq__irq_handler_entry': | |
187 | handle_irq_handler_entry(event_info) | |
188 | elif name == 'irq__irq_handler_exit': | |
189 | handle_irq_handler_exit(event_info) | |
190 | elif name == 'napi__napi_poll': | |
191 | handle_napi_poll(event_info) | |
192 | elif name == 'net__netif_receive_skb': | |
193 | handle_netif_receive_skb(event_info) | |
194 | elif name == 'net__netif_rx': | |
195 | handle_netif_rx(event_info) | |
196 | elif name == 'skb__skb_copy_datagram_iovec': | |
197 | handle_skb_copy_datagram_iovec(event_info) | |
198 | elif name == 'net__net_dev_queue': | |
199 | handle_net_dev_queue(event_info) | |
200 | elif name == 'net__net_dev_xmit': | |
201 | handle_net_dev_xmit(event_info) | |
202 | elif name == 'skb__kfree_skb': | |
203 | handle_kfree_skb(event_info) | |
204 | elif name == 'skb__consume_skb': | |
205 | handle_consume_skb(event_info) | |
206 | # display receive hunks | |
207 | if show_rx: | |
208 | for i in range(len(receive_hunk_list)): | |
209 | print_receive(receive_hunk_list[i]) | |
210 | # display transmit hunks | |
211 | if show_tx: | |
212 | print " dev len Qdisc " \ | |
213 | " netdevice free" | |
214 | for i in range(len(tx_free_list)): | |
215 | print_transmit(tx_free_list[i]) | |
216 | if debug: | |
217 | print "debug buffer status" | |
218 | print "----------------------------" | |
219 | print "xmit Qdisc:remain:%d overflow:%d" % \ | |
220 | (len(tx_queue_list), of_count_tx_queue_list) | |
221 | print "xmit netdevice:remain:%d overflow:%d" % \ | |
222 | (len(tx_xmit_list), of_count_tx_xmit_list) | |
223 | print "receive:remain:%d overflow:%d" % \ | |
224 | (len(rx_skb_list), of_count_rx_skb_list) | |
225 | ||
226 | # called from perf, when it finds a correspoinding event | |
0f5f5bcd | 227 | def irq__softirq_entry(name, context, cpu, sec, nsec, pid, comm, callchain, vec): |
359d5106 KS |
228 | if symbol_str("irq__softirq_entry", "vec", vec) != "NET_RX": |
229 | return | |
230 | event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm, vec) | |
231 | all_event_list.append(event_info) | |
232 | ||
0f5f5bcd | 233 | def irq__softirq_exit(name, context, cpu, sec, nsec, pid, comm, callchain, vec): |
359d5106 KS |
234 | if symbol_str("irq__softirq_entry", "vec", vec) != "NET_RX": |
235 | return | |
236 | event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm, vec) | |
237 | all_event_list.append(event_info) | |
238 | ||
0f5f5bcd | 239 | def irq__softirq_raise(name, context, cpu, sec, nsec, pid, comm, callchain, vec): |
359d5106 KS |
240 | if symbol_str("irq__softirq_entry", "vec", vec) != "NET_RX": |
241 | return | |
242 | event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm, vec) | |
243 | all_event_list.append(event_info) | |
244 | ||
245 | def irq__irq_handler_entry(name, context, cpu, sec, nsec, pid, comm, | |
0f5f5bcd | 246 | callchain, irq, irq_name): |
359d5106 KS |
247 | event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm, |
248 | irq, irq_name) | |
249 | all_event_list.append(event_info) | |
250 | ||
0f5f5bcd | 251 | def irq__irq_handler_exit(name, context, cpu, sec, nsec, pid, comm, callchain, irq, ret): |
359d5106 KS |
252 | event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm, irq, ret) |
253 | all_event_list.append(event_info) | |
254 | ||
0f5f5bcd | 255 | def napi__napi_poll(name, context, cpu, sec, nsec, pid, comm, callchain, napi, dev_name): |
359d5106 KS |
256 | event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm, |
257 | napi, dev_name) | |
258 | all_event_list.append(event_info) | |
259 | ||
0f5f5bcd | 260 | def net__netif_receive_skb(name, context, cpu, sec, nsec, pid, comm, callchain, skbaddr, |
359d5106 KS |
261 | skblen, dev_name): |
262 | event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm, | |
263 | skbaddr, skblen, dev_name) | |
264 | all_event_list.append(event_info) | |
265 | ||
0f5f5bcd | 266 | def net__netif_rx(name, context, cpu, sec, nsec, pid, comm, callchain, skbaddr, |
359d5106 KS |
267 | skblen, dev_name): |
268 | event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm, | |
269 | skbaddr, skblen, dev_name) | |
270 | all_event_list.append(event_info) | |
271 | ||
0f5f5bcd | 272 | def net__net_dev_queue(name, context, cpu, sec, nsec, pid, comm, callchain, |
359d5106 KS |
273 | skbaddr, skblen, dev_name): |
274 | event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm, | |
275 | skbaddr, skblen, dev_name) | |
276 | all_event_list.append(event_info) | |
277 | ||
0f5f5bcd | 278 | def net__net_dev_xmit(name, context, cpu, sec, nsec, pid, comm, callchain, |
359d5106 KS |
279 | skbaddr, skblen, rc, dev_name): |
280 | event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm, | |
281 | skbaddr, skblen, rc ,dev_name) | |
282 | all_event_list.append(event_info) | |
283 | ||
0f5f5bcd | 284 | def skb__kfree_skb(name, context, cpu, sec, nsec, pid, comm, callchain, |
359d5106 KS |
285 | skbaddr, protocol, location): |
286 | event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm, | |
287 | skbaddr, protocol, location) | |
288 | all_event_list.append(event_info) | |
289 | ||
0f5f5bcd | 290 | def skb__consume_skb(name, context, cpu, sec, nsec, pid, comm, callchain, skbaddr): |
359d5106 KS |
291 | event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm, |
292 | skbaddr) | |
293 | all_event_list.append(event_info) | |
294 | ||
0f5f5bcd | 295 | def skb__skb_copy_datagram_iovec(name, context, cpu, sec, nsec, pid, comm, callchain, |
359d5106 KS |
296 | skbaddr, skblen): |
297 | event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm, | |
298 | skbaddr, skblen) | |
299 | all_event_list.append(event_info) | |
300 | ||
301 | def handle_irq_handler_entry(event_info): | |
302 | (name, context, cpu, time, pid, comm, irq, irq_name) = event_info | |
303 | if cpu not in irq_dic.keys(): | |
304 | irq_dic[cpu] = [] | |
305 | irq_record = {'irq':irq, 'name':irq_name, 'cpu':cpu, 'irq_ent_t':time} | |
306 | irq_dic[cpu].append(irq_record) | |
307 | ||
308 | def handle_irq_handler_exit(event_info): | |
309 | (name, context, cpu, time, pid, comm, irq, ret) = event_info | |
310 | if cpu not in irq_dic.keys(): | |
311 | return | |
312 | irq_record = irq_dic[cpu].pop() | |
313 | if irq != irq_record['irq']: | |
314 | return | |
315 | irq_record.update({'irq_ext_t':time}) | |
316 | # if an irq doesn't include NET_RX softirq, drop. | |
317 | if 'event_list' in irq_record.keys(): | |
318 | irq_dic[cpu].append(irq_record) | |
319 | ||
320 | def handle_irq_softirq_raise(event_info): | |
321 | (name, context, cpu, time, pid, comm, vec) = event_info | |
322 | if cpu not in irq_dic.keys() \ | |
323 | or len(irq_dic[cpu]) == 0: | |
324 | return | |
325 | irq_record = irq_dic[cpu].pop() | |
326 | if 'event_list' in irq_record.keys(): | |
327 | irq_event_list = irq_record['event_list'] | |
328 | else: | |
329 | irq_event_list = [] | |
330 | irq_event_list.append({'time':time, 'event':'sirq_raise'}) | |
331 | irq_record.update({'event_list':irq_event_list}) | |
332 | irq_dic[cpu].append(irq_record) | |
333 | ||
334 | def handle_irq_softirq_entry(event_info): | |
335 | (name, context, cpu, time, pid, comm, vec) = event_info | |
336 | net_rx_dic[cpu] = {'sirq_ent_t':time, 'event_list':[]} | |
337 | ||
338 | def handle_irq_softirq_exit(event_info): | |
339 | (name, context, cpu, time, pid, comm, vec) = event_info | |
340 | irq_list = [] | |
341 | event_list = 0 | |
342 | if cpu in irq_dic.keys(): | |
343 | irq_list = irq_dic[cpu] | |
344 | del irq_dic[cpu] | |
345 | if cpu in net_rx_dic.keys(): | |
346 | sirq_ent_t = net_rx_dic[cpu]['sirq_ent_t'] | |
347 | event_list = net_rx_dic[cpu]['event_list'] | |
348 | del net_rx_dic[cpu] | |
349 | if irq_list == [] or event_list == 0: | |
350 | return | |
351 | rec_data = {'sirq_ent_t':sirq_ent_t, 'sirq_ext_t':time, | |
352 | 'irq_list':irq_list, 'event_list':event_list} | |
353 | # merge information realted to a NET_RX softirq | |
354 | receive_hunk_list.append(rec_data) | |
355 | ||
356 | def handle_napi_poll(event_info): | |
357 | (name, context, cpu, time, pid, comm, napi, dev_name) = event_info | |
358 | if cpu in net_rx_dic.keys(): | |
359 | event_list = net_rx_dic[cpu]['event_list'] | |
360 | rec_data = {'event_name':'napi_poll', | |
361 | 'dev':dev_name, 'event_t':time} | |
362 | event_list.append(rec_data) | |
363 | ||
364 | def handle_netif_rx(event_info): | |
365 | (name, context, cpu, time, pid, comm, | |
366 | skbaddr, skblen, dev_name) = event_info | |
367 | if cpu not in irq_dic.keys() \ | |
368 | or len(irq_dic[cpu]) == 0: | |
369 | return | |
370 | irq_record = irq_dic[cpu].pop() | |
371 | if 'event_list' in irq_record.keys(): | |
372 | irq_event_list = irq_record['event_list'] | |
373 | else: | |
374 | irq_event_list = [] | |
375 | irq_event_list.append({'time':time, 'event':'netif_rx', | |
376 | 'skbaddr':skbaddr, 'skblen':skblen, 'dev_name':dev_name}) | |
377 | irq_record.update({'event_list':irq_event_list}) | |
378 | irq_dic[cpu].append(irq_record) | |
379 | ||
380 | def handle_netif_receive_skb(event_info): | |
381 | global of_count_rx_skb_list | |
382 | ||
383 | (name, context, cpu, time, pid, comm, | |
384 | skbaddr, skblen, dev_name) = event_info | |
385 | if cpu in net_rx_dic.keys(): | |
386 | rec_data = {'event_name':'netif_receive_skb', | |
387 | 'event_t':time, 'skbaddr':skbaddr, 'len':skblen} | |
388 | event_list = net_rx_dic[cpu]['event_list'] | |
389 | event_list.append(rec_data) | |
390 | rx_skb_list.insert(0, rec_data) | |
391 | if len(rx_skb_list) > buffer_budget: | |
392 | rx_skb_list.pop() | |
393 | of_count_rx_skb_list += 1 | |
394 | ||
395 | def handle_net_dev_queue(event_info): | |
396 | global of_count_tx_queue_list | |
397 | ||
398 | (name, context, cpu, time, pid, comm, | |
399 | skbaddr, skblen, dev_name) = event_info | |
400 | skb = {'dev':dev_name, 'skbaddr':skbaddr, 'len':skblen, 'queue_t':time} | |
401 | tx_queue_list.insert(0, skb) | |
402 | if len(tx_queue_list) > buffer_budget: | |
403 | tx_queue_list.pop() | |
404 | of_count_tx_queue_list += 1 | |
405 | ||
406 | def handle_net_dev_xmit(event_info): | |
407 | global of_count_tx_xmit_list | |
408 | ||
409 | (name, context, cpu, time, pid, comm, | |
410 | skbaddr, skblen, rc, dev_name) = event_info | |
411 | if rc == 0: # NETDEV_TX_OK | |
412 | for i in range(len(tx_queue_list)): | |
413 | skb = tx_queue_list[i] | |
414 | if skb['skbaddr'] == skbaddr: | |
415 | skb['xmit_t'] = time | |
416 | tx_xmit_list.insert(0, skb) | |
417 | del tx_queue_list[i] | |
418 | if len(tx_xmit_list) > buffer_budget: | |
419 | tx_xmit_list.pop() | |
420 | of_count_tx_xmit_list += 1 | |
421 | return | |
422 | ||
423 | def handle_kfree_skb(event_info): | |
424 | (name, context, cpu, time, pid, comm, | |
425 | skbaddr, protocol, location) = event_info | |
426 | for i in range(len(tx_queue_list)): | |
427 | skb = tx_queue_list[i] | |
428 | if skb['skbaddr'] == skbaddr: | |
429 | del tx_queue_list[i] | |
430 | return | |
431 | for i in range(len(tx_xmit_list)): | |
432 | skb = tx_xmit_list[i] | |
433 | if skb['skbaddr'] == skbaddr: | |
434 | skb['free_t'] = time | |
435 | tx_free_list.append(skb) | |
436 | del tx_xmit_list[i] | |
437 | return | |
438 | for i in range(len(rx_skb_list)): | |
439 | rec_data = rx_skb_list[i] | |
440 | if rec_data['skbaddr'] == skbaddr: | |
441 | rec_data.update({'handle':"kfree_skb", | |
442 | 'comm':comm, 'pid':pid, 'comm_t':time}) | |
443 | del rx_skb_list[i] | |
444 | return | |
445 | ||
446 | def handle_consume_skb(event_info): | |
447 | (name, context, cpu, time, pid, comm, skbaddr) = event_info | |
448 | for i in range(len(tx_xmit_list)): | |
449 | skb = tx_xmit_list[i] | |
450 | if skb['skbaddr'] == skbaddr: | |
451 | skb['free_t'] = time | |
452 | tx_free_list.append(skb) | |
453 | del tx_xmit_list[i] | |
454 | return | |
455 | ||
456 | def handle_skb_copy_datagram_iovec(event_info): | |
457 | (name, context, cpu, time, pid, comm, skbaddr, skblen) = event_info | |
458 | for i in range(len(rx_skb_list)): | |
459 | rec_data = rx_skb_list[i] | |
460 | if skbaddr == rec_data['skbaddr']: | |
461 | rec_data.update({'handle':"skb_copy_datagram_iovec", | |
462 | 'comm':comm, 'pid':pid, 'comm_t':time}) | |
463 | del rx_skb_list[i] | |
464 | return |