Re: [PATCH 1/8] perf: Allow to block process in syscall tracepoints

[Peter Zijlstra]

On Fri, Dec 07, 2018 at 12:49:21PM -0300, Arnaldo Carvalho de Melo wrote:
> Em Fri, Dec 07, 2018 at 04:11:05PM +0100, Peter Zijlstra escreveu:
> > On Fri, Dec 07, 2018 at 08:41:18AM -0500, Steven Rostedt wrote:
> > > On Fri, 7 Dec 2018 09:58:39 +0100 Peter Zijlstra <peterz@xxxxxxxxxxxxx> wrote:
> 
> > > > These patches give no justification *what*so*ever* for why we're doing
> > > > ugly arse things like this. And why does this, whatever this is, need to
> > > > be done in perf?
> 
> > > > IOW, what problem are we solving ?
> 
> > > I guess the cover letter should have had a link (or copy) of this:
> 
> > >  http://lkml.kernel.org/r/20181128134700.212ed035@xxxxxxxxxxxxxxxxxx
> 
> > That doesn't even begin to explain. Who cares about strace and why? And
> > why is it such a bad thing to loose the occasional record etc..
> 
> The following almost addresses all the details for doing such a perf
> based strace tool (modulo signals), was started by Thomas a long time
> ago [1] and is in the tree for a long time, with BPF attached to the
> raw_syscalls:sys_{enter,exit} (that -e augmented_raw_syscalls.c thing
> that lives in tools/perf/examples/bpf now but would be put in place
> transparently and pre-compiled as augmented_raw_syscalls.o) to collect
> pointer contents without using ptrace:

> For system wide stracing elliminating the feedback loop of your GUI
> components will most of the time work with the default ring buffer size
> and when it doesn't, you'll get things like that "LOST events!" message,
> and for such extreme cases, just use '-m' to bump the rb size some more.

> # trace  --filter-pids 2279,1643

>   8793.640 ( 0.001 ms): cc1/19097 read(fd: 21, buf: 0x3ed6a13, count: 4096                              ) = 0
> LOST 34956 events!
>   9497.921 ( 0.006 ms): gcc/19180 openat(dfd: CWD, filename: 0x3115e20, flags: NOCTTY                   ) = -1 ENOENT No such file or directory

> 'trace' is just 'perf trace', perf has logic to see if argv[0]  is
> 'trace', then it goes and does a 'perf trace'. The above case does't use
> bpf at all, gets details from /proc.
> 
> With bpf we get the 'filename' contents:
> 
> [root@seventh bpf]# trace -e augmented_raw_syscalls.c  --filter-pids 2279,1643
> <SNIP>
>  19766.027 ( 0.003 ms): gcc/27524 openat(dfd: CWD, filename: /lib64/libz.so.1, flags: CLOEXEC           ) = 5
>  19766.035 ( 0.001 ms): gcc/27524 fstat(fd: 5, statbuf: 0x7ffe9323e2a0                                  ) = 0
>  19766.037 ( 0.003 ms): gcc/27524 mmap(len: 2187272, prot: EXEC|READ, flags: PRIVATE|DENYWRITE, fd: 5   ) = 0x7fa2df435000
>  19766.042 ( 0.003 ms): gcc/27524 mprotect(start: 0x7fa2df44b000, len: 2093056                          ) = 0
>  19766.046 ( 0.004 ms): gcc/27524 mmap(addr: 0x7fa2df64a000, len: 4096, prot: READ|WRITE, flags: PRIVATE|FIXED|DENYWRITE, fd: 5, off: 86016) = 0x7fa2df64a000
>  19766.051 ( 0.002 ms): gcc/27524 mmap(addr: 0x7fa2df64b000, len: 8, prot: READ|WRITE, flags: PRIVATE|FIXED|ANONYMOUS) = 0x7fa2df64b000
>  19766.057 ( 0.001 ms): gcc/27524 close(fd: 5                                                           ) = 0
>  19766.062 ( 0.003 ms): gcc/27524 openat(dfd: CWD, filename: /lib64/libc.so.6, flags: CLOEXEC           ) = 5
> <SNIP>

Right; and that is all nice. And exactly doesn't answer my question. Why
do we care about those LOST entries so much that we have to do such
horribly ugly things?

Esp. as you point out, they're clearly marked in the output and easily
avoided by using a slightly larger buffer.