perf trace: do not lose last events in a race

PATCH In review Benjamin Peterson 3 participants 5 messages Nov 7, 2024 – Nov 14, 2024 perf events

Share & tools

Benjamin Peterson

author

2024-11-07 23:21 UTC #0 lore raw

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

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 <[email protected]>

Signed-off-by Benjamin Peterson <[email protected]>

---
 tools/perf/builtin-trace.c | 9 ++-------
 1 file changed, 2 insertions(+), 7 deletions(-)

tools/perf/builtin-trace.c +2 -7

index d3f11b90d025..f6179b13b8b4 100644
@@ -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);

Signature · 1 line

2.39.5

Benjamin Peterson

author

2024-11-07 23:21 UTC #1 lore raw

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

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 <[email protected]>

---
 tools/perf/builtin-trace.c | 5 +++--
 1 file changed, 3 insertions(+), 2 deletions(-)

tools/perf/builtin-trace.c +3 -2

index f6179b13b8b4..28f61d10a2f8 100644
@@ -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);

Signature · 1 line

2.39.5

Howard Chu

2024-11-08 16:21 UTC #2 lore raw

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

Hello,

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

Thanks,
Howard

Quoted 42 lines · Benjamin Peterson

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 <[email protected]>

---
 tools/perf/builtin-trace.c | 5 +++--
 1 file changed, 3 insertions(+), 2 deletions(-)

tools/perf/builtin-trace.c +3 -3

index f6179b13b8b4..28f61d10a2f8 100644
@@ -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

Arnaldo Carvalho de Melo

maintainer

2024-11-14 21:08 UTC #3 lore raw

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

Quoted 3 lines · Howard Chu

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

Quoted 46 lines

Thanks,
Howard

Quoted 42 lines · Benjamin Peterson

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 <[email protected]>

---
 tools/perf/builtin-trace.c | 5 +++--
 1 file changed, 3 insertions(+), 2 deletions(-)

tools/perf/builtin-trace.c +3 -3

index f6179b13b8b4..28f61d10a2f8 100644
@@ -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

Benjamin Peterson

author

2024-11-07 23:21 UTC #4 lore raw

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

In reply to 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 <[email protected]>

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

tools/perf/tests/shell/trace_exit_race.sh new file +31 -0

new file mode 100755
index 000000000000..f9cfe44bce86
@@ -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

Signature · 1 line

2.39.5