tracepoint filter problems

* tracepoint filter problems
@ 2015-10-29 15:27 Arnaldo Carvalho de Melo
  2015-11-02  9:50 ` Peter Zijlstra
  0 siblings, 1 reply; 4+ messages in thread
From: Arnaldo Carvalho de Melo @ 2015-10-29 15:27 UTC (permalink / raw)
  To: Peter Zijlstra
  Cc: Frédéric Weisbecker, Jiri Olsa, David Ahern,
	Adrian Hunter, Wang Nan, Steven Rostedt,
	Linux Kernel Mailing List

Hi,

	In 'perf trace' we have an equivalent to strace's -e option, i.e. a way
to state which syscalls one wants to see, so, when we do:

[root@felicio linux]# trace -e open
     0.348 ( 0.005 ms): ls/6887 open(filename: /etc/ld.so.cache, flags: CLOEXEC                       ) = 3
     0.363 ( 0.005 ms): ls/6887 open(filename: /lib64/libselinux.so.1, flags: CLOEXEC                 ) = 3
     0.400 ( 0.006 ms): ls/6887 open(filename: /lib64/libcap.so.2, flags: CLOEXEC                     ) = 3
     0.427 ( 0.006 ms): ls/6887 open(filename: /lib64/libacl.so.1, flags: CLOEXEC                     ) = 3
     0.454 ( 0.006 ms): ls/6887 open(filename: /lib64/libc.so.6, flags: CLOEXEC                       ) = 3
     0.497 ( 0.006 ms): ls/6887 open(filename: /lib64/libpcre.so.1, flags: CLOEXEC                    ) = 3
     0.533 ( 0.006 ms): ls/6887 open(filename: /lib64/liblzma.so.5, flags: CLOEXEC                    ) = 3
     0.561 ( 0.006 ms): ls/6887 open(filename: /lib64/libdl.so.2, flags: CLOEXEC                      ) = 3
     0.586 ( 0.006 ms): ls/6887 open(filename: /lib64/libattr.so.1, flags: CLOEXEC                    ) = 3
     0.611 ( 0.006 ms): ls/6887 open(filename: /lib64/libpthread.so.0, flags: CLOEXEC                 ) = 3
     0.859 ( 0.007 ms): ls/6887 open(filename: /usr/lib/locale/locale-archive, flags: CLOEXEC         ) = 3
^C[root@felicio linux]#

I.e. tracing system wide, looking for any program that calls the open syscall, it works, as it
used the PERF_EVENT_IOC_SET_FILTER to set the relevant 'id == 486' to filter it:

[root@felicio linux]# head -2 /sys/kernel/debug/tracing/events/syscalls/sys_enter_open/format 
name: sys_enter_open
ID: 486

Ok, this is how it should be, all works, but if I try instead calling a program
that in turn calls another, the filter will apply for the first in line, but
not for the calls made by another program called from it.

In the example below 'perf trace' will ask to see just the 'open' syscall, and
it works for the started workload, namely 'perf record', but then it'll call
'sleep 100000000000' and there the filter doesn't apply, bummer :-\

The inherit bit is set, sure, as we can see when adding -vv to the 'perf trace'
call, ideas?

I came accross this wanting to trace perf record with a bpf proggie that would
call another workload, and I wanted to see just the perf_event_open and bpf
syscalls, but ended up seeing all the syscalls in the leaf workload.

- Arnaldo

[root@felicio linux]# perf trace -e open perf record -e /tmp/foo.o sleep 100000000000
     0.091 ( 0.007 ms): perf/6875 open(filename: 0x96590bf0, flags: CLOEXEC                             ) = -1 ENOENT No such file or directory
     0.096 ( 0.002 ms): perf/6875 open(filename: 0x96590bf0, flags: CLOEXEC                             ) = -1 ENOENT No such file or directory
     0.100 ( 0.002 ms): perf/6875 open(filename: 0x96590bf0, flags: CLOEXEC                             ) = -1 ENOENT No such file or directory
     0.103 ( 0.002 ms): perf/6875 open(filename: 0x96590bf0, flags: CLOEXEC                             ) = -1 ENOENT No such file or directory
     0.110 ( 0.003 ms): perf/6875 open(filename: 0x7629da98, flags: CLOEXEC                             ) = 3
   386.185 ( 0.005 ms): perf/6875 open(filename: 0x965868a0, mode: 20                                   ) = 10
   386.800 ( 0.008 ms): perf/6875 open(filename: 0x96588ae0, mode: 20                                   ) = 8
<SNIP tons of open syscalls>
   387.426 ( 0.002 ms): :6876/6876 set_robust_list(head: 0x7faa76484a60, len: 24                         ) = 0
   387.446 ( 0.002 ms): :6876/6876 rt_sigaction(sig: TERM, act: 0x7ffe9658ebc0, oact: 0x7ffe9658ec60, sigsetsize: 8) = 0
   387.449 ( 0.001 ms): :6876/6876 close(fd: 5                                                           ) = 0
   387.450 ( 0.001 ms): :6876/6876 close(fd: 8                                                           ) = 0
<SNIP some syscalls for pid 6876>
   391.573 ( 0.002 ms): perf/6876 execve(arg0: 140731420831140, arg1: 140731420841520, arg2: 140731420841568, arg3: 140731420830688, arg4: 7307199665339051828, arg5: 140731420830816) = -2
   391.580 ( 0.006 ms): perf/6876 execve(arg0: 140731420831149, arg1: 140731420841520, arg2: 140731420841568, arg3: 140731420830688, arg4: 7307199665339051828, arg5: 140731420830816) = -2
   392.009 ( 0.428 ms): sleep/6876 execve(arg0: 140731420831150, arg1: 140731420841520, arg2: 140731420841568, arg3: 140731420830688, arg4: 7307199665339051828, arg5: 140731420830816) = 0
   392.030 ( 0.001 ms): sleep/6876 brk(                                                                  ) = 0x14f1000
   392.042 ( 0.003 ms): sleep/6876 mmap(len: 4096, prot: READ|WRITE, flags: PRIVATE|ANONYMOUS, fd: -1    ) = 0x7f9223117000
   392.050 ( 0.004 ms): sleep/6876 access(filename: 0x22f151a0, mode: R                                  ) = -1 ENOENT No such file or directory
   392.058 ( 0.004 ms): sleep/6876 open(filename: 0x22f13a98, flags: CLOEXEC                             ) = 3
   392.060 ( 0.001 ms): sleep/6876 fstat(fd: 3, statbuf: 0x7ffeb5f28660                                  ) = 0
   392.064 ( 0.003 ms): sleep/6876 mmap(len: 62420, prot: READ, flags: PRIVATE, fd: 3                    ) = 0x7f9223107000
   392.066 ( 0.001 ms): sleep/6876 close(fd: 3                                                           ) = 0
   392.076 ( 0.005 ms): sleep/6876 open(filename: 0x23114dcf, flags: CLOEXEC                             ) = 3
<SNIP> some more

^ permalink raw reply	[flat|nested] 4+ messages in thread