Re: [PATCH v3 5/8] perf trace: Pretty print buffer data

[Arnaldo Carvalho de Melo <acme@kernel.org>]

On Mon, Sep 09, 2024 at 10:17:34AM -0700, Howard Chu wrote:
> On Mon, Sep 9, 2024 at 9:45 AM Arnaldo Carvalho de Melo <acme@kernel.org> wrote:
> >
> > On Mon, Sep 09, 2024 at 01:33:17PM -0300, Arnaldo Carvalho de Melo wrote:
> > > >  static bool trace__filter_duration(struct trace *trace, double t)
> > > >  {
> > > >     return t < (trace->duration_filter * NSEC_PER_MSEC);
> > > > @@ -1956,6 +1987,8 @@ syscall_arg_fmt__init_array(struct syscall_arg_fmt *arg, struct tep_format_field
> > > >                 ((len >= 4 && strcmp(field->name + len - 4, "name") == 0) ||
> > > >                  strstr(field->name, "path") != NULL))
> > > >                     arg->scnprintf = SCA_FILENAME;
> > > > +           else if (strstr(field->type, "char *") && strstr(field->name, "buf"))
> > > > +                   arg->scnprintf = SCA_BUF;
> > >
> > > You can't really do this for things like 'read' as we would be printing
> > > whatever is in the buffer when we enter the syscall, right? As we can
> > > see testing after applying the following patch:
> >
> > This is also valid for the struct dumper, where I'll have to add some
> > indication in the syscall_fmt table when the pointer should be read in
> > the BPF augmenter, and thus we shouldn't bother to get it in the
> > sys_enter if it is, say, fstat().
> 
> Yes you are right, problems with read buffers happen in structs too.
> I'll get my read family patch out soon to ease your pain...

And then we have things like prctl, arch_prctl where it depends on the
command to see if the arg is to go from user to kernel or the other way
around :-)

But lets leave that for later...
 
> Thanks,
> Howard
> >
> > - Arnaldo
> >
> > > root@number:~# perf trace -e read,write cat /etc/passwd > /dev/null
> > >      0.000 ( 0.004 ms): cat/291442 read(fd: 3, buf: \0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0, count: 832) = 832
> > >      0.231 ( 0.004 ms): cat/291442 read(fd: 3, buf: , count: 131072)                                     = 3224
> > >      0.236 ( 0.001 ms): cat/291442 write(fd: 1, buf: root:x:0:0:Super User:/root:/bin, count: 3224)      = 3224
> > >      0.239 ( 0.001 ms): cat/291442 read(fd: 3, buf: root:x:0:0:Super User:/root:/bin, count: 131072)     = 0
> > > root@number:~#
> > >
> > > So we can't really do it at this point, we have to do it, for now, by
> > > doing it on that syscall table initialization, for instance, for the
> > > 'write' syscall:
> > >
> > > diff --git a/tools/perf/builtin-trace.c b/tools/perf/builtin-trace.c
> > > index 5f0877e891c2047d..1bcb45e737d830bf 100644
> > > --- a/tools/perf/builtin-trace.c
> > > +++ b/tools/perf/builtin-trace.c
> > > @@ -1379,6 +1379,8 @@ static const struct syscall_fmt syscall_fmts[] = {
> > >         .arg = { [2] = { .scnprintf = SCA_WAITID_OPTIONS, /* options */ }, }, },
> > >       { .name     = "waitid",     .errpid = true,
> > >         .arg = { [3] = { .scnprintf = SCA_WAITID_OPTIONS, /* options */ }, }, },
> > > +     { .name     = "write",      .errpid = true,
> > > +       .arg = { [1] = { .scnprintf = SCA_BUF, /* buf */ }, }, },
> > >  };
> > >
> > >  static int syscall_fmt__cmp(const void *name, const void *fmtp)
> > > @@ -1987,8 +1989,6 @@ syscall_arg_fmt__init_array(struct syscall_arg_fmt *arg, struct tep_format_field
> > >                   ((len >= 4 && strcmp(field->name + len - 4, "name") == 0) ||
> > >                    strstr(field->name, "path") != NULL))
> > >                       arg->scnprintf = SCA_FILENAME;
> > > -             else if (strstr(field->type, "char *") && strstr(field->name, "buf"))
> > > -                     arg->scnprintf = SCA_BUF;
> > >               else if ((field->flags & TEP_FIELD_IS_POINTER) || strstr(field->name, "addr"))
> > >                       arg->scnprintf = SCA_PTR;
> > >               else if (strcmp(field->type, "pid_t") == 0)
> > >
> > > With that we get:
> > >
> > > root@number:~# perf trace -e read,write cat /etc/passwd > /dev/null
> > >      0.000 ( 0.005 ms): cat/296870 read(fd: 3, buf: 0x7ffe9cb8df98, count: 832)                          = 832
> > >      0.268 ( 0.004 ms): cat/296870 read(fd: 3, buf: 0x7fa7d700a000, count: 131072)                       = 3224
> > >      0.273 ( 0.002 ms): cat/296870 write(fd: 1, buf: root:x:0:0:Super User:/root:/bin, count: 3224)      =
> > >      0.276 ( 0.001 ms): cat/296870 read(fd: 3, buf: 0x7fa7d700a000, count: 131072)                       = 0
> > > root@number:~#
> > >
> > > After the following patch is applied.
> > >
> > > - Arnaldo