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

[Howard Chu]

Hello Arnaldo,

On Mon, Sep 9, 2024 at 9:33 AM Arnaldo Carvalho de Melo <acme@xxxxxxxxxx> 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@xxxxxxxxx>
> > Cc: Adrian Hunter <adrian.hunter@xxxxxxxxx>
> > Cc: Ian Rogers <irogers@xxxxxxxxxx>
> > Cc: Jiri Olsa <jolsa@xxxxxxxxxx>
> > Cc: Kan Liang <kan.liang@xxxxxxxxxxxxxxx>
> > Cc: Namhyung Kim <namhyung@xxxxxxxxxx>
> > Link: https://lore.kernel.org/r/20240815013626.935097-8-howardchu95@xxxxxxxxx
> > Signed-off-by: Arnaldo Carvalho de Melo <acme@xxxxxxxxxx>
> > ---
> >  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