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

Howard Chu posted 8 patches 1 year, 3 months ago
[PATCH v3 5/8] perf trace: Pretty print buffer data
Posted by Howard Chu 1 year, 3 months ago
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;
 		else if ((field->flags & TEP_FIELD_IS_POINTER) || strstr(field->name, "addr"))
 			arg->scnprintf = SCA_PTR;
 		else if (strcmp(field->type, "pid_t") == 0)
diff --git a/tools/perf/util/trace_augment.h b/tools/perf/util/trace_augment.h
new file mode 100644
index 000000000000..57a3e5045937
--- /dev/null
+++ b/tools/perf/util/trace_augment.h
@@ -0,0 +1,6 @@
+#ifndef TRACE_AUGMENT_H
+#define TRACE_AUGMENT_H
+
+#define TRACE_AUG_MAX_BUF 32 /* for buffer augmentation in perf trace */
+
+#endif
-- 
2.45.2
Re: [PATCH v3 5/8] perf trace: Pretty print buffer data
Posted by Arnaldo Carvalho de Melo 1 year, 3 months ago
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
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.

- Arnaldo
Re: [PATCH v3 5/8] perf trace: Pretty print buffer data
Posted by Howard Chu 1 year, 3 months ago
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
Re: [PATCH v3 5/8] perf trace: Pretty print buffer data
Posted by Arnaldo Carvalho de Melo 1 year, 3 months ago
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
Re: [PATCH v3 5/8] perf trace: Pretty print buffer data
Posted by Howard Chu 1 year, 3 months ago
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...

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
Re: [PATCH v3 5/8] perf trace: Pretty print buffer data
Posted by Arnaldo Carvalho de Melo 1 year, 3 months ago
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
Re: [PATCH v3 5/8] perf trace: Pretty print buffer data
Posted by Arnaldo Carvalho de Melo 1 year, 3 months ago
On Mon, Sep 09, 2024 at 01:45:41PM -0300, Arnaldo Carvalho de Melo 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().

BTW, what I have so far, without addressing this last comment about the
struct pretty printing/collection is at the tmp.perf-tools-next branch:

⬢[acme@toolbox perf-tools-next]$ git log --oneline perf-tools-next/perf-tools-next..
14053de1be2bf3b1 (HEAD -> perf-tools-next, x1/perf-tools-next, perf-tools-next/tmp.perf-tools-next, acme/tmp.perf-tools-next) perf trace: Collect augmented data using BPF
3f060c2fe93b8298 perf trace: Pretty print buffer data
01ca0102b80c7b5c perf trace: Pretty print struct data
bb0819cf7392b797 perf trace: Add trace__bpf_sys_enter_beauty_map() to prepare for fetching data in BPF
6b22c2b502a1c21b perf trace: Use a common encoding for augmented arguments, with size + error + payload
5d9cd24924f57066 perf trace augmented_syscalls.bpf: Move the renameat aumenter to renameat2, temporarily
⬢[acme@toolbox perf-tools-next]$

⬢[acme@toolbox perf-tools-next]$ git remote -v | grep ^perf-tools-next
perf-tools-next	https://git.kernel.org/pub/scm/linux/kernel/git/perf/perf-tools-next.git (fetch)
perf-tools-next	https://git.kernel.org/pub/scm/linux/kernel/git/perf/perf-tools-next.git (push)
⬢[acme@toolbox perf-tools-next]$
 
- Arnaldo