[PATCH v2 0/2] perf test shell trace_exit_race improvements

[PATCH v2 0/2] perf test shell trace_exit_race improvements

[Arnaldo Carvalho de Melo]

Hi,

	Here is v2, folding a slightly modified version from Howard
reviewing patch, with an extra patch to use --no-comm with 'perf trace'
as discussed previously and in the patch log message,

	Please see if everything is all right now,

- Arnaldo

Arnaldo Carvalho de Melo (2):
  perf test shell trace_exit_race: Show what went wrong in verbose mode
  perf test shell trace_exit_race: Use --no-comm to avoid cases where
    COMM isn't resolved

 tools/perf/tests/shell/trace_exit_race.sh | 26 ++++++++++++++++++++---
 1 file changed, 23 insertions(+), 3 deletions(-)

-- 
2.47.0

[PATCH 1/2] perf test shell trace_exit_race: Show what went wrong in verbose mode

[Arnaldo Carvalho de Melo]

From: Arnaldo Carvalho de Melo <acme@redhat.com>

If it fails we need to check what was the reason, what were the lines
that didn't match the expected format, so:

  root@number:~# perf test -v "trace exit race"
  --- start ---
  test child forked, pid 2028724
  Lines not matching the expected regexp: ' +[0-9]+\.[0-9]+ +true/[0-9]+ syscalls:sys_enter_exit_group\(\)$':
       0.000 :2028750/2028750 syscalls:sys_enter_exit_group()
  ---- end(-1) ----
  110: perf trace exit race                                            : FAILED!
  root@number:~#

In this case we're not resolving the process COMM for some reason and
fallback to printing just the pid/tid, this will be fixed in a followup
patch.

Howard Chu spotted a problem with single code surrounding a regexp, that
made the test always fail, but since there were some failures when I
tested (COMM not being resolved in some of the results) the end inverse
grep would show some lines and thus didn't notice the single quote
problem.

He also provided a patch to test if less than the number of expected
matches took place but all of them with the expected output, in which
case the inverse grep wouldn't show anything, confusing the tester.

Reviewed-by: Howard Chu <howardchu95@gmail.com>
Cc: Adrian Hunter <adrian.hunter@intel.com>
Cc: Alexander Shishkin <alexander.shishkin@linux.intel.com>
Cc: Benjamin Peterson <benjamin@engflow.com>
Cc: Ian Rogers <irogers@google.com>
Cc: Ingo Molnar <mingo@redhat.com>
Cc: Jiri Olsa <jolsa@kernel.org>
Cc: Kan Liang <kan.liang@linux.intel.com>
Cc: Mark Rutland <mark.rutland@arm.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Link: https://lore.kernel.org/lkml/ZzdknoHqrJbojb6P@x1
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
---
 tools/perf/tests/shell/trace_exit_race.sh | 24 +++++++++++++++++++++--
 1 file changed, 22 insertions(+), 2 deletions(-)

diff --git a/tools/perf/tests/shell/trace_exit_race.sh b/tools/perf/tests/shell/trace_exit_race.sh
index 3cf2d71a5c3b9278..8ea24f4256bc8f5e 100755
--- a/tools/perf/tests/shell/trace_exit_race.sh
+++ b/tools/perf/tests/shell/trace_exit_race.sh
@@ -11,11 +11,19 @@
 
 skip_if_no_perf_trace || exit 2
 
+if [ "$1" = "-v" ]; then
+	verbose="1"
+fi
+
+iter=10
+regexp=" +[0-9]+\.[0-9]+ +true/[0-9]+ syscalls:sys_enter_exit_group\(\)$"
+
 trace_shutdown_race() {
-	for _ in $(seq 10); do
+	for _ in $(seq $iter); 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" ]
+	result="$(grep -c -E "$regexp" $file)"
+	[ $result = $iter ]
 }
 
 
@@ -27,5 +35,17 @@ export PERF_CONFIG=/dev/null
 
 trace_shutdown_race
 err=$?
+
+if [ $err != 0 ] && [ "${verbose}" = "1" ]; then
+	lines_not_matching=$(mktemp /tmp/temporary_file.XXXXX)
+	if grep -v -E "$regexp" $file > $lines_not_matching ; then
+		echo "Lines not matching the expected regexp: '$regexp':"
+		cat $lines_not_matching
+	else
+		echo "Missing output, expected $iter but only got $result"
+	fi
+	rm -f $lines_not_matching
+fi
+
 rm -f ${file}
 exit $err
-- 
2.47.0

Re: [PATCH 1/2] perf test shell trace_exit_race: Show what went wrong in verbose mode

[Howard Chu]

Hello Arnaldo,

On Fri, Nov 15, 2024 at 7:36 AM Arnaldo Carvalho de Melo
<acme@kernel.org> wrote:
>
> From: Arnaldo Carvalho de Melo <acme@redhat.com>
>
> If it fails we need to check what was the reason, what were the lines
> that didn't match the expected format, so:
>
>   root@number:~# perf test -v "trace exit race"
>   --- start ---
>   test child forked, pid 2028724
>   Lines not matching the expected regexp: ' +[0-9]+\.[0-9]+ +true/[0-9]+ syscalls:sys_enter_exit_group\(\)$':
>        0.000 :2028750/2028750 syscalls:sys_enter_exit_group()
>   ---- end(-1) ----
>   110: perf trace exit race                                            : FAILED!
>   root@number:~#
>
> In this case we're not resolving the process COMM for some reason and
> fallback to printing just the pid/tid, this will be fixed in a followup
> patch.
>
> Howard Chu spotted a problem with single code surrounding a regexp, that
> made the test always fail, but since there were some failures when I
> tested (COMM not being resolved in some of the results) the end inverse
> grep would show some lines and thus didn't notice the single quote
> problem.
>
> He also provided a patch to test if less than the number of expected
> matches took place but all of them with the expected output, in which
> case the inverse grep wouldn't show anything, confusing the tester.
>
> Reviewed-by: Howard Chu <howardchu95@gmail.com>
> Cc: Adrian Hunter <adrian.hunter@intel.com>
> Cc: Alexander Shishkin <alexander.shishkin@linux.intel.com>
> Cc: Benjamin Peterson <benjamin@engflow.com>
> Cc: Ian Rogers <irogers@google.com>
> Cc: Ingo Molnar <mingo@redhat.com>
> Cc: Jiri Olsa <jolsa@kernel.org>
> Cc: Kan Liang <kan.liang@linux.intel.com>
> Cc: Mark Rutland <mark.rutland@arm.com>
> Cc: Namhyung Kim <namhyung@kernel.org>
> Cc: Peter Zijlstra <peterz@infradead.org>
> Link: https://lore.kernel.org/lkml/ZzdknoHqrJbojb6P@x1
> Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
> ---
>  tools/perf/tests/shell/trace_exit_race.sh | 24 +++++++++++++++++++++--
>  1 file changed, 22 insertions(+), 2 deletions(-)
>
> diff --git a/tools/perf/tests/shell/trace_exit_race.sh b/tools/perf/tests/shell/trace_exit_race.sh
> index 3cf2d71a5c3b9278..8ea24f4256bc8f5e 100755
> --- a/tools/perf/tests/shell/trace_exit_race.sh
> +++ b/tools/perf/tests/shell/trace_exit_race.sh
> @@ -11,11 +11,19 @@
>
>  skip_if_no_perf_trace || exit 2
>
> +if [ "$1" = "-v" ]; then
> +       verbose="1"
> +fi
> +
> +iter=10
> +regexp=" +[0-9]+\.[0-9]+ +true/[0-9]+ syscalls:sys_enter_exit_group\(\)$"
> +
>  trace_shutdown_race() {
> -       for _ in $(seq 10); do
> +       for _ in $(seq $iter); 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" ]
> +       result="$(grep -c -E "$regexp" $file)"
> +       [ $result = $iter ]
>  }
>
>
> @@ -27,5 +35,17 @@ export PERF_CONFIG=/dev/null
>
>  trace_shutdown_race
>  err=$?
> +
> +if [ $err != 0 ] && [ "${verbose}" = "1" ]; then
> +       lines_not_matching=$(mktemp /tmp/temporary_file.XXXXX)
> +       if grep -v -E "$regexp" $file > $lines_not_matching ; then
> +               echo "Lines not matching the expected regexp: '$regexp':"
> +               cat $lines_not_matching
> +       else
> +               echo "Missing output, expected $iter but only got $result"
> +       fi
> +       rm -f $lines_not_matching
> +fi
> +
>  rm -f ${file}
>  exit $err

LGTM.

Thanks,
Howard

> --
> 2.47.0
>

[PATCH 2/2] perf test shell trace_exit_race: Use --no-comm to avoid cases where COMM isn't resolved

[Arnaldo Carvalho de Melo]

From: Arnaldo Carvalho de Melo <acme@redhat.com>

The purpose of this test is to test for races in the exit of 'perf
trace' missing the last events, it was failing when the COMM wasn't
resolved either because we missed some PERF_RECORD_COMM or somehow
raced on getting it from procfs.

Add --no-comm to the 'perf trace' command line so that we get a
consistent, pid only output, which allows the test to achieve its goal.

This is the output from
'perf trace --no-comm -e syscalls:sys_enter_exit_group':

     0.000 21953 syscalls:sys_enter_exit_group()
     0.000 21955 syscalls:sys_enter_exit_group()
     0.000 21957 syscalls:sys_enter_exit_group()
     0.000 21959 syscalls:sys_enter_exit_group()
     0.000 21961 syscalls:sys_enter_exit_group()
     0.000 21963 syscalls:sys_enter_exit_group()
     0.000 21965 syscalls:sys_enter_exit_group()
     0.000 21967 syscalls:sys_enter_exit_group()
     0.000 21969 syscalls:sys_enter_exit_group()
     0.000 21971 syscalls:sys_enter_exit_group()

Now it passes:

  root@number:~# perf test "trace exit race"
  110: perf trace exit race                                            : Ok
  root@number:~#
  root@number:~# perf test -v "trace exit race"
  110: perf trace exit race                                            : Ok
  root@number:~#

If we artificially make it run just 9 times instead of the 10 it runs,
i.e. by manually doing:

	trace_shutdown_race() {
		for _ in $(seq 9); do

that 9 is $iter, 10 in the patch, we get:

  root@number:~# vim ~acme/libexec/perf-core/tests/shell/trace_exit_race.sh
  root@number:~# perf test -v "trace exit race"
  --- start ---
  test child forked, pid 24629
  Missing output, expected 10 but only got 9
  ---- end(-1) ----
  110: perf trace exit race                                            : FAILED!
  root@number:~#

I.e. 9 'perf trace' calls produced the expected output, the inverse grep
didn't show anything, so the patch provided by Howard for the previous
patch kicks in and shows a more informative message.

Cc: Adrian Hunter <adrian.hunter@intel.com>
Cc: Alexander Shishkin <alexander.shishkin@linux.intel.com>
Cc: Benjamin Peterson <benjamin@engflow.com>
Cc: Howard Chu <howardchu95@gmail.com>
Cc: Ian Rogers <irogers@google.com>
Cc: Ingo Molnar <mingo@redhat.com>
Cc: Jiri Olsa <jolsa@kernel.org>
Cc: Kan Liang <kan.liang@linux.intel.com>
Cc: Mark Rutland <mark.rutland@arm.com>
Cc: Namhyung Kim <namhyung@kernel.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Link: https://lore.kernel.org/lkml/ZzdknoHqrJbojb6P@x1
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
---
 tools/perf/tests/shell/trace_exit_race.sh | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/tools/perf/tests/shell/trace_exit_race.sh b/tools/perf/tests/shell/trace_exit_race.sh
index 8ea24f4256bc8f5e..fbb0adc33a889516 100755
--- a/tools/perf/tests/shell/trace_exit_race.sh
+++ b/tools/perf/tests/shell/trace_exit_race.sh
@@ -16,11 +16,11 @@ if [ "$1" = "-v" ]; then
 fi
 
 iter=10
-regexp=" +[0-9]+\.[0-9]+ +true/[0-9]+ syscalls:sys_enter_exit_group\(\)$"
+regexp=" +[0-9]+\.[0-9]+ [0-9]+ syscalls:sys_enter_exit_group\(\)$"
 
 trace_shutdown_race() {
 	for _ in $(seq $iter); do
-		perf trace -e syscalls:sys_enter_exit_group true 2>>$file
+		perf trace --no-comm -e syscalls:sys_enter_exit_group true 2>>$file
 	done
 	result="$(grep -c -E "$regexp" $file)"
 	[ $result = $iter ]
-- 
2.47.0

Re: [PATCH 2/2] perf test shell trace_exit_race: Use --no-comm to avoid cases where COMM isn't resolved

[Howard Chu]

perf $ ./perf test "perf trace exit race" -v

110: perf trace exit race                                            : Ok

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

Thanks,
Howard

On Fri, Nov 15, 2024 at 7:36 AM Arnaldo Carvalho de Melo
<acme@kernel.org> wrote:
>
> From: Arnaldo Carvalho de Melo <acme@redhat.com>
>
> The purpose of this test is to test for races in the exit of 'perf
> trace' missing the last events, it was failing when the COMM wasn't
> resolved either because we missed some PERF_RECORD_COMM or somehow
> raced on getting it from procfs.
>
> Add --no-comm to the 'perf trace' command line so that we get a
> consistent, pid only output, which allows the test to achieve its goal.
>
> This is the output from
> 'perf trace --no-comm -e syscalls:sys_enter_exit_group':
>
>      0.000 21953 syscalls:sys_enter_exit_group()
>      0.000 21955 syscalls:sys_enter_exit_group()
>      0.000 21957 syscalls:sys_enter_exit_group()
>      0.000 21959 syscalls:sys_enter_exit_group()
>      0.000 21961 syscalls:sys_enter_exit_group()
>      0.000 21963 syscalls:sys_enter_exit_group()
>      0.000 21965 syscalls:sys_enter_exit_group()
>      0.000 21967 syscalls:sys_enter_exit_group()
>      0.000 21969 syscalls:sys_enter_exit_group()
>      0.000 21971 syscalls:sys_enter_exit_group()
>
> Now it passes:
>
>   root@number:~# perf test "trace exit race"
>   110: perf trace exit race                                            : Ok
>   root@number:~#
>   root@number:~# perf test -v "trace exit race"
>   110: perf trace exit race                                            : Ok
>   root@number:~#
>
> If we artificially make it run just 9 times instead of the 10 it runs,
> i.e. by manually doing:
>
>         trace_shutdown_race() {
>                 for _ in $(seq 9); do
>
> that 9 is $iter, 10 in the patch, we get:
>
>   root@number:~# vim ~acme/libexec/perf-core/tests/shell/trace_exit_race.sh
>   root@number:~# perf test -v "trace exit race"
>   --- start ---
>   test child forked, pid 24629
>   Missing output, expected 10 but only got 9
>   ---- end(-1) ----
>   110: perf trace exit race                                            : FAILED!
>   root@number:~#
>
> I.e. 9 'perf trace' calls produced the expected output, the inverse grep
> didn't show anything, so the patch provided by Howard for the previous
> patch kicks in and shows a more informative message.
>
> Cc: Adrian Hunter <adrian.hunter@intel.com>
> Cc: Alexander Shishkin <alexander.shishkin@linux.intel.com>
> Cc: Benjamin Peterson <benjamin@engflow.com>
> Cc: Howard Chu <howardchu95@gmail.com>
> Cc: Ian Rogers <irogers@google.com>
> Cc: Ingo Molnar <mingo@redhat.com>
> Cc: Jiri Olsa <jolsa@kernel.org>
> Cc: Kan Liang <kan.liang@linux.intel.com>
> Cc: Mark Rutland <mark.rutland@arm.com>
> Cc: Namhyung Kim <namhyung@kernel.org>
> Cc: Peter Zijlstra <peterz@infradead.org>
> Link: https://lore.kernel.org/lkml/ZzdknoHqrJbojb6P@x1
> Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
> ---
>  tools/perf/tests/shell/trace_exit_race.sh | 4 ++--
>  1 file changed, 2 insertions(+), 2 deletions(-)
>
> diff --git a/tools/perf/tests/shell/trace_exit_race.sh b/tools/perf/tests/shell/trace_exit_race.sh
> index 8ea24f4256bc8f5e..fbb0adc33a889516 100755
> --- a/tools/perf/tests/shell/trace_exit_race.sh
> +++ b/tools/perf/tests/shell/trace_exit_race.sh
> @@ -16,11 +16,11 @@ if [ "$1" = "-v" ]; then
>  fi
>
>  iter=10
> -regexp=" +[0-9]+\.[0-9]+ +true/[0-9]+ syscalls:sys_enter_exit_group\(\)$"
> +regexp=" +[0-9]+\.[0-9]+ [0-9]+ syscalls:sys_enter_exit_group\(\)$"
>
>  trace_shutdown_race() {
>         for _ in $(seq $iter); do
> -               perf trace -e syscalls:sys_enter_exit_group true 2>>$file
> +               perf trace --no-comm -e syscalls:sys_enter_exit_group true 2>>$file
>         done
>         result="$(grep -c -E "$regexp" $file)"
>         [ $result = $iter ]
> --
> 2.47.0
>

Re: [PATCH 2/2] perf test shell trace_exit_race: Use --no-comm to avoid cases where COMM isn't resolved

[Arnaldo Carvalho de Melo]

On Fri, Nov 15, 2024 at 10:36:45AM -0800, Howard Chu wrote:
> perf $ ./perf test "perf trace exit race" -v
> 
> 110: perf trace exit race                                            : Ok
> 
> Tested-by: Howard Chu <howardchu95@gmail.com>

Thanks, added to the cset.

- Arnaldo