[PATCH v1 0/5] perf test trace: Reduce test failures and make error messages verbose

[PATCH v1 0/5] perf test trace: Reduce test failures and make error messages verbose

[Howard Chu]

Currently, BTF tests fail constantly, this series fixes two major reasons
why they fail, and makes the error messages acquired when using '-vv'
more verbose, so when they fail, one can easily diagnose the problem.

Before:
    $ sudo /tmp/perf test enum -vv
    107: perf trace enum augmentation tests:
    107: perf trace enum augmentation tests                              : Running
    --- start ---
    test child forked, pid 783533
    Checking if vmlinux exists
    Tracing syscall landlock_add_rule
    Tracing non-syscall tracepoint syscall
    ---- end(-1) ----
    107: perf trace enum augmentation tests                              : FAILED!

After:
    $ sudo /tmp/perf test enum -vv
    107: perf trace enum augmentation tests:
    107: perf trace enum augmentation tests                              : Running
    --- start ---
    test child forked, pid 851658
    Checking if vmlinux exists
    Tracing syscall landlock_add_rule
    Tracing non-syscall tracepoint timer:hrtimer_setup,timer:hrtimer_start
    [tracepoint failure] Failed to trace tracepoint timer:hrtimer_setup,timer:hrtimer_start, output:
    event syntax error: 'timer:hrtimer_setup,timer:hrtimer_start'
			 \___ unknown tracepoint

    Error:  File /sys/kernel/tracing//events/timer/hrtimer_setup not found.
    Hint:   Perhaps this kernel misses some CONFIG_ setting to enable this feature?.

    Run 'perf list' for a list of valid events

     Usage: perf trace [<options>] [<command>]
	or: perf trace [<options>] -- <command> [<options>]
	or: perf trace record [<options>] [<command>]
	or: perf trace record [<options>] -- <command> [<options>]

	-e, --event <event>   event/syscall selector. use 'perf list' to list available events---- end(-1) ----
    107: perf trace enum augmentation tests                              : FAILED!

Howard Chu (5):
  perf test trace: Use shell's -f flag to check if vmlinux exists
  perf test trace: Remove set -e and print trace test's error messages
  perf test trace: Stop tracing hrtimer_init event in trace enum test
  perf test trace: Remove set -e for BTF general tests
  perf test trace BTF: Use --sort-events in BTF general tests

 tools/perf/tests/shell/trace_btf_enum.sh    | 17 +++++++++--------
 tools/perf/tests/shell/trace_btf_general.sh | 19 +++++++++----------
 2 files changed, 18 insertions(+), 18 deletions(-)

-- 
2.45.2

[PATCH v1 1/5] perf test trace: Use shell's -f flag to check if vmlinux exists

[Howard Chu]

To match the style of the existing codebase, no functional changes
were applied.

Signed-off-by: Howard Chu <howardchu95@gmail.com>
---
 tools/perf/tests/shell/trace_btf_enum.sh | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/tools/perf/tests/shell/trace_btf_enum.sh b/tools/perf/tests/shell/trace_btf_enum.sh
index f0b49f7fb57d..b3775209a0b1 100755
--- a/tools/perf/tests/shell/trace_btf_enum.sh
+++ b/tools/perf/tests/shell/trace_btf_enum.sh
@@ -17,7 +17,7 @@ skip_if_no_perf_trace || exit 2
 
 check_vmlinux() {
   echo "Checking if vmlinux exists"
-  if ! ls /sys/kernel/btf/vmlinux 1>/dev/null 2>&1
+  if [ ! -f /sys/kernel/btf/vmlinux ]
   then
     echo "trace+enum test [Skipped missing vmlinux BTF support]"
     err=2
-- 
2.45.2

[PATCH v1 2/5] perf test trace: Remove set -e and print trace test's error messages

[Howard Chu]

Currently perf test utilizes the set -e option in shell that exit
immediately if a command exits with a non-zero status, this prevents
further error handling and introduces ambiguity. This patch removes set
-e and prints the error message after invoking perf trace during perf
tests.

In my case, the command that exits with a non-zero status is perf
trace instead of grep, because it can't find the 'timer:hrtimer_setup'
tracepoint, see below.

Before:
    $ sudo /tmp/perf test enum -vv
    107: perf trace enum augmentation tests:
    107: perf trace enum augmentation tests                              : Running
    --- start ---
    test child forked, pid 783533
    Checking if vmlinux exists
    Tracing syscall landlock_add_rule
    Tracing non-syscall tracepoint syscall
    ---- end(-1) ----
    107: perf trace enum augmentation tests                              : FAILED!

After:
    $ sudo /tmp/perf test enum -vv
    107: perf trace enum augmentation tests:
    107: perf trace enum augmentation tests                              : Running
    --- start ---
    test child forked, pid 851658
    Checking if vmlinux exists
    Tracing syscall landlock_add_rule
    Tracing non-syscall tracepoint timer:hrtimer_setup,timer:hrtimer_start
    [tracepoint failure] Failed to trace tracepoint timer:hrtimer_setup,timer:hrtimer_start, output:
    event syntax error: 'timer:hrtimer_setup,timer:hrtimer_start'
			 \___ unknown tracepoint

    Error:  File /sys/kernel/tracing//events/timer/hrtimer_setup not found.
    Hint:   Perhaps this kernel misses some CONFIG_ setting to enable this feature?.

    Run 'perf list' for a list of valid events

     Usage: perf trace [<options>] [<command>]
	or: perf trace [<options>] -- <command> [<options>]
	or: perf trace record [<options>] [<command>]
	or: perf trace record [<options>] -- <command> [<options>]

	-e, --event <event>   event/syscall selector. use 'perf list' to list available events---- end(-1) ----
    107: perf trace enum augmentation tests                              : FAILED!

Signed-off-by: Howard Chu <howardchu95@gmail.com>
---
 tools/perf/tests/shell/trace_btf_enum.sh | 13 +++++++------
 1 file changed, 7 insertions(+), 6 deletions(-)

diff --git a/tools/perf/tests/shell/trace_btf_enum.sh b/tools/perf/tests/shell/trace_btf_enum.sh
index b3775209a0b1..cd4c8754f5d4 100755
--- a/tools/perf/tests/shell/trace_btf_enum.sh
+++ b/tools/perf/tests/shell/trace_btf_enum.sh
@@ -3,7 +3,6 @@
 # SPDX-License-Identifier: GPL-2.0
 
 err=0
-set -e
 
 syscall="landlock_add_rule"
 non_syscall="timer:hrtimer_setup,timer:hrtimer_start"
@@ -34,22 +33,24 @@ trace_landlock() {
     return
   fi
 
-  if perf trace -e $syscall $TESTPROG 2>&1 | \
-     grep -q -E ".*landlock_add_rule\(ruleset_fd: 11, rule_type: (LANDLOCK_RULE_PATH_BENEATH|LANDLOCK_RULE_NET_PORT), rule_attr: 0x[a-f0-9]+, flags: 45\) = -1.*"
+  output="$(perf trace -e $syscall $TESTPROG 2>&1)"
+  if echo "$output" | grep -q -E ".*landlock_add_rule\(ruleset_fd: 11, rule_type: (LANDLOCK_RULE_PATH_BENEATH|LANDLOCK_RULE_NET_PORT), rule_attr: 0x[a-f0-9]+, flags: 45\) = -1.*"
   then
     err=0
   else
+	printf "[syscall failure] Failed to trace syscall $syscall, output:\n$output"
     err=1
   fi
 }
 
 trace_non_syscall() {
-  echo "Tracing non-syscall tracepoint ${non-syscall}"
-  if perf trace -e $non_syscall --max-events=1 2>&1 | \
-     grep -q -E '.*timer:hrtimer_.*\(.*mode: HRTIMER_MODE_.*\)$'
+  echo "Tracing non-syscall tracepoint ${non_syscall}"
+  output="$(perf trace -e $non_syscall --max-events=1 2>&1)"
+  if echo "$output" | grep -q -E '.*timer:hrtimer_.*\(.*mode: HRTIMER_MODE_.*\)$'
   then
     err=0
   else
+	printf "[tracepoint failure] Failed to trace tracepoint $non_syscall, output:\n$output"
     err=1
   fi
 }
-- 
2.45.2

Re: [PATCH v1 2/5] perf test trace: Remove set -e and print trace test's error messages

[Namhyung Kim]

Hi Howard,

On Sat, May 17, 2025 at 09:32:27AM -0700, Howard Chu wrote:
> Currently perf test utilizes the set -e option in shell that exit
> immediately if a command exits with a non-zero status, this prevents
> further error handling and introduces ambiguity. This patch removes set
> -e and prints the error message after invoking perf trace during perf
> tests.

I think it's fine to exits with non-zero inside 'if' statements.  But
it won't work if you want to move it out of the 'if' statements.  I'm
not sure how it'd work in a subshll for the assignment.  But it'd be ok
to remove 'set -e' anyway since the test checks the result manually.

Thanks,
Namhyung

> 
> In my case, the command that exits with a non-zero status is perf
> trace instead of grep, because it can't find the 'timer:hrtimer_setup'
> tracepoint, see below.
> 
> Before:
>     $ sudo /tmp/perf test enum -vv
>     107: perf trace enum augmentation tests:
>     107: perf trace enum augmentation tests                              : Running
>     --- start ---
>     test child forked, pid 783533
>     Checking if vmlinux exists
>     Tracing syscall landlock_add_rule
>     Tracing non-syscall tracepoint syscall
>     ---- end(-1) ----
>     107: perf trace enum augmentation tests                              : FAILED!
> 
> After:
>     $ sudo /tmp/perf test enum -vv
>     107: perf trace enum augmentation tests:
>     107: perf trace enum augmentation tests                              : Running
>     --- start ---
>     test child forked, pid 851658
>     Checking if vmlinux exists
>     Tracing syscall landlock_add_rule
>     Tracing non-syscall tracepoint timer:hrtimer_setup,timer:hrtimer_start
>     [tracepoint failure] Failed to trace tracepoint timer:hrtimer_setup,timer:hrtimer_start, output:
>     event syntax error: 'timer:hrtimer_setup,timer:hrtimer_start'
> 			 \___ unknown tracepoint
> 
>     Error:  File /sys/kernel/tracing//events/timer/hrtimer_setup not found.
>     Hint:   Perhaps this kernel misses some CONFIG_ setting to enable this feature?.
> 
>     Run 'perf list' for a list of valid events
> 
>      Usage: perf trace [<options>] [<command>]
> 	or: perf trace [<options>] -- <command> [<options>]
> 	or: perf trace record [<options>] [<command>]
> 	or: perf trace record [<options>] -- <command> [<options>]
> 
> 	-e, --event <event>   event/syscall selector. use 'perf list' to list available events---- end(-1) ----
>     107: perf trace enum augmentation tests                              : FAILED!
> 
> Signed-off-by: Howard Chu <howardchu95@gmail.com>
> ---
>  tools/perf/tests/shell/trace_btf_enum.sh | 13 +++++++------
>  1 file changed, 7 insertions(+), 6 deletions(-)
> 
> diff --git a/tools/perf/tests/shell/trace_btf_enum.sh b/tools/perf/tests/shell/trace_btf_enum.sh
> index b3775209a0b1..cd4c8754f5d4 100755
> --- a/tools/perf/tests/shell/trace_btf_enum.sh
> +++ b/tools/perf/tests/shell/trace_btf_enum.sh
> @@ -3,7 +3,6 @@
>  # SPDX-License-Identifier: GPL-2.0
>  
>  err=0
> -set -e
>  
>  syscall="landlock_add_rule"
>  non_syscall="timer:hrtimer_setup,timer:hrtimer_start"
> @@ -34,22 +33,24 @@ trace_landlock() {
>      return
>    fi
>  
> -  if perf trace -e $syscall $TESTPROG 2>&1 | \
> -     grep -q -E ".*landlock_add_rule\(ruleset_fd: 11, rule_type: (LANDLOCK_RULE_PATH_BENEATH|LANDLOCK_RULE_NET_PORT), rule_attr: 0x[a-f0-9]+, flags: 45\) = -1.*"
> +  output="$(perf trace -e $syscall $TESTPROG 2>&1)"
> +  if echo "$output" | grep -q -E ".*landlock_add_rule\(ruleset_fd: 11, rule_type: (LANDLOCK_RULE_PATH_BENEATH|LANDLOCK_RULE_NET_PORT), rule_attr: 0x[a-f0-9]+, flags: 45\) = -1.*"
>    then
>      err=0
>    else
> +	printf "[syscall failure] Failed to trace syscall $syscall, output:\n$output"
>      err=1
>    fi
>  }
>  
>  trace_non_syscall() {
> -  echo "Tracing non-syscall tracepoint ${non-syscall}"
> -  if perf trace -e $non_syscall --max-events=1 2>&1 | \
> -     grep -q -E '.*timer:hrtimer_.*\(.*mode: HRTIMER_MODE_.*\)$'
> +  echo "Tracing non-syscall tracepoint ${non_syscall}"
> +  output="$(perf trace -e $non_syscall --max-events=1 2>&1)"
> +  if echo "$output" | grep -q -E '.*timer:hrtimer_.*\(.*mode: HRTIMER_MODE_.*\)$'
>    then
>      err=0
>    else
> +	printf "[tracepoint failure] Failed to trace tracepoint $non_syscall, output:\n$output"
>      err=1
>    fi
>  }
> -- 
> 2.45.2
> 

Re: [PATCH v1 2/5] perf test trace: Remove set -e and print trace test's error messages

[Howard Chu]

Hello Namhyung,

On Sun, May 18, 2025 at 10:36 AM Namhyung Kim <namhyung@kernel.org> wrote:
>
> Hi Howard,
>
> On Sat, May 17, 2025 at 09:32:27AM -0700, Howard Chu wrote:
> > Currently perf test utilizes the set -e option in shell that exit
> > immediately if a command exits with a non-zero status, this prevents
> > further error handling and introduces ambiguity. This patch removes set
> > -e and prints the error message after invoking perf trace during perf
> > tests.
>
> I think it's fine to exits with non-zero inside 'if' statements.  But
> it won't work if you want to move it out of the 'if' statements.  I'm
> not sure how it'd work in a subshll for the assignment.  But it'd be ok
> to remove 'set -e' anyway since the test checks the result manually.

Yeah it won't exit from the non-zero status from the if statement. Thanks.

Thanks,
Howard

[PATCH v1 3/5] perf test trace: Stop tracing hrtimer_init event in trace enum test

[Howard Chu]

The event 'timer:hrtimer_setup' is relatively new, for older kernels,
perf trace enum tests won't run as the event 'timer:hrtimer_setup'
cannot be found.

It was originally called 'timer:hrtimer_init', before being renamed in:

commit 244132c4e577 ("tracing/timers: Rename the hrtimer_init event to hrtimer_setup")

Using timer:hrtimer_start should be enough for current testing, and
hopefully 'start' won't be renamed in the future.

Before:
    $ sudo /tmp/perf test enum -vv
    107: perf trace enum augmentation tests:
    107: perf trace enum augmentation tests                              : Running
    --- start ---
    test child forked, pid 786187
    Checking if vmlinux exists
    Tracing syscall landlock_add_rule
    Tracing non-syscall tracepoint timer:hrtimer_setup,timer:hrtimer_start
    [tracepoint failure] Failed to trace timer:hrtimer_setup,timer:hrtimer_start tracepoint, output:
    event syntax error: 'timer:hrtimer_setup,timer:hrtimer_start'
			 \___ unknown tracepoint

    Error:  File /sys/kernel/tracing//events/timer/hrtimer_setup not found.
    Hint:   Perhaps this kernel misses some CONFIG_ setting to enable this feature?.

    Run 'perf list' for a list of valid events

     Usage: perf trace [<options>] [<command>]
	or: perf trace [<options>] -- <command> [<options>]
	or: perf trace record [<options>] [<command>]
	or: perf trace record [<options>] -- <command> [<options>]

	-e, --event <event>   event/syscall selector. use 'perf list' to list available events
    ---- end(-1) ----
    107: perf trace enum augmentation tests                              : FAILED!

After:
    $ sudo /tmp/perf test enum -vv
    107: perf trace enum augmentation tests:
    107: perf trace enum augmentation tests                              : Running
    --- start ---
    test child forked, pid 808547
    Checking if vmlinux exists
    Tracing syscall landlock_add_rule
    Tracing non-syscall tracepoint timer:hrtimer_start
    ---- end(0) ----
    107: perf trace enum augmentation tests                              : Ok

Signed-off-by: Howard Chu <howardchu95@gmail.com>
---
 tools/perf/tests/shell/trace_btf_enum.sh | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/tools/perf/tests/shell/trace_btf_enum.sh b/tools/perf/tests/shell/trace_btf_enum.sh
index cd4c8754f5d4..da6903108c8b 100755
--- a/tools/perf/tests/shell/trace_btf_enum.sh
+++ b/tools/perf/tests/shell/trace_btf_enum.sh
@@ -5,7 +5,7 @@
 err=0
 
 syscall="landlock_add_rule"
-non_syscall="timer:hrtimer_setup,timer:hrtimer_start"
+non_syscall="timer:hrtimer_start"
 
 TESTPROG="perf test -w landlock"
 
-- 
2.45.2

[PATCH v1 4/5] perf test trace: Remove set -e for BTF general tests

[Howard Chu]

Remove set -e and print error messages in BTF general tests.

Before:
    $ sudo /tmp/perf test btf -vv
    108: perf trace BTF general tests:
    108: perf trace BTF general tests                                    : Running
    --- start ---
    test child forked, pid 889299
    Checking if vmlinux BTF exists
    Testing perf trace's string augmentation
    String augmentation test failed
    ---- end(-1) ----
    108: perf trace BTF general tests                                    : FAILED!

After:
    $ sudo /tmp/perf test btf -vv
    108: perf trace BTF general tests:
    108: perf trace BTF general tests                                    : Running
    --- start ---
    test child forked, pid 886551
    Checking if vmlinux BTF exists
    Testing perf trace's string augmentation
    String augmentation test failed, output:
    :886566/886566 renameat2(CWD, "/tmp/file1_RcMa", CWD, "/tmp/file2_RcMa", NOREPLACE) = 0---- end(-1) ----
    108: perf trace BTF general tests                                    : FAILED!

Signed-off-by: Howard Chu <howardchu95@gmail.com>
---
 tools/perf/tests/shell/trace_btf_general.sh | 19 +++++++++----------
 1 file changed, 9 insertions(+), 10 deletions(-)

diff --git a/tools/perf/tests/shell/trace_btf_general.sh b/tools/perf/tests/shell/trace_btf_general.sh
index a25d8744695e..e78e653fc8f1 100755
--- a/tools/perf/tests/shell/trace_btf_general.sh
+++ b/tools/perf/tests/shell/trace_btf_general.sh
@@ -3,7 +3,6 @@
 # SPDX-License-Identifier: GPL-2.0
 
 err=0
-set -e
 
 # shellcheck source=lib/probe.sh
 . "$(dirname $0)"/lib/probe.sh
@@ -28,10 +27,10 @@ check_vmlinux() {
 
 trace_test_string() {
   echo "Testing perf trace's string augmentation"
-  if ! perf trace -e renameat* --max-events=1 -- mv ${file1} ${file2} 2>&1 | \
-    grep -q -E "^mv/[0-9]+ renameat(2)?\(.*, \"${file1}\", .*, \"${file2}\", .*\) += +[0-9]+$"
+  output="$(perf trace -e renameat* --max-events=1 -- mv ${file1} ${file2} 2>&1)"
+  if ! echo "$output" | grep -q -E "^mv/[0-9]+ renameat(2)?\(.*, \"${file1}\", .*, \"${file2}\", .*\) += +[0-9]+$"
   then
-    echo "String augmentation test failed"
+    printf "String augmentation test failed, output:\n$output"
     err=1
   fi
 }
@@ -39,20 +38,20 @@ trace_test_string() {
 trace_test_buffer() {
   echo "Testing perf trace's buffer augmentation"
   # echo will insert a newline (\10) at the end of the buffer
-  if ! perf trace -e write --max-events=1 -- echo "${buffer}" 2>&1 | \
-    grep -q -E "^echo/[0-9]+ write\([0-9]+, ${buffer}.*, [0-9]+\) += +[0-9]+$"
+  output="$(perf trace -e write --max-events=1 -- echo "${buffer}" 2>&1)"
+  if ! echo "$output" | grep -q -E "^echo/[0-9]+ write\([0-9]+, ${buffer}.*, [0-9]+\) += +[0-9]+$"
   then
-    echo "Buffer augmentation test failed"
+    printf "Buffer augmentation test failed, output:\n$output"
     err=1
   fi
 }
 
 trace_test_struct_btf() {
   echo "Testing perf trace's struct augmentation"
-  if ! perf trace -e clock_nanosleep --force-btf --max-events=1 -- sleep 1 2>&1 | \
-    grep -q -E "^sleep/[0-9]+ clock_nanosleep\(0, 0, \{1,\}, 0x[0-9a-f]+\) += +[0-9]+$"
+  output="$(perf trace -e clock_nanosleep --force-btf --max-events=1 -- sleep 1 2>&1)"
+  if ! echo "$output" | grep -q -E "^sleep/[0-9]+ clock_nanosleep\(0, 0, \{1,\}, 0x[0-9a-f]+\) += +[0-9]+$"
   then
-    echo "BTF struct augmentation test failed"
+	printf "BTF struct augmentation test failed, output:\n$output"
     err=1
   fi
 }
-- 
2.45.2

Re: [PATCH v1 4/5] perf test trace: Remove set -e for BTF general tests

[Namhyung Kim]

On Sat, May 17, 2025 at 09:32:29AM -0700, Howard Chu wrote:
> Remove set -e and print error messages in BTF general tests.
> 
> Before:
>     $ sudo /tmp/perf test btf -vv
>     108: perf trace BTF general tests:
>     108: perf trace BTF general tests                                    : Running
>     --- start ---
>     test child forked, pid 889299
>     Checking if vmlinux BTF exists
>     Testing perf trace's string augmentation
>     String augmentation test failed
>     ---- end(-1) ----
>     108: perf trace BTF general tests                                    : FAILED!
> 
> After:
>     $ sudo /tmp/perf test btf -vv
>     108: perf trace BTF general tests:
>     108: perf trace BTF general tests                                    : Running
>     --- start ---
>     test child forked, pid 886551
>     Checking if vmlinux BTF exists
>     Testing perf trace's string augmentation
>     String augmentation test failed, output:
>     :886566/886566 renameat2(CWD, "/tmp/file1_RcMa", CWD, "/tmp/file2_RcMa", NOREPLACE) = 0---- end(-1) ----
>     108: perf trace BTF general tests                                    : FAILED!
> 
> Signed-off-by: Howard Chu <howardchu95@gmail.com>
> ---
>  tools/perf/tests/shell/trace_btf_general.sh | 19 +++++++++----------
>  1 file changed, 9 insertions(+), 10 deletions(-)
> 
> diff --git a/tools/perf/tests/shell/trace_btf_general.sh b/tools/perf/tests/shell/trace_btf_general.sh
> index a25d8744695e..e78e653fc8f1 100755
> --- a/tools/perf/tests/shell/trace_btf_general.sh
> +++ b/tools/perf/tests/shell/trace_btf_general.sh
> @@ -3,7 +3,6 @@
>  # SPDX-License-Identifier: GPL-2.0
>  
>  err=0
> -set -e
>  
>  # shellcheck source=lib/probe.sh
>  . "$(dirname $0)"/lib/probe.sh
> @@ -28,10 +27,10 @@ check_vmlinux() {
>  
>  trace_test_string() {
>    echo "Testing perf trace's string augmentation"
> -  if ! perf trace -e renameat* --max-events=1 -- mv ${file1} ${file2} 2>&1 | \
> -    grep -q -E "^mv/[0-9]+ renameat(2)?\(.*, \"${file1}\", .*, \"${file2}\", .*\) += +[0-9]+$"
> +  output="$(perf trace -e renameat* --max-events=1 -- mv ${file1} ${file2} 2>&1)"
> +  if ! echo "$output" | grep -q -E "^mv/[0-9]+ renameat(2)?\(.*, \"${file1}\", .*, \"${file2}\", .*\) += +[0-9]+$"
>    then
> -    echo "String augmentation test failed"
> +    printf "String augmentation test failed, output:\n$output"

Looks like you need "\n" after the output as well.

>      err=1
>    fi
>  }
> @@ -39,20 +38,20 @@ trace_test_string() {
>  trace_test_buffer() {
>    echo "Testing perf trace's buffer augmentation"
>    # echo will insert a newline (\10) at the end of the buffer
> -  if ! perf trace -e write --max-events=1 -- echo "${buffer}" 2>&1 | \
> -    grep -q -E "^echo/[0-9]+ write\([0-9]+, ${buffer}.*, [0-9]+\) += +[0-9]+$"
> +  output="$(perf trace -e write --max-events=1 -- echo "${buffer}" 2>&1)"
> +  if ! echo "$output" | grep -q -E "^echo/[0-9]+ write\([0-9]+, ${buffer}.*, [0-9]+\) += +[0-9]+$"
>    then
> -    echo "Buffer augmentation test failed"
> +    printf "Buffer augmentation test failed, output:\n$output"

Ditto.  And probably for the previous patch too.

>      err=1
>    fi
>  }
>  
>  trace_test_struct_btf() {
>    echo "Testing perf trace's struct augmentation"
> -  if ! perf trace -e clock_nanosleep --force-btf --max-events=1 -- sleep 1 2>&1 | \
> -    grep -q -E "^sleep/[0-9]+ clock_nanosleep\(0, 0, \{1,\}, 0x[0-9a-f]+\) += +[0-9]+$"
> +  output="$(perf trace -e clock_nanosleep --force-btf --max-events=1 -- sleep 1 2>&1)"
> +  if ! echo "$output" | grep -q -E "^sleep/[0-9]+ clock_nanosleep\(0, 0, \{1,\}, 0x[0-9a-f]+\) += +[0-9]+$"
>    then
> -    echo "BTF struct augmentation test failed"
> +	printf "BTF struct augmentation test failed, output:\n$output"

And here as well.

Thanks,
Namhyung


>      err=1
>    fi
>  }
> -- 
> 2.45.2
> 

Re: [PATCH v1 4/5] perf test trace: Remove set -e for BTF general tests

[Howard Chu]

Hello,

On Sun, May 18, 2025 at 10:38 AM Namhyung Kim <namhyung@kernel.org> wrote:
>
> On Sat, May 17, 2025 at 09:32:29AM -0700, Howard Chu wrote:
> > Remove set -e and print error messages in BTF general tests.

<SNIP>

> > +  if ! echo "$output" | grep -q -E "^mv/[0-9]+ renameat(2)?\(.*, \"${file1}\", .*, \"${file2}\", .*\) += +[0-9]+$"
> >    then
> > -    echo "String augmentation test failed"
> > +    printf "String augmentation test failed, output:\n$output"
>
> Looks like you need "\n" after the output as well.
>
> >      err=1
> >    fi
> >  }
> > @@ -39,20 +38,20 @@ trace_test_string() {
> >  trace_test_buffer() {
> >    echo "Testing perf trace's buffer augmentation"
> >    # echo will insert a newline (\10) at the end of the buffer
> > -  if ! perf trace -e write --max-events=1 -- echo "${buffer}" 2>&1 | \
> > -    grep -q -E "^echo/[0-9]+ write\([0-9]+, ${buffer}.*, [0-9]+\) += +[0-9]+$"
> > +  output="$(perf trace -e write --max-events=1 -- echo "${buffer}" 2>&1)"
> > +  if ! echo "$output" | grep -q -E "^echo/[0-9]+ write\([0-9]+, ${buffer}.*, [0-9]+\) += +[0-9]+$"
> >    then
> > -    echo "Buffer augmentation test failed"
> > +    printf "Buffer augmentation test failed, output:\n$output"
>
> Ditto.  And probably for the previous patch too.

No problem, thanks. I should also mention I used the wrong title for
patch 3. It should be 'perf test trace: Stop tracing hrtimer_setup
event in trace enum test' instead of 'perf test trace: Stop tracing
hrtimer_init event in trace enum test'. Thanks for the review and I
will change them in v2.

Thanks,
Howard

[PATCH v1 5/5] perf test trace BTF: Use --sort-events in BTF general tests

[Howard Chu]

Without the '--sort-events' flag, perf trace doesn't receive and process
events based on their arrival time, thus PERF_RECORD_COMM event that
assigns the correct comm to a PID, may be delivered and processed after
regular samples, causing trace outputs not having a 'comm', e.g.
'mv', instead, having the default PID placeholder, e.g. ':14514'.

Hopefully this answers Namhyung's question in [1].

You can simply justify the statement with this diff:

---8<---
diff --git a/tools/perf/builtin-trace.c b/tools/perf/builtin-trace.c
index edab0ff60b3c..f042afed5b74 100644
--- a/tools/perf/builtin-trace.c
+++ b/tools/perf/builtin-trace.c
@@ -4204,6 +4204,7 @@ static int trace__deliver_event(struct trace *trace, union perf_event *event)
 {
 	int err;

+	printf("[debug] deliver\n");
 	if (!trace->sort_events)
 		return __trace__deliver_event(trace, event);

diff --git a/tools/perf/util/comm.c b/tools/perf/util/comm.c
index 8aa456d7c2cd..76df9886429e 100644
--- a/tools/perf/util/comm.c
+++ b/tools/perf/util/comm.c
@@ -213,6 +213,7 @@ int comm__override(struct comm *comm, const char *str, u64 timestamp, bool exec)
 	new = comm_strs__findnew(str);
 	if (!new)
 		return -ENOMEM;
+	printf("[OVERRIDE] old %s new %s str %s\n", old->str, new->str, str);

 	comm_str__put(old);
 	comm->comm_str = new;
diff --git a/tools/perf/util/machine.c b/tools/perf/util/machine.c
index 2531b373f2cf..5a501fe304d2 100644
--- a/tools/perf/util/machine.c
+++ b/tools/perf/util/machine.c
@@ -578,6 +578,7 @@ int machine__process_comm_event(struct machine *machine, union perf_event *event
 	if (dump_trace)
 		perf_event__fprintf_comm(event, stdout);

+	printf("[debug] machine__process_comm_event\n");
 	if (thread == NULL ||
 	    __thread__set_comm(thread, event->comm.comm, sample->time, exec)) {
 		dump_printf("problem processing PERF_RECORD_COMM, skipping event.\n");

Now, simply run this command multiple times:
    $ touch /tmp/file1 && sudo /tmp/perf trace -e renameat* -- mv /tmp/file1 /tmp/file2 && rm -f /tmp/file2
And you should see two types of results:

    $ touch /tmp/file1 && sudo /tmp/perf trace -e renameat* -- mv /tmp/file1 /tmp/file2 && rm -f /tmp/file2
    [debug] deliver
    [debug] machine__process_comm_event
    [OVERRIDE] old :1221169 new mv str mv
    [debug] deliver
    [debug] deliver
    [debug] deliver
    [debug] deliver
    [debug] deliver
    [debug] deliver
    [debug] deliver
    [debug] deliver
    [debug] deliver
    [debug] deliver
	 0.000 ( 0.013 ms): mv/1221169 renameat2(olddfd: CWD, oldname: "/tmp/file1", newdfd: CWD, newname: "/tmp/file2", flags: NOREPLACE) = 0
    [debug] deliver

    $ touch /tmp/file1 && sudo /tmp/perf trace -e renameat* -- mv /tmp/file1 /tmp/file2 && rm -f /tmp/file2
    [debug] deliver
    [debug] deliver
    [debug] deliver
    [debug] deliver
    [debug] deliver
    [debug] deliver
    [debug] deliver
	 0.000 ( 0.014 ms): :1221398/1221398 renameat2(olddfd: CWD, oldname: "/tmp/file1", newdfd: CWD, newname: "/tmp/file2", flags: NOREPLACE) = 0
    [debug] deliver
    [debug] deliver
    [debug] machine__process_comm_event
    [OVERRIDE] old :1221398 new mv str mv
    [debug] deliver
    [debug] deliver
    [debug] deliver

Anyway, use --sort-events in BTF general tests to avoid :PID, a comm is
preferred.

[1]: https://lore.kernel.org/linux-perf-users/Z_AeswETE5xLcPT8@google.com/

Signed-off-by: Howard Chu <howardchu95@gmail.com>
---
 tools/perf/tests/shell/trace_btf_general.sh | 6 +++---
 1 file changed, 3 insertions(+), 3 deletions(-)

diff --git a/tools/perf/tests/shell/trace_btf_general.sh b/tools/perf/tests/shell/trace_btf_general.sh
index e78e653fc8f1..a15cdb5fa309 100755
--- a/tools/perf/tests/shell/trace_btf_general.sh
+++ b/tools/perf/tests/shell/trace_btf_general.sh
@@ -27,7 +27,7 @@ check_vmlinux() {
 
 trace_test_string() {
   echo "Testing perf trace's string augmentation"
-  output="$(perf trace -e renameat* --max-events=1 -- mv ${file1} ${file2} 2>&1)"
+  output="$(perf trace --sort-events -e renameat* --max-events=1 -- mv ${file1} ${file2} 2>&1)"
   if ! echo "$output" | grep -q -E "^mv/[0-9]+ renameat(2)?\(.*, \"${file1}\", .*, \"${file2}\", .*\) += +[0-9]+$"
   then
     printf "String augmentation test failed, output:\n$output"
@@ -38,7 +38,7 @@ trace_test_string() {
 trace_test_buffer() {
   echo "Testing perf trace's buffer augmentation"
   # echo will insert a newline (\10) at the end of the buffer
-  output="$(perf trace -e write --max-events=1 -- echo "${buffer}" 2>&1)"
+  output="$(perf trace --sort-events -e write --max-events=1 -- echo "${buffer}" 2>&1)"
   if ! echo "$output" | grep -q -E "^echo/[0-9]+ write\([0-9]+, ${buffer}.*, [0-9]+\) += +[0-9]+$"
   then
     printf "Buffer augmentation test failed, output:\n$output"
@@ -48,7 +48,7 @@ trace_test_buffer() {
 
 trace_test_struct_btf() {
   echo "Testing perf trace's struct augmentation"
-  output="$(perf trace -e clock_nanosleep --force-btf --max-events=1 -- sleep 1 2>&1)"
+  output="$(perf trace --sort-events -e clock_nanosleep --force-btf --max-events=1 -- sleep 1 2>&1)"
   if ! echo "$output" | grep -q -E "^sleep/[0-9]+ clock_nanosleep\(0, 0, \{1,\}, 0x[0-9a-f]+\) += +[0-9]+$"
   then
 	printf "BTF struct augmentation test failed, output:\n$output"
-- 
2.45.2

Re: [PATCH v1 5/5] perf test trace BTF: Use --sort-events in BTF general tests

[Namhyung Kim]

On Sat, May 17, 2025 at 09:32:30AM -0700, Howard Chu wrote:
> Without the '--sort-events' flag, perf trace doesn't receive and process
> events based on their arrival time, thus PERF_RECORD_COMM event that
> assigns the correct comm to a PID, may be delivered and processed after
> regular samples, causing trace outputs not having a 'comm', e.g.
> 'mv', instead, having the default PID placeholder, e.g. ':14514'.
> 
> Hopefully this answers Namhyung's question in [1].

Thanks, it makes sense.  Maybe it migrated to another CPU after exec.

> 
> You can simply justify the statement with this diff:
> 
> ---8<---

Please do not use this in the format patch emails.  This makes git treat
the following contents as commit body so it'll be added to the commit as
if it's a valid change.  Maybe adding some spaces at the beginning of
each line help.  But I think it's better if you publish it somewhere else
and add a link instead.

Thanks,
Namhyung

> diff --git a/tools/perf/builtin-trace.c b/tools/perf/builtin-trace.c
> index edab0ff60b3c..f042afed5b74 100644
> --- a/tools/perf/builtin-trace.c
> +++ b/tools/perf/builtin-trace.c
> @@ -4204,6 +4204,7 @@ static int trace__deliver_event(struct trace *trace, union perf_event *event)
>  {
>  	int err;
> 
> +	printf("[debug] deliver\n");
>  	if (!trace->sort_events)
>  		return __trace__deliver_event(trace, event);
> 
> diff --git a/tools/perf/util/comm.c b/tools/perf/util/comm.c
> index 8aa456d7c2cd..76df9886429e 100644
> --- a/tools/perf/util/comm.c
> +++ b/tools/perf/util/comm.c
> @@ -213,6 +213,7 @@ int comm__override(struct comm *comm, const char *str, u64 timestamp, bool exec)
>  	new = comm_strs__findnew(str);
>  	if (!new)
>  		return -ENOMEM;
> +	printf("[OVERRIDE] old %s new %s str %s\n", old->str, new->str, str);
> 
>  	comm_str__put(old);
>  	comm->comm_str = new;
> diff --git a/tools/perf/util/machine.c b/tools/perf/util/machine.c
> index 2531b373f2cf..5a501fe304d2 100644
> --- a/tools/perf/util/machine.c
> +++ b/tools/perf/util/machine.c
> @@ -578,6 +578,7 @@ int machine__process_comm_event(struct machine *machine, union perf_event *event
>  	if (dump_trace)
>  		perf_event__fprintf_comm(event, stdout);
> 
> +	printf("[debug] machine__process_comm_event\n");
>  	if (thread == NULL ||
>  	    __thread__set_comm(thread, event->comm.comm, sample->time, exec)) {
>  		dump_printf("problem processing PERF_RECORD_COMM, skipping event.\n");
> 
> Now, simply run this command multiple times:
>     $ touch /tmp/file1 && sudo /tmp/perf trace -e renameat* -- mv /tmp/file1 /tmp/file2 && rm -f /tmp/file2
> And you should see two types of results:
> 
>     $ touch /tmp/file1 && sudo /tmp/perf trace -e renameat* -- mv /tmp/file1 /tmp/file2 && rm -f /tmp/file2
>     [debug] deliver
>     [debug] machine__process_comm_event
>     [OVERRIDE] old :1221169 new mv str mv
>     [debug] deliver
>     [debug] deliver
>     [debug] deliver
>     [debug] deliver
>     [debug] deliver
>     [debug] deliver
>     [debug] deliver
>     [debug] deliver
>     [debug] deliver
>     [debug] deliver
> 	 0.000 ( 0.013 ms): mv/1221169 renameat2(olddfd: CWD, oldname: "/tmp/file1", newdfd: CWD, newname: "/tmp/file2", flags: NOREPLACE) = 0
>     [debug] deliver
> 
>     $ touch /tmp/file1 && sudo /tmp/perf trace -e renameat* -- mv /tmp/file1 /tmp/file2 && rm -f /tmp/file2
>     [debug] deliver
>     [debug] deliver
>     [debug] deliver
>     [debug] deliver
>     [debug] deliver
>     [debug] deliver
>     [debug] deliver
> 	 0.000 ( 0.014 ms): :1221398/1221398 renameat2(olddfd: CWD, oldname: "/tmp/file1", newdfd: CWD, newname: "/tmp/file2", flags: NOREPLACE) = 0
>     [debug] deliver
>     [debug] deliver
>     [debug] machine__process_comm_event
>     [OVERRIDE] old :1221398 new mv str mv
>     [debug] deliver
>     [debug] deliver
>     [debug] deliver
> 
> Anyway, use --sort-events in BTF general tests to avoid :PID, a comm is
> preferred.
> 
> [1]: https://lore.kernel.org/linux-perf-users/Z_AeswETE5xLcPT8@google.com/
> 
> Signed-off-by: Howard Chu <howardchu95@gmail.com>
> ---
>  tools/perf/tests/shell/trace_btf_general.sh | 6 +++---
>  1 file changed, 3 insertions(+), 3 deletions(-)
> 
> diff --git a/tools/perf/tests/shell/trace_btf_general.sh b/tools/perf/tests/shell/trace_btf_general.sh
> index e78e653fc8f1..a15cdb5fa309 100755
> --- a/tools/perf/tests/shell/trace_btf_general.sh
> +++ b/tools/perf/tests/shell/trace_btf_general.sh
> @@ -27,7 +27,7 @@ check_vmlinux() {
>  
>  trace_test_string() {
>    echo "Testing perf trace's string augmentation"
> -  output="$(perf trace -e renameat* --max-events=1 -- mv ${file1} ${file2} 2>&1)"
> +  output="$(perf trace --sort-events -e renameat* --max-events=1 -- mv ${file1} ${file2} 2>&1)"
>    if ! echo "$output" | grep -q -E "^mv/[0-9]+ renameat(2)?\(.*, \"${file1}\", .*, \"${file2}\", .*\) += +[0-9]+$"
>    then
>      printf "String augmentation test failed, output:\n$output"
> @@ -38,7 +38,7 @@ trace_test_string() {
>  trace_test_buffer() {
>    echo "Testing perf trace's buffer augmentation"
>    # echo will insert a newline (\10) at the end of the buffer
> -  output="$(perf trace -e write --max-events=1 -- echo "${buffer}" 2>&1)"
> +  output="$(perf trace --sort-events -e write --max-events=1 -- echo "${buffer}" 2>&1)"
>    if ! echo "$output" | grep -q -E "^echo/[0-9]+ write\([0-9]+, ${buffer}.*, [0-9]+\) += +[0-9]+$"
>    then
>      printf "Buffer augmentation test failed, output:\n$output"
> @@ -48,7 +48,7 @@ trace_test_buffer() {
>  
>  trace_test_struct_btf() {
>    echo "Testing perf trace's struct augmentation"
> -  output="$(perf trace -e clock_nanosleep --force-btf --max-events=1 -- sleep 1 2>&1)"
> +  output="$(perf trace --sort-events -e clock_nanosleep --force-btf --max-events=1 -- sleep 1 2>&1)"
>    if ! echo "$output" | grep -q -E "^sleep/[0-9]+ clock_nanosleep\(0, 0, \{1,\}, 0x[0-9a-f]+\) += +[0-9]+$"
>    then
>  	printf "BTF struct augmentation test failed, output:\n$output"
> -- 
> 2.45.2
> 

Re: [PATCH v1 5/5] perf test trace BTF: Use --sort-events in BTF general tests

[Howard Chu]

Hello Namhyung,

On Sun, May 18, 2025 at 10:51 AM Namhyung Kim <namhyung@kernel.org> wrote:
>
> On Sat, May 17, 2025 at 09:32:30AM -0700, Howard Chu wrote:
> > Without the '--sort-events' flag, perf trace doesn't receive and process
> > events based on their arrival time, thus PERF_RECORD_COMM event that
> > assigns the correct comm to a PID, may be delivered and processed after
> > regular samples, causing trace outputs not having a 'comm', e.g.
> > 'mv', instead, having the default PID placeholder, e.g. ':14514'.
> >
> > Hopefully this answers Namhyung's question in [1].
>
> Thanks, it makes sense.  Maybe it migrated to another CPU after exec.
>
> >
> > You can simply justify the statement with this diff:
> >
> > ---8<---
>
> Please do not use this in the format patch emails.  This makes git treat
> the following contents as commit body so it'll be added to the commit as
> if it's a valid change.  Maybe adding some spaces at the beginning of
> each line help.  But I think it's better if you publish it somewhere else
> and add a link instead.

Sorry. I will delete this scissor in v2.

Thanks,
Howard