[v2] perf trace: avoid garbage when not printing a trace event's arguments

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

Posted by Benjamin Peterson 3 weeks, 2 days ago

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.

Remove the return value of trace__fprintf_tp_fields, since it was meaningless
and ignored.

Fixes: f11b2803bb88 ("perf trace: Allow choosing how to augment the tracepoint arguments")
Signed-off-by: Benjamin Peterson <benjamin@engflow.com>
---
 tools/perf/builtin-trace.c | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/tools/perf/builtin-trace.c b/tools/perf/builtin-trace.c
index d3f11b90d025..4e785ea29df6 100644
--- a/tools/perf/builtin-trace.c
+++ b/tools/perf/builtin-trace.c
@@ -3021,7 +3021,7 @@ static void bpf_output__fprintf(struct trace *trace,
 	++trace->nr_events_printed;
 }
 
-static size_t trace__fprintf_tp_fields(struct trace *trace, struct evsel *evsel, struct perf_sample *sample,
+static void 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];
@@ -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);
+	fprintf(trace->output, "%.*s", (int)printed, bf);
 }
 
 static int trace__event_handler(struct trace *trace, struct evsel *evsel,
-- 
2.39.5

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

Posted by Howard Chu 3 weeks, 1 day ago

Hello Benjamin,

Before your patch:

perf $ ./perf trace -e net:netif_rx_exit
     0.000 irq/79-brcmf_p/1694977 net:netif_rx_exit(6n<)
    28.153 irq/79-brcmf_p/1694977 net:netif_rx_exit(6n<)
    36.429 irq/79-brcmf_p/1694977 net:netif_rx_exit(6n<)
    36.461 irq/79-brcmf_p/1694977 net:netif_rx_exit(6n<)

After:

perf $ ./perf trace -e net:netif_rx_exit
     0.000 irq/79-brcmf_p/1694977 net:netif_rx_exit()
     7.352 irq/79-brcmf_p/1694977 net:netif_rx_exit()
    30.232 irq/79-brcmf_p/1694977 net:netif_rx_exit()
    37.529 irq/79-brcmf_p/1694977 net:netif_rx_exit()

It works beautifully, but I'm thinking can we simplify it by just doing:

+       char bf[2048] = { 0 };
        size_t size = sizeof(bf);

That being said, trace__fprintf_tp_fields() should return void because
currently its return value is not used by any other functions, plus
this line:

return printed + fprintf(trace->output, "%s", bf);

in trace__fprintf_tp_fields() does not make much sense, since that
will be 2 * printed. So I'm thinking maybe:

diff --git a/tools/perf/builtin-trace.c b/tools/perf/builtin-trace.c
index 748b061f8678..8a628d1e80f3 100644
--- a/tools/perf/builtin-trace.c
+++ b/tools/perf/builtin-trace.c
@@ -3021,10 +3021,10 @@ static void bpf_output__fprintf(struct trace *trace,
        ++trace->nr_events_printed;
 }

-static size_t trace__fprintf_tp_fields(struct trace *trace, struct
evsel *evsel, struct perf_sample *sample,
+static void 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] = { 0 };
        size_t size = sizeof(bf);
        struct tep_format_field *field = evsel->tp_format->format.fields;
        struct syscall_arg_fmt *arg = __evsel__syscall_arg_fmt(evsel);
@@ -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);
+       fprintf(trace->output, "%s", bf);
 }

 static int trace__event_handler(struct trace *trace, struct evsel *evsel,


Then this will be one more diff line than yours.

But that's just my opinion, yours works just fine, thank you :).
Arnaldo, what do you think?

Tested-by: Howard Chu <howardchu95@gmail.com>

Thanks,
Howard

On Fri, Nov 1, 2024 at 10:27 AM Benjamin Peterson <benjamin@engflow.com> 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.
>
> Remove the return value of trace__fprintf_tp_fields, since it was meaningless
> and ignored.
>
> Fixes: f11b2803bb88 ("perf trace: Allow choosing how to augment the tracepoint arguments")
> Signed-off-by: Benjamin Peterson <benjamin@engflow.com>
> ---
>  tools/perf/builtin-trace.c | 4 ++--
>  1 file changed, 2 insertions(+), 2 deletions(-)
>
> diff --git a/tools/perf/builtin-trace.c b/tools/perf/builtin-trace.c
> index d3f11b90d025..4e785ea29df6 100644
> --- a/tools/perf/builtin-trace.c
> +++ b/tools/perf/builtin-trace.c
> @@ -3021,7 +3021,7 @@ static void bpf_output__fprintf(struct trace *trace,
>         ++trace->nr_events_printed;
>  }
>
> -static size_t trace__fprintf_tp_fields(struct trace *trace, struct evsel *evsel, struct perf_sample *sample,
> +static void 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];
> @@ -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);
> +       fprintf(trace->output, "%.*s", (int)printed, bf);
>  }
>
>  static int trace__event_handler(struct trace *trace, struct evsel *evsel,
> --
> 2.39.5
>

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

Posted by Arnaldo Carvalho de Melo 3 weeks, 1 day ago

On Fri, Nov 01, 2024 at 02:00:46PM -0700, Howard Chu wrote:
> Hello Benjamin,
> 
> Before your patch:
> 
> perf $ ./perf trace -e net:netif_rx_exit
>      0.000 irq/79-brcmf_p/1694977 net:netif_rx_exit(6n<)
>     28.153 irq/79-brcmf_p/1694977 net:netif_rx_exit(6n<)
>     36.429 irq/79-brcmf_p/1694977 net:netif_rx_exit(6n<)
>     36.461 irq/79-brcmf_p/1694977 net:netif_rx_exit(6n<)
> 
> After:
> 
> perf $ ./perf trace -e net:netif_rx_exit
>      0.000 irq/79-brcmf_p/1694977 net:netif_rx_exit()
>      7.352 irq/79-brcmf_p/1694977 net:netif_rx_exit()
>     30.232 irq/79-brcmf_p/1694977 net:netif_rx_exit()
>     37.529 irq/79-brcmf_p/1694977 net:netif_rx_exit()
> 
> It works beautifully, but I'm thinking can we simplify it by just doing:
> 
> +       char bf[2048] = { 0 };
>         size_t size = sizeof(bf);
> 
> That being said, trace__fprintf_tp_fields() should return void because
> currently its return value is not used by any other functions, plus
> this line:
> 
> return printed + fprintf(trace->output, "%s", bf);
> 
> in trace__fprintf_tp_fields() does not make much sense, since that
> will be 2 * printed. So I'm thinking maybe:
> 
> diff --git a/tools/perf/builtin-trace.c b/tools/perf/builtin-trace.c
> index 748b061f8678..8a628d1e80f3 100644
> --- a/tools/perf/builtin-trace.c
> +++ b/tools/perf/builtin-trace.c
> @@ -3021,10 +3021,10 @@ static void bpf_output__fprintf(struct trace *trace,
>         ++trace->nr_events_printed;
>  }
> 
> -static size_t trace__fprintf_tp_fields(struct trace *trace, struct
> evsel *evsel, struct perf_sample *sample,
> +static void 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] = { 0 };
>         size_t size = sizeof(bf);
>         struct tep_format_field *field = evsel->tp_format->format.fields;
>         struct syscall_arg_fmt *arg = __evsel__syscall_arg_fmt(evsel);
> @@ -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);
> +       fprintf(trace->output, "%s", bf);
>  }
> 
>  static int trace__event_handler(struct trace *trace, struct evsel *evsel,
> 
> 
> Then this will be one more diff line than yours.
> 
> But that's just my opinion, yours works just fine, thank you :).
> Arnaldo, what do you think?
> 
> Tested-by: Howard Chu <howardchu95@gmail.com>

I haven't tested it yet, just in my mind :-)

The patch looks ok and seems to fix a real problem, my only concern, a
pet peeve, was that it, in addition to fixing a real problem, did an
unrelated change, the "Remove the return value...", that part looks like
a distraction, something that shouldn't be there.

- Arnaldo
 
> Thanks,
> Howard
> 
> On Fri, Nov 1, 2024 at 10:27 AM Benjamin Peterson <benjamin@engflow.com> 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.
> >
> > Remove the return value of trace__fprintf_tp_fields, since it was meaningless
> > and ignored.
> >
> > Fixes: f11b2803bb88 ("perf trace: Allow choosing how to augment the tracepoint arguments")
> > Signed-off-by: Benjamin Peterson <benjamin@engflow.com>
> > ---
> >  tools/perf/builtin-trace.c | 4 ++--
> >  1 file changed, 2 insertions(+), 2 deletions(-)
> >
> > diff --git a/tools/perf/builtin-trace.c b/tools/perf/builtin-trace.c
> > index d3f11b90d025..4e785ea29df6 100644
> > --- a/tools/perf/builtin-trace.c
> > +++ b/tools/perf/builtin-trace.c
> > @@ -3021,7 +3021,7 @@ static void bpf_output__fprintf(struct trace *trace,
> >         ++trace->nr_events_printed;
> >  }
> >
> > -static size_t trace__fprintf_tp_fields(struct trace *trace, struct evsel *evsel, struct perf_sample *sample,
> > +static void 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];
> > @@ -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);
> > +       fprintf(trace->output, "%.*s", (int)printed, bf);
> >  }
> >
> >  static int trace__event_handler(struct trace *trace, struct evsel *evsel,
> > --
> > 2.39.5
> >

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

Posted by Benjamin Peterson 3 weeks, 1 day ago

On Fri, Nov 1, 2024 at 2:30 PM Arnaldo Carvalho de Melo <acme@kernel.org> wrote:
>
> On Fri, Nov 01, 2024 at 02:00:46PM -0700, Howard Chu wrote:
> > Hello Benjamin,

Thanks for testing & reviewing.

> >
> > Before your patch:
> >
> > perf $ ./perf trace -e net:netif_rx_exit
> >      0.000 irq/79-brcmf_p/1694977 net:netif_rx_exit(6n<)
> >     28.153 irq/79-brcmf_p/1694977 net:netif_rx_exit(6n<)
> >     36.429 irq/79-brcmf_p/1694977 net:netif_rx_exit(6n<)
> >     36.461 irq/79-brcmf_p/1694977 net:netif_rx_exit(6n<)
> >
> > After:
> >
> > perf $ ./perf trace -e net:netif_rx_exit
> >      0.000 irq/79-brcmf_p/1694977 net:netif_rx_exit()
> >      7.352 irq/79-brcmf_p/1694977 net:netif_rx_exit()
> >     30.232 irq/79-brcmf_p/1694977 net:netif_rx_exit()
> >     37.529 irq/79-brcmf_p/1694977 net:netif_rx_exit()
> >
> > It works beautifully, but I'm thinking can we simplify it by just doing:
> >
> > +       char bf[2048] = { 0 };
> >         size_t size = sizeof(bf);
> >

I believe this is slightly suboptimal because it obliges the compiler
to zero out 2kib of the stack every time the function is called.

> >
> > Tested-by: Howard Chu <howardchu95@gmail.com>
>
> I haven't tested it yet, just in my mind :-)
>
> The patch looks ok and seems to fix a real problem, my only concern, a
> pet peeve, was that it, in addition to fixing a real problem, did an
> unrelated change, the "Remove the return value...", that part looks like
> a distraction, something that shouldn't be there.

In my mind, it was related because both the bug and the odd return
value arise from incorrect counting of the number of written bytes.
Obviously, the fix is what I care about, so feel free to strip out the
return value change on import, or I can resend.

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

Posted by Arnaldo Carvalho de Melo 3 weeks, 1 day ago

On Fri, Nov 01, 2024 at 02:41:46PM -0700, Benjamin Peterson wrote:
> On Fri, Nov 1, 2024 at 2:30 PM Arnaldo Carvalho de Melo <acme@kernel.org> wrote:
> > I haven't tested it yet, just in my mind :-)

> > The patch looks ok and seems to fix a real problem, my only concern, a
> > pet peeve, was that it, in addition to fixing a real problem, did an
> > unrelated change, the "Remove the return value...", that part looks like
> > a distraction, something that shouldn't be there.
 
> In my mind, it was related because both the bug and the odd return
> value arise from incorrect counting of the number of written bytes.

> Obviously, the fix is what I care about, so feel free to strip out the
> return value change on import, or I can resend.

The point is to try to focus on the fix, and do just what is needed for
that. Everything else ends up being a distraction.

- Arnaldo

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

Posted by Benjamin Peterson 2 weeks, 6 days ago

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>
---
 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

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

Posted by Namhyung Kim 2 weeks, 4 days ago

On Sun, 03 Nov 2024 20:48:16 +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.
> 
> 

Applied to perf-tools-next, thanks!

Best regards,
Namhyung

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

Posted by Arnaldo Carvalho de Melo 2 weeks, 4 days ago

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
>