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

Arnaldo Carvalho de Melo
2024-09-09T16:45:41Z

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