All of lore.kernel.org
 help / color / mirror / Atom feed
From: Arnaldo Carvalho de Melo <acme@kernel.org>
To: Peter Zijlstra <peterz@infradead.org>
Cc: "Frédéric Weisbecker" <fweisbec@gmail.com>,
	"Jiri Olsa" <jolsa@kernel.org>, "David Ahern" <dsahern@gmail.com>,
	"Adrian Hunter" <adrian.hunter@intel.com>,
	"Wang Nan" <wangnan0@huawei.com>,
	"Steven Rostedt" <rostedt@goodmis.org>,
	"Linux Kernel Mailing List" <linux-kernel@vger.kernel.org>
Subject: tracepoint filter problems
Date: Thu, 29 Oct 2015 12:27:42 -0300	[thread overview]
Message-ID: <20151029152742.GB2923@kernel.org> (raw)

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

             reply	other threads:[~2015-10-29 15:27 UTC|newest]

Thread overview: 4+ messages / expand[flat|nested]  mbox.gz  Atom feed  top
2015-10-29 15:27 Arnaldo Carvalho de Melo [this message]
2015-11-02  9:50 ` Peter Zijlstra
2015-11-03  1:13   ` Arnaldo Carvalho de Melo
2015-11-10  6:40   ` [tip:perf/urgent] perf: Fix inherited events vs. tracepoint filters tip-bot for Peter Zijlstra

Reply instructions:

You may reply publicly to this message via plain-text email
using any one of the following methods:

* Save the following mbox file, import it into your mail client,
  and reply-to-all from there: mbox

  Avoid top-posting and favor interleaved quoting:
  https://en.wikipedia.org/wiki/Posting_style#Interleaved_style

* Reply using the --to, --cc, and --in-reply-to
  switches of git-send-email(1):

  git send-email \
    --in-reply-to=20151029152742.GB2923@kernel.org \
    --to=acme@kernel.org \
    --cc=adrian.hunter@intel.com \
    --cc=dsahern@gmail.com \
    --cc=fweisbec@gmail.com \
    --cc=jolsa@kernel.org \
    --cc=linux-kernel@vger.kernel.org \
    --cc=peterz@infradead.org \
    --cc=rostedt@goodmis.org \
    --cc=wangnan0@huawei.com \
    --subject='Re: tracepoint filter problems' \
    /path/to/YOUR_REPLY

  https://kernel.org/pub/software/scm/git/docs/git-send-email.html

* If your mail client supports setting the In-Reply-To header
  via mailto: links, try the mailto: link

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.