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

Howard Chu
2024-09-09T17:14:13Z

Hello Arnaldo,

On Mon, Sep 9, 2024 at 9:33 AM Arnaldo Carvalho de Melo <acme@kernel.org> wrote:
>
> On Sun, Aug 25, 2024 at 12:33:19AM +0800, Howard Chu wrote:
> > Define TRACE_AUG_MAX_BUF in trace_augment.h data, which is the maximum
> > buffer size we can augment. BPF will include this header too.
> >
> > Print buffer in a way that's different than just printing a string, we
> > print all the control characters in \digits (such as \0 for null, and
> > \10 for newline, LF).
> >
> > For character that has a bigger value than 127, we print the digits
> > instead of the character itself as well.
> >
> > Committer notes:
> >
> > Simplified the buffer scnprintf to avoid using multiple buffers as
> > discussed in the patch review thread.
> >
> > Signed-off-by: Howard Chu <howardchu95@gmail.com>
> > Cc: Adrian Hunter <adrian.hunter@intel.com>
> > Cc: Ian Rogers <irogers@google.com>
> > Cc: Jiri Olsa <jolsa@kernel.org>
> > Cc: Kan Liang <kan.liang@linux.intel.com>
> > Cc: Namhyung Kim <namhyung@kernel.org>
> > Link: https://lore.kernel.org/r/20240815013626.935097-8-howardchu95@gmail.com
> > Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
> > ---
> > tools/perf/builtin-trace.c | 33 +++++++++++++++++++++++++++++++++
> > tools/perf/util/trace_augment.h | 6 ++++++
> > 2 files changed, 39 insertions(+)
> > create mode 100644 tools/perf/util/trace_augment.h
> >
> > diff --git a/tools/perf/builtin-trace.c b/tools/perf/builtin-trace.c
> > index 048bcb92624c..470d74e3f875 100644
> > --- a/tools/perf/builtin-trace.c
> > +++ b/tools/perf/builtin-trace.c
> > @@ -65,6 +65,7 @@
> > #include "syscalltbl.h"
> > #include "rb_resort.h"
> > #include "../perf.h"
> > +#include "trace_augment.h"
> >
> > #include <errno.h>
> > #include <inttypes.h>
> > @@ -852,6 +853,10 @@ static size_t syscall_arg__scnprintf_filename(char *bf, size_t size,
> >
> > #define SCA_FILENAME syscall_arg__scnprintf_filename
> >
> > +static size_t syscall_arg__scnprintf_buf(char *bf, size_t size, struct syscall_arg *arg);
> > +
> > +#define SCA_BUF syscall_arg__scnprintf_buf
> > +
> > static size_t syscall_arg__scnprintf_pipe_flags(char *bf, size_t size,
> > struct syscall_arg *arg)
> > {
> > @@ -1745,6 +1750,32 @@ static size_t syscall_arg__scnprintf_filename(char *bf, size_t size,
> > return 0;
> > }
> >
> > +#define MAX_CONTROL_CHAR 31
> > +#define MAX_ASCII 127
> > +
> > +static size_t syscall_arg__scnprintf_buf(char *bf, size_t size, struct syscall_arg *arg)
> > +{
> > + struct augmented_arg *augmented_arg = arg->augmented.args;
> > + unsigned char *orig = (unsigned char *)augmented_arg->value;
> > + size_t printed = 0;
> > + int consumed;
> > +
> > + if (augmented_arg == NULL)
> > + return 0;
> > +
> > + for (int j = 0; j < augmented_arg->size; ++j) {
> > + bool control_char = orig[j] <= MAX_CONTROL_CHAR || orig[j] >= MAX_ASCII;
> > + /* print control characters (0~31 and 127), and non-ascii characters in \(digits) */
> > + printed += scnprintf(bf + printed, size - printed, control_char ? "\\%d" : "%c", (int)orig[j]);
> > + }
> > +
> > + consumed = sizeof(*augmented_arg) + augmented_arg->size;
> > + arg->augmented.args = ((void *)arg->augmented.args) + consumed;
> > + arg->augmented.size -= consumed;
> > +
> > + return printed;
> > +}
> > +
> > 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

No, we can't do it just now. Same with 'read family' such as
readlinkat, and getrandom.

> see testing after applying the following patch:
>
> 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.

Thank you so much!
>
> - Arnaldo

Thanks,
Howard