[PATCH v2 1/3] perf trace: do not lose last events in a race

[PATCH v2 1/3] perf trace: do not lose last events in a race

[Benjamin Peterson]

If a perf trace event selector specifies a maximum number of events to output
(i.e., "/nr=N/" syntax), the event printing handler, trace__event_handler,
disables the event selector after the maximum number events are
printed. Furthermore, trace__event_handler checked if the event selector was
disabled before doing any work. This avoided exceeding the maximum number of
events to print if more events were in the buffer before the selector was
disabled. However, the event selector can be disabled for reasons other than
exceeding the maximum number of events. In particular, when the traced
subprocess exits, the main loop disables all event selectors. This meant the
last events of a traced subprocess might be lost to the printing handler's
short-circuiting logic.

This nondeterministic problem could be seen by running the following many times:

  $ perf trace -e syscalls:sys_enter_exit_group true

trace__event_handler should simply check for exceeding the maximum number of
events to print rather than the state of the event selector.

Fixes: a9c5e6c1e9bff ("perf trace: Introduce per-event maximum number of events property")
Tested-by: Howard Chu <howardchu95@gmail.com>
Signed-off-by: Benjamin Peterson <benjamin@engflow.com>
---
 tools/perf/builtin-trace.c | 9 ++-------
 1 file changed, 2 insertions(+), 7 deletions(-)

diff --git a/tools/perf/builtin-trace.c b/tools/perf/builtin-trace.c
index d3f11b90d025..f6179b13b8b4 100644
--- a/tools/perf/builtin-trace.c
+++ b/tools/perf/builtin-trace.c
@@ -3096,13 +3096,8 @@ static int trace__event_handler(struct trace *trace, struct evsel *evsel,
 {
 	struct thread *thread;
 	int callchain_ret = 0;
-	/*
-	 * Check if we called perf_evsel__disable(evsel) due to, for instance,
-	 * this event's max_events having been hit and this is an entry coming
-	 * from the ring buffer that we should discard, since the max events
-	 * have already been considered/printed.
-	 */
-	if (evsel->disabled)
+
+	if (evsel->nr_events_printed >= evsel->max_events)
 		return 0;
 
 	thread = machine__findnew_thread(trace->host, sample->pid, sample->tid);
-- 
2.39.5

[PATCH v2 2/3] perf trace: avoid garbage when not printing a syscall's arguments

[Benjamin Peterson]

syscall__scnprintf_args may not place anything in the output buffer
(e.g., because the arguments are all zero). If that happened in
trace__fprintf_sys_enter, its fprintf would receive an unitialized
buffer leading to garbage output.

Fix the problem by passing the (possibly zero) bounds of the argument
buffer to the output fprintf.

Fixes: a98392bb1e169 ("perf trace: Use beautifiers on syscalls:sys_enter_ handlers")
Signed-off-by: Benjamin Peterson <benjamin@engflow.com>
---
 tools/perf/builtin-trace.c | 5 +++--
 1 file changed, 3 insertions(+), 2 deletions(-)

diff --git a/tools/perf/builtin-trace.c b/tools/perf/builtin-trace.c
index f6179b13b8b4..28f61d10a2f8 100644
--- a/tools/perf/builtin-trace.c
+++ b/tools/perf/builtin-trace.c
@@ -2702,6 +2702,7 @@ static int trace__fprintf_sys_enter(struct trace *trace, struct evsel *evsel,
 	char msg[1024];
 	void *args, *augmented_args = NULL;
 	int augmented_args_size;
+	size_t printed = 0;
 
 	if (sc == NULL)
 		return -1;
@@ -2717,8 +2718,8 @@ static int trace__fprintf_sys_enter(struct trace *trace, struct evsel *evsel,
 
 	args = perf_evsel__sc_tp_ptr(evsel, args, sample);
 	augmented_args = syscall__augmented_args(sc, sample, &augmented_args_size, trace->raw_augmented_syscalls_args_size);
-	syscall__scnprintf_args(sc, msg, sizeof(msg), args, augmented_args, augmented_args_size, trace, thread);
-	fprintf(trace->output, "%s", msg);
+	printed += syscall__scnprintf_args(sc, msg, sizeof(msg), args, augmented_args, augmented_args_size, trace, thread);
+	fprintf(trace->output, "%.*s", (int)printed, msg);
 	err = 0;
 out_put:
 	thread__put(thread);
-- 
2.39.5

[PATCH v2 3/3] perf tests: add test for trace output loss

[Benjamin Peterson]

Add a test that checks that trace output is not lost to races. This is
accomplished by tracing the exit_group syscall of "true" multiple times and
checking for correct output.

Signed-off-by: Benjamin Peterson <benjamin@engflow.com>
---
 tools/perf/tests/shell/trace_exit_race.sh | 31 +++++++++++++++++++++++
 1 file changed, 31 insertions(+)
 create mode 100755 tools/perf/tests/shell/trace_exit_race.sh

diff --git a/tools/perf/tests/shell/trace_exit_race.sh b/tools/perf/tests/shell/trace_exit_race.sh
new file mode 100755
index 000000000000..f9cfe44bce86
--- /dev/null
+++ b/tools/perf/tests/shell/trace_exit_race.sh
@@ -0,0 +1,31 @@
+#!/bin/sh
+# perf trace exit race
+# SPDX-License-Identifier: GPL-2.0
+
+# Check that the last events of a perf trace'd subprocess are not
+# lost. Specifically, trace the exiting syscall of "true" 10 times and ensure
+# the output contains 10 correct lines.
+
+# shellcheck source=lib/probe.sh
+. "$(dirname $0)"/lib/probe.sh
+
+skip_if_no_perf_trace || exit 2
+
+trace_shutdown_race() {
+	for i in $(seq 10); do
+		perf trace -e syscalls:sys_enter_exit_group true 2>>$file
+	done
+	[ $(grep -c -E " +[0-9]+\.[0-9]+ +true/[0-9]+ syscalls:sys_enter_exit_group\(\)$" $file) = "10" ]
+}
+
+
+file=$(mktemp /tmp/temporary_file.XXXXX)
+
+# Do not use whatever ~/.perfconfig file, it may change the output
+# via trace.{show_timestamp,show_prefix,etc}
+export PERF_CONFIG=/dev/null
+
+trace_shutdown_race
+err=$?
+rm -f ${file}
+exit $err
-- 
2.39.5

Re: [PATCH v2 2/3] perf trace: avoid garbage when not printing a syscall's arguments

[Howard Chu]

Hello,

This patch solves the garbage output problem I got, and your test can be run.

Thanks,
Howard

On Thu, Nov 7, 2024 at 3:21 PM Benjamin Peterson <benjamin@engflow.com> wrote:
>
> syscall__scnprintf_args may not place anything in the output buffer
> (e.g., because the arguments are all zero). If that happened in
> trace__fprintf_sys_enter, its fprintf would receive an unitialized
> buffer leading to garbage output.
>
> Fix the problem by passing the (possibly zero) bounds of the argument
> buffer to the output fprintf.
>
> Fixes: a98392bb1e169 ("perf trace: Use beautifiers on syscalls:sys_enter_ handlers")
> Signed-off-by: Benjamin Peterson <benjamin@engflow.com>
> ---
>  tools/perf/builtin-trace.c | 5 +++--
>  1 file changed, 3 insertions(+), 2 deletions(-)
>
> diff --git a/tools/perf/builtin-trace.c b/tools/perf/builtin-trace.c
> index f6179b13b8b4..28f61d10a2f8 100644
> --- a/tools/perf/builtin-trace.c
> +++ b/tools/perf/builtin-trace.c
> @@ -2702,6 +2702,7 @@ static int trace__fprintf_sys_enter(struct trace *trace, struct evsel *evsel,
>         char msg[1024];
>         void *args, *augmented_args = NULL;
>         int augmented_args_size;
> +       size_t printed = 0;
>
>         if (sc == NULL)
>                 return -1;
> @@ -2717,8 +2718,8 @@ static int trace__fprintf_sys_enter(struct trace *trace, struct evsel *evsel,
>
>         args = perf_evsel__sc_tp_ptr(evsel, args, sample);
>         augmented_args = syscall__augmented_args(sc, sample, &augmented_args_size, trace->raw_augmented_syscalls_args_size);
> -       syscall__scnprintf_args(sc, msg, sizeof(msg), args, augmented_args, augmented_args_size, trace, thread);
> -       fprintf(trace->output, "%s", msg);
> +       printed += syscall__scnprintf_args(sc, msg, sizeof(msg), args, augmented_args, augmented_args_size, trace, thread);
> +       fprintf(trace->output, "%.*s", (int)printed, msg);
>         err = 0;
>  out_put:
>         thread__put(thread);
> --
> 2.39.5
>
>

Re: [PATCH v2 2/3] perf trace: avoid garbage when not printing a syscall's arguments

[Arnaldo Carvalho de Melo]

On Fri, Nov 08, 2024 at 08:21:30AM -0800, Howard Chu wrote:
> Hello,
> 
> This patch solves the garbage output problem I got, and your test can be run.

I'm taking this as a Tested-by you, ok?

- Arnaldo
 
> Thanks,
> Howard
> 
> On Thu, Nov 7, 2024 at 3:21 PM Benjamin Peterson <benjamin@engflow.com> wrote:
> >
> > syscall__scnprintf_args may not place anything in the output buffer
> > (e.g., because the arguments are all zero). If that happened in
> > trace__fprintf_sys_enter, its fprintf would receive an unitialized
> > buffer leading to garbage output.
> >
> > Fix the problem by passing the (possibly zero) bounds of the argument
> > buffer to the output fprintf.
> >
> > Fixes: a98392bb1e169 ("perf trace: Use beautifiers on syscalls:sys_enter_ handlers")
> > Signed-off-by: Benjamin Peterson <benjamin@engflow.com>
> > ---
> >  tools/perf/builtin-trace.c | 5 +++--
> >  1 file changed, 3 insertions(+), 2 deletions(-)
> >
> > diff --git a/tools/perf/builtin-trace.c b/tools/perf/builtin-trace.c
> > index f6179b13b8b4..28f61d10a2f8 100644
> > --- a/tools/perf/builtin-trace.c
> > +++ b/tools/perf/builtin-trace.c
> > @@ -2702,6 +2702,7 @@ static int trace__fprintf_sys_enter(struct trace *trace, struct evsel *evsel,
> >         char msg[1024];
> >         void *args, *augmented_args = NULL;
> >         int augmented_args_size;
> > +       size_t printed = 0;
> >
> >         if (sc == NULL)
> >                 return -1;
> > @@ -2717,8 +2718,8 @@ static int trace__fprintf_sys_enter(struct trace *trace, struct evsel *evsel,
> >
> >         args = perf_evsel__sc_tp_ptr(evsel, args, sample);
> >         augmented_args = syscall__augmented_args(sc, sample, &augmented_args_size, trace->raw_augmented_syscalls_args_size);
> > -       syscall__scnprintf_args(sc, msg, sizeof(msg), args, augmented_args, augmented_args_size, trace, thread);
> > -       fprintf(trace->output, "%s", msg);
> > +       printed += syscall__scnprintf_args(sc, msg, sizeof(msg), args, augmented_args, augmented_args_size, trace, thread);
> > +       fprintf(trace->output, "%.*s", (int)printed, msg);
> >         err = 0;
> >  out_put:
> >         thread__put(thread);
> > --
> > 2.39.5
> >
> >