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
10import os
11import sys
12
13sys.path.append(os.environ['PERF_EXEC_PATH'] + \
14	'/scripts/python/Perf-Trace-Util/lib/Perf/Trace')
15
16from perf_trace_context import *
17from Core import *
18from Util import *
19
20all_event_list = []; # insert all tracepoint event related with this script
21irq_dic = {}; # key is cpu and value is a list which stacks irqs
22              # which raise NET_RX softirq
23net_rx_dic = {}; # key is cpu and value include time of NET_RX softirq-entry
24		 # and a list which stacks receive
25receive_hunk_list = []; # a list which include a sequence of receive events
26rx_skb_list = []; # received packet list for matching
27		       # skb_copy_datagram_iovec
28
29buffer_budget = 65536; # the budget of rx_skb_list, tx_queue_list and
30		       # tx_xmit_list
31of_count_rx_skb_list = 0; # overflow count
32
33tx_queue_list = []; # list of packets which pass through dev_queue_xmit
34of_count_tx_queue_list = 0; # overflow count
35
36tx_xmit_list = [];  # list of packets which pass through dev_hard_start_xmit
37of_count_tx_xmit_list = 0; # overflow count
38
39tx_free_list = [];  # list of packets which is freed
40
41# options
42show_tx = 0;
43show_rx = 0;
44dev = 0; # store a name of device specified by option "dev="
45debug = 0;
46
47# indices of event_info tuple
48EINFO_IDX_NAME=   0
49EINFO_IDX_CONTEXT=1
50EINFO_IDX_CPU=    2
51EINFO_IDX_TIME=   3
52EINFO_IDX_PID=    4
53EINFO_IDX_COMM=   5
54
55# Calculate a time interval(msec) from src(nsec) to dst(nsec)
56def diff_msec(src, dst):
57	return (dst - src) / 1000000.0
58
59# Display a process of transmitting a packet
60def 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
71PF_IRQ_ENTRY= "  irq_entry(+%.3fmsec irq=%d:%s)"
72PF_SOFT_ENTRY="  softirq_entry(+%.3fmsec)"
73PF_NAPI_POLL= "  napi_poll_exit(+%.3fmsec %s)"
74PF_JOINT=     "         |"
75PF_WJOINT=    "         |            |"
76PF_NET_RECV=  "         |---netif_receive_skb(+%.3fmsec skb=%x len=%d)"
77PF_NET_RX=    "         |---netif_rx(+%.3fmsec skb=%x)"
78PF_CPY_DGRAM= "         |      skb_copy_datagram_iovec(+%.3fmsec %d:%s)"
79PF_KFREE_SKB= "         |      kfree_skb(+%.3fmsec location=%x)"
80PF_CONS_SKB=  "         |      consume_skb(+%.3fmsec)"
81
82# Display a process of received packets and interrputs associated with
83# a NET_RX softirq
84def 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
150def 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
172def 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
227def irq__softirq_entry(name, context, cpu, sec, nsec, pid, comm, callchain, 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
233def irq__softirq_exit(name, context, cpu, sec, nsec, pid, comm, callchain, 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
239def irq__softirq_raise(name, context, cpu, sec, nsec, pid, comm, callchain, 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
245def irq__irq_handler_entry(name, context, cpu, sec, nsec, pid, comm,
246			callchain, 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
251def irq__irq_handler_exit(name, context, cpu, sec, nsec, pid, comm, callchain, irq, ret):
252	event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm, irq, ret)
253	all_event_list.append(event_info)
254
255def napi__napi_poll(name, context, cpu, sec, nsec, pid, comm, callchain, 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
260def net__netif_receive_skb(name, context, cpu, sec, nsec, pid, comm, callchain, 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
266def net__netif_rx(name, context, cpu, sec, nsec, pid, comm, callchain, 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
272def net__net_dev_queue(name, context, cpu, sec, nsec, pid, comm, callchain,
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
278def net__net_dev_xmit(name, context, cpu, sec, nsec, pid, comm, callchain,
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
284def skb__kfree_skb(name, context, cpu, sec, nsec, pid, comm, callchain,
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
290def skb__consume_skb(name, context, cpu, sec, nsec, pid, comm, callchain, skbaddr):
291	event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm,
292			skbaddr)
293	all_event_list.append(event_info)
294
295def skb__skb_copy_datagram_iovec(name, context, cpu, sec, nsec, pid, comm, callchain,
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
301def 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
308def 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
320def 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
334def 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
338def 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
356def 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
364def 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
380def 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
395def 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
406def 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
423def 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
446def 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
456def 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
465