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