474 lines · python
1# Display a process of packets and processed time.2# SPDX-License-Identifier: GPL-2.03# It helps us to investigate networking or network device.4#5# options6# tx: show only tx chart7# rx: show only rx chart8# dev=: show only thing related to specified device9# debug: work with debug mode. It shows buffer status.10 11from __future__ import print_function12 13import os14import sys15 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_key23 24all_event_list = []; # insert all tracepoint event related with this script25irq_dic = {}; # key is cpu and value is a list which stacks irqs26 # which raise NET_RX softirq27net_rx_dic = {}; # key is cpu and value include time of NET_RX softirq-entry28 # and a list which stacks receive29receive_hunk_list = []; # a list which include a sequence of receive events30rx_skb_list = []; # received packet list for matching31 # skb_copy_datagram_iovec32 33buffer_budget = 65536; # the budget of rx_skb_list, tx_queue_list and34 # tx_xmit_list35of_count_rx_skb_list = 0; # overflow count36 37tx_queue_list = []; # list of packets which pass through dev_queue_xmit38of_count_tx_queue_list = 0; # overflow count39 40tx_xmit_list = []; # list of packets which pass through dev_hard_start_xmit41of_count_tx_xmit_list = 0; # overflow count42 43tx_free_list = []; # list of packets which is freed44 45# options46show_tx = 0;47show_rx = 0;48dev = 0; # store a name of device specified by option "dev="49debug = 0;50 51# indices of event_info tuple52EINFO_IDX_NAME= 053EINFO_IDX_CONTEXT=154EINFO_IDX_CPU= 255EINFO_IDX_TIME= 356EINFO_IDX_PID= 457EINFO_IDX_COMM= 558 59# Calculate a time interval(msec) from src(nsec) to dst(nsec)60def diff_msec(src, dst):61 return (dst - src) / 1000000.062 63# Display a process of transmitting a packet64def print_transmit(hunk):65 if dev != 0 and hunk['dev'].find(dev) < 0:66 return67 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 processing75PF_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 with87# a NET_RX softirq88def print_receive(hunk):89 show_hunk = 090 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 showed94 if dev != 0:95 for i in range(len(irq_list)):96 if irq_list[i]['name'].find(dev) >= 0:97 show_hunk = 198 break99 else:100 show_hunk = 1101 if show_hunk == 0:102 return103 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_tx158 global show_rx159 global dev160 global debug161 162 for i in range(len(sys.argv)):163 if i == 0:164 continue165 arg = sys.argv[i]166 if arg == 'tx':167 show_tx = 1168 elif arg =='rx':169 show_rx = 1170 elif arg.find('dev=',0, 4) >= 0:171 dev = arg[4:]172 elif arg == 'debug':173 debug = 1174 if show_tx == 0 and show_rx == 0:175 show_tx = 1176 show_rx = 1177 178def trace_end():179 # order all events in time180 all_event_list.sort(key=cmp_to_key(lambda a,b :a[EINFO_IDX_TIME] < b[EINFO_IDX_TIME]))181 # process all events182 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 hunks212 if show_rx:213 for i in range(len(receive_hunk_list)):214 print_receive(receive_hunk_list[i])215 # display transmit hunks216 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 event232def irq__softirq_entry(name, context, cpu, sec, nsec, pid, comm, callchain, vec):233 if symbol_str("irq__softirq_entry", "vec", vec) != "NET_RX":234 return235 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 return241 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 return247 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, location, protocol, reason):292 event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm,293 skbaddr, location, protocol, reason)294 all_event_list.append(event_info)295 296def skb__consume_skb(name, context, cpu, sec, nsec, pid, comm, callchain,297 skbaddr, location):298 event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm,299 skbaddr)300 all_event_list.append(event_info)301 302def skb__skb_copy_datagram_iovec(name, context, cpu, sec, nsec, pid, comm, callchain,303 skbaddr, skblen):304 event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm,305 skbaddr, skblen)306 all_event_list.append(event_info)307 308def handle_irq_handler_entry(event_info):309 (name, context, cpu, time, pid, comm, irq, irq_name) = event_info310 if cpu not in irq_dic.keys():311 irq_dic[cpu] = []312 irq_record = {'irq':irq, 'name':irq_name, 'cpu':cpu, 'irq_ent_t':time}313 irq_dic[cpu].append(irq_record)314 315def handle_irq_handler_exit(event_info):316 (name, context, cpu, time, pid, comm, irq, ret) = event_info317 if cpu not in irq_dic.keys():318 return319 irq_record = irq_dic[cpu].pop()320 if irq != irq_record['irq']:321 return322 irq_record.update({'irq_ext_t':time})323 # if an irq doesn't include NET_RX softirq, drop.324 if 'event_list' in irq_record.keys():325 irq_dic[cpu].append(irq_record)326 327def handle_irq_softirq_raise(event_info):328 (name, context, cpu, time, pid, comm, vec) = event_info329 if cpu not in irq_dic.keys() \330 or len(irq_dic[cpu]) == 0:331 return332 irq_record = irq_dic[cpu].pop()333 if 'event_list' in irq_record.keys():334 irq_event_list = irq_record['event_list']335 else:336 irq_event_list = []337 irq_event_list.append({'time':time, 'event':'sirq_raise'})338 irq_record.update({'event_list':irq_event_list})339 irq_dic[cpu].append(irq_record)340 341def handle_irq_softirq_entry(event_info):342 (name, context, cpu, time, pid, comm, vec) = event_info343 net_rx_dic[cpu] = {'sirq_ent_t':time, 'event_list':[]}344 345def handle_irq_softirq_exit(event_info):346 (name, context, cpu, time, pid, comm, vec) = event_info347 irq_list = []348 event_list = 0349 if cpu in irq_dic.keys():350 irq_list = irq_dic[cpu]351 del irq_dic[cpu]352 if cpu in net_rx_dic.keys():353 sirq_ent_t = net_rx_dic[cpu]['sirq_ent_t']354 event_list = net_rx_dic[cpu]['event_list']355 del net_rx_dic[cpu]356 if irq_list == [] or event_list == 0:357 return358 rec_data = {'sirq_ent_t':sirq_ent_t, 'sirq_ext_t':time,359 'irq_list':irq_list, 'event_list':event_list}360 # merge information related to a NET_RX softirq361 receive_hunk_list.append(rec_data)362 363def handle_napi_poll(event_info):364 (name, context, cpu, time, pid, comm, napi, dev_name,365 work, budget) = event_info366 if cpu in net_rx_dic.keys():367 event_list = net_rx_dic[cpu]['event_list']368 rec_data = {'event_name':'napi_poll',369 'dev':dev_name, 'event_t':time,370 'work':work, 'budget':budget}371 event_list.append(rec_data)372 373def handle_netif_rx(event_info):374 (name, context, cpu, time, pid, comm,375 skbaddr, skblen, dev_name) = event_info376 if cpu not in irq_dic.keys() \377 or len(irq_dic[cpu]) == 0:378 return379 irq_record = irq_dic[cpu].pop()380 if 'event_list' in irq_record.keys():381 irq_event_list = irq_record['event_list']382 else:383 irq_event_list = []384 irq_event_list.append({'time':time, 'event':'netif_rx',385 'skbaddr':skbaddr, 'skblen':skblen, 'dev_name':dev_name})386 irq_record.update({'event_list':irq_event_list})387 irq_dic[cpu].append(irq_record)388 389def handle_netif_receive_skb(event_info):390 global of_count_rx_skb_list391 392 (name, context, cpu, time, pid, comm,393 skbaddr, skblen, dev_name) = event_info394 if cpu in net_rx_dic.keys():395 rec_data = {'event_name':'netif_receive_skb',396 'event_t':time, 'skbaddr':skbaddr, 'len':skblen}397 event_list = net_rx_dic[cpu]['event_list']398 event_list.append(rec_data)399 rx_skb_list.insert(0, rec_data)400 if len(rx_skb_list) > buffer_budget:401 rx_skb_list.pop()402 of_count_rx_skb_list += 1403 404def handle_net_dev_queue(event_info):405 global of_count_tx_queue_list406 407 (name, context, cpu, time, pid, comm,408 skbaddr, skblen, dev_name) = event_info409 skb = {'dev':dev_name, 'skbaddr':skbaddr, 'len':skblen, 'queue_t':time}410 tx_queue_list.insert(0, skb)411 if len(tx_queue_list) > buffer_budget:412 tx_queue_list.pop()413 of_count_tx_queue_list += 1414 415def handle_net_dev_xmit(event_info):416 global of_count_tx_xmit_list417 418 (name, context, cpu, time, pid, comm,419 skbaddr, skblen, rc, dev_name) = event_info420 if rc == 0: # NETDEV_TX_OK421 for i in range(len(tx_queue_list)):422 skb = tx_queue_list[i]423 if skb['skbaddr'] == skbaddr:424 skb['xmit_t'] = time425 tx_xmit_list.insert(0, skb)426 del tx_queue_list[i]427 if len(tx_xmit_list) > buffer_budget:428 tx_xmit_list.pop()429 of_count_tx_xmit_list += 1430 return431 432def handle_kfree_skb(event_info):433 (name, context, cpu, time, pid, comm,434 skbaddr, location, protocol, reason) = event_info435 for i in range(len(tx_queue_list)):436 skb = tx_queue_list[i]437 if skb['skbaddr'] == skbaddr:438 del tx_queue_list[i]439 return440 for i in range(len(tx_xmit_list)):441 skb = tx_xmit_list[i]442 if skb['skbaddr'] == skbaddr:443 skb['free_t'] = time444 tx_free_list.append(skb)445 del tx_xmit_list[i]446 return447 for i in range(len(rx_skb_list)):448 rec_data = rx_skb_list[i]449 if rec_data['skbaddr'] == skbaddr:450 rec_data.update({'handle':"kfree_skb",451 'comm':comm, 'pid':pid, 'comm_t':time})452 del rx_skb_list[i]453 return454 455def handle_consume_skb(event_info):456 (name, context, cpu, time, pid, comm, skbaddr) = event_info457 for i in range(len(tx_xmit_list)):458 skb = tx_xmit_list[i]459 if skb['skbaddr'] == skbaddr:460 skb['free_t'] = time461 tx_free_list.append(skb)462 del tx_xmit_list[i]463 return464 465def handle_skb_copy_datagram_iovec(event_info):466 (name, context, cpu, time, pid, comm, skbaddr, skblen) = event_info467 for i in range(len(rx_skb_list)):468 rec_data = rx_skb_list[i]469 if skbaddr == rec_data['skbaddr']:470 rec_data.update({'handle':"skb_copy_datagram_iovec",471 'comm':comm, 'pid':pid, 'comm_t':time})472 del rx_skb_list[i]473 return474