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

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

[arnaldo.melo]

This is in the tmp.perf-tools-next  branch at:

https://git.kernel.org/pub/scm/linux/kernel/git/perf/perf-tools-next.git

I'll later add another patch adding the --no-comm to the 'perf trace'
command line and will adjust the regexp.

- Arnaldo

---

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.

Cc: Adrian Hunter <adrian.hunter@intel.com>
Cc: Alexander Shishkin <alexander.shishkin@linux.intel.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>
To: Benjamin Peterson <benjamin@engflow.com>
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
---
 tools/perf/tests/shell/trace_exit_race.sh | 14 +++++++++++++-
 1 file changed, 13 insertions(+), 1 deletion(-)

diff --git a/tools/perf/tests/shell/trace_exit_race.sh b/tools/perf/tests/shell/trace_exit_race.sh
index 3cf2d71a5c3b9278..ce05d4e6e7133cd1 100755
--- a/tools/perf/tests/shell/trace_exit_race.sh
+++ b/tools/perf/tests/shell/trace_exit_race.sh
@@ -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 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" ]
+	[ "$(grep -c -E '$regexp' $file)" = "10" ]
 }
 
 
@@ -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
-- 
2.47.0

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

[Howard Chu]

Hello Arnaldo,

On Thu, Nov 14, 2024 at 1:19 PM <arnaldo.melo@gmail.com> wrote:
>
> This is in the tmp.perf-tools-next  branch at:
>
> https://git.kernel.org/pub/scm/linux/kernel/git/perf/perf-tools-next.git
>
> I'll later add another patch adding the --no-comm to the 'perf trace'
> command line and will adjust the regexp.
>
> - Arnaldo
>
> ---
>
> 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()

This output looks good but I got an empty grep -v:

perf $ ./perf test 110 -v
110: perf trace exit race                                            :
Running (1
--- start ---
test child forked, pid 3865874
Lines not matching the expected regexp: ' +[0-9]+\.[0-9]+ +true/[0-9]+
syscalls:sys_enter_exit_group\(\)$':
---- end(-1) ----
110: perf trace exit race                                            : FAILED!

In temp file:
0.000 true/3867219 syscalls:sys_enter_exit_group()
0.000 true/3867221 syscalls:sys_enter_exit_group()
0.000 true/3867223 syscalls:sys_enter_exit_group()
0.000 true/3867226 syscalls:sys_enter_exit_group()
0.000 true/3867250 syscalls:sys_enter_exit_group()
0.000 true/3867252 syscalls:sys_enter_exit_group()
0.000 true/3867255 syscalls:sys_enter_exit_group()
0.000 true/3867257 syscalls:sys_enter_exit_group()
0.000 true/3867259 syscalls:sys_enter_exit_group()
0.000 true/3867262 syscalls:sys_enter_exit_group()

There are 10 lines of output which match the regex (I got the comm
instead of pid), but it still falls into error, and inverse regex got
nothing because they are all right.

>   ---- 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.
>
> Cc: Adrian Hunter <adrian.hunter@intel.com>
> Cc: Alexander Shishkin <alexander.shishkin@linux.intel.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>
> To: Benjamin Peterson <benjamin@engflow.com>
> Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
> ---
>  tools/perf/tests/shell/trace_exit_race.sh | 14 +++++++++++++-
>  1 file changed, 13 insertions(+), 1 deletion(-)
>
> diff --git a/tools/perf/tests/shell/trace_exit_race.sh b/tools/perf/tests/shell/trace_exit_race.sh
> index 3cf2d71a5c3b9278..ce05d4e6e7133cd1 100755
> --- a/tools/perf/tests/shell/trace_exit_race.sh
> +++ b/tools/perf/tests/shell/trace_exit_race.sh
> @@ -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 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" ]
> +       [ "$(grep -c -E '$regexp' $file)" = "10" ]

shouldn't this be
[ "$(grep -c -E "$regexp" $file)" = "10" ]
?

In shell script single quote doesn't interpolate, in this case you are
literally grepping the string "$regexp". After changing this to double
quotes it works for me.

>  }
>
>
> @@ -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':"

Also, I think there is a case, where $err != 0 can come from not
having 10 matches, say 4 (because of racing), and these 4 can all be
correct, the inverse grep -v won't match anything, results in an empty
output as above:

Lines not matching the expected regexp: ' +[0-9]+\.[0-9]+ +true/[0-9]+
syscalls:sys_enter_exit_group\(\)$':
---- end(-1) ----

> +       grep -v -E "$regexp" $file
> +fi
> +
>  rm -f ${file}
>  exit $err
> --
> 2.47.0
>

Maybe this? (based on your test)

diff --git a/tools/perf/tests/shell/trace_exit_race.sh
b/tools/perf/tests/shell/trace_exit_race.sh
index ce05d4e6e713..3633907e9e2a 100755
--- a/tools/perf/tests/shell/trace_exit_race.sh
+++ b/tools/perf/tests/shell/trace_exit_race.sh
@@ -16,12 +16,15 @@ if [ "$1" = "-v" ]; then
 fi

 regexp=" +[0-9]+\.[0-9]+ +true/[0-9]+ syscalls:sys_enter_exit_group\(\)$"
+iter=15

 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 '$regexp' $file)" = "10" ]
+
+        result="$(grep -c -E "$regexp" $file)"
+        [ $result  = $iter ]
 }


@@ -35,8 +38,12 @@ trace_shutdown_race
 err=$?

 if [ $err != 0 ] && [ "${verbose}" = "1" ]; then
-        echo "Lines not matching the expected regexp: '$regexp':"
-        grep -v -E "$regexp" $file
+        if grep -q -v -E "$regexp" $file; then
+                echo "Lines not matching the expected regexp: '$regexp':"
+                grep -v -E "$regexp" $file
+        else
+                echo "Missing output, expected $iter but only got $result"
+        fi
 fi

 rm -f ${file}

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

Thanks,
Howard

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

[Arnaldo Carvalho de Melo]

On Fri, Nov 15, 2024 at 01:32:15AM -0800, Howard Chu wrote:
> On Thu, Nov 14, 2024 at 1:19 PM <arnaldo.melo@gmail.com> wrote:
> > This is in the tmp.perf-tools-next  branch at:

> > https://git.kernel.org/pub/scm/linux/kernel/git/perf/perf-tools-next.git

> > I'll later add another patch adding the --no-comm to the 'perf trace'
> > command line and will adjust the regexp.

> > 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()
 
> This output looks good but I got an empty grep -v:
 
> perf $ ./perf test 110 -v
> 110: perf trace exit race                                            :
> Running (1
> --- start ---
> test child forked, pid 3865874
> Lines not matching the expected regexp: ' +[0-9]+\.[0-9]+ +true/[0-9]+
> syscalls:sys_enter_exit_group\(\)$':
> ---- end(-1) ----
> 110: perf trace exit race                                            : FAILED!
 
> In temp file:
> 0.000 true/3867219 syscalls:sys_enter_exit_group()
> 0.000 true/3867221 syscalls:sys_enter_exit_group()
> 0.000 true/3867223 syscalls:sys_enter_exit_group()
> 0.000 true/3867226 syscalls:sys_enter_exit_group()
> 0.000 true/3867250 syscalls:sys_enter_exit_group()
> 0.000 true/3867252 syscalls:sys_enter_exit_group()
> 0.000 true/3867255 syscalls:sys_enter_exit_group()
> 0.000 true/3867257 syscalls:sys_enter_exit_group()
> 0.000 true/3867259 syscalls:sys_enter_exit_group()
> 0.000 true/3867262 syscalls:sys_enter_exit_group()
> 
> There are 10 lines of output which match the regex (I got the comm
> instead of pid), but it still falls into error, and inverse regex got
> nothing because they are all right.

You're right, I got confused with the other problem, namely in my case
some failures due to non-COMM resolution which ended up showing a few
that are not matching, so I thought it was about that.

Also at some point ShellCheck complained about some quoting and I ended
up adding that thinko, well spotted!

So with:

⬢ [acme@toolbox perf-tools-next]$ git diff
diff --git a/tools/perf/tests/shell/trace_exit_race.sh b/tools/perf/tests/shell/trace_exit_race.sh
index ce05d4e6e7133cd1..2e5581f550c50d16 100755
--- a/tools/perf/tests/shell/trace_exit_race.sh
+++ b/tools/perf/tests/shell/trace_exit_race.sh
@@ -21,7 +21,7 @@ trace_shutdown_race() {
        for _ in $(seq 10); do
                perf trace -e syscalls:sys_enter_exit_group true 2>>$file
        done
-       [ "$(grep -c -E '$regexp' $file)" = "10" ]
+       [ "$(grep -c -E "$regexp" $file)" = "10" ]
 }
 
 
@@ -39,5 +39,5 @@ if [ $err != 0 ] && [ "${verbose}" = "1" ]; then
        grep -v -E "$regexp" $file
 fi
 
-rm -f ${file}
+echo rm -f ${file}
 exit $err
⬢ [acme@toolbox perf-tools-next]$

I'm getting what you're getting:

root@number:~# perf test -v "trace exit race"
--- start ---
test child forked, pid 12139
Lines not matching the expected regexp: ' +[0-9]+\.[0-9]+ +true/[0-9]+ syscalls:sys_enter_exit_group\(\)$':
     0.000 :12161/12161 syscalls:sys_enter_exit_group()
     0.000 :12167/12167 syscalls:sys_enter_exit_group()
rm -f /tmp/temporary_file.v7REF
---- end(-1) ----
110: perf trace exit race                                            : FAILED!
root@number:~# cat /tmp/temporary_file.v7REF
     0.000 true/12147 syscalls:sys_enter_exit_group()
     0.000 true/12151 syscalls:sys_enter_exit_group()
     0.000 true/12153 syscalls:sys_enter_exit_group()
     0.000 true/12155 syscalls:sys_enter_exit_group()
     0.000 true/12157 syscalls:sys_enter_exit_group()
     0.000 true/12159 syscalls:sys_enter_exit_group()
     0.000 :12161/12161 syscalls:sys_enter_exit_group()
     0.000 true/12163 syscalls:sys_enter_exit_group()
     0.000 true/12165 syscalls:sys_enter_exit_group()
     0.000 :12167/12167 syscalls:sys_enter_exit_group()
root@number:~# grep -E ' +[0-9]+\.[0-9]+ +true/[0-9]+ syscalls:sys_enter_exit_group\(\)$' /tmp/temporary_file.v7REF
     0.000 true/12147 syscalls:sys_enter_exit_group()
     0.000 true/12151 syscalls:sys_enter_exit_group()
     0.000 true/12153 syscalls:sys_enter_exit_group()
     0.000 true/12155 syscalls:sys_enter_exit_group()
     0.000 true/12157 syscalls:sys_enter_exit_group()
     0.000 true/12159 syscalls:sys_enter_exit_group()
     0.000 true/12163 syscalls:sys_enter_exit_group()
     0.000 true/12165 syscalls:sys_enter_exit_group()
root@number:~# grep -v -E ' +[0-9]+\.[0-9]+ +true/[0-9]+ syscalls:sys_enter_exit_group\(\)$' /tmp/temporary_file.v7REF
     0.000 :12161/12161 syscalls:sys_enter_exit_group()
     0.000 :12167/12167 syscalls:sys_enter_exit_group()
root@number:~# git difroot@number:~# perf test -v "trace exit race"
--- start ---
test child forked, pid 12139
Lines not matching the expected regexp: ' +[0-9]+\.[0-9]+ +true/[0-9]+ syscalls:sys_enter_exit_group\(\)$':
     0.000 :12161/12161 syscalls:sys_enter_exit_group()
     0.000 :12167/12167 syscalls:sys_enter_exit_group()
rm -f /tmp/temporary_file.v7REF
---- end(-1) ----
110: perf trace exit race                                            : FAILED!
root@number:~# cat /tmp/temporary_file.v7REF
     0.000 true/12147 syscalls:sys_enter_exit_group()
     0.000 true/12151 syscalls:sys_enter_exit_group()
     0.000 true/12153 syscalls:sys_enter_exit_group()
     0.000 true/12155 syscalls:sys_enter_exit_group()
     0.000 true/12157 syscalls:sys_enter_exit_group()
     0.000 true/12159 syscalls:sys_enter_exit_group()
     0.000 :12161/12161 syscalls:sys_enter_exit_group()
     0.000 true/12163 syscalls:sys_enter_exit_group()
     0.000 true/12165 syscalls:sys_enter_exit_group()
     0.000 :12167/12167 syscalls:sys_enter_exit_group()
root@number:~# grep -E ' +[0-9]+\.[0-9]+ +true/[0-9]+ syscalls:sys_enter_exit_group\(\)$' /tmp/temporary_file.v7REF
     0.000 true/12147 syscalls:sys_enter_exit_group()
     0.000 true/12151 syscalls:sys_enter_exit_group()
     0.000 true/12153 syscalls:sys_enter_exit_group()
     0.000 true/12155 syscalls:sys_enter_exit_group()
     0.000 true/12157 syscalls:sys_enter_exit_group()
     0.000 true/12159 syscalls:sys_enter_exit_group()
     0.000 true/12163 syscalls:sys_enter_exit_group()
     0.000 true/12165 syscalls:sys_enter_exit_group()
root@number:~# grep -v -E ' +[0-9]+\.[0-9]+ +true/[0-9]+ syscalls:sys_enter_exit_group\(\)$' /tmp/temporary_file.v7REF
     0.000 :12161/12161 syscalls:sys_enter_exit_group()
     0.000 :12167/12167 syscalls:sys_enter_exit_group()
root@number:~# git diff
 
> >   ---- 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.
> > -       [ "$(grep -c -E ' +[0-9]+\.[0-9]+ +true/[0-9]+ syscalls:sys_enter_exit_group\(\)$' $file)" = "10" ]
> > +       [ "$(grep -c -E '$regexp' $file)" = "10" ]
> 
> shouldn't this be
> [ "$(grep -c -E "$regexp" $file)" = "10" ]
> ?
> 
> In shell script single quote doesn't interpolate, in this case you are
> literally grepping the string "$regexp". After changing this to double
> quotes it works for me.

Right, see above.
 
> >  err=$?
> > +
> > +if [ $err != 0 ] && [ "${verbose}" = "1" ]; then
> > +       echo "Lines not matching the expected regexp: '$regexp':"
 
> Also, I think there is a case, where $err != 0 can come from not
> having 10 matches, say 4 (because of racing), and these 4 can all be
> correct, the inverse grep -v won't match anything, results in an empty
> output as above:

Right again,
 
> Lines not matching the expected regexp: ' +[0-9]+\.[0-9]+ +true/[0-9]+
> syscalls:sys_enter_exit_group\(\)$':
> ---- end(-1) ----
> 
> > +       grep -v -E "$regexp" $file
> > +fi
> > +
> >  rm -f ${file}
> >  exit $err
> > --
> > 2.47.0
> >
> 
> Maybe this? (based on your test)
> 
> +++ b/tools/perf/tests/shell/trace_exit_race.sh
> @@ -16,12 +16,15 @@ if [ "$1" = "-v" ]; then
>  fi
> 
>  regexp=" +[0-9]+\.[0-9]+ +true/[0-9]+ syscalls:sys_enter_exit_group\(\)$"
> +iter=15
> 
>  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 '$regexp' $file)" = "10" ]
> +
> +        result="$(grep -c -E "$regexp" $file)"
> +        [ $result = $iter ]
>  }
> 
> 
> @@ -35,8 +38,12 @@ trace_shutdown_race
>  err=$?
> 
>  if [ $err != 0 ] && [ "${verbose}" = "1" ]; then
> -        echo "Lines not matching the expected regexp: '$regexp':"
> -        grep -v -E "$regexp" $file
> +        if grep -q -v -E "$regexp" $file; then
> +                echo "Lines not matching the expected regexp: '$regexp':"
> +                grep -v -E "$regexp" $file
> +        else
> +                echo "Missing output, expected $iter but only got $result"
> +        fi
>  fi
> 
>  rm -f ${file}
> 
> Reviewed-by: Howard Chu <howardchu95@gmail.com>

Please see if you keep it, I ended up applying the slight variation
below, to avoid an repeating the last inverse grep.

Thanks a lot for reviewing and spotting that st00pid problem and
suggesting the improvement for the inverse grep!

- Arnaldo

diff --git a/tools/perf/tests/shell/trace_exit_race.sh b/tools/perf/tests/shell/trace_exit_race.sh
index ce05d4e6e7133cd1..8ea24f4256bc8f5e 100755
--- a/tools/perf/tests/shell/trace_exit_race.sh
+++ b/tools/perf/tests/shell/trace_exit_race.sh
@@ -15,13 +15,15 @@ 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 '$regexp' $file)" = "10" ]
+	result="$(grep -c -E "$regexp" $file)"
+	[ $result = $iter ]
 }
 
 
@@ -35,8 +37,14 @@ trace_shutdown_race
 err=$?
 
 if [ $err != 0 ] && [ "${verbose}" = "1" ]; then
-	echo "Lines not matching the expected regexp: '$regexp':"
-	grep -v -E "$regexp" $file
+	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}