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

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

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