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