History

perf: Add a script to show packets processing

Add a perf script which shows packets processing and processed time. It helps us to investigate networking or network devices. If you want to use it, install perf and record perf.data like following. If you set script, perf gathers records until it ends. If not, you must Ctrl-C to stop recording. And if you want a report from record, If you use some options, you can limit the output. Option is below. tx: show only tx packets processing rx: show only rx packets processing dev=: show processing on this device debug: work with debug mode. It shows buffer status. For example, if you want to show received packets processing associated with eth4, 106133.171439sec cpu=0 irq_entry(+0.000msec irq=24:eth4) | softirq_entry(+0.006msec) | |---netif_receive_skb(+0.010msec skb=f2d15900 len=100) | | | skb_copy_datagram_iovec(+0.039msec 10291::10291) | napi_poll_exit(+0.022msec eth4) This perf script helps us to analyze the processing time of a transmit/receive sequence.

Koki Sanagi committed 16 years ago

Commit 359d5101 parent 07dc22e3 files · +477 −0Browse files

Unified · Split

3 files
  1. tools/perf/scripts/python/bin/netdev-times-record +8 −0
  2. tools/perf/scripts/python/bin/netdev-times-report +5 −0
  3. tools/perf/scripts/python/netdev-times.py +464 −0
tools/perf/scripts/python/bin/netdev-times-record+8−0
@@ -0,0 +1,8 @@
1+#!/bin/bash
2+perf record -a -e net:net_dev_xmit -e net:net_dev_queue \
3+ -e net:netif_receive_skb -e net:netif_rx \
4+ -e skb:consume_skb -e skb:kfree_skb \
5+ -e skb:skb_copy_datagram_iovec -e napi:napi_poll \
6+ -e irq:irq_handler_entry -e irq:irq_handler_exit \
7+ -e irq:softirq_entry -e irq:softirq_exit \
8+ -e irq:softirq_raise $@
tools/perf/scripts/python/bin/netdev-times-report+5−0
@@ -0,0 +1,5 @@
1+#!/bin/bash
2+# description: display a process of packet and processing time
3+# args: [tx] [rx] [dev=] [debug]
4+
5+perf trace -s ~/libexec/perf-core/scripts/python/netdev-times.py $@
tools/perf/scripts/python/netdev-times.py+464−0
@@ -0,0 +1,464 @@
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
227+def irq__softirq_entry(name, context, cpu, sec, nsec, pid, comm, vec):
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+
233+def irq__softirq_exit(name, context, cpu, sec, nsec, pid, comm, vec):
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+
239+def irq__softirq_raise(name, context, cpu, sec, nsec, pid, comm, vec):
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,
246+ irq, irq_name):
247+ event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm,
248+ irq, irq_name)
249+ all_event_list.append(event_info)
250+
251+def irq__irq_handler_exit(name, context, cpu, sec, nsec, pid, comm, irq, ret):
252+ event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm, irq, ret)
253+ all_event_list.append(event_info)
254+
255+def napi__napi_poll(name, context, cpu, sec, nsec, pid, comm, napi, dev_name):
256+ event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm,
257+ napi, dev_name)
258+ all_event_list.append(event_info)
259+
260+def net__netif_receive_skb(name, context, cpu, sec, nsec, pid, comm, skbaddr,
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+
266+def net__netif_rx(name, context, cpu, sec, nsec, pid, comm, skbaddr,
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+
272+def net__net_dev_queue(name, context, cpu, sec, nsec, pid, comm,
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+
278+def net__net_dev_xmit(name, context, cpu, sec, nsec, pid, comm,
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+
284+def skb__kfree_skb(name, context, cpu, sec, nsec, pid, comm,
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+
290+def skb__consume_skb(name, context, cpu, sec, nsec, pid, comm, skbaddr):
291+ event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm,
292+ skbaddr)
293+ all_event_list.append(event_info)
294+
295+def skb__skb_copy_datagram_iovec(name, context, cpu, sec, nsec, pid, comm,
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