linux/tools/perf/scripts/python/netdev-times.py
<<
>>
Prefs
   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
  10import os
  11import sys
  12
  13sys.path.append(os.environ['PERF_EXEC_PATH'] + \
  14        '/scripts/python/Perf-Trace-Util/lib/Perf/Trace')
  15
  16from perf_trace_context import *
  17from Core import *
  18from Util import *
  19
  20all_event_list = []; # insert all tracepoint event related with this script
  21irq_dic = {}; # key is cpu and value is a list which stacks irqs
  22              # which raise NET_RX softirq
  23net_rx_dic = {}; # key is cpu and value include time of NET_RX softirq-entry
  24                 # and a list which stacks receive
  25receive_hunk_list = []; # a list which include a sequence of receive events
  26rx_skb_list = []; # received packet list for matching
  27                       # skb_copy_datagram_iovec
  28
  29buffer_budget = 65536; # the budget of rx_skb_list, tx_queue_list and
  30                       # tx_xmit_list
  31of_count_rx_skb_list = 0; # overflow count
  32
  33tx_queue_list = []; # list of packets which pass through dev_queue_xmit
  34of_count_tx_queue_list = 0; # overflow count
  35
  36tx_xmit_list = [];  # list of packets which pass through dev_hard_start_xmit
  37of_count_tx_xmit_list = 0; # overflow count
  38
  39tx_free_list = [];  # list of packets which is freed
  40
  41# options
  42show_tx = 0;
  43show_rx = 0;
  44dev = 0; # store a name of device specified by option "dev="
  45debug = 0;
  46
  47# indices of event_info tuple
  48EINFO_IDX_NAME=   0
  49EINFO_IDX_CONTEXT=1
  50EINFO_IDX_CPU=    2
  51EINFO_IDX_TIME=   3
  52EINFO_IDX_PID=    4
  53EINFO_IDX_COMM=   5
  54
  55# Calculate a time interval(msec) from src(nsec) to dst(nsec)
  56def diff_msec(src, dst):
  57        return (dst - src) / 1000000.0
  58
  59# Display a process of transmitting a packet
  60def 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
  71PF_IRQ_ENTRY= "  irq_entry(+%.3fmsec irq=%d:%s)"
  72PF_SOFT_ENTRY="  softirq_entry(+%.3fmsec)"
  73PF_NAPI_POLL= "  napi_poll_exit(+%.3fmsec %s)"
  74PF_JOINT=     "         |"
  75PF_WJOINT=    "         |            |"
  76PF_NET_RECV=  "         |---netif_receive_skb(+%.3fmsec skb=%x len=%d)"
  77PF_NET_RX=    "         |---netif_rx(+%.3fmsec skb=%x)"
  78PF_CPY_DGRAM= "         |      skb_copy_datagram_iovec(+%.3fmsec %d:%s)"
  79PF_KFREE_SKB= "         |      kfree_skb(+%.3fmsec location=%x)"
  80PF_CONS_SKB=  "         |      consume_skb(+%.3fmsec)"
  81
  82# Display a process of received packets and interrputs associated with
  83# a NET_RX softirq
  84def 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
 150def 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
 172def 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
 227def irq__softirq_entry(name, context, cpu, sec, nsec, pid, comm, 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
 233def irq__softirq_exit(name, context, cpu, sec, nsec, pid, comm, 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
 239def irq__softirq_raise(name, context, cpu, sec, nsec, pid, comm, 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
 245def irq__irq_handler_entry(name, context, cpu, sec, nsec, pid, comm,
 246                        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
 251def irq__irq_handler_exit(name, context, cpu, sec, nsec, pid, comm, irq, ret):
 252        event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm, irq, ret)
 253        all_event_list.append(event_info)
 254
 255def napi__napi_poll(name, context, cpu, sec, nsec, pid, comm, 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
 260def net__netif_receive_skb(name, context, cpu, sec, nsec, pid, comm, 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
 266def net__netif_rx(name, context, cpu, sec, nsec, pid, comm, 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
 272def net__net_dev_queue(name, context, cpu, sec, nsec, pid, comm,
 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
 278def net__net_dev_xmit(name, context, cpu, sec, nsec, pid, comm,
 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
 284def skb__kfree_skb(name, context, cpu, sec, nsec, pid, comm,
 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
 290def skb__consume_skb(name, context, cpu, sec, nsec, pid, comm, skbaddr):
 291        event_info = (name, context, cpu, nsecs(sec, nsec), pid, comm,
 292                        skbaddr)
 293        all_event_list.append(event_info)
 294
 295def skb__skb_copy_datagram_iovec(name, context, cpu, sec, nsec, pid, comm,
 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
 301def 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
 308def 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
 320def 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
 334def 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
 338def 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
 356def 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
 364def 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
 380def 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
 395def 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
 406def 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
 423def 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
 446def 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
 456def 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
 465
lxr.linux.no kindly hosted by Redpill Linpro AS, provider of Linux consulting and operations services since 1995.