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

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

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().

- 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