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 10import os 11import sys 12 13sys.path.append(os.environ['PERF_EXEC_PATH'] + \ 14 '/scripts/python/Perf-Trace-Util/lib/Perf/Trace') 15 16from perf_trace_context import * 17from Core import * 18from Util import * 19 20all_event_list = []; # insert all tracepoint event related with this script 21irq_dic = {}; # key is cpu and value is a list which stacks irqs 22 # which raise NET_RX softirq 23net_rx_dic = {}; # key is cpu and value include time of NET_RX softirq-entry 24 # and a list which stacks receive 25receive_hunk_list = []; # a list which include a sequence of receive events 26rx_skb_list = []; # received packet list for matching 27 # skb_copy_datagram_iovec 28 29buffer_budget = 65536; # the budget of rx_skb_list, tx_queue_list and 30 # tx_xmit_list 31of_count_rx_skb_list = 0; # overflow count 32 33tx_queue_list = []; # list of packets which pass through dev_queue_xmit 34of_count_tx_queue_list = 0; # overflow count 35 36tx_xmit_list = []; # list of packets which pass through dev_hard_start_xmit 37of_count_tx_xmit_list = 0; # overflow count 38 39tx_free_list = []; # list of packets which is freed 40 41# options 42show_tx = 0; 43show_rx = 0; 44dev = 0; # store a name of device specified by option "dev=" 45debug = 0; 46 47# indices of event_info tuple 48EINFO_IDX_NAME= 0 49EINFO_IDX_CONTEXT=1 50EINFO_IDX_CPU= 2 51EINFO_IDX_TIME= 3 52EINFO_IDX_PID= 4 53EINFO_IDX_COMM= 5 54 55# Calculate a time interval(msec) from src(nsec) to dst(nsec) 56def diff_msec(src, dst): 57 return (dst - src) / 1000000.0 58 59# Display a process of transmitting a packet 60def 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 71PF_IRQ_ENTRY= " irq_entry(+%.3fmsec irq=%d:%s)" 72PF_SOFT_ENTRY=" softirq_entry(+%.3fmsec)" 73PF_NAPI_POLL= " napi_poll_exit(+%.3fmsec %s)" 74PF_JOINT= " |" 75PF_WJOINT= " | |" 76PF_NET_RECV= " |---netif_receive_skb(+%.3fmsec skb=%x len=%d)" 77PF_NET_RX= " |---netif_rx(+%.3fmsec skb=%x)" 78PF_CPY_DGRAM= " | skb_copy_datagram_iovec(+%.3fmsec %d:%s)" 79PF_KFREE_SKB= " | kfree_skb(+%.3fmsec location=%x)" 80PF_CONS_SKB= " | consume_skb(+%.3fmsec)" 81 82# Display a process of received packets and interrputs associated with 83# a NET_RX softirq 84def 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 150def 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 172def 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 227def irq__softirq_entry(name, context, cpu, sec, nsec, pid, comm, callchain, 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 233def irq__softirq_exit(name, context, cpu, sec, nsec, pid, comm, callchain, 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 239def irq__softirq_raise(name, context, cpu, sec, nsec, pid, comm, callchain, 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 245def irq__irq_handler_entry(name, context, cpu, sec, nsec, pid, comm, 246 callchain, 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 251def irq__irq_handler_exit(name, context, cpu, sec, nsec, pid, comm, callchain, irq, ret): 252 event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm, irq, ret) 253 all_event_list.append(event_info) 254 255def napi__napi_poll(name, context, cpu, sec, nsec, pid, comm, callchain, napi, 256 dev_name, work=None, budget=None): 257 event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm, 258 napi, dev_name, work, budget) 259 all_event_list.append(event_info) 260 261def net__netif_receive_skb(name, context, cpu, sec, nsec, pid, comm, callchain, skbaddr, 262 skblen, dev_name): 263 event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm, 264 skbaddr, skblen, dev_name) 265 all_event_list.append(event_info) 266 267def net__netif_rx(name, context, cpu, sec, nsec, pid, comm, callchain, skbaddr, 268 skblen, dev_name): 269 event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm, 270 skbaddr, skblen, dev_name) 271 all_event_list.append(event_info) 272 273def net__net_dev_queue(name, context, cpu, sec, nsec, pid, comm, callchain, 274 skbaddr, skblen, dev_name): 275 event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm, 276 skbaddr, skblen, dev_name) 277 all_event_list.append(event_info) 278 279def net__net_dev_xmit(name, context, cpu, sec, nsec, pid, comm, callchain, 280 skbaddr, skblen, rc, dev_name): 281 event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm, 282 skbaddr, skblen, rc ,dev_name) 283 all_event_list.append(event_info) 284 285def skb__kfree_skb(name, context, cpu, sec, nsec, pid, comm, callchain, 286 skbaddr, protocol, location): 287 event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm, 288 skbaddr, protocol, location) 289 all_event_list.append(event_info) 290 291def skb__consume_skb(name, context, cpu, sec, nsec, pid, comm, callchain, skbaddr): 292 event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm, 293 skbaddr) 294 all_event_list.append(event_info) 295 296def skb__skb_copy_datagram_iovec(name, context, cpu, sec, nsec, pid, comm, callchain, 297 skbaddr, skblen): 298 event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm, 299 skbaddr, skblen) 300 all_event_list.append(event_info) 301 302def handle_irq_handler_entry(event_info): 303 (name, context, cpu, time, pid, comm, irq, irq_name) = event_info 304 if cpu not in irq_dic.keys(): 305 irq_dic[cpu] = [] 306 irq_record = {'irq':irq, 'name':irq_name, 'cpu':cpu, 'irq_ent_t':time} 307 irq_dic[cpu].append(irq_record) 308 309def handle_irq_handler_exit(event_info): 310 (name, context, cpu, time, pid, comm, irq, ret) = event_info 311 if cpu not in irq_dic.keys(): 312 return 313 irq_record = irq_dic[cpu].pop() 314 if irq != irq_record['irq']: 315 return 316 irq_record.update({'irq_ext_t':time}) 317 # if an irq doesn't include NET_RX softirq, drop. 318 if 'event_list' in irq_record.keys(): 319 irq_dic[cpu].append(irq_record) 320 321def handle_irq_softirq_raise(event_info): 322 (name, context, cpu, time, pid, comm, vec) = event_info 323 if cpu not in irq_dic.keys() \ 324 or len(irq_dic[cpu]) == 0: 325 return 326 irq_record = irq_dic[cpu].pop() 327 if 'event_list' in irq_record.keys(): 328 irq_event_list = irq_record['event_list'] 329 else: 330 irq_event_list = [] 331 irq_event_list.append({'time':time, 'event':'sirq_raise'}) 332 irq_record.update({'event_list':irq_event_list}) 333 irq_dic[cpu].append(irq_record) 334 335def handle_irq_softirq_entry(event_info): 336 (name, context, cpu, time, pid, comm, vec) = event_info 337 net_rx_dic[cpu] = {'sirq_ent_t':time, 'event_list':[]} 338 339def handle_irq_softirq_exit(event_info): 340 (name, context, cpu, time, pid, comm, vec) = event_info 341 irq_list = [] 342 event_list = 0 343 if cpu in irq_dic.keys(): 344 irq_list = irq_dic[cpu] 345 del irq_dic[cpu] 346 if cpu in net_rx_dic.keys(): 347 sirq_ent_t = net_rx_dic[cpu]['sirq_ent_t'] 348 event_list = net_rx_dic[cpu]['event_list'] 349 del net_rx_dic[cpu] 350 if irq_list == [] or event_list == 0: 351 return 352 rec_data = {'sirq_ent_t':sirq_ent_t, 'sirq_ext_t':time, 353 'irq_list':irq_list, 'event_list':event_list} 354 # merge information realted to a NET_RX softirq 355 receive_hunk_list.append(rec_data) 356 357def handle_napi_poll(event_info): 358 (name, context, cpu, time, pid, comm, napi, dev_name, 359 work, budget) = event_info 360 if cpu in net_rx_dic.keys(): 361 event_list = net_rx_dic[cpu]['event_list'] 362 rec_data = {'event_name':'napi_poll', 363 'dev':dev_name, 'event_t':time, 364 'work':work, 'budget':budget} 365 event_list.append(rec_data) 366 367def handle_netif_rx(event_info): 368 (name, context, cpu, time, pid, comm, 369 skbaddr, skblen, dev_name) = event_info 370 if cpu not in irq_dic.keys() \ 371 or len(irq_dic[cpu]) == 0: 372 return 373 irq_record = irq_dic[cpu].pop() 374 if 'event_list' in irq_record.keys(): 375 irq_event_list = irq_record['event_list'] 376 else: 377 irq_event_list = [] 378 irq_event_list.append({'time':time, 'event':'netif_rx', 379 'skbaddr':skbaddr, 'skblen':skblen, 'dev_name':dev_name}) 380 irq_record.update({'event_list':irq_event_list}) 381 irq_dic[cpu].append(irq_record) 382 383def handle_netif_receive_skb(event_info): 384 global of_count_rx_skb_list 385 386 (name, context, cpu, time, pid, comm, 387 skbaddr, skblen, dev_name) = event_info 388 if cpu in net_rx_dic.keys(): 389 rec_data = {'event_name':'netif_receive_skb', 390 'event_t':time, 'skbaddr':skbaddr, 'len':skblen} 391 event_list = net_rx_dic[cpu]['event_list'] 392 event_list.append(rec_data) 393 rx_skb_list.insert(0, rec_data) 394 if len(rx_skb_list) > buffer_budget: 395 rx_skb_list.pop() 396 of_count_rx_skb_list += 1 397 398def handle_net_dev_queue(event_info): 399 global of_count_tx_queue_list 400 401 (name, context, cpu, time, pid, comm, 402 skbaddr, skblen, dev_name) = event_info 403 skb = {'dev':dev_name, 'skbaddr':skbaddr, 'len':skblen, 'queue_t':time} 404 tx_queue_list.insert(0, skb) 405 if len(tx_queue_list) > buffer_budget: 406 tx_queue_list.pop() 407 of_count_tx_queue_list += 1 408 409def handle_net_dev_xmit(event_info): 410 global of_count_tx_xmit_list 411 412 (name, context, cpu, time, pid, comm, 413 skbaddr, skblen, rc, dev_name) = event_info 414 if rc == 0: # NETDEV_TX_OK 415 for i in range(len(tx_queue_list)): 416 skb = tx_queue_list[i] 417 if skb['skbaddr'] == skbaddr: 418 skb['xmit_t'] = time 419 tx_xmit_list.insert(0, skb) 420 del tx_queue_list[i] 421 if len(tx_xmit_list) > buffer_budget: 422 tx_xmit_list.pop() 423 of_count_tx_xmit_list += 1 424 return 425 426def handle_kfree_skb(event_info): 427 (name, context, cpu, time, pid, comm, 428 skbaddr, protocol, location) = event_info 429 for i in range(len(tx_queue_list)): 430 skb = tx_queue_list[i] 431 if skb['skbaddr'] == skbaddr: 432 del tx_queue_list[i] 433 return 434 for i in range(len(tx_xmit_list)): 435 skb = tx_xmit_list[i] 436 if skb['skbaddr'] == skbaddr: 437 skb['free_t'] = time 438 tx_free_list.append(skb) 439 del tx_xmit_list[i] 440 return 441 for i in range(len(rx_skb_list)): 442 rec_data = rx_skb_list[i] 443 if rec_data['skbaddr'] == skbaddr: 444 rec_data.update({'handle':"kfree_skb", 445 'comm':comm, 'pid':pid, 'comm_t':time}) 446 del rx_skb_list[i] 447 return 448 449def handle_consume_skb(event_info): 450 (name, context, cpu, time, pid, comm, skbaddr) = event_info 451 for i in range(len(tx_xmit_list)): 452 skb = tx_xmit_list[i] 453 if skb['skbaddr'] == skbaddr: 454 skb['free_t'] = time 455 tx_free_list.append(skb) 456 del tx_xmit_list[i] 457 return 458 459def handle_skb_copy_datagram_iovec(event_info): 460 (name, context, cpu, time, pid, comm, skbaddr, skblen) = event_info 461 for i in range(len(rx_skb_list)): 462 rec_data = rx_skb_list[i] 463 if skbaddr == rec_data['skbaddr']: 464 rec_data.update({'handle':"skb_copy_datagram_iovec", 465 'comm':comm, 'pid':pid, 'comm_t':time}) 466 del rx_skb_list[i] 467 return 468