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, dev_name):
 256         event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm,
 257                         napi, dev_name)
 258         all_event_list.append(event_info)
 259
 260 def net__netif_receive_skb(name, context, cpu, sec, nsec, pid, comm, callchain, skbaddr,
 261                         skblen, dev_name):
 262         event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm,
 263                         skbaddr, skblen, dev_name)
 264         all_event_list.append(event_info)
 265
 266 def net__netif_rx(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
 272 def net__net_dev_queue(name, context, cpu, sec, nsec, pid, comm, callchain,
 273                         skbaddr, 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
 278 def net__net_dev_xmit(name, context, cpu, sec, nsec, pid, comm, callchain,
 279                         skbaddr, skblen, rc, dev_name):
 280         event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm,
 281                         skbaddr, skblen, rc ,dev_name)
 282         all_event_list.append(event_info)
 283
 284 def skb__kfree_skb(name, context, cpu, sec, nsec, pid, comm, callchain,
 285                         skbaddr, protocol, location):
 286         event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm,
 287                         skbaddr, protocol, location)
 288         all_event_list.append(event_info)
 289
 290 def skb__consume_skb(name, context, cpu, sec, nsec, pid, comm, callchain, skbaddr):
 291         event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm,
 292                         skbaddr)
 293         all_event_list.append(event_info)
 294
 295 def skb__skb_copy_datagram_iovec(name, context, cpu, sec, nsec, pid, comm, callchain,
 296         skbaddr, skblen):
 297         event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm,
 298                         skbaddr, skblen)
 299         all_event_list.append(event_info)
 300
 301 def handle_irq_handler_entry(event_info):
 302         (name, context, cpu, time, pid, comm, irq, irq_name) = event_info
 303         if cpu not in irq_dic.keys():
 304                 irq_dic[cpu] = []
 305         irq_record = {'irq':irq, 'name':irq_name, 'cpu':cpu, 'irq_ent_t':time}
 306         irq_dic[cpu].append(irq_record)
 307
 308 def handle_irq_handler_exit(event_info):
 309         (name, context, cpu, time, pid, comm, irq, ret) = event_info
 310         if cpu not in irq_dic.keys():
 311                 return
 312         irq_record = irq_dic[cpu].pop()
 313         if irq != irq_record['irq']:
 314                 return
 315         irq_record.update({'irq_ext_t':time})
 316         # if an irq doesn't include NET_RX softirq, drop.
 317         if 'event_list' in irq_record.keys():
 318                 irq_dic[cpu].append(irq_record)
 319
 320 def handle_irq_softirq_raise(event_info):
 321         (name, context, cpu, time, pid, comm, vec) = event_info
 322         if cpu not in irq_dic.keys() \
 323         or len(irq_dic[cpu]) == 0:
 324                 return
 325         irq_record = irq_dic[cpu].pop()
 326         if 'event_list' in irq_record.keys():
 327                 irq_event_list = irq_record['event_list']
 328         else:
 329                 irq_event_list = []
 330         irq_event_list.append({'time':time, 'event':'sirq_raise'})
 331         irq_record.update({'event_list':irq_event_list})
 332         irq_dic[cpu].append(irq_record)
 333
 334 def handle_irq_softirq_entry(event_info):
 335         (name, context, cpu, time, pid, comm, vec) = event_info
 336         net_rx_dic[cpu] = {'sirq_ent_t':time, 'event_list':[]}
 337
 338 def handle_irq_softirq_exit(event_info):
 339         (name, context, cpu, time, pid, comm, vec) = event_info
 340         irq_list = []
 341         event_list = 0
 342         if cpu in irq_dic.keys():
 343                 irq_list = irq_dic[cpu]
 344                 del irq_dic[cpu]
 345         if cpu in net_rx_dic.keys():
 346                 sirq_ent_t = net_rx_dic[cpu]['sirq_ent_t']
 347                 event_list = net_rx_dic[cpu]['event_list']
 348                 del net_rx_dic[cpu]
 349         if irq_list == [] or event_list == 0:
 350                 return
 351         rec_data = {'sirq_ent_t':sirq_ent_t, 'sirq_ext_t':time,
 352                     'irq_list':irq_list, 'event_list':event_list}
 353         # merge information realted to a NET_RX softirq
 354         receive_hunk_list.append(rec_data)
 355
 356 def handle_napi_poll(event_info):
 357         (name, context, cpu, time, pid, comm, napi, dev_name) = event_info
 358         if cpu in net_rx_dic.keys():
 359                 event_list = net_rx_dic[cpu]['event_list']
 360                 rec_data = {'event_name':'napi_poll',
 361                                 'dev':dev_name, 'event_t':time}
 362                 event_list.append(rec_data)
 363
 364 def handle_netif_rx(event_info):
 365         (name, context, cpu, time, pid, comm,
 366                 skbaddr, skblen, dev_name) = event_info
 367         if cpu not in irq_dic.keys() \
 368         or len(irq_dic[cpu]) == 0:
 369                 return
 370         irq_record = irq_dic[cpu].pop()
 371         if 'event_list' in irq_record.keys():
 372                 irq_event_list = irq_record['event_list']
 373         else:
 374                 irq_event_list = []
 375         irq_event_list.append({'time':time, 'event':'netif_rx',
 376                 'skbaddr':skbaddr, 'skblen':skblen, 'dev_name':dev_name})
 377         irq_record.update({'event_list':irq_event_list})
 378         irq_dic[cpu].append(irq_record)
 379
 380 def handle_netif_receive_skb(event_info):
 381         global of_count_rx_skb_list
 382
 383         (name, context, cpu, time, pid, comm,
 384                 skbaddr, skblen, dev_name) = event_info
 385         if cpu in net_rx_dic.keys():
 386                 rec_data = {'event_name':'netif_receive_skb',
 387                             'event_t':time, 'skbaddr':skbaddr, 'len':skblen}
 388                 event_list = net_rx_dic[cpu]['event_list']
 389                 event_list.append(rec_data)
 390                 rx_skb_list.insert(0, rec_data)
 391                 if len(rx_skb_list) > buffer_budget:
 392                         rx_skb_list.pop()
 393                         of_count_rx_skb_list += 1
 394
 395 def handle_net_dev_queue(event_info):
 396         global of_count_tx_queue_list
 397
 398         (name, context, cpu, time, pid, comm,
 399                 skbaddr, skblen, dev_name) = event_info
 400         skb = {'dev':dev_name, 'skbaddr':skbaddr, 'len':skblen, 'queue_t':time}
 401         tx_queue_list.insert(0, skb)
 402         if len(tx_queue_list) > buffer_budget:
 403                 tx_queue_list.pop()
 404                 of_count_tx_queue_list += 1
 405
 406 def handle_net_dev_xmit(event_info):
 407         global of_count_tx_xmit_list
 408
 409         (name, context, cpu, time, pid, comm,
 410                 skbaddr, skblen, rc, dev_name) = event_info
 411         if rc == 0: # NETDEV_TX_OK
 412                 for i in range(len(tx_queue_list)):
 413                         skb = tx_queue_list[i]
 414                         if skb['skbaddr'] == skbaddr:
 415                                 skb['xmit_t'] = time
 416                                 tx_xmit_list.insert(0, skb)
 417                                 del tx_queue_list[i]
 418                                 if len(tx_xmit_list) > buffer_budget:
 419                                         tx_xmit_list.pop()
 420                                         of_count_tx_xmit_list += 1
 421                                 return
 422
 423 def handle_kfree_skb(event_info):
 424         (name, context, cpu, time, pid, comm,
 425                 skbaddr, protocol, location) = event_info
 426         for i in range(len(tx_queue_list)):
 427                 skb = tx_queue_list[i]
 428                 if skb['skbaddr'] == skbaddr:
 429                         del tx_queue_list[i]
 430                         return
 431         for i in range(len(tx_xmit_list)):
 432                 skb = tx_xmit_list[i]
 433                 if skb['skbaddr'] == skbaddr:
 434                         skb['free_t'] = time
 435                         tx_free_list.append(skb)
 436                         del tx_xmit_list[i]
 437                         return
 438         for i in range(len(rx_skb_list)):
 439                 rec_data = rx_skb_list[i]
 440                 if rec_data['skbaddr'] == skbaddr:
 441                         rec_data.update({'handle':"kfree_skb",
 442                                         'comm':comm, 'pid':pid, 'comm_t':time})
 443                         del rx_skb_list[i]
 444                         return
 445
 446 def handle_consume_skb(event_info):
 447         (name, context, cpu, time, pid, comm, skbaddr) = event_info
 448         for i in range(len(tx_xmit_list)):
 449                 skb = tx_xmit_list[i]
 450                 if skb['skbaddr'] == skbaddr:
 451                         skb['free_t'] = time
 452                         tx_free_list.append(skb)
 453                         del tx_xmit_list[i]
 454                         return
 455
 456 def handle_skb_copy_datagram_iovec(event_info):
 457         (name, context, cpu, time, pid, comm, skbaddr, skblen) = event_info
 458         for i in range(len(rx_skb_list)):
 459                 rec_data = rx_skb_list[i]
 460                 if skbaddr == rec_data['skbaddr']:
 461                         rec_data.update({'handle':"skb_copy_datagram_iovec",
 462                                         'comm':comm, 'pid':pid, 'comm_t':time})
 463                         del rx_skb_list[i]
 464                         return