lkml.org 
[lkml]   [2010]   [Nov]   [4]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
Date
From
Subjectperf probe/trace python scripting integration issues
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


\
 
 \ /
  Last update: 2010-11-04 18:37    [W:0.039 / U:0.016 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site