Home | History | Annotate | Download | only in python
      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
    465