1. Patchew
  2. linux
  3. View series

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

Benjamin Peterson posted 1 patch 3 weeks, 2 days ago 
tools/perf/builtin-trace.c | 4 ++--
1 file changed, 2 insertions(+), 2 deletions(-)
[PATCH] perf trace: avoid garbage when not printing an 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..e93f795e680f 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", printed, bf);
 }
 
 static int trace__event_handler(struct trace *trace, struct evsel *evsel,
-- 
2.39.5
Re: [PATCH] perf trace: avoid garbage when not printing an trace event's arguments
Posted by kernel test robot 3 weeks ago 
Hi Benjamin,

kernel test robot noticed the following build errors:

[auto build test ERROR on perf-tools-next/perf-tools-next]
[also build test ERROR on tip/perf/core perf-tools/perf-tools linus/master acme/perf/core v6.12-rc5 next-20241101]
[If your patch is applied to the wrong git tree, kindly drop us a note.
And when submitting patch, we suggest to use '--base' as documented in
https://git-scm.com/docs/git-format-patch#_base_tree_information]

url:    https://github.com/intel-lab-lkp/linux/commits/Benjamin-Peterson/perf-trace-avoid-garbage-when-not-printing-an-trace-event-s-arguments/20241101-085413
base:   https://git.kernel.org/pub/scm/linux/kernel/git/perf/perf-tools-next.git perf-tools-next
patch link:    https://lore.kernel.org/r/20241101005338.5846-1-benjamin%40engflow.com
patch subject: [PATCH] perf trace: avoid garbage when not printing an trace event's arguments
compiler: gcc-12 (Debian 12.2.0-14) 12.2.0
reproduce (this is a W=1 build): (https://download.01.org/0day-ci/archive/20241103/202411031202.CkbT89xW-lkp@intel.com/reproduce)

If you fix the issue in a separate patch/commit (i.e. not just a new version of
the same patch/commit), kindly add following tags
| Reported-by: kernel test robot <lkp@intel.com>
| Closes: https://lore.kernel.org/oe-kbuild-all/202411031202.CkbT89xW-lkp@intel.com/

All errors (new ones prefixed by >>):

   Makefile.config:652: No libunwind found. Please install libunwind-dev[el] >= 1.1 and/or set LIBUNWIND_DIR
     PERF_VERSION = 6.12.rc3.g6e02cf5e2f22
   builtin-trace.c: In function 'trace__fprintf_tp_fields':
>> builtin-trace.c:3090:35: error: field precision specifier '.*' expects argument of type 'int', but argument 3 has type 'size_t' {aka 'long unsigned int'} [-Werror=format=]
    3090 |         fprintf(trace->output, "%.*s", printed, bf);
         |                                 ~~^~   ~~~~~~~
         |                                   |    |
         |                                   int  size_t {aka long unsigned int}
   cc1: all warnings being treated as errors
   make[6]: *** [tools/build/Makefile.build:105: tools/perf/builtin-trace.o] Error 1
   make[5]: *** [Makefile.perf:762: tools/perf/perf-in.o] Error 2
   make[5]: *** Waiting for unfinished jobs....
   make[4]: *** [Makefile.perf:292: sub-make] Error 2
   make[3]: *** [Makefile:76: all] Error 2

-- 
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests/wiki
Re: [PATCH] perf trace: avoid garbage when not printing an trace event's arguments
Posted by Howard Chu 3 weeks, 2 days ago 
Hello Benjamin,

It does not build on my system due to this warning:

builtin-trace.c: In function ‘trace__fprintf_tp_fields’:
builtin-trace.c:3090:35: error: field precision specifier ‘.*’ expects
argument of type ‘int’, but argument 3 has type ‘size_t’ {aka ‘long
unsigned int’} [-Werror=format=]
 3090 |         fprintf(trace->output, "%.*s", printed, bf);
      |                                 ~~^~   ~~~~~~~
      |                                   |    |
      |                                   int  size_t {aka long unsigned int}

Thanks,
Howard

On Thu, Oct 31, 2024 at 5:54 PM 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..e93f795e680f 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", printed, bf);
>  }
>
>  static int trace__event_handler(struct trace *trace, struct evsel *evsel,
> --
> 2.39.5
>
>
Re: [PATCH] perf trace: avoid garbage when not printing an trace event's arguments
Posted by Benjamin Peterson 3 weeks, 2 days ago 
On Thu, Oct 31, 2024 at 7:03 PM Howard Chu <howardchu95@gmail.com> wrote:
>
> Hello Benjamin,
>
> It does not build on my system due to this warning:
>
> builtin-trace.c: In function ‘trace__fprintf_tp_fields’:
> builtin-trace.c:3090:35: error: field precision specifier ‘.*’ expects
> argument of type ‘int’, but argument 3 has type ‘size_t’ {aka ‘long
> unsigned int’} [-Werror=format=]
>  3090 |         fprintf(trace->output, "%.*s", printed, bf);
>       |                                 ~~^~   ~~~~~~~
>       |                                   |    |
>       |                                   int  size_t {aka long unsigned int}

Thanks; that's what I getting for building with clang rather than gcc.
v2 incoming...
[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, 2 days 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 3 weeks 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, 5 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
>

Patchew 2.1-devel-b67e4c2

© 2016 - 2024 Red Hat, Inc.