summaryrefslogtreecommitdiffstats
path: root/tools/perf/scripts/python/netdev-times.py
blob: 9b2050f778f10e67a825ac5a334722c0e984a57b (plain)
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
378
379
380
381
382
383
384
385
386
387
388
389
390
391
392
393
394
395
396
397
398
399
400
401
402
403
404
405
406
407
408
409
410
411
412
413
414
415
416
417
418
419
420
421
422
423
424
425
426
427
428
429
430
431
432
433
434
435
436
437
438
439
440
441
442
443
444
445
446
447
448
449
450
451
452
453
454
455
456
457
458
459
460
461
462
463
464
465
466
467
468
# Display a process of packets and processed time.
# SPDX-License-Identifier: GPL-2.0
# It helps us to investigate networking or network device.
#
# options
# tx: show only tx chart
# rx: show only rx chart
# dev=: show only thing related to specified device
# debug: work with debug mode. It shows buffer status.

import os
import sys

sys.path.append(os.environ['PERF_EXEC_PATH'] + \
	'/scripts/python/Perf-Trace-Util/lib/Perf/Trace')

from perf_trace_context import *
from Core import *
from Util import *

all_event_list = []; # insert all tracepoint event related with this script
irq_dic = {}; # key is cpu and value is a list which stacks irqs
              # which raise NET_RX softirq
net_rx_dic = {}; # key is cpu and value include time of NET_RX softirq-entry
		 # and a list which stacks receive
receive_hunk_list = []; # a list which include a sequence of receive events
rx_skb_list = []; # received packet list for matching
		       # skb_copy_datagram_iovec

buffer_budget = 65536; # the budget of rx_skb_list, tx_queue_list and
		       # tx_xmit_list
of_count_rx_skb_list = 0; # overflow count

tx_queue_list = []; # list of packets which pass through dev_queue_xmit
of_count_tx_queue_list = 0; # overflow count

tx_xmit_list = [];  # list of packets which pass through dev_hard_start_xmit
of_count_tx_xmit_list = 0; # overflow count

tx_free_list = [];  # list of packets which is freed

# options
show_tx = 0;
show_rx = 0;
dev = 0; # store a name of device specified by option "dev="
debug = 0;

# indices of event_info tuple
EINFO_IDX_NAME=   0
EINFO_IDX_CONTEXT=1
EINFO_IDX_CPU=    2
EINFO_IDX_TIME=   3
EINFO_IDX_PID=    4
EINFO_IDX_COMM=   5

# Calculate a time interval(msec) from src(nsec) to dst(nsec)
def diff_msec(src, dst):
	return (dst - src) / 1000000.0

# Display a process of transmitting a packet
def print_transmit(hunk):
	if dev != 0 and hunk['dev'].find(dev) < 0:
		return
	print "%7s %5d %6d.%06dsec %12.3fmsec      %12.3fmsec" % \
		(hunk['dev'], hunk['len'],
		nsecs_secs(hunk['queue_t']),
		nsecs_nsecs(hunk['queue_t'])/1000,
		diff_msec(hunk['queue_t'], hunk['xmit_t']),
		diff_msec(hunk['xmit_t'], hunk['free_t']))

# Format for displaying rx packet processing
PF_IRQ_ENTRY= "  irq_entry(+%.3fmsec irq=%d:%s)"
PF_SOFT_ENTRY="  softirq_entry(+%.3fmsec)"
PF_NAPI_POLL= "  napi_poll_exit(+%.3fmsec %s)"
PF_JOINT=     "         |"
PF_WJOINT=    "         |            |"
PF_NET_RECV=  "         |---netif_receive_skb(+%.3fmsec skb=%x len=%d)"
PF_NET_RX=    "         |---netif_rx(+%.3fmsec skb=%x)"
PF_CPY_DGRAM= "         |      skb_copy_datagram_iovec(+%.3fmsec %d:%s)"
PF_KFREE_SKB= "         |      kfree_skb(+%.3fmsec location=%x)"
PF_CONS_SKB=  "         |      consume_skb(+%.3fmsec)"

# Display a process of received packets and interrputs associated with
# a NET_RX softirq
def print_receive(hunk):
	show_hunk = 0
	irq_list = hunk['irq_list']
	cpu = irq_list[0]['cpu']
	base_t = irq_list[0]['irq_ent_t']
	# check if this hunk should be showed
	if dev != 0:
		for i in range(len(irq_list)):
			if irq_list[i]['name'].find(dev) >= 0:
				show_hunk = 1
				break
	else:
		show_hunk = 1
	if show_hunk == 0:
		return

	print "%d.%06dsec cpu=%d" % \
		(nsecs_secs(base_t), nsecs_nsecs(base_t)/1000, cpu)
	for i in range(len(irq_list)):
		print PF_IRQ_ENTRY % \
			(diff_msec(base_t, irq_list[i]['irq_ent_t']),
			irq_list[i]['irq'], irq_list[i]['name'])
		print PF_JOINT
		irq_event_list = irq_list[i]['event_list']
		for j in range(len(irq_event_list)):
			irq_event = irq_event_list[j]
			if irq_event['event'] == 'netif_rx':
				print PF_NET_RX % \
					(diff_msec(base_t, irq_event['time']),
					irq_event['skbaddr'])
				print PF_JOINT
	print PF_SOFT_ENTRY % \
		diff_msec(base_t, hunk['sirq_ent_t'])
	print PF_JOINT
	event_list = hunk['event_list']
	for i in range(len(event_list)):
		event = event_list[i]
		if event['event_name'] == 'napi_poll':
			print PF_NAPI_POLL % \
			    (diff_msec(base_t, event['event_t']), event['dev'])
			if i == len(event_list) - 1:
				print ""
			else:
				print PF_JOINT
		else:
			print PF_NET_RECV % \
			    (diff_msec(base_t, event['event_t']), event['skbaddr'],
				event['len'])
			if 'comm' in event.keys():
				print PF_WJOINT
				print PF_CPY_DGRAM % \
					(diff_msec(base_t, event['comm_t']),
					event['pid'], event['comm'])
			elif 'handle' in event.keys():
				print PF_WJOINT
				if event['handle'] == "kfree_skb":
					print PF_KFREE_SKB % \
						(diff_msec(base_t,
						event['comm_t']),
						event['location'])
				elif event['handle'] == "consume_skb":
					print PF_CONS_SKB % \
						diff_msec(base_t,
							event['comm_t'])
			print PF_JOINT

def trace_begin():
	global show_tx
	global show_rx
	global dev
	global debug

	for i in range(len(sys.argv)):
		if i == 0:
			continue
		arg = sys.argv[i]
		if arg == 'tx':
			show_tx = 1
		elif arg =='rx':
			show_rx = 1
		elif arg.find('dev=',0, 4) >= 0:
			dev = arg[4:]
		elif arg == 'debug':
			debug = 1
	if show_tx == 0  and show_rx == 0:
		show_tx = 1
		show_rx = 1

def trace_end():
	# order all events in time
	all_event_list.sort(lambda a,b :cmp(a[EINFO_IDX_TIME],
					    b[EINFO_IDX_TIME]))
	# process all events
	for i in range(len(all_event_list)):
		event_info = all_event_list[i]
		name = event_info[EINFO_IDX_NAME]
		if name == 'irq__softirq_exit':
			handle_irq_softirq_exit(event_info)
		elif name == 'irq__softirq_entry':
			handle_irq_softirq_entry(event_info)
		elif name == 'irq__softirq_raise':
			handle_irq_softirq_raise(event_info)
		elif name == 'irq__irq_handler_entry':
			handle_irq_handler_entry(event_info)
		elif name == 'irq__irq_handler_exit':
			handle_irq_handler_exit(event_info)
		elif name == 'napi__napi_poll':
			handle_napi_poll(event_info)
		elif name == 'net__netif_receive_skb':
			handle_netif_receive_skb(event_info)
		elif name == 'net__netif_rx':
			handle_netif_rx(event_info)
		elif name == 'skb__skb_copy_datagram_iovec':
			handle_skb_copy_datagram_iovec(event_info)
		elif name == 'net__net_dev_queue':
			handle_net_dev_queue(event_info)
		elif name == 'net__net_dev_xmit':
			handle_net_dev_xmit(event_info)
		elif name == 'skb__kfree_skb':
			handle_kfree_skb(event_info)
		elif name == 'skb__consume_skb':
			handle_consume_skb(event_info)
	# display receive hunks
	if show_rx:
		for i in range(len(receive_hunk_list)):
			print_receive(receive_hunk_list[i])
	# display transmit hunks
	if show_tx:
		print "   dev    len      Qdisc        " \
			"       netdevice             free"
		for i in range(len(tx_free_list)):
			print_transmit(tx_free_list[i])
	if debug:
		print "debug buffer status"
		print "----------------------------"
		print "xmit Qdisc:remain:%d overflow:%d" % \
			(len(tx_queue_list), of_count_tx_queue_list)
		print "xmit netdevice:remain:%d overflow:%d" % \
			(len(tx_xmit_list), of_count_tx_xmit_list)
		print "receive:remain:%d overflow:%d" % \
			(len(rx_skb_list), of_count_rx_skb_list)

# called from perf, when it finds a correspoinding event
def irq__softirq_entry(name, context, cpu, sec, nsec, pid, comm, callchain, vec):
	if symbol_str("irq__softirq_entry", "vec", vec) != "NET_RX":
		return
	event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm, vec)
	all_event_list.append(event_info)

def irq__softirq_exit(name, context, cpu, sec, nsec, pid, comm, callchain, vec):
	if symbol_str("irq__softirq_entry", "vec", vec) != "NET_RX":
		return
	event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm, vec)
	all_event_list.append(event_info)

def irq__softirq_raise(name, context, cpu, sec, nsec, pid, comm, callchain, vec):
	if symbol_str("irq__softirq_entry", "vec", vec) != "NET_RX":
		return
	event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm, vec)
	all_event_list.append(event_info)

def irq__irq_handler_entry(name, context, cpu, sec, nsec, pid, comm,
			callchain, irq, irq_name):
	event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm,
			irq, irq_name)
	all_event_list.append(event_info)

def irq__irq_handler_exit(name, context, cpu, sec, nsec, pid, comm, callchain, irq, ret):
	event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm, irq, ret)
	all_event_list.append(event_info)

def napi__napi_poll(name, context, cpu, sec, nsec, pid, comm, callchain, napi,
                    dev_name, work=None, budget=None):
	event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm,
			napi, dev_name, work, budget)
	all_event_list.append(event_info)

def net__netif_receive_skb(name, context, cpu, sec, nsec, pid, comm, callchain, skbaddr,
			skblen, dev_name):
	event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm,
			skbaddr, skblen, dev_name)
	all_event_list.append(event_info)

def net__netif_rx(name, context, cpu, sec, nsec, pid, comm, callchain, skbaddr,
			skblen, dev_name):
	event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm,
			skbaddr, skblen, dev_name)
	all_event_list.append(event_info)

def net__net_dev_queue(name, context, cpu, sec, nsec, pid, comm, callchain,
			skbaddr, skblen, dev_name):
	event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm,
			skbaddr, skblen, dev_name)
	all_event_list.append(event_info)

def net__net_dev_xmit(name, context, cpu, sec, nsec, pid, comm, callchain,
			skbaddr, skblen, rc, dev_name):
	event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm,
			skbaddr, skblen, rc ,dev_name)
	all_event_list.append(event_info)

def skb__kfree_skb(name, context, cpu, sec, nsec, pid, comm, callchain,
			skbaddr, protocol, location):
	event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm,
			skbaddr, protocol, location)
	all_event_list.append(event_info)

def skb__consume_skb(name, context, cpu, sec, nsec, pid, comm, callchain, skbaddr):
	event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm,
			skbaddr)
	all_event_list.append(event_info)

def skb__skb_copy_datagram_iovec(name, context, cpu, sec, nsec, pid, comm, callchain,
	skbaddr, skblen):
	event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm,
			skbaddr, skblen)
	all_event_list.append(event_info)

def handle_irq_handler_entry(event_info):
	(name, context, cpu, time, pid, comm, irq, irq_name) = event_info
	if cpu not in irq_dic.keys():
		irq_dic[cpu] = []
	irq_record = {'irq':irq, 'name':irq_name, 'cpu':cpu, 'irq_ent_t':time}
	irq_dic[cpu].append(irq_record)

def handle_irq_handler_exit(event_info):
	(name, context, cpu, time, pid, comm, irq, ret) = event_info
	if cpu not in irq_dic.keys():
		return
	irq_record = irq_dic[cpu].pop()
	if irq != irq_record['irq']:
		return
	irq_record.update({'irq_ext_t':time})
	# if an irq doesn't include NET_RX softirq, drop.
	if 'event_list' in irq_record.keys():
		irq_dic[cpu].append(irq_record)

def handle_irq_softirq_raise(event_info):
	(name, context, cpu, time, pid, comm, vec) = event_info
	if cpu not in irq_dic.keys() \
	or len(irq_dic[cpu]) == 0:
		return
	irq_record = irq_dic[cpu].pop()
	if 'event_list' in irq_record.keys():
		irq_event_list = irq_record['event_list']
	else:
		irq_event_list = []
	irq_event_list.append({'time':time, 'event':'sirq_raise'})
	irq_record.update({'event_list':irq_event_list})
	irq_dic[cpu].append(irq_record)

def handle_irq_softirq_entry(event_info):
	(name, context, cpu, time, pid, comm, vec) = event_info
	net_rx_dic[cpu] = {'sirq_ent_t':time, 'event_list':[]}

def handle_irq_softirq_exit(event_info):
	(name, context, cpu, time, pid, comm, vec) = event_info
	irq_list = []
	event_list = 0
	if cpu in irq_dic.keys():
		irq_list = irq_dic[cpu]
		del irq_dic[cpu]
	if cpu in net_rx_dic.keys():
		sirq_ent_t = net_rx_dic[cpu]['sirq_ent_t']
		event_list = net_rx_dic[cpu]['event_list']
		del net_rx_dic[cpu]
	if irq_list == [] or event_list == 0:
		return
	rec_data = {'sirq_ent_t':sirq_ent_t, 'sirq_ext_t':time,
		    'irq_list':irq_list, 'event_list':event_list}
	# merge information realted to a NET_RX softirq
	receive_hunk_list.append(rec_data)

def handle_napi_poll(event_info):
	(name, context, cpu, time, pid, comm, napi, dev_name,
		work, budget) = event_info
	if cpu in net_rx_dic.keys():
		event_list = net_rx_dic[cpu]['event_list']
		rec_data = {'event_name':'napi_poll',
				'dev':dev_name, 'event_t':time,
				'work':work, 'budget':budget}
		event_list.append(rec_data)

def handle_netif_rx(event_info):
	(name, context, cpu, time, pid, comm,
		skbaddr, skblen, dev_name) = event_info
	if cpu not in irq_dic.keys() \
	or len(irq_dic[cpu]) == 0:
		return
	irq_record = irq_dic[cpu].pop()
	if 'event_list' in irq_record.keys():
		irq_event_list = irq_record['event_list']
	else:
		irq_event_list = []
	irq_event_list.append({'time':time, 'event':'netif_rx',
		'skbaddr':skbaddr, 'skblen':skblen, 'dev_name':dev_name})
	irq_record.update({'event_list':irq_event_list})
	irq_dic[cpu].append(irq_record)

def handle_netif_receive_skb(event_info):
	global of_count_rx_skb_list

	(name, context, cpu, time, pid, comm,
		skbaddr, skblen, dev_name) = event_info
	if cpu in net_rx_dic.keys():
		rec_data = {'event_name':'netif_receive_skb',
			    'event_t':time, 'skbaddr':skbaddr, 'len':skblen}
		event_list = net_rx_dic[cpu]['event_list']
		event_list.append(rec_data)
		rx_skb_list.insert(0, rec_data)
		if len(rx_skb_list) > buffer_budget:
			rx_skb_list.pop()
			of_count_rx_skb_list += 1

def handle_net_dev_queue(event_info):
	global of_count_tx_queue_list

	(name, context, cpu, time, pid, comm,
		skbaddr, skblen, dev_name) = event_info
	skb = {'dev':dev_name, 'skbaddr':skbaddr, 'len':skblen, 'queue_t':time}
	tx_queue_list.insert(0, skb)
	if len(tx_queue_list) > buffer_budget:
		tx_queue_list.pop()
		of_count_tx_queue_list += 1

def handle_net_dev_xmit(event_info):
	global of_count_tx_xmit_list

	(name, context, cpu, time, pid, comm,
		skbaddr, skblen, rc, dev_name) = event_info
	if rc == 0: # NETDEV_TX_OK
		for i in range(len(tx_queue_list)):
			skb = tx_queue_list[i]
			if skb['skbaddr'] == skbaddr:
				skb['xmit_t'] = time
				tx_xmit_list.insert(0, skb)
				del tx_queue_list[i]
				if len(tx_xmit_list) > buffer_budget:
					tx_xmit_list.pop()
					of_count_tx_xmit_list += 1
				return

def handle_kfree_skb(event_info):
	(name, context, cpu, time, pid, comm,
		skbaddr, protocol, location) = event_info
	for i in range(len(tx_queue_list)):
		skb = tx_queue_list[i]
		if skb['skbaddr'] == skbaddr:
			del tx_queue_list[i]
			return
	for i in range(len(tx_xmit_list)):
		skb = tx_xmit_list[i]
		if skb['skbaddr'] == skbaddr:
			skb['free_t'] = time
			tx_free_list.append(skb)
			del tx_xmit_list[i]
			return
	for i in range(len(rx_skb_list)):
		rec_data = rx_skb_list[i]
		if rec_data['skbaddr'] == skbaddr:
			rec_data.update({'handle':"kfree_skb",
					'comm':comm, 'pid':pid, 'comm_t':time})
			del rx_skb_list[i]
			return

def handle_consume_skb(event_info):
	(name, context, cpu, time, pid, comm, skbaddr) = event_info
	for i in range(len(tx_xmit_list)):
		skb = tx_xmit_list[i]
		if skb['skbaddr'] == skbaddr:
			skb['free_t'] = time
			tx_free_list.append(skb)
			del tx_xmit_list[i]
			return

def handle_skb_copy_datagram_iovec(event_info):
	(name, context, cpu, time, pid, comm, skbaddr, skblen) = event_info
	for i in range(len(rx_skb_list)):
		rec_data = rx_skb_list[i]
		if skbaddr == rec_data['skbaddr']:
			rec_data.update({'handle':"skb_copy_datagram_iovec",
					'comm':comm, 'pid':pid, 'comm_t':time})
			del rx_skb_list[i]
			return