tools/perf/scripts/python/netdev-times.py

   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, 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
 233 def 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
 239 def 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
 245 def 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
 251 def 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
 255 def 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
 261 def 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
 267 def 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
 273 def 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
 279 def 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
 285 def 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
 291 def 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
 296 def 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
 302 def 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
 309 def 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
 321 def 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
 335 def 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
 339 def 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
 357 def 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
 367 def 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
 383 def 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
 398 def 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
 409 def 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
 426 def 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
 449 def 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
 459 def 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