Linux Perf
netdev-times.py
Go to the documentation of this file.
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 
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':
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 
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
def handle_irq_softirq_raise(event_info)
def skb__skb_copy_datagram_iovec(name, context, cpu, sec, nsec, pid, comm, callchain, skbaddr, skblen)
def handle_irq_softirq_entry(event_info)
def net__netif_receive_skb(name, context, cpu, sec, nsec, pid, comm, callchain, skbaddr, skblen, dev_name)
def trace_begin()
def handle_irq_handler_exit(event_info)
def handle_net_dev_xmit(event_info)
def print_transmit(hunk)
Definition: netdev-times.py:61
def diff_msec(src, dst)
Definition: netdev-times.py:57
def irq__softirq_exit(name, context, cpu, sec, nsec, pid, comm, callchain, vec)
def handle_skb_copy_datagram_iovec(event_info)
def handle_irq_handler_entry(event_info)
def irq__irq_handler_entry(name, context, cpu, sec, nsec, pid, comm, callchain, irq, irq_name)
def skb__kfree_skb(name, context, cpu, sec, nsec, pid, comm, callchain, skbaddr, protocol, location)
def handle_net_dev_queue(event_info)
def net__netif_rx(name, context, cpu, sec, nsec, pid, comm, callchain, skbaddr, skblen, dev_name)
def nsecs_secs(nsecs)
Definition: Util.py:25
def handle_netif_receive_skb(event_info)
def net__net_dev_xmit(name, context, cpu, sec, nsec, pid, comm, callchain, skbaddr, skblen, rc, dev_name)
def handle_netif_rx(event_info)
def symbol_str(event_name, field_name, value)
Definition: Core.py:50
def napi__napi_poll(name, context, cpu, sec, nsec, pid, comm, callchain, napi, dev_name, work=None, budget=None)
def handle_consume_skb(event_info)
def handle_kfree_skb(event_info)
static unsigned int nsecs
Definition: futex-hash.c:32
def net__net_dev_queue(name, context, cpu, sec, nsec, pid, comm, callchain, skbaddr, skblen, dev_name)
def print_receive(hunk)
Definition: netdev-times.py:85
def irq__softirq_entry(name, context, cpu, sec, nsec, pid, comm, callchain, vec)
def irq__irq_handler_exit(name, context, cpu, sec, nsec, pid, comm, callchain, irq, ret)
def handle_napi_poll(event_info)
def skb__consume_skb(name, context, cpu, sec, nsec, pid, comm, callchain, skbaddr)
def nsecs_nsecs(nsecs)
Definition: Util.py:28
def handle_irq_softirq_exit(event_info)
def irq__softirq_raise(name, context, cpu, sec, nsec, pid, comm, callchain, vec)