Subject: [RFC PATCH 2/2] netdev: perf script to show the number of tx-packets in device

From: Koki Sanagi <[email-masked]>
Date: Mon, 24 May 2010 13:52:36 +0900

This patch adds perf script to calculate the time from entry of
ndo_start_xmit to dev_kfree_skb_* and the number of tx-packets in device.

Signed-off-by: Koki Sanagi <[email-masked]>
---
 .../scripts/python/bin/tx-packet-in-device-record  |    2 +
 .../scripts/python/bin/tx-packet-in-device-report  |    4 +
 tools/perf/scripts/python/tx-packet-in-device.py   |  109 ++++++++++++++++++++
 3 files changed, 115 insertions(+), 0 deletions(-)

diff --git a/tools/perf/scripts/python/bin/tx-packet-in-device-record b/tools/perf/scripts/python/bin/tx-packet-in-device-record
new file mode 100644
index 0000000..18f2356
--- /dev/null
+++ b/tools/perf/scripts/python/bin/tx-packet-in-device-record
@@ -0,0 +1,2 @@
+#!/bin/bash
+perf record -c 1 -f -a -M -R -e skb:netdev_start_xmit -e skb:consume_skb -e skb:dev_kfree_skb_irq
diff --git a/tools/perf/scripts/python/bin/tx-packet-in-device-report b/tools/perf/scripts/python/bin/tx-packet-in-device-report
new file mode 100644
index 0000000..8ef4cc2
--- /dev/null
+++ b/tools/perf/scripts/python/bin/tx-packet-in-device-report
@@ -0,0 +1,4 @@
+#!/bin/bash
+# description: netif_receive_skb counts per poll
+# args: [comm]
+perf trace -s ~/libexec/perf-core/scripts/python/tx-packet-in-device.py $1
diff --git a/tools/perf/scripts/python/tx-packet-in-device.py b/tools/perf/scripts/python/tx-packet-in-device.py
new file mode 100644
index 0000000..fb1933f
--- /dev/null
+++ b/tools/perf/scripts/python/tx-packet-in-device.py
@@ -0,0 +1,109 @@
+# perf trace event handlers, generated by perf trace -g python
+# Licensed under the terms of the GNU GPL License version 2
+
+# The common_* event handler fields are the most useful fields common to
+# all events.  They don't necessarily correspond to the 'common_*' fields
+# in the format files.  Those fields not available as handler params can
+# be retrieved using Python functions of the form common_*(context).
+# See the perf-trace-python Documentation for the list of available functions.
+
+import os
+import sys
+
+sys.path.append(os.environ['PERF_EXEC_PATH'] + \
+	'/scripts/python/Perf-Trace-Util/lib/Perf/Trace')
+
+from perf_trace_context import *
+from Core import *
+from Util import *
+
+# skb_dic = {skbaddr: {name:*, start_time:*}}
+#
+# skbaddr: address of skb through dev_hard_start_xmit
+# name: name of device
+# start_time: the time dev_start_hard_xmit pass
+skb_dic = {};
+
+# dev_stat_dic = {name: {pkt_in_tx:*, max_pkt_in_tx:*, total_pkt:*,
+#			 prev_time:*, total_time:*, max_lap_time:*,
+#			 total_lap_time:*}}
+#
+# name: name of device
+# pkt_in_tx: tx-packets a device has currently
+# max_pkt_in_tx: maximum of the above
+# total_pkt: total tx-packets through a device
+# prev_time: the time starting xmit or freeing skb
+#            happened previously
+# total_time: the time from first starting xmit to now
+# max_lap_time: maximum time from starting xmit to freein skb
+# total_lap_time: sum of time tx-packet is in device
+dev_stat_dic = {};
+
+def trace_end():
+	for name in sorted(dev_stat_dic.keys()):
+		cstat = dev_stat_dic[name]
+		print "%s\tTX packets=%d" %\
+			(name, cstat['total_pkt'])
+		print "\tlap time between start_xmit - free_skb:"
+		avg_nsec = avg(1.0 * cstat['total_lap_time'],
+				cstat['total_pkt'])
+		print "\t    avg=%fmsec" % (avg_nsec / 1000000.0)
+		print "\t    max=%fmsec" % (cstat['max_lap_time'] / 1000000.0)
+		print "\tnumber of packets in device:"
+		print "\t    avg=%7.2f" % avg(cstat['total_lap_time'] * 1.0,
+						cstat['total_time'])
+		print "\t    max=%4d" % cstat['max_pkt_in_tx']
+		print ""
+
+def skb__dev_kfree_skb_irq(event_name, context, common_cpu,
+	common_secs, common_nsecs, common_pid, common_comm,
+	skbaddr):
+		free_skb(event_name, context, common_cpu,
+		common_secs, common_nsecs, common_pid, common_comm,
+		skbaddr)
+
+def skb__consume_skb(event_name, context, common_cpu,
+	common_secs, common_nsecs, common_pid, common_comm,
+	skbaddr):
+		free_skb(event_name, context, common_cpu,
+		common_secs, common_nsecs, common_pid, common_comm,
+		skbaddr)
+
+def free_skb(event_name, context, common_cpu,
+	common_secs, common_nsecs, common_pid, common_comm,
+	skbaddr):
+		if skbaddr in skb_dic.keys():
+			ctime = nsecs(common_secs, common_nsecs)
+			lap_time = ctime - skb_dic[skbaddr]['start_time']
+			cstat = dev_stat_dic[skb_dic[skbaddr]['name']]
+			cstat['total_lap_time'] += lap_time;
+			cstat['total_pkt'] += 1;
+			cstat = dev_stat_dic[skb_dic[skbaddr]['name']]
+			cstat['total_time'] += ctime - cstat['prev_time']
+			cstat['prev_time'] = ctime
+			cstat['pkt_in_tx'] -= 1;
+			if lap_time > cstat['max_lap_time']:
+				cstat['max_lap_time'] = lap_time
+			del skb_dic[skbaddr]
+
+def skb__netdev_start_xmit(event_name, context, common_cpu,
+	common_secs, common_nsecs, common_pid, common_comm,
+	skbaddr, len, name):
+		retry = 0
+		ctime = nsecs(common_secs, common_nsecs)
+		if skbaddr in skb_dic.keys():
+			retry = 1;
+		skb_dic[skbaddr] = {'name':name, 'start_time':ctime}
+		if name not in dev_stat_dic.keys():
+			dev_stat_dic[name] = {'pkt_in_tx':0, 'max_pkt_in_tx':0,\
+					'total_pkt':0,\
+					'prev_time':ctime, 'total_time':0,\
+					'max_lap_time':0, 'total_lap_time':0}
+		cstat = dev_stat_dic[name]
+		cstat['total_time'] += ctime - cstat['prev_time']
+		cstat['prev_time'] = ctime
+		if retry == 0:
+			cstat['pkt_in_tx'] += 1
+		if cstat['pkt_in_tx'] > cstat['max_pkt_in_tx']:
+			cstat['max_pkt_in_tx'] = cstat['pkt_in_tx']
+