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, 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_info 310 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_info 317 if cpu not in irq_dic.keys(): 318 return 319 irq_record = irq_dic[cpu].pop() 320 if irq != irq_record['irq']: 321 return 322 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_info 329 if cpu not in irq_dic.keys() \ 330 or len(irq_dic[cpu]) == 0: 331 return 332 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_info 343 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_info 347 irq_list = [] 348 event_list = 0 349 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 return 358 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 softirq 361 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_info 366 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_info 376 if cpu not in irq_dic.keys() \ 377 or len(irq_dic[cpu]) == 0: 378 return 379 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_list 391 392 (name, context, cpu, time, pid, comm, 393 skbaddr, skblen, dev_name) = event_info 394 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 += 1 403 404def handle_net_dev_queue(event_info): 405 global of_count_tx_queue_list 406 407 (name, context, cpu, time, pid, comm, 408 skbaddr, skblen, dev_name) = event_info 409 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 += 1 414 415def handle_net_dev_xmit(event_info): 416 global of_count_tx_xmit_list 417 418 (name, context, cpu, time, pid, comm, 419 skbaddr, skblen, rc, dev_name) = event_info 420 if rc == 0: # NETDEV_TX_OK 421 for i in range(len(tx_queue_list)): 422 skb = tx_queue_list[i] 423 if skb['skbaddr'] == skbaddr: 424 skb['xmit_t'] = time 425 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 += 1 430 return 431 432def handle_kfree_skb(event_info): 433 (name, context, cpu, time, pid, comm, 434 skbaddr, location, protocol, reason) = event_info 435 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 return 440 for i in range(len(tx_xmit_list)): 441 skb = tx_xmit_list[i] 442 if skb['skbaddr'] == skbaddr: 443 skb['free_t'] = time 444 tx_free_list.append(skb) 445 del tx_xmit_list[i] 446 return 447 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 return 454 455def handle_consume_skb(event_info): 456 (name, context, cpu, time, pid, comm, skbaddr) = event_info 457 for i in range(len(tx_xmit_list)): 458 skb = tx_xmit_list[i] 459 if skb['skbaddr'] == skbaddr: 460 skb['free_t'] = time 461 tx_free_list.append(skb) 462 del tx_xmit_list[i] 463 return 464 465def handle_skb_copy_datagram_iovec(event_info): 466 (name, context, cpu, time, pid, comm, skbaddr, skblen) = event_info 467 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 return 474