Re: [PATCH v3] perf trace: avoid garbage when not printing a trace event's arguments

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

On Sun, Nov 03, 2024 at 08:48:16PM +0000, Benjamin Peterson wrote:
> trace__fprintf_tp_fields may not print any tracepoint arguments. E.g., if the
> argument values are all zero. Previously, this would result in a totally
> uninitialized buffer being passed to fprintf, which could lead to garbage on the
> console. Fix the problem by passing the number of initialized bytes fprintf.
> 
> Fixes: f11b2803bb88 ("perf trace: Allow choosing how to augment the tracepoint arguments")
> Signed-off-by: Benjamin Peterson <benjamin@engflow.com>
> Tested-by: Howard Chu <howardchu95@gmail.com>

How did you guys tested this? Was this found by visual inspection alone?
It clearly is correct, but I had to use:

diff --git a/tools/perf/builtin-trace.c b/tools/perf/builtin-trace.c
index e663be6f04e70640..a32eafd000fa99e6 100644
--- a/tools/perf/builtin-trace.c
+++ b/tools/perf/builtin-trace.c
@@ -3033,7 +3033,7 @@ static void bpf_output__fprintf(struct trace *trace,
 static size_t trace__fprintf_tp_fields(struct trace *trace, struct evsel *evsel, struct perf_sample *sample,
 				       struct thread *thread, void *augmented_args, int augmented_args_size)
 {
-	char bf[2048];
+	char bf[2048] = "garbage";
 	size_t size = sizeof(bf);
 	const struct tep_event *tp_format = evsel__tp_format(evsel);
 	struct tep_format_field *field = tp_format ? tp_format->format.fields : NULL;
@@ -3053,7 +3053,7 @@ static size_t trace__fprintf_tp_fields(struct trace *trace, struct evsel *evsel,
 		.show_string_prefix = trace->show_string_prefix,
 	};
 
-	for (; field && arg; field = field->next, ++syscall_arg.idx, bit <<= 1, ++arg) {
+	for (field = field->next; field && arg; field = field->next, ++syscall_arg.idx, bit <<= 1, ++arg) {
 		if (syscall_arg.mask & bit)
 			continue;
 
@@ -3097,7 +3097,7 @@ static size_t trace__fprintf_tp_fields(struct trace *trace, struct evsel *evsel,
 		printed += syscall_arg_fmt__scnprintf_val(arg, bf + printed, size - printed, &syscall_arg, val);
 	}
 
-	return printed + fprintf(trace->output, "%s", bf);
+	return printed + fprintf(trace->output, "printed=%zd, %s", printed, bf);
 }
 
 static int trace__event_handler(struct trace *trace, struct evsel *evsel,

To skip the first arg as a perf probe would still have one argument (the
probe addr), i.e.  what tracepoint did you use to test this that has all
its args as zeroes? If we really can generate something like that we
could use it in a 'perf test' entry.

And then come up with:

root@x1:/home/acme/c# cat loop.c 
#include <unistd.h>

static int function(int i, int j, int k, int l, int m)
{
	sleep(1);
	return i + j + k + l + m;
}

int main(void)
{
	unsigned long long total = 0;

	for (int i = 0; i < 3; i++)
		total += function(0, 0, 0, 0, 0);

	return total;
}
root@x1:/home/acme/c# cc -g -o loop loop.c
root@x1:/home/acme/c# perf probe -x ./loop function i j k l m
Target program is compiled without optimization. Skipping prologue.
Probe on address 0x401126 to force probing at the function entry.

Added new event:
  probe_loop:function  (on function in /home/acme/c/loop with i j k l m)

You can now use it in all perf tools, such as:

	perf record -e probe_loop:function -aR sleep 1

root@x1:/home/acme/c# perf trace -e clock_nanosleep,probe_loop:function ./loop
     0.000 (         ): loop/846057 probe_loop:function(printed=0, garbage)
     0.037 (1000.154 ms): loop/846057 clock_nanosleep(rqtp: { .tv_sec: 1, .tv_nsec: 0 }, rmtp: 0x7ffd43aaa290) = 0
  1000.232 (         ): loop/846057 probe_loop:function(printed=0, garbage)
  1000.253 (1000.123 ms): loop/846057 clock_nanosleep(rqtp: { .tv_sec: 1, .tv_nsec: 0 }, rmtp: 0x7ffd43aaa290) = 0
  2000.416 (         ): loop/846057 probe_loop:function(printed=0, garbage)
^Croot@x1:/home/acme/c#

Anyway, with your patch and this one on top:

⬢ [acme@toolbox perf-tools-next]$ git diff
diff --git a/tools/perf/builtin-trace.c b/tools/perf/builtin-trace.c
index de191ef425fe574a..5c9f3fdb9e5732f4 100644
--- a/tools/perf/builtin-trace.c
+++ b/tools/perf/builtin-trace.c
@@ -3033,7 +3033,7 @@ static void bpf_output__fprintf(struct trace *trace,
 static size_t trace__fprintf_tp_fields(struct trace *trace, struct evsel *evsel, struct perf_sample *sample,
                                       struct thread *thread, void *augmented_args, int augmented_args_size)
 {
-       char bf[2048];
+       char bf[2048] = "garbage";
        size_t size = sizeof(bf);
        const struct tep_event *tp_format = evsel__tp_format(evsel);
        struct tep_format_field *field = tp_format ? tp_format->format.fields : NULL;
@@ -3053,7 +3053,7 @@ static size_t trace__fprintf_tp_fields(struct trace *trace, struct evsel *evsel,
                .show_string_prefix = trace->show_string_prefix,
        };
 
-       for (; field && arg; field = field->next, ++syscall_arg.idx, bit <<= 1, ++arg) {
+       for (field = field->next; field && arg; field = field->next, ++syscall_arg.idx, bit <<= 1, ++arg) {
                if (syscall_arg.mask & bit)
                        continue;
 
⬢ [acme@toolbox perf-tools-next]$

root@x1:/home/acme/c# perf probe -x ./loop function i j k l m
Target program is compiled without optimization. Skipping prologue.
Probe on address 0x401126 to force probing at the function entry.

Added new event:
  probe_loop:function  (on function in /home/acme/c/loop with i j k l m)

You can now use it in all perf tools, such as:

	perf record -e probe_loop:function -aR sleep 1

root@x1:/home/acme/c# perf trace -e clock_nanosleep,probe_loop:function ./loop
     0.000 (         ): loop/849218 probe_loop:function()
     0.033 (1000.109 ms): loop/849218 clock_nanosleep(rqtp: { .tv_sec: 1, .tv_nsec: 0 }, rmtp: 0x7fffe6dc38e0) = 0
  1000.182 (         ): loop/849218 probe_loop:function()
  1000.200 (1000.142 ms): loop/849218 clock_nanosleep(rqtp: { .tv_sec: 1, .tv_nsec: 0 }, rmtp: 0x7fffe6dc38e0) = 0
  2000.387 (         ): loop/849218 probe_loop:function()
  2000.413 (1000.151 ms): loop/849218 clock_nanosleep(rqtp: { .tv_sec: 1, .tv_nsec: 0 }, rmtp: 0x7fffe6dc38e0) = 0
root@x1:/home/acme/c#

To see the zeroes:

root@x1:/home/acme/c# perf config trace.show_zeros=1
root@x1:/home/acme/c# perf trace -e probe_loop:function ./loop
     0.000 loop/849542 probe_loop:function(i: 0, j: 0, k: 0, l: 0, m: 0)
  1000.338 loop/849542 probe_loop:function(i: 0, j: 0, k: 0, l: 0, m: 0)
  2000.542 loop/849542 probe_loop:function(i: 0, j: 0, k: 0, l: 0, m: 0)
root@x1:/home/acme/c#

So,

Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>

- Arnaldo

> ---
>  tools/perf/builtin-trace.c | 2 +-
>  1 file changed, 1 insertion(+), 1 deletion(-)
> 
> diff --git a/tools/perf/builtin-trace.c b/tools/perf/builtin-trace.c
> index d3f11b90d025..5af55f4192b5 100644
> --- a/tools/perf/builtin-trace.c
> +++ b/tools/perf/builtin-trace.c
> @@ -3087,7 +3087,7 @@ static size_t trace__fprintf_tp_fields(struct trace *trace, struct evsel *evsel,
>  		printed += syscall_arg_fmt__scnprintf_val(arg, bf + printed, size - printed, &syscall_arg, val);
>  	}
>  
> -	return printed + fprintf(trace->output, "%s", bf);
> +	return printed + fprintf(trace->output, "%.*s", (int)printed, bf);
>  }
>  
>  static int trace__event_handler(struct trace *trace, struct evsel *evsel,
> -- 
> 2.39.5
>