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

   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
  11 import os
  12 import sys
  13
  14 sys.path.append(os.environ['PERF_EXEC_PATH'] + \
  15         '/scripts/python/Perf-Trace-Util/lib/Perf/Trace')
  16
  17 from perf_trace_context import *
  18 from Core import *
  19 from Util import *
  20
  21 all_event_list = []; # insert all tracepoint event related with this script
  22 irq_dic = {}; # key is cpu and value is a list which stacks irqs
  23               # which raise NET_RX softirq
  24 net_rx_dic = {}; # key is cpu and value include time of NET_RX softirq-entry
  25                  # and a list which stacks receive
  26 receive_hunk_list = []; # a list which include a sequence of receive events
  27 rx_skb_list = []; # received packet list for matching
  28                        # skb_copy_datagram_iovec
  29
  30 buffer_budget = 65536; # the budget of rx_skb_list, tx_queue_list and
  31                        # tx_xmit_list
  32 of_count_rx_skb_list = 0; # overflow count
  33
  34 tx_queue_list = []; # list of packets which pass through dev_queue_xmit
  35 of_count_tx_queue_list = 0; # overflow count
  36
  37 tx_xmit_list = [];  # list of packets which pass through dev_hard_start_xmit
  38 of_count_tx_xmit_list = 0; # overflow count
  39
  40 tx_free_list = [];  # list of packets which is freed
  41
  42 # options
  43 show_tx = 0;
  44 show_rx = 0;
  45 dev = 0; # store a name of device specified by option "dev="
  46 debug = 0;
  47
  48 # indices of event_info tuple
  49 EINFO_IDX_NAME=   0
  50 EINFO_IDX_CONTEXT=1
  51 EINFO_IDX_CPU=    2
  52 EINFO_IDX_TIME=   3
  53 EINFO_IDX_PID=    4
  54 EINFO_IDX_COMM=   5
  55
  56 # Calculate a time interval(msec) from src(nsec) to dst(nsec)
  57 def diff_msec(src, dst):
  58         return (dst - src) / 1000000.0
  59
  60 # Display a process of transmitting a packet
  61 def 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
  72 PF_IRQ_ENTRY= "  irq_entry(+%.3fmsec irq=%d:%s)"
  73 PF_SOFT_ENTRY="  softirq_entry(+%.3fmsec)"
  74 PF_NAPI_POLL= "  napi_poll_exit(+%.3fmsec %s)"
  75 PF_JOINT=     "         |"
  76 PF_WJOINT=    "         |            |"
  77 PF_NET_RECV=  "         |---netif_receive_skb(+%.3fmsec skb=%x len=%d)"
  78 PF_NET_RX=    "         |---netif_rx(+%.3fmsec skb=%x)"
  79 PF_CPY_DGRAM= "         |      skb_copy_datagram_iovec(+%.3fmsec %d:%s)"
  80 PF_KFREE_SKB= "         |      kfree_skb(+%.3fmsec location=%x)"
  81 PF_CONS_SKB=  "         |      consume_skb(+%.3fmsec)"
  82
  83 # Display a process of received packets and interrputs associated with
  84 # a NET_RX softirq
  85 def 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
 151 def 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
 173 def 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
 228 def 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
 234 def 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
 240 def 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
 246 def 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
 252 def 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
 256 def 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
 262 def 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
 268 def 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
 274 def 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
 280 def 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
 286 def 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
 292 def 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
 297 def 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
 303 def 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
 310 def 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
 322 def 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
 336 def 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
 340 def 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
 358 def 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
 368 def 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
 384 def 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
 399 def 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
 410 def 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
 427 def 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
 450 def 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
 460 def 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