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