perf trace: do not lose last events in a race
PATCH 1/2 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.
--- tools/perf/builtin-trace.c | 9 ++------- 1 file changed, 2 insertions(+), 7 deletions(-)
tools/perf/builtin-trace.c +2 -7
@@ -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
PATCH 2/2 perf tests: add test for trace output loss
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.
Conveniently, this test also serves as a regression test for 5fb8e56542a3 ("perf
trace: avoid garbage when not printing a trace event's arguments") because exit_group triggers the previously buggy printing behavior.
--- 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
@@ -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" 100 times and ensure +# the output contains 100 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 100); 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) = "100" ] +} + + +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
Re: [PATCH 2/2] perf tests: add test for trace output loss
Hello,
Quoted 29 lines · Benjamin Peterson
Add a test that checks that trace output is not lost to races. This is accomplished by tracing the
exit_groupsyscall of "true" multiple times and checking for correct output.Conveniently, this test also serves as a regression test for
5fb8e56542a3("perf
trace: avoid garbage when not printing a trace event's arguments") becauseexit_grouptriggers the previously buggy printing behavior.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.shtools/perf/tests/shell/trace_exit_race.sh new file +8
-0@@ -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" 100 times and ensure +# the output contains 100 correct lines. +
tools/perf/tests/shell/trace_exit_race.sh line 18
Quoted 10 lines
tools/perf/tests/shell/trace_exit_race.sh new file +10
-0+# shellcheck source=lib/probe.sh +. "$(dirname $0)"/lib/probe.sh + +skip_if_no_perf_trace || exit 2 + +trace_shutdown_race() { + for i in $(seq 100); 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) = "100" ]
The test failed due to regex mismatched, I think because of this:
0.000 true/1526046 syscalls:sys_enter_exit_group( )
0.000 true/1526212 syscalls:sys_enter_exit_group( )
0.000 true/1526383 syscalls:sys_enter_exit_group(SSSSSSSSSSSSSSSS)Ironically the junk buffer problem you fixed last time, thanks for finding another printing problem in perf trace :), I'll figure out the cause of this.
Another thing is this test takes a long time to finish
perf $ time ./perf test 109
109: perf trace exit race : FAILED!
real 0m38.762s user 0m15.090s sys 0m21.794s
Is it really necessary to run it 100 times? To me it seems to be just a wrong handling logic of draining samples, will there be coincidence?
Thanks,
Howard
Quoted 17 lines
tools/perf/tests/shell/trace_exit_race.sh new file +13
-1+} + + +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 2/2] perf tests: add test for trace output loss
Quoted 46 lines · Howard Chu
Hello,
Quoted 29 lines · Benjamin Peterson
Add a test that checks that trace output is not lost to races. This is accomplished by tracing the
exit_groupsyscall of "true" multiple times and checking for correct output.Conveniently, this test also serves as a regression test for
5fb8e56542a3("perf
trace: avoid garbage when not printing a trace event's arguments") becauseexit_grouptriggers the previously buggy printing behavior.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.shtools/perf/tests/shell/trace_exit_race.sh new file +8
-0@@ -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" 100 times and ensure +# the output contains 100 correct lines. +tools/perf/tests/shell/trace_exit_race.sh line 18
Quoted 10 lines
tools/perf/tests/shell/trace_exit_race.sh new file +10
-0+# shellcheck source=lib/probe.sh +. "$(dirname $0)"/lib/probe.sh + +skip_if_no_perf_trace || exit 2 + +trace_shutdown_race() { + for i in $(seq 100); 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) = "100" ]The test failed due to regex mismatched, I think because of this:
Quoted 7 lines
0.000 true/1526046 syscalls:sys_enter_exit_group( ) 0.000 true/1526212 syscalls:sys_enter_exit_group( ) 0.000 true/1526383 syscalls:sys_enter_exit_group(SSSSSSSSSSSSSSSS)Ironically the junk buffer problem you fixed last time, thanks for finding another printing problem in perf trace :), I'll figure out the cause of this.
Thanks, the problem is a parallel issue with trace__fprintf_sys_enter. I will include a patch for the problem in my spin of this series.
Quoted 6 lines
Another thing is this test takes a long time to finish
perf $ time ./perf test 109
109: perf trace exit race : FAILED!
Quoted 6 lines
real 0m38.762s user 0m15.090s sys 0m21.794sIs it really necessary to run it 100 times? To me it seems to be just a wrong handling logic of draining samples, will there be coincidence?
Yes, it's racy. In my testing, sometimes the correct output would appear. However, I will reduce the number of iterations to 10.
Re: [PATCH 2/2] perf tests: add test for trace output loss
Hello Benjamin,
Quoted 69 lines · Benjamin Peterson
Quoted 46 lines · Howard Chu
Hello,
Quoted 29 lines · Benjamin Peterson
Add a test that checks that trace output is not lost to races. This is accomplished by tracing the
exit_groupsyscall of "true" multiple times and checking for correct output.Conveniently, this test also serves as a regression test for
5fb8e56542a3("perf
trace: avoid garbage when not printing a trace event's arguments") becauseexit_grouptriggers the previously buggy printing behavior.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.shtools/perf/tests/shell/trace_exit_race.sh new file +8
-0@@ -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" 100 times and ensure +# the output contains 100 correct lines. +tools/perf/tests/shell/trace_exit_race.sh line 18
Quoted 10 lines
tools/perf/tests/shell/trace_exit_race.sh new file +10
-0+# shellcheck source=lib/probe.sh +. "$(dirname $0)"/lib/probe.sh + +skip_if_no_perf_trace || exit 2 + +trace_shutdown_race() { + for i in $(seq 100); 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) = "100" ]The test failed due to regex mismatched, I think because of this:
Quoted 7 lines
0.000 true/1526046 syscalls:sys_enter_exit_group( ) 0.000 true/1526212 syscalls:sys_enter_exit_group( ) 0.000 true/1526383 syscalls:sys_enter_exit_group(SSSSSSSSSSSSSSSS)Ironically the junk buffer problem you fixed last time, thanks for finding another printing problem in perf trace :), I'll figure out the cause of this.
Thanks, the problem is a parallel issue with
trace__fprintf_sys_enter. I will include a patch for the problem in my spin of this series.Quoted 10 lines
Another thing is this test takes a long time to finish
perf $ time ./perf test 109
109: perf trace exit race : FAILED!real 0m38.762s user 0m15.090s sys 0m21.794s
Quoted 5 lines
Quoted 2 lines
Is it really necessary to run it 100 times? To me it seems to be just a wrong handling logic of draining samples, will there be coincidence?
Yes, it's racy. In my testing, sometimes the correct output would appear. However, I will reduce the number of iterations to 10.
Could you be a bit more specific about this race condition issue? Could you please tell us how one might emulate and test the scenario you mentioned? I ran the command 1,000 times before and after applying the patch, and each time I got the expected output. Could you please provide more information about your use cases?
Thanks,
Howard
Re: [PATCH 2/2] perf tests: add test for trace output loss
Quoted 73 lines · Howard Chu
Hello Benjamin,
Quoted 69 lines · Benjamin Peterson
Quoted 46 lines · Howard Chu
Hello,
Quoted 29 lines · Benjamin Peterson
Add a test that checks that trace output is not lost to races. This is accomplished by tracing the
exit_groupsyscall of "true" multiple times and checking for correct output.Conveniently, this test also serves as a regression test for
5fb8e56542a3("perf
trace: avoid garbage when not printing a trace event's arguments") becauseexit_grouptriggers the previously buggy printing behavior.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.shtools/perf/tests/shell/trace_exit_race.sh new file +8
-0@@ -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" 100 times and ensure +# the output contains 100 correct lines. +tools/perf/tests/shell/trace_exit_race.sh line 18
Quoted 10 lines
tools/perf/tests/shell/trace_exit_race.sh new file +10
-0+# shellcheck source=lib/probe.sh +. "$(dirname $0)"/lib/probe.sh + +skip_if_no_perf_trace || exit 2 + +trace_shutdown_race() { + for i in $(seq 100); 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) = "100" ]The test failed due to regex mismatched, I think because of this:
Quoted 7 lines
0.000 true/1526046 syscalls:sys_enter_exit_group( ) 0.000 true/1526212 syscalls:sys_enter_exit_group( ) 0.000 true/1526383 syscalls:sys_enter_exit_group(SSSSSSSSSSSSSSSS)Ironically the junk buffer problem you fixed last time, thanks for finding another printing problem in perf trace :), I'll figure out the cause of this.
Thanks, the problem is a parallel issue with
trace__fprintf_sys_enter. I will include a patch for the problem in my spin of this series.Quoted 10 lines
Another thing is this test takes a long time to finish
perf $ time ./perf test 109
109: perf trace exit race : FAILED!real 0m38.762s user 0m15.090s sys 0m21.794s
Quoted 7 lines
Quoted 5 lines
Quoted 2 lines
Is it really necessary to run it 100 times? To me it seems to be just a wrong handling logic of draining samples, will there be coincidence?
Yes, it's racy. In my testing, sometimes the correct output would appear. However, I will reduce the number of iterations to 10.
Could you be a bit more specific about this race condition issue?
From the code, it's apparent that if the SIGCHLD from the traced process is seen before the exit_group trace event, output will be lost. If the signal is received after the trace event, the trace event will be correctly printed.
Quoted 4 lines
Could you please tell us how one might emulate and test the scenario you mentioned? I ran the command 1,000 times before and after applying the patch, and each time I got the expected output. Could you please provide more information about your use cases?
I can see it simply by running the unpatched perf few times in the terminal, but it might be helpful for reproduction to create some scheduling contention with stress.
Arnaldo Carvalho de Melo
maintainerRe: [PATCH 2/2] perf tests: add test for trace output loss
In reply to Benjamin PetersonQuoted 42 lines · Benjamin Peterson
Add a test that checks that trace output is not lost to races. This is accomplished by tracing the
exit_groupsyscall of "true" multiple times and checking for correct output.Conveniently, this test also serves as a regression test for
5fb8e56542a3("perf
trace: avoid garbage when not printing a trace event's arguments") becauseexit_grouptriggers the previously buggy printing behavior.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.shtools/perf/tests/shell/trace_exit_race.sh new file +21
-0@@ -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" 100 times and ensure +# the output contains 100 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 100); 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) = "100" ] +} + +
tools/perf/tests/shell/trace_exit_race.sh line 31
Quoted 10 lines
tools/perf/tests/shell/trace_exit_race.sh new file +10
-0+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
Its failing with shellcheck, I'm trying to fix it:
CC /tmp/build/perf-tools-next/builtin-trace.o
TEST /tmp/build/perf-tools-next/tests/shell/trace_exit_race.sh.shellcheck_log
In tests/shell/trace_exit_race.sh line 15:
for i in $(seq 100); do
^-^ SC2034 (warning): i appears unused. Verify use (or export if used externally).In tests/shell/trace_exit_race.sh line 18:
[ $(grep -c -E " +[0-9]+\.[0-9]+ +true/[0-9]+ syscalls:sys_enter_exit_group\(\)$" $file) = "100" ]
^-- SC2046 (warning): Quote this to prevent word splitting.For more information:
https://www.shellcheck.net/wiki/SC2034 -- i appears unused. Verify use (or ...
https://www.shellcheck.net/wiki/SC2046 -- Quote this to prevent word splitt...
make[4]: *** [tests/Build:91: /tmp/build/perf-tools-next/tests/shell/trace_exit_race.sh.shellcheck_log] Error 1 make[3]: *** [/home/acme/git/perf-tools-next/tools/build/Makefile.build:158: tests] Error 2 make[2]: *** [Makefile.perf:777: /tmp/build/perf-tools-next/perf-test-in.o] Error 2
make[2]: *** Waiting for unfinished jobs....
Arnaldo Carvalho de Melo
maintainerRe: [PATCH 2/2] perf tests: add test for trace output loss
Quoted 68 lines · Arnaldo Carvalho de Melo
Quoted 42 lines · Benjamin Peterson
Add a test that checks that trace output is not lost to races. This is accomplished by tracing the
exit_groupsyscall of "true" multiple times and checking for correct output.Conveniently, this test also serves as a regression test for
5fb8e56542a3("perf
trace: avoid garbage when not printing a trace event's arguments") becauseexit_grouptriggers the previously buggy printing behavior.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.shtools/perf/tests/shell/trace_exit_race.sh new file +21
-0@@ -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" 100 times and ensure +# the output contains 100 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 100); 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) = "100" ] +} + +tools/perf/tests/shell/trace_exit_race.sh line 31
Quoted 10 lines
tools/perf/tests/shell/trace_exit_race.sh new file +10
-0+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 $errIts failing with shellcheck, I'm trying to fix it:
CC
/tmp/build/perf-tools-next/builtin-trace.o
TEST/tmp/build/perf-tools-next/tests/shell/trace_exit_race.sh.shellcheck_logIn
tests/shell/trace_exit_race.shline 15:for i in $(seq 100); do ^-^ SC2034 (warning): i appears unused. Verify use (or export if used externally).In
tests/shell/trace_exit_race.shline 18:[ $(grep -c -E " +[0-9]+\.[0-9]+ +true/[0-9]+ syscalls:sys_enter_exit_group\(\)$" $file) = "100" ] ^-- SC2046 (warning): Quote this to prevent word splitting.
Quoted 7 lines
For more information:
https://www.shellcheck.net/wiki/SC2034 -- i appears unused. Verify use (or ...
https://www.shellcheck.net/wiki/SC2046 -- Quote this to prevent word splitt...
make[4]: *** [tests/Build:91:/tmp/build/perf-tools-next/tests/shell/trace_exit_race.sh.shellcheck_log] Error 1 make[3]: *** [/home/acme/git/perf-tools-next/tools/build/Makefile.build:158: tests] Error 2 make[2]: *** [Makefile.perf:777:/tmp/build/perf-tools-next/perf-test-in.o] Error 2
make[2]: *** Waiting for unfinished jobs....
I've read the links provided by ShellCheck and folded this to satisfy it, please consider installing ShellCheck, the perf build process will use it when avaiable.
- Arnaldo
tools/perf/tests/shell/trace_exit_race.sh +2 -2
@@ -12,10 +12,10 @@ skip_if_no_perf_trace || exit 2 trace_shutdown_race() { - for i in $(seq 100); do + for _ in $(seq 100); 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) = "100" ] + [ "$(grep -c -E ' +[0-9]+\.[0-9]+ +true/[0-9]+ syscalls:sys_enter_exit_group\(\)$' $file)" = "100" ] }
Re: [PATCH 2/2] perf tests: add test for trace output loss
Quoted 78 lines · Arnaldo Carvalho de Melo
Quoted 68 lines · Arnaldo Carvalho de Melo
Quoted 42 lines · Benjamin Peterson
Add a test that checks that trace output is not lost to races. This is accomplished by tracing the
exit_groupsyscall of "true" multiple times and checking for correct output.Conveniently, this test also serves as a regression test for
5fb8e56542a3("perf
trace: avoid garbage when not printing a trace event's arguments") becauseexit_grouptriggers the previously buggy printing behavior.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.shtools/perf/tests/shell/trace_exit_race.sh new file +22
-0@@ -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" 100 times and ensure +# the output contains 100 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 100); 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) = "100" ] +} + + +file=$(mktemp /tmp/temporary_file.XXXXX)tools/perf/tests/shell/trace_exit_race.sh
Quoted 10 lines
tools/perf/tests/shell/trace_exit_race.sh new file +9
-1+ +# 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 --Its failing with shellcheck, I'm trying to fix it:
CC
/tmp/build/perf-tools-next/builtin-trace.o
TEST/tmp/build/perf-tools-next/tests/shell/trace_exit_race.sh.shellcheck_logIn
tests/shell/trace_exit_race.shline 15:
for i in $(seq 100); do
^-^ SC2034 (warning): i appears unused. Verify use (or export if used externally).In
tests/shell/trace_exit_race.shline 18:
[ $(grep -c -E " +[0-9]+\.[0-9]+ +true/[0-9]+ syscalls:sys_enter_exit_group\(\)$" $file) = "100" ]
^-- SC2046 (warning): Quote this to prevent word splitting.Quoted 7 lines
For more information:
https://www.shellcheck.net/wiki/SC2034 -- i appears unused. Verify use (or ...
https://www.shellcheck.net/wiki/SC2046 -- Quote this to prevent word splitt...
make[4]: *** [tests/Build:91:/tmp/build/perf-tools-next/tests/shell/trace_exit_race.sh.shellcheck_log] Error 1 make[3]: *** [/home/acme/git/perf-tools-next/tools/build/Makefile.build:158: tests] Error 2 make[2]: *** [Makefile.perf:777:/tmp/build/perf-tools-next/perf-test-in.o] Error 2
make[2]: *** Waiting for unfinished jobs....
Quoted 3 lines
I've read the links provided by ShellCheck and folded this to satisfy it, please consider installing ShellCheck, the perf build process will use it when avaiable.
Thank you.
Quoted 8 lines
- Arnaldo
tools/perf/tests/shell/trace_exit_race.sh +0
-0
tools/perf/tests/shell/trace_exit_race.sh line 19
Quoted 10 lines
tools/perf/tests/shell/trace_exit_race.sh +2
-2@@ -12,10 +12,10 @@ skip_if_no_perf_trace || exit 2 trace_shutdown_race() { - for i in $(seq 100); do + for _ in $(seq 100); 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) = "100" ] + [ "$(grep -c -E ' +[0-9]+\.[0-9]+ +true/[0-9]+ syscalls:sys_enter_exit_group\(\)$' $file)" = "100" ] }
This all looks okay.
Arnaldo Carvalho de Melo
maintainerRe: [PATCH 2/2] perf tests: add test for trace output loss
Quoted 17 lines · Benjamin Peterson
Quoted 6 lines · Arnaldo Carvalho de Melo
tools/perf/tests/shell/trace_exit_race.sh +0
-0tools/perf/tests/shell/trace_exit_race.sh line 19
Quoted 10 lines
tools/perf/tests/shell/trace_exit_race.sh +2
-2@@ -12,10 +12,10 @@ skip_if_no_perf_trace || exit 2 trace_shutdown_race() { - for i in $(seq 100); do + for _ in $(seq 100); 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) = "100" ] + [ "$(grep -c -E ' +[0-9]+\.[0-9]+ +true/[0-9]+ syscalls:sys_enter_exit_group\(\)$' $file)" = "100" ] }
Quoted 1 line
This all looks okay.
The test is failing for me as there is garbage in the output of perf trace even with Namhyung having already applied your previous patch:
⬢ [acme@toolbox perf-tools-next]$ git log --oneline --author [email protected]12bd434f68ea45c7 (HEAD -> perf-tools-next) perf tests: Add test for 'perf trace' output loss efbcd2cd7eac10a9 perf trace: Do not lose last events in a race5fb8e56542a3cf46 (perf-tools-next/tmp.perf-tools-next) perf trace: avoid garbage when not printing a trace event's arguments ⬢ [acme@toolbox perf-tools-next]$
root@number:~# perf trace -e syscalls:sys_enter_exit_group true
0.000 true/1982428 syscalls:sys_enter_exit_group( k?m)
root@number:~# perf trace -e syscalls:sys_enter_exit_group true
0.000 true/1982430 syscalls:sys_enter_exit_group()
root@number:~# perf trace -e syscalls:sys_enter_exit_group true
0.000 true/1982432 syscalls:sys_enter_exit_group()
root@number:~# perf trace -e syscalls:sys_enter_exit_group true
0.000 true/1982434 syscalls:sys_enter_exit_group()
root@number:~# perf trace -e syscalls:sys_enter_exit_group true
0.000 true/1982437 syscalls:sys_enter_exit_group( k�)
root@number:~# perf trace -e syscalls:sys_enter_exit_group true
0.000 true/1982439 syscalls:sys_enter_exit_group(, loads 8��1)
root@number:~#So we don't _miss_ the events, which I was noticing and brought me to test your latest 2 patches, which I applied and added a Tested-by, now tryint to figure out this garbage...
- Arnaldo
Re: [PATCH 2/2] perf tests: add test for trace output loss
Hello,
Quoted 44 lines · Arnaldo Carvalho de Melo
Quoted 17 lines · Benjamin Peterson
Quoted 6 lines · Arnaldo Carvalho de Melo
tools/perf/tests/shell/trace_exit_race.sh +0
-0tools/perf/tests/shell/trace_exit_race.sh line 19
Quoted 10 lines
tools/perf/tests/shell/trace_exit_race.sh +2
-2@@ -12,10 +12,10 @@ skip_if_no_perf_trace || exit 2 trace_shutdown_race() { - for i in $(seq 100); do + for _ in $(seq 100); 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) = "100" ] + [ "$(grep -c -E ' +[0-9]+\.[0-9]+ +true/[0-9]+ syscalls:sys_enter_exit_group\(\)$' $file)" = "100" ] }Quoted 1 line
This all looks okay.
The test is failing for me as there is garbage in the output of perf trace even with Namhyung having already applied your previous patch:
⬢ [acme@toolbox perf-tools-next]$ git log --oneline --author [email protected]
12bd434f68ea45c7(HEAD -> perf-tools-next) perf tests: Add test for 'perf trace' output lossefbcd2cd7eac10a9perf trace: Do not lose last events in a race5fb8e56542a3cf46(perf-tools-next/tmp.perf-tools-next) perf trace: avoid garbage when not printing a trace event's arguments ⬢ [acme@toolbox perf-tools-next]$root@number:~# perf trace -e syscalls:sys_enter_exit_group true 0.000 true/1982428 syscalls:sys_enter_exit_group( k?m) root@number:~# perf trace -e syscalls:sys_enter_exit_group true 0.000 true/1982430 syscalls:sys_enter_exit_group() root@number:~# perf trace -e syscalls:sys_enter_exit_group true 0.000 true/1982432 syscalls:sys_enter_exit_group() root@number:~# perf trace -e syscalls:sys_enter_exit_group true 0.000 true/1982434 syscalls:sys_enter_exit_group() root@number:~# perf trace -e syscalls:sys_enter_exit_group true 0.000 true/1982437 syscalls:sys_enter_exit_group( k�) root@number:~# perf trace -e syscalls:sys_enter_exit_group true 0.000 true/1982439 syscalls:sys_enter_exit_group(, loads 8��1) root@number:~#
Quoted 3 lines
So we don't _miss_ the events, which I was noticing and brought me to test your latest 2 patches, which I applied and added a Tested-by, now tryint to figure out this garbage...
Benjamin has already sent v2 to fix this:
https://lore.kernel.org/linux-perf-users/[email protected]/
Thanks,
Howard
Quoted 3 lines
- Arnaldo
Arnaldo Carvalho de Melo
maintainerRe: [PATCH 2/2] perf tests: add test for trace output loss
Quoted 48 lines · Howard Chu
Hello,
Quoted 44 lines · Arnaldo Carvalho de Melo
Quoted 17 lines · Benjamin Peterson
Quoted 6 lines · Arnaldo Carvalho de Melo
tools/perf/tests/shell/trace_exit_race.sh +0
-0tools/perf/tests/shell/trace_exit_race.sh line 19
Quoted 10 lines
tools/perf/tests/shell/trace_exit_race.sh +2
-2@@ -12,10 +12,10 @@ skip_if_no_perf_trace || exit 2 trace_shutdown_race() { - for i in $(seq 100); do + for _ in $(seq 100); 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) = "100" ] + [ "$(grep -c -E ' +[0-9]+\.[0-9]+ +true/[0-9]+ syscalls:sys_enter_exit_group\(\)$' $file)" = "100" ] }Quoted 1 line
This all looks okay.
The test is failing for me as there is garbage in the output of perf trace even with Namhyung having already applied your previous patch:
⬢ [acme@toolbox perf-tools-next]$ git log --oneline --author [email protected]
12bd434f68ea45c7(HEAD -> perf-tools-next) perf tests: Add test for 'perf trace' output lossefbcd2cd7eac10a9perf trace: Do not lose last events in a race5fb8e56542a3cf46(perf-tools-next/tmp.perf-tools-next) perf trace: avoid garbage when not printing a trace event's arguments ⬢ [acme@toolbox perf-tools-next]$root@number:~# perf trace -e syscalls:sys_enter_exit_group true 0.000 true/1982428 syscalls:sys_enter_exit_group( k?m) root@number:~# perf trace -e syscalls:sys_enter_exit_group true 0.000 true/1982430 syscalls:sys_enter_exit_group() root@number:~# perf trace -e syscalls:sys_enter_exit_group true 0.000 true/1982432 syscalls:sys_enter_exit_group() root@number:~# perf trace -e syscalls:sys_enter_exit_group true 0.000 true/1982434 syscalls:sys_enter_exit_group() root@number:~# perf trace -e syscalls:sys_enter_exit_group true 0.000 true/1982437 syscalls:sys_enter_exit_group( k�) root@number:~# perf trace -e syscalls:sys_enter_exit_group true 0.000 true/1982439 syscalls:sys_enter_exit_group(, loads 8��1) root@number:~#
Quoted 6 lines
Quoted 3 lines
So we don't _miss_ the events, which I was noticing and brought me to test your latest 2 patches, which I applied and added a Tested-by, now tryint to figure out this garbage...
Benjamin has already sent v2 to fix this:
https://lore.kernel.org/linux-perf-users/[email protected]/
Interesting, I wonder why b4 didn't pick the v2 :-\
I'll try it, but see my other message, maybe the way I fixed is simpler? Its a two liner that could be turned into a one liner by right at the start of the function setting bf[0] = '\0', that way we wouldn't need even to check if printed == 0 at the end.
Anyway, will test the newer version.
- Arnaldo
Arnaldo Carvalho de Melo
maintainerRe: [PATCH 2/2] perf tests: add test for trace output loss
In reply to Arnaldo Carvalho de MeloQuoted 43 lines · Arnaldo Carvalho de Melo
Quoted 17 lines · Benjamin Peterson
Quoted 6 lines · Arnaldo Carvalho de Melo
tools/perf/tests/shell/trace_exit_race.sh +0
-0tools/perf/tests/shell/trace_exit_race.sh line 19
Quoted 10 lines
tools/perf/tests/shell/trace_exit_race.sh +2
-2@@ -12,10 +12,10 @@ skip_if_no_perf_trace || exit 2 trace_shutdown_race() { - for i in $(seq 100); do + for _ in $(seq 100); 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) = "100" ] + [ "$(grep -c -E ' +[0-9]+\.[0-9]+ +true/[0-9]+ syscalls:sys_enter_exit_group\(\)$' $file)" = "100" ] }Quoted 1 line
This all looks okay.
The test is failing for me as there is garbage in the output of perf trace even with Namhyung having already applied your previous patch:
⬢ [acme@toolbox perf-tools-next]$ git log --oneline --author [email protected]
12bd434f68ea45c7(HEAD -> perf-tools-next) perf tests: Add test for 'perf trace' output lossefbcd2cd7eac10a9perf trace: Do not lose last events in a race5fb8e56542a3cf46(perf-tools-next/tmp.perf-tools-next) perf trace: avoid garbage when not printing a trace event's arguments ⬢ [acme@toolbox perf-tools-next]$root@number:~# perf trace -e syscalls:sys_enter_exit_group true 0.000 true/1982428 syscalls:sys_enter_exit_group( k?m) root@number:~# perf trace -e syscalls:sys_enter_exit_group true 0.000 true/1982430 syscalls:sys_enter_exit_group() root@number:~# perf trace -e syscalls:sys_enter_exit_group true 0.000 true/1982432 syscalls:sys_enter_exit_group() root@number:~# perf trace -e syscalls:sys_enter_exit_group true 0.000 true/1982434 syscalls:sys_enter_exit_group() root@number:~# perf trace -e syscalls:sys_enter_exit_group true 0.000 true/1982437 syscalls:sys_enter_exit_group( k�) root@number:~# perf trace -e syscalls:sys_enter_exit_group true 0.000 true/1982439 syscalls:sys_enter_exit_group(, loads 8��1) root@number:~#
Quoted 3 lines
So we don't _miss_ the events, which I was noticing and brought me to test your latest 2 patches, which I applied and added a Tested-by, now tryint to figure out this garbage...
So, I fixed it with this simple patch:
And then, after adding this patch to the 'perf test' for the exit race that you contributed:
⬢ [acme@toolbox perf-tools-next]$ git diff tools/perf/tests/
tools/perf/tests/shell/trace_exit_race.sh +13 -1
@@ -11,11 +11,17 @@ skip_if_no_perf_trace || exit 2 +if [ "$1" = "-v" ]; then + verbose="1" +fi + +regexp=" +[0-9]+\.[0-9]+ +true/[0-9]+ syscalls:sys_enter_exit_group\(\)$" + trace_shutdown_race() { for _ in $(seq 100); 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)" = "100" ] + [ "$(grep -c -E '$regexp' $file)" = "100" ] }
@@ -27,5 +33,11 @@ export PERF_CONFIG=/dev/null trace_shutdown_race err=$? + +if [ $err != 0 ] && [ "${verbose}" = "1" ]; then + echo "Lines not matching the expected regexp: '$regexp':" + grep -v -E "$regexp" $file +fi + rm -f ${file} exit $err
⬢ [acme@toolbox perf-tools-next]
⬢ [acme@toolbox perf-tools-next]$ git diff tools/perf/builtin-trace.c
tools/perf/builtin-trace.c +3 -0
@@ -2405,6 +2405,9 @@ static size_t syscall__scnprintf_args(struct syscall *sc, char *bf, size_t size, } } +if (printed ==0 ) + bf[0 ] ='\0' ; +return printed; }
⬢ [acme@toolbox perf-tools-next]$
The test still fails but for another reason:
root@number:~# perf test -v "trace exit race"
--- start ---
test child forked, pid 2002298
Lines not matching the expected regexp: ' +[0-9]+\.[0-9]+ +true/[0-9]+ syscalls:sys_enter_exit_group\(\)$':
0.000 :2002317/2002317 syscalls:sys_enter_exit_group()
0.000 :2002319/2002319 syscalls:sys_enter_exit_group()
0.000 :2002353/2002353 syscalls:sys_enter_exit_group()
0.000 :2002357/2002357 syscalls:sys_enter_exit_group()
0.000 :2002376/2002376 syscalls:sys_enter_exit_group()
0.000 :2002378/2002378 syscalls:sys_enter_exit_group()
0.000 :2002393/2002393 syscalls:sys_enter_exit_group()
0.000 :2002444/2002444 syscalls:sys_enter_exit_group()
0.000 :2002491/2002491 syscalls:sys_enter_exit_group()
0.000 :2002503/2002503 syscalls:sys_enter_exit_group()
---- end(-1) ----
110: perf trace exit race : FAILED!
root@number:~# Somehow we're missing the PERF_RECORD_COMM or racing to get it from /proc for those processes and thus we end up printing just the pid/ppid
Since what we are testing here is garbage when printing the argument list, we can just disable comm printing and get consistent results:
root@number:~# perf trace --no-comm -e syscalls:sys_enter_exit_group true
0.000 2003312 syscalls:sys_enter_exit_group()
root@number:~#I'll take this route and sent a patch series.
- Arnaldo
Hello Benjamin,
Without your patch (no output):
perf $ ./perf trace -e syscalls:sys_enter_exit_group true perf $
With your patch:
perf $ ./perf trace -e syscalls:sys_enter_exit_group true
0.000 true/1530009 syscalls:sys_enter_exit_group()
The result looks good.
Thanks,
Howard
Quoted 50 lines · 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_handlerchecked 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_handlershould 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")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
-8@@ -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