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