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']), event['dev']))
 128                         if i == len(event_list) - 1:
 129                                 print("")
 130                         else:
 131                                 print(PF_JOINT)
 132                 else:
 133                         print(PF_NET_RECV %
 134                             (diff_msec(base_t, event['event_t']), event['skbaddr'],
 135                                 event['len']))
 136                         if 'comm' in event.keys():
 137                                 print(PF_WJOINT)
 138                                 print(PF_CPY_DGRAM %
 139                                         (diff_msec(base_t, event['comm_t']),
 140                                         event['pid'], event['comm']))
 141                         elif 'handle' in event.keys():
 142                                 print(PF_WJOINT)
 143                                 if event['handle'] == "kfree_skb":
 144                                         print(PF_KFREE_SKB %
 145                                                 (diff_msec(base_t,
 146                                                 event['comm_t']),
 147                                                 event['location']))
 148                                 elif event['handle'] == "consume_skb":
 149                                         print(PF_CONS_SKB %
 150                                                 diff_msec(base_t,
 151                                                         event['comm_t']))
 152                         print(PF_JOINT)
 153
 154 def trace_begin():
 155         global show_tx
 156         global show_rx
 157         global dev
 158         global debug
 159
 160         for i in range(len(sys.argv)):
 161                 if i == 0:
 162                         continue
 163                 arg = sys.argv[i]
 164                 if arg == 'tx':
 165                         show_tx = 1
 166                 elif arg =='rx':
 167                         show_rx = 1
 168                 elif arg.find('dev=',0, 4) >= 0:
 169                         dev = arg[4:]
 170                 elif arg == 'debug':
 171                         debug = 1
 172         if show_tx == 0  and show_rx == 0:
 173                 show_tx = 1
 174                 show_rx = 1
 175
 176 def trace_end():
 177         # order all events in time
 178         all_event_list.sort(key=cmp_to_key(lambda a,b :a[EINFO_IDX_TIME] < b[EINFO_IDX_TIME]))
 179         # process all events
 180         for i in range(len(all_event_list)):
 181                 event_info = all_event_list[i]
 182                 name = event_info[EINFO_IDX_NAME]
 183                 if name == 'irq__softirq_exit':
 184                         handle_irq_softirq_exit(event_info)
 185                 elif name == 'irq__softirq_entry':
 186                         handle_irq_softirq_entry(event_info)
 187                 elif name == 'irq__softirq_raise':
 188                         handle_irq_softirq_raise(event_info)
 189                 elif name == 'irq__irq_handler_entry':
 190                         handle_irq_handler_entry(event_info)
 191                 elif name == 'irq__irq_handler_exit':
 192                         handle_irq_handler_exit(event_info)
 193                 elif name == 'napi__napi_poll':
 194                         handle_napi_poll(event_info)
 195                 elif name == 'net__netif_receive_skb':
 196                         handle_netif_receive_skb(event_info)
 197                 elif name == 'net__netif_rx':
 198                         handle_netif_rx(event_info)
 199                 elif name == 'skb__skb_copy_datagram_iovec':
 200                         handle_skb_copy_datagram_iovec(event_info)
 201                 elif name == 'net__net_dev_queue':
 202                         handle_net_dev_queue(event_info)
 203                 elif name == 'net__net_dev_xmit':
 204                         handle_net_dev_xmit(event_info)
 205                 elif name == 'skb__kfree_skb':
 206                         handle_kfree_skb(event_info)
 207                 elif name == 'skb__consume_skb':
 208                         handle_consume_skb(event_info)
 209         # display receive hunks
 210         if show_rx:
 211                 for i in range(len(receive_hunk_list)):
 212                         print_receive(receive_hunk_list[i])
 213         # display transmit hunks
 214         if show_tx:
 215                 print("   dev    len      Qdisc        "
 216                         "       netdevice             free")
 217                 for i in range(len(tx_free_list)):
 218                         print_transmit(tx_free_list[i])
 219         if debug:
 220                 print("debug buffer status")
 221                 print("----------------------------")
 222                 print("xmit Qdisc:remain:%d overflow:%d" %
 223                         (len(tx_queue_list), of_count_tx_queue_list))
 224                 print("xmit netdevice:remain:%d overflow:%d" %
 225                         (len(tx_xmit_list), of_count_tx_xmit_list))
 226                 print("receive:remain:%d overflow:%d" %
 227                         (len(rx_skb_list), of_count_rx_skb_list))
 228
 229 # called from perf, when it finds a correspoinding event
 230 def irq__softirq_entry(name, context, cpu, sec, nsec, pid, comm, callchain, vec):
 231         if symbol_str("irq__softirq_entry", "vec", vec) != "NET_RX":
 232                 return
 233         event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm, vec)
 234         all_event_list.append(event_info)
 235
 236 def irq__softirq_exit(name, context, cpu, sec, nsec, pid, comm, callchain, vec):
 237         if symbol_str("irq__softirq_entry", "vec", vec) != "NET_RX":
 238                 return
 239         event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm, vec)
 240         all_event_list.append(event_info)
 241
 242 def irq__softirq_raise(name, context, cpu, sec, nsec, pid, comm, callchain, vec):
 243         if symbol_str("irq__softirq_entry", "vec", vec) != "NET_RX":
 244                 return
 245         event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm, vec)
 246         all_event_list.append(event_info)
 247
 248 def irq__irq_handler_entry(name, context, cpu, sec, nsec, pid, comm,
 249                         callchain, irq, irq_name):
 250         event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm,
 251                         irq, irq_name)
 252         all_event_list.append(event_info)
 253
 254 def irq__irq_handler_exit(name, context, cpu, sec, nsec, pid, comm, callchain, irq, ret):
 255         event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm, irq, ret)
 256         all_event_list.append(event_info)
 257
 258 def napi__napi_poll(name, context, cpu, sec, nsec, pid, comm, callchain, napi,
 259                     dev_name, work=None, budget=None):
 260         event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm,
 261                         napi, dev_name, work, budget)
 262         all_event_list.append(event_info)
 263
 264 def net__netif_receive_skb(name, context, cpu, sec, nsec, pid, comm, callchain, skbaddr,
 265                         skblen, dev_name):
 266         event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm,
 267                         skbaddr, skblen, dev_name)
 268         all_event_list.append(event_info)
 269
 270 def net__netif_rx(name, context, cpu, sec, nsec, pid, comm, callchain, skbaddr,
 271                         skblen, dev_name):
 272         event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm,
 273                         skbaddr, skblen, dev_name)
 274         all_event_list.append(event_info)
 275
 276 def net__net_dev_queue(name, context, cpu, sec, nsec, pid, comm, callchain,
 277                         skbaddr, skblen, dev_name):
 278         event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm,
 279                         skbaddr, skblen, dev_name)
 280         all_event_list.append(event_info)
 281
 282 def net__net_dev_xmit(name, context, cpu, sec, nsec, pid, comm, callchain,
 283                         skbaddr, skblen, rc, dev_name):
 284         event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm,
 285                         skbaddr, skblen, rc ,dev_name)
 286         all_event_list.append(event_info)
 287
 288 def skb__kfree_skb(name, context, cpu, sec, nsec, pid, comm, callchain,
 289                         skbaddr, protocol, location):
 290         event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm,
 291                         skbaddr, protocol, location)
 292         all_event_list.append(event_info)
 293
 294 def skb__consume_skb(name, context, cpu, sec, nsec, pid, comm, callchain, skbaddr):
 295         event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm,
 296                         skbaddr)
 297         all_event_list.append(event_info)
 298
 299 def skb__skb_copy_datagram_iovec(name, context, cpu, sec, nsec, pid, comm, callchain,
 300         skbaddr, skblen):
 301         event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm,
 302                         skbaddr, skblen)
 303         all_event_list.append(event_info)
 304
 305 def handle_irq_handler_entry(event_info):
 306         (name, context, cpu, time, pid, comm, irq, irq_name) = event_info
 307         if cpu not in irq_dic.keys():
 308                 irq_dic[cpu] = []
 309         irq_record = {'irq':irq, 'name':irq_name, 'cpu':cpu, 'irq_ent_t':time}
 310         irq_dic[cpu].append(irq_record)
 311
 312 def handle_irq_handler_exit(event_info):
 313         (name, context, cpu, time, pid, comm, irq, ret) = event_info
 314         if cpu not in irq_dic.keys():
 315                 return
 316         irq_record = irq_dic[cpu].pop()
 317         if irq != irq_record['irq']:
 318                 return
 319         irq_record.update({'irq_ext_t':time})
 320         # if an irq doesn't include NET_RX softirq, drop.
 321         if 'event_list' in irq_record.keys():
 322                 irq_dic[cpu].append(irq_record)
 323
 324 def handle_irq_softirq_raise(event_info):
 325         (name, context, cpu, time, pid, comm, vec) = event_info
 326         if cpu not in irq_dic.keys() \
 327         or len(irq_dic[cpu]) == 0:
 328                 return
 329         irq_record = irq_dic[cpu].pop()
 330         if 'event_list' in irq_record.keys():
 331                 irq_event_list = irq_record['event_list']
 332         else:
 333                 irq_event_list = []
 334         irq_event_list.append({'time':time, 'event':'sirq_raise'})
 335         irq_record.update({'event_list':irq_event_list})
 336         irq_dic[cpu].append(irq_record)
 337
 338 def handle_irq_softirq_entry(event_info):
 339         (name, context, cpu, time, pid, comm, vec) = event_info
 340         net_rx_dic[cpu] = {'sirq_ent_t':time, 'event_list':[]}
 341
 342 def handle_irq_softirq_exit(event_info):
 343         (name, context, cpu, time, pid, comm, vec) = event_info
 344         irq_list = []
 345         event_list = 0
 346         if cpu in irq_dic.keys():
 347                 irq_list = irq_dic[cpu]
 348                 del irq_dic[cpu]
 349         if cpu in net_rx_dic.keys():
 350                 sirq_ent_t = net_rx_dic[cpu]['sirq_ent_t']
 351                 event_list = net_rx_dic[cpu]['event_list']
 352                 del net_rx_dic[cpu]
 353         if irq_list == [] or event_list == 0:
 354                 return
 355         rec_data = {'sirq_ent_t':sirq_ent_t, 'sirq_ext_t':time,
 356                     'irq_list':irq_list, 'event_list':event_list}
 357         # merge information realted to a NET_RX softirq
 358         receive_hunk_list.append(rec_data)
 359
 360 def handle_napi_poll(event_info):
 361         (name, context, cpu, time, pid, comm, napi, dev_name,
 362                 work, budget) = event_info
 363         if cpu in net_rx_dic.keys():
 364                 event_list = net_rx_dic[cpu]['event_list']
 365                 rec_data = {'event_name':'napi_poll',
 366                                 'dev':dev_name, 'event_t':time,
 367                                 'work':work, 'budget':budget}
 368                 event_list.append(rec_data)
 369
 370 def handle_netif_rx(event_info):
 371         (name, context, cpu, time, pid, comm,
 372                 skbaddr, skblen, dev_name) = event_info
 373         if cpu not in irq_dic.keys() \
 374         or len(irq_dic[cpu]) == 0:
 375                 return
 376         irq_record = irq_dic[cpu].pop()
 377         if 'event_list' in irq_record.keys():
 378                 irq_event_list = irq_record['event_list']
 379         else:
 380                 irq_event_list = []
 381         irq_event_list.append({'time':time, 'event':'netif_rx',
 382                 'skbaddr':skbaddr, 'skblen':skblen, 'dev_name':dev_name})
 383         irq_record.update({'event_list':irq_event_list})
 384         irq_dic[cpu].append(irq_record)
 385
 386 def handle_netif_receive_skb(event_info):
 387         global of_count_rx_skb_list
 388
 389         (name, context, cpu, time, pid, comm,
 390                 skbaddr, skblen, dev_name) = event_info
 391         if cpu in net_rx_dic.keys():
 392                 rec_data = {'event_name':'netif_receive_skb',
 393                             'event_t':time, 'skbaddr':skbaddr, 'len':skblen}
 394                 event_list = net_rx_dic[cpu]['event_list']
 395                 event_list.append(rec_data)
 396                 rx_skb_list.insert(0, rec_data)
 397                 if len(rx_skb_list) > buffer_budget:
 398                         rx_skb_list.pop()
 399                         of_count_rx_skb_list += 1
 400
 401 def handle_net_dev_queue(event_info):
 402         global of_count_tx_queue_list
 403
 404         (name, context, cpu, time, pid, comm,
 405                 skbaddr, skblen, dev_name) = event_info
 406         skb = {'dev':dev_name, 'skbaddr':skbaddr, 'len':skblen, 'queue_t':time}
 407         tx_queue_list.insert(0, skb)
 408         if len(tx_queue_list) > buffer_budget:
 409                 tx_queue_list.pop()
 410                 of_count_tx_queue_list += 1
 411
 412 def handle_net_dev_xmit(event_info):
 413         global of_count_tx_xmit_list
 414
 415         (name, context, cpu, time, pid, comm,
 416                 skbaddr, skblen, rc, dev_name) = event_info
 417         if rc == 0: # NETDEV_TX_OK
 418                 for i in range(len(tx_queue_list)):
 419                         skb = tx_queue_list[i]
 420                         if skb['skbaddr'] == skbaddr:
 421                                 skb['xmit_t'] = time
 422                                 tx_xmit_list.insert(0, skb)
 423                                 del tx_queue_list[i]
 424                                 if len(tx_xmit_list) > buffer_budget:
 425                                         tx_xmit_list.pop()
 426                                         of_count_tx_xmit_list += 1
 427                                 return
 428
 429 def handle_kfree_skb(event_info):
 430         (name, context, cpu, time, pid, comm,
 431                 skbaddr, protocol, location) = event_info
 432         for i in range(len(tx_queue_list)):
 433                 skb = tx_queue_list[i]
 434                 if skb['skbaddr'] == skbaddr:
 435                         del tx_queue_list[i]
 436                         return
 437         for i in range(len(tx_xmit_list)):
 438                 skb = tx_xmit_list[i]
 439                 if skb['skbaddr'] == skbaddr:
 440                         skb['free_t'] = time
 441                         tx_free_list.append(skb)
 442                         del tx_xmit_list[i]
 443                         return
 444         for i in range(len(rx_skb_list)):
 445                 rec_data = rx_skb_list[i]
 446                 if rec_data['skbaddr'] == skbaddr:
 447                         rec_data.update({'handle':"kfree_skb",
 448                                         'comm':comm, 'pid':pid, 'comm_t':time})
 449                         del rx_skb_list[i]
 450                         return
 451
 452 def handle_consume_skb(event_info):
 453         (name, context, cpu, time, pid, comm, skbaddr) = event_info
 454         for i in range(len(tx_xmit_list)):
 455                 skb = tx_xmit_list[i]
 456                 if skb['skbaddr'] == skbaddr:
 457                         skb['free_t'] = time
 458                         tx_free_list.append(skb)
 459                         del tx_xmit_list[i]
 460                         return
 461
 462 def handle_skb_copy_datagram_iovec(event_info):
 463         (name, context, cpu, time, pid, comm, skbaddr, skblen) = event_info
 464         for i in range(len(rx_skb_list)):
 465                 rec_data = rx_skb_list[i]
 466                 if skbaddr == rec_data['skbaddr']:
 467                         rec_data.update({'handle':"skb_copy_datagram_iovec",
 468                                         'comm':comm, 'pid':pid, 'comm_t':time})
 469                         del rx_skb_list[i]
 470                         return