perf probe/trace python scripting integration issues

perf probe/trace python scripting integration issues

[Arnaldo Carvalho de Melo]

Ok, now I'm trying to convert net/ipv4/tcp_probe.c to perf probe + perf
trace python scripting, so first thing I stumbled was:

[root@ana ~]# perf probe tcp_rcv_established:32 'saddr=tp->inet_conn.icsk_inet.inet_saddr daddr=tp->inet_conn.icsk_inet.inet_daddr sport=tp->inet_conn.icsk_inet.inet_sport dport=tp->inet_conn.icsk_inet.inet_dport'
Add new events:
Failed to write event: Invalid argument
  Error: Failed to add events. (-1)
[root@ana ~]#

The message is cryptic, but then I looked at dmesg and:

Line length is too long: Should be less than 128.

128 seems like too little for real fun, but anyway, I suppressed saddr,
assuming a machine with just an IP address then:

[root@ana ~]# perf probe tcp_rcv_established:32 'daddr=tp->inet_conn.icsk_inet.inet_daddr sport=tp->inet_conn.icsk_inet.inet_sport dport=tp->inet_conn.icsk_inet.inet_dport'
Add new events:
  probe:tcp_rcv_established (on tcp_rcv_established:32 with daddr=tp->inet_conn.icsk_inet.inet_daddr sport=tp->inet_conn.icsk_inet.inet_sport dport=tp->inet_conn.icsk_inet.inet_dport)
  probe:tcp_rcv_established_1 (on tcp_rcv_established:32 with daddr=tp->inet_conn.icsk_inet.inet_daddr sport=tp->inet_conn.icsk_inet.inet_sport dport=tp->inet_conn.icsk_inet.inet_dport)

You can now use it on all perf tools, such as:

	perf record -e probe:tcp_rcv_established_1 -aR sleep 1

[root@ana ~]#

Better, but why that _1? I did this several times, but:

[root@ana ~]# perf probe --list
  probe:tcp_rcv_established (on tcp_rcv_established:32@ipv4/tcp_input.c with daddr sport dport)
  probe:tcp_rcv_established_1 (on tcp_rcv_established:32@ipv4/tcp_input.c with daddr sport dport)
[root@ana ~]# perf probe -d probe:tcp_rcv_established
Remove event: probe:tcp_rcv_established
[root@ana ~]# perf probe --list
  probe:tcp_rcv_established_1 (on tcp_rcv_established:32@ipv4/tcp_input.c with daddr sport dport)
[root@ana ~]# perf probe -d probe:tcp_rcv_established_1
Remove event: probe:tcp_rcv_established_1
[root@ana ~]# perf probe --list
[root@ana ~]# perf probe tcp_rcv_established:32 'daddr=tp->inet_conn.icsk_inet.inet_daddr sport=tp->inet_conn.icsk_inet.inet_sport dport=tp->inet_conn.icsk_inet.inet_dport'
Add new events:
  probe:tcp_rcv_established (on tcp_rcv_established:32 with daddr=tp->inet_conn.icsk_inet.inet_daddr sport=tp->inet_conn.icsk_inet.inet_sport dport=tp->inet_conn.icsk_inet.inet_dport)
  probe:tcp_rcv_established_1 (on tcp_rcv_established:32 with daddr=tp->inet_conn.icsk_inet.inet_daddr sport=tp->inet_conn.icsk_inet.inet_sport dport=tp->inet_conn.icsk_inet.inet_dport)

You can now use it on all perf tools, such as:

	perf record -e probe:tcp_rcv_established_1 -aR sleep 1

[root@ana ~]#

Strange! It is adding two events for the price of one :-\

Anyway, then:

[root@ana ~]# perf record -a -e probe:tcp_rcv_established
^C[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.354 MB perf.data (~15445 samples) ]

[root@ana ~]#

And then lets get to perf trace --gen-script, which is a pearl, great stuff :-)

[root@ana ~]# perf trace --gen-script python
generated Python script: perf-trace.py
[root@ana ~]# cat perf-trace.py
# 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 *


def trace_begin():
	print "in trace_begin"

def trace_end():
	print "in trace_end"

def probe__tcp_rcv_established(event_name, context, common_cpu,
	common_secs, common_nsecs, common_pid, common_comm,
	__probe_ip, __probe_nargs, daddr, sport, 
	dport):
		print_header(event_name, common_cpu, common_secs, common_nsecs,
			common_pid, common_comm)

		print "__probe_ip=%u, __probe_nargs=%d, daddr=%u, " \
		"sport=%u, dport=%u\n" % \
		(__probe_ip, __probe_nargs, daddr, sport, 
		dport),

def trace_unhandled(event_name, context, event_fields_dict):
		print ' '.join(['%s=%s'%(k,str(v))for k,v in sorted(event_fields_dict.items())])

def print_header(event_name, cpu, secs, nsecs, pid, comm):
	print "%-20s %5u %05u.%09u %8u %-20s " % \
	(event_name, cpu, secs, nsecs, pid, comm),
[root@ana ~]#

If I add socket.inet_ntoa to pretty print daddr it works, but there is a
problem with sport:

[root@ana ~]# perf trace -s perf-trace.py
in trace_begin
probe__tcp_rcv_established 1 26900.345379960 2322 synergys daddr=192.168.1.9, sport=3577733216(<type 'long'>), dport=1625350111(<type 'int'>)
probe__tcp_rcv_established 1 26900.346405454    0 init     daddr=192.168.1.9, sport=3577733216(<type 'long'>), dport=1625350111(<type 'int'>)
probe__tcp_rcv_established 1 26901.638974088    0 init     daddr=192.168.1.120, sport=4043300960(<type 'long'>), dport=1625311633(<type 'int'>)
probe__tcp_rcv_established 1 26903.347126354 2320 synergys daddr=192.168.1.9, sport=3577864288(<type 'long'>), dport=1625350111(<type 'int'>)
probe__tcp_rcv_established 1 26903.349344114    0 init     daddr=192.168.1.9, sport=3577864288(<type 'long'>), dport=1625350111(<type 'int'>)
probe__tcp_rcv_established 1 26903.544836656    0 init     daddr=192.168.1.120, sport=4043432032(<type 'long'>), dport=1625311633(<type 'int'>)
probe__tcp_rcv_established 1 26903.610710303    0 init     daddr=192.168.1.120, sport=2052265472(<type 'int'>), dport=1487502(<type 'int'>)
in trace_end
[root@ana ~]#

Look at the sport type, it flips from long to int sometimes, I saw this on
dport too, ideas?

[root@ana ~]# cat /sys/kernel/debug/tracing/events/probe/tcp_rcv_established/format 
name: tcp_rcv_established
ID: 804
format:
	field:unsigned short common_type;	offset:0;	size:2;	signed:0;
	field:unsigned char common_flags;	offset:2;	size:1;	signed:0;
	field:unsigned char common_preempt_count;	offset:3;	size:1;	signed:0;
	field:int common_pid;	offset:4;	size:4;	signed:1;
	field:int common_lock_depth;	offset:8;	size:4;	signed:1;

	field:unsigned long __probe_ip;	offset:12;	size:4;	signed:0;
	field:int __probe_nargs;	offset:16;	size:4;	signed:1;
	field:unsigned long daddr;	offset:20;	size:4;	signed:0;
	field:unsigned long sport;	offset:24;	size:4;	signed:0;
	field:unsigned long dport;	offset:28;	size:4;	signed:0;

print fmt: "(%lx) daddr=%lx sport=%lx dport=%lx", REC->__probe_ip, REC->daddr, REC->sport, REC->dport
[root@ana ~]#

[root@ana ~]# uname -a
Linux ana.ghostprotocols.net 2.6.34.7-61.fc13.i686 #1 SMP Tue Oct 19 04:42:47 UTC 2010 i686 i686 i386 GNU/Linux

Ok, maybe this is just me trying to use the latest relesed kernel for a
current distribution, will try with 2.6.36-rc8 :-\

- Arnaldo