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

[PATCH v2 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!

Changes in v2:
- Add an extra newline after error messages
- Rename the title of patch 3 to 'Stop tracing hrtimer_setup...'
- Take the debug diff for explanation out of patch 5 to make it apply
  normally
- Add base-commit in this cover letter

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_setup 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(-)


base-commit: f3061d526714ac6cc936c48e76a6eb0512c69b1a
-- 
2.45.2

[PATCH v2 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 v2 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..f59ba34fac4c 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\n"
     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\n"
     err=1
   fi
 }
-- 
2.45.2

[PATCH v2 3/5] perf test trace: Stop tracing hrtimer_setup 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 f59ba34fac4c..c37017bfeb5e 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 v2 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..5fa50d815203 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\n"
     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\n"
     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\n"
     err=1
   fi
 }
-- 
2.45.2

[PATCH v2 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: [2].

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/
[2]: https://gist.githubusercontent.com/Sberm/6b72b2a1cf1c62244f1f996481769baf/raw/529667bd74a2e7e1953bbd4be545bf875da8a3e7/unsorted.patch

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 5fa50d815203..30cd3a53f868 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\n"
@@ -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\n"
@@ -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\n"
-- 
2.45.2

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

[Ian Rogers]

On Sun, May 18, 2025 at 12:10 PM Howard Chu <howardchu95@gmail.com> wrote:
>
> 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!
>
> Changes in v2:
> - Add an extra newline after error messages
> - Rename the title of patch 3 to 'Stop tracing hrtimer_setup...'
> - Take the debug diff for explanation out of patch 5 to make it apply
>   normally
> - Add base-commit in this cover letter

Thanks Howard! I did some testing but see failures that may be
pre-existing issues:

```
--- start ---
test child forked, pid 264236
Checking if vmlinux exists
Tracing syscall landlock_add_rule
[syscall failure] Failed to trace syscall landlock_add_rule, output:

---- end(-1) ----
107: perf trace enum augmentation tests                              : FAILED!
--- start ---
test child forked, pid 264248
Checking if vmlinux BTF exists
Testing perf trace's string augmentation
String augmentation test failed, output:

---- end(-1) ----
--- start ---
test child forked, pid 278774
Checking if vmlinux exists
Tracing syscall landlock_add_rule
[syscall failure] Failed to trace syscall landlock_add_rule, output:
     0.000 (         ): perf/278843 landlock_add_rule(ruleset_fd: 11,
rule_type: LANDLOCK_RULE_PATH_BENEATH, rule_attr: 0x7ffdcf1dad90,
flags: 45) ...
---- end(-1) ----
107: perf trace enum augmentation tests                              : FAILED!
--- start ---
test child forked, pid 279196
Checking if vmlinux exists
Tracing syscall landlock_add_rule
[syscall failure] Failed to trace syscall landlock_add_rule, output:
     0.000 (         ): perf/279262 landlock_add_rule(ruleset_fd: 11,
rule_type: LANDLOCK_RULE_PATH_BENEATH, rule_attr: 0x7fff37a70fd0,
flags: 45) ...
---- end(-1) ----
107: perf trace enum augmentation tests                              : FAILED!
108: perf trace BTF general tests                                    : FAILED!
--- start ---
test child forked, pid 278187
Checking if vmlinux BTF exists
Testing perf trace's string augmentation
Testing perf trace's buffer augmentation
Testing perf trace's struct augmentation
BTF struct augmentation test failed, output:
sleep/278352 clock_nanosleep(0, 0, {1,1,}, 0x7ffd31550f50) = 0
---- end(-1) ----
108: perf trace BTF general tests                                    : FAILED!
--- start ---
test child forked, pid 278775
Checking if vmlinux BTF exists
Testing perf trace's string augmentation
Testing perf trace's buffer augmentation
Buffer augmentation test failed, output:
buffer content
---- end(-1) ----
108: perf trace BTF general tests                                    : FAILED!
--- start ---
test child forked, pid 279547
Checking if vmlinux BTF exists
Testing perf trace's string augmentation
Testing perf trace's buffer augmentation
Testing perf trace's struct augmentation
BTF struct augmentation test failed, output:
sleep/279619 clock_nanosleep(0, 0, {1,1,}, 0x7ffcd47b6450) = 0
---- end(-1) ----
108: perf trace BTF general tests                                    : FAILED!
--- start ---
test child forked, pid 264252
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.333 MB /tmp/temporary_file.pl459 ]
Failed: cannot find *nanosleep syscall
---- end(-1) ----
110: perf trace record and replay                                    : FAILED!
--- start ---
test child forked, pid 278193
testing: perf trace -s -- true
Error: cannot find enough pattern ^\s*(open|read|close).*[0-9]+%$ in the output

 Summary of events:

 true (278235), 5 events, 45.5%

   syscall            calls  errors  total       min       avg
max       stddev
                                     (msec)    (msec)    (msec)
(msec)        (%)
   --------------- --------  ------ -------- --------- ---------
---------     ------


---- end(-1) ----
111: perf trace summary                                              : FAILED!
```

Thanks,
Ian

> 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_setup 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(-)
>
>
> base-commit: f3061d526714ac6cc936c48e76a6eb0512c69b1a
> --
> 2.45.2
>

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

[Howard Chu]

Hello Ian,

On Sun, May 18, 2025 at 3:18 PM Ian Rogers <irogers@google.com> wrote:
>
> On Sun, May 18, 2025 at 12:10 PM Howard Chu <howardchu95@gmail.com> wrote:
> >
> > 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 ---

<SNIP>

> > Changes in v2:
> > - Add an extra newline after error messages
> > - Rename the title of patch 3 to 'Stop tracing hrtimer_setup...'
> > - Take the debug diff for explanation out of patch 5 to make it apply
> >   normally
> > - Add base-commit in this cover letter
>
> Thanks Howard! I did some testing but see failures that may be
> pre-existing issues:

I don't know the command you used but if this is the result of 'perf
test trace', it is the parallelism issue. I will fix it once I'm back
from Costco :).

Thanks,
Howard

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

[Howard Chu]

BTW thanks for testing this series, I will add your tested-by

Thanks,
Howard

On Sun, May 18, 2025 at 3:26 PM Howard Chu <howardchu95@gmail.com> wrote:
>
> Hello Ian,
>
> On Sun, May 18, 2025 at 3:18 PM Ian Rogers <irogers@google.com> wrote:
> >
> > On Sun, May 18, 2025 at 12:10 PM Howard Chu <howardchu95@gmail.com> wrote:
> > >
> > > 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 ---
>
> <SNIP>
>
> > > Changes in v2:
> > > - Add an extra newline after error messages
> > > - Rename the title of patch 3 to 'Stop tracing hrtimer_setup...'
> > > - Take the debug diff for explanation out of patch 5 to make it apply
> > >   normally
> > > - Add base-commit in this cover letter
> >
> > Thanks Howard! I did some testing but see failures that may be
> > pre-existing issues:
>
> I don't know the command you used but if this is the result of 'perf
> test trace', it is the parallelism issue. I will fix it once I'm back
> from Costco :).
>
> Thanks,
> Howard

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

[Howard Chu]

Hello Ian,

I jumped to a conclusion, there are reasons other than running tests
in parallel.

On Sun, May 18, 2025 at 3:18 PM Ian Rogers <irogers@google.com> wrote:
>
> On Sun, May 18, 2025 at 12:10 PM Howard Chu <howardchu95@gmail.com> wrote:
> >
> > 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!
> >
> > Changes in v2:
> > - Add an extra newline after error messages
> > - Rename the title of patch 3 to 'Stop tracing hrtimer_setup...'
> > - Take the debug diff for explanation out of patch 5 to make it apply
> >   normally
> > - Add base-commit in this cover letter
>
> Thanks Howard! I did some testing but see failures that may be
> pre-existing issues:
>
> ```
> --- start ---
> test child forked, pid 264236
> Checking if vmlinux exists
> Tracing syscall landlock_add_rule
> [syscall failure] Failed to trace syscall landlock_add_rule, output:
>

I think this doesn't have any output, a sign of failure of collection
on the BPF side.

> ---- end(-1) ----
> 107: perf trace enum augmentation tests                              : FAILED!
> --- start ---
> test child forked, pid 264248
> Checking if vmlinux BTF exists
> Testing perf trace's string augmentation
> String augmentation test failed, output:
>

Here too.

> ---- end(-1) ----
> --- start ---
> test child forked, pid 278774
> Checking if vmlinux exists
> Tracing syscall landlock_add_rule
> [syscall failure] Failed to trace syscall landlock_add_rule, output:
>      0.000 (         ): perf/278843 landlock_add_rule(ruleset_fd: 11,
> rule_type: LANDLOCK_RULE_PATH_BENEATH, rule_attr: 0x7ffdcf1dad90,
> flags: 45) ...

This is strange to me. No return value, no elapsed time. Judging from
experience this comes from the lack of the second sys_exit event that
sets both of them.

> ---- end(-1) ----
> 107: perf trace enum augmentation tests                              : FAILED!
> --- start ---
> test child forked, pid 279196
> Checking if vmlinux exists
> Tracing syscall landlock_add_rule
> [syscall failure] Failed to trace syscall landlock_add_rule, output:
>      0.000 (         ): perf/279262 landlock_add_rule(ruleset_fd: 11,
> rule_type: LANDLOCK_RULE_PATH_BENEATH, rule_attr: 0x7fff37a70fd0,
> flags: 45) ...

Ditto.

> ---- end(-1) ----
> 107: perf trace enum augmentation tests                              : FAILED!
> 108: perf trace BTF general tests                                    : FAILED!
> --- start ---
> test child forked, pid 278187
> Checking if vmlinux BTF exists
> Testing perf trace's string augmentation
> Testing perf trace's buffer augmentation
> Testing perf trace's struct augmentation
> BTF struct augmentation test failed, output:
> sleep/278352 clock_nanosleep(0, 0, {1,1,}, 0x7ffd31550f50) = 0

This is the difference in libbpf's btf_dump's behavior. I grepped
"grep -q -E "^sleep/[0-9]+ clock_nanosleep\(0, 0, \{1,\},
0x[0-9a-f]+\) += +[0-9]+$"", the {1, 1,} didn't match. On my machine
it is '{1,}'
~~~
sudo /tmp/perf trace --sort-events -e clock_nanosleep --force-btf
--max-events=1 -- sleep 1
sleep/338371 clock_nanosleep(0, 0, {1,}, 0x7ffeb4e9dd10) = 0
~~~

Which is strange, I thought we used the same libbpf from the kernel
tree and statically link it. Why is it different on our machines?
FWIW, I do have libbpf installed on my system, from their github
repo's main branch.
~~~
$ cat /usr/include/bpf/libbpf_version.h
/* SPDX-License-Identifier: (LGPL-2.1 OR BSD-2-Clause) */
/* Copyright (C) 2021 Facebook */
#ifndef __LIBBPF_VERSION_H
#define __LIBBPF_VERSION_H

#define LIBBPF_MAJOR_VERSION 1
#define LIBBPF_MINOR_VERSION 6

#endif /* __LIBBPF_VERSION_H */
~~~

But I thought we used the same 1.6.x version from the tree...
~~~
$ cat tools/lib/bpf/libbpf_version.h
/* SPDX-License-Identifier: (LGPL-2.1 OR BSD-2-Clause) */
/* Copyright (C) 2021 Facebook */
#ifndef __LIBBPF_VERSION_H
#define __LIBBPF_VERSION_H

#define LIBBPF_MAJOR_VERSION 1
#define LIBBPF_MINOR_VERSION 6

#endif /* __LIBBPF_VERSION_H */
~~~

> ---- end(-1) ----
> 108: perf trace BTF general tests                                    : FAILED!
> --- start ---
> test child forked, pid 278775
> Checking if vmlinux BTF exists
> Testing perf trace's string augmentation
> Testing perf trace's buffer augmentation
> Buffer augmentation test failed, output:
> buffer content

This should have two lines of output, the second line is missing,
something to do with the BPF collection I mentioned above.
~~~
$ sudo /tmp/perf/perf trace --sort-events -e write --force-btf
--max-events=1 -- echo "buffer content"
buffer content
echo/393319 write(1, buffer content\10, 15) = 15
~~~

> ---- end(-1) ----
> 108: perf trace BTF general tests                                    : FAILED!
> --- start ---
> test child forked, pid 279547
> Checking if vmlinux BTF exists
> Testing perf trace's string augmentation
> Testing perf trace's buffer augmentation
> Testing perf trace's struct augmentation
> BTF struct augmentation test failed, output:
> sleep/279619 clock_nanosleep(0, 0, {1,1,}, 0x7ffcd47b6450) = 0

Same '{1,1,}' appears.

> ---- end(-1) ----
> 108: perf trace BTF general tests                                    : FAILED!
> --- start ---
> test child forked, pid 264252
> [ perf record: Woken up 1 times to write data ]
> [ perf record: Captured and wrote 0.333 MB /tmp/temporary_file.pl459 ]
> Failed: cannot find *nanosleep syscall

This test was written by Namhyung, again it failed to collect some samples.

> ---- end(-1) ----
> 110: perf trace record and replay                                    : FAILED!
> --- start ---
> test child forked, pid 278193
> testing: perf trace -s -- true
> Error: cannot find enough pattern ^\s*(open|read|close).*[0-9]+%$ in the output

May also be a loss of samples.

There are some problems. From the output you provided, I can see the
obvious sample loss in perf trace, and the differing behavior in
libbpf's btf_dump. Fixing them.

Thanks,
Howard

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

[Ian Rogers]

On Mon, May 19, 2025 at 8:01 AM Howard Chu <howardchu95@gmail.com> wrote:
>
> Hello Ian,
>
> I jumped to a conclusion, there are reasons other than running tests
> in parallel.
>
> On Sun, May 18, 2025 at 3:18 PM Ian Rogers <irogers@google.com> wrote:
> >
> > On Sun, May 18, 2025 at 12:10 PM Howard Chu <howardchu95@gmail.com> wrote:
> > >
> > > 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!
> > >
> > > Changes in v2:
> > > - Add an extra newline after error messages
> > > - Rename the title of patch 3 to 'Stop tracing hrtimer_setup...'
> > > - Take the debug diff for explanation out of patch 5 to make it apply
> > >   normally
> > > - Add base-commit in this cover letter
> >
> > Thanks Howard! I did some testing but see failures that may be
> > pre-existing issues:
> >
> > ```
> > --- start ---
> > test child forked, pid 264236
> > Checking if vmlinux exists
> > Tracing syscall landlock_add_rule
> > [syscall failure] Failed to trace syscall landlock_add_rule, output:
> >
>
> I think this doesn't have any output, a sign of failure of collection
> on the BPF side.
>
> > ---- end(-1) ----
> > 107: perf trace enum augmentation tests                              : FAILED!
> > --- start ---
> > test child forked, pid 264248
> > Checking if vmlinux BTF exists
> > Testing perf trace's string augmentation
> > String augmentation test failed, output:
> >
>
> Here too.
>
> > ---- end(-1) ----
> > --- start ---
> > test child forked, pid 278774
> > Checking if vmlinux exists
> > Tracing syscall landlock_add_rule
> > [syscall failure] Failed to trace syscall landlock_add_rule, output:
> >      0.000 (         ): perf/278843 landlock_add_rule(ruleset_fd: 11,
> > rule_type: LANDLOCK_RULE_PATH_BENEATH, rule_attr: 0x7ffdcf1dad90,
> > flags: 45) ...
>
> This is strange to me. No return value, no elapsed time. Judging from
> experience this comes from the lack of the second sys_exit event that
> sets both of them.
>
> > ---- end(-1) ----
> > 107: perf trace enum augmentation tests                              : FAILED!
> > --- start ---
> > test child forked, pid 279196
> > Checking if vmlinux exists
> > Tracing syscall landlock_add_rule
> > [syscall failure] Failed to trace syscall landlock_add_rule, output:
> >      0.000 (         ): perf/279262 landlock_add_rule(ruleset_fd: 11,
> > rule_type: LANDLOCK_RULE_PATH_BENEATH, rule_attr: 0x7fff37a70fd0,
> > flags: 45) ...
>
> Ditto.
>
> > ---- end(-1) ----
> > 107: perf trace enum augmentation tests                              : FAILED!
> > 108: perf trace BTF general tests                                    : FAILED!
> > --- start ---
> > test child forked, pid 278187
> > Checking if vmlinux BTF exists
> > Testing perf trace's string augmentation
> > Testing perf trace's buffer augmentation
> > Testing perf trace's struct augmentation
> > BTF struct augmentation test failed, output:
> > sleep/278352 clock_nanosleep(0, 0, {1,1,}, 0x7ffd31550f50) = 0
>
> This is the difference in libbpf's btf_dump's behavior. I grepped
> "grep -q -E "^sleep/[0-9]+ clock_nanosleep\(0, 0, \{1,\},
> 0x[0-9a-f]+\) += +[0-9]+$"", the {1, 1,} didn't match. On my machine
> it is '{1,}'
> ~~~
> sudo /tmp/perf trace --sort-events -e clock_nanosleep --force-btf
> --max-events=1 -- sleep 1
> sleep/338371 clock_nanosleep(0, 0, {1,}, 0x7ffeb4e9dd10) = 0
> ~~~
>
> Which is strange, I thought we used the same libbpf from the kernel
> tree and statically link it. Why is it different on our machines?
> FWIW, I do have libbpf installed on my system, from their github
> repo's main branch.
> ~~~
> $ cat /usr/include/bpf/libbpf_version.h
> /* SPDX-License-Identifier: (LGPL-2.1 OR BSD-2-Clause) */
> /* Copyright (C) 2021 Facebook */
> #ifndef __LIBBPF_VERSION_H
> #define __LIBBPF_VERSION_H
>
> #define LIBBPF_MAJOR_VERSION 1
> #define LIBBPF_MINOR_VERSION 6
>
> #endif /* __LIBBPF_VERSION_H */
> ~~~
>
> But I thought we used the same 1.6.x version from the tree...
> ~~~
> $ cat tools/lib/bpf/libbpf_version.h
> /* SPDX-License-Identifier: (LGPL-2.1 OR BSD-2-Clause) */
> /* Copyright (C) 2021 Facebook */
> #ifndef __LIBBPF_VERSION_H
> #define __LIBBPF_VERSION_H
>
> #define LIBBPF_MAJOR_VERSION 1
> #define LIBBPF_MINOR_VERSION 6
>
> #endif /* __LIBBPF_VERSION_H */
> ~~~
>
> > ---- end(-1) ----
> > 108: perf trace BTF general tests                                    : FAILED!
> > --- start ---
> > test child forked, pid 278775
> > Checking if vmlinux BTF exists
> > Testing perf trace's string augmentation
> > Testing perf trace's buffer augmentation
> > Buffer augmentation test failed, output:
> > buffer content
>
> This should have two lines of output, the second line is missing,
> something to do with the BPF collection I mentioned above.
> ~~~
> $ sudo /tmp/perf/perf trace --sort-events -e write --force-btf
> --max-events=1 -- echo "buffer content"
> buffer content
> echo/393319 write(1, buffer content\10, 15) = 15
> ~~~
>
> > ---- end(-1) ----
> > 108: perf trace BTF general tests                                    : FAILED!
> > --- start ---
> > test child forked, pid 279547
> > Checking if vmlinux BTF exists
> > Testing perf trace's string augmentation
> > Testing perf trace's buffer augmentation
> > Testing perf trace's struct augmentation
> > BTF struct augmentation test failed, output:
> > sleep/279619 clock_nanosleep(0, 0, {1,1,}, 0x7ffcd47b6450) = 0
>
> Same '{1,1,}' appears.
>
> > ---- end(-1) ----
> > 108: perf trace BTF general tests                                    : FAILED!
> > --- start ---
> > test child forked, pid 264252
> > [ perf record: Woken up 1 times to write data ]
> > [ perf record: Captured and wrote 0.333 MB /tmp/temporary_file.pl459 ]
> > Failed: cannot find *nanosleep syscall
>
> This test was written by Namhyung, again it failed to collect some samples.
>
> > ---- end(-1) ----
> > 110: perf trace record and replay                                    : FAILED!
> > --- start ---
> > test child forked, pid 278193
> > testing: perf trace -s -- true
> > Error: cannot find enough pattern ^\s*(open|read|close).*[0-9]+%$ in the output
>
> May also be a loss of samples.
>
> There are some problems. From the output you provided, I can see the
> obvious sample loss in perf trace, and the differing behavior in
> libbpf's btf_dump. Fixing them.

Massively appreciated! I was running the tests with `perf test -v
"perf trace"` so there was parallelism. Running the tests with your
changes and with "-S" for sequential I still reliably see:
```
--- start ---
test child forked, pid 279547
Checking if vmlinux BTF exists
Testing perf trace's string augmentation
Testing perf trace's buffer augmentation
Testing perf trace's struct augmentation
BTF struct augmentation test failed, output:
sleep/279619 clock_nanosleep(0, 0, {1,1,}, 0x7ffcd47b6450) = 0
---- end(-1) ----
108: perf trace BTF general tests                                    : FAILED!
```
but the other problems appear to go away.

Thanks,
Ian

> Thanks,
> Howard

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

[Howard Chu]

Hello Ian,

On Mon, May 19, 2025 at 10:00 AM Ian Rogers <irogers@google.com> wrote:
>

<SNIP>

> ```
> --- start ---
> test child forked, pid 279547
> Checking if vmlinux BTF exists
> Testing perf trace's string augmentation
> Testing perf trace's buffer augmentation
> Testing perf trace's struct augmentation
> BTF struct augmentation test failed, output:
> sleep/279619 clock_nanosleep(0, 0, {1,1,}, 0x7ffcd47b6450) = 0

Thank you so much for testing it :)

My bad, I have just realized this is because of the data in the
timespec, nothing to do with libbpf... The tv_nsec has a value of 1. I
think the 'sleep' on your machine has a different implementation. On
my machine, the second member has a value of 0, see below:
~~~
$ sudo /tmp/perf/perf trace -e clock_nanosleep -- sleep 1
     0.000 (1000.196 ms): sleep/54261 clock_nanosleep(rqtp: { .tv_sec:
1, .tv_nsec: 0 }, rmtp: 0x7ffe13529550) = 0

$ strace -e clock_nanosleep -- sleep 1
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=1, tv_nsec=0}, 0x7fff859365a0) = 0
+++ exited with 0 +++
~~~

Can you please run any of the commands above and see what
happens(please change the perf executable path)? If you get 'rqtp: {
.tv_sec: 1, .tv_nsec: 1 }' then I will just make the regex less
strict, because it differs between different 'sleep' implementations
instead of having anything to do with perf itself.

Thanks,
Howard

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

[Ian Rogers]

On Mon, May 19, 2025 at 12:28 PM Howard Chu <howardchu95@gmail.com> wrote:
>
> Hello Ian,
>
> On Mon, May 19, 2025 at 10:00 AM Ian Rogers <irogers@google.com> wrote:
> >
>
> <SNIP>
>
> > ```
> > --- start ---
> > test child forked, pid 279547
> > Checking if vmlinux BTF exists
> > Testing perf trace's string augmentation
> > Testing perf trace's buffer augmentation
> > Testing perf trace's struct augmentation
> > BTF struct augmentation test failed, output:
> > sleep/279619 clock_nanosleep(0, 0, {1,1,}, 0x7ffcd47b6450) = 0
>
> Thank you so much for testing it :)
>
> My bad, I have just realized this is because of the data in the
> timespec, nothing to do with libbpf... The tv_nsec has a value of 1. I
> think the 'sleep' on your machine has a different implementation. On
> my machine, the second member has a value of 0, see below:
> ~~~
> $ sudo /tmp/perf/perf trace -e clock_nanosleep -- sleep 1
>      0.000 (1000.196 ms): sleep/54261 clock_nanosleep(rqtp: { .tv_sec:
> 1, .tv_nsec: 0 }, rmtp: 0x7ffe13529550) = 0
>
> $ strace -e clock_nanosleep -- sleep 1
> clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=1, tv_nsec=0}, 0x7fff859365a0) = 0
> +++ exited with 0 +++
> ~~~
>
> Can you please run any of the commands above and see what
> happens(please change the perf executable path)? If you get 'rqtp: {
> .tv_sec: 1, .tv_nsec: 1 }' then I will just make the regex less
> strict, because it differs between different 'sleep' implementations
> instead of having anything to do with perf itself.

Ack. Here is the output:
```
$ sudo /tmp/perf/perf trace -e clock_nanosleep -- sleep 1
    0.000 (1000.208 ms): sleep/1710732 clock_nanosleep(rqtp: {
.tv_sec: 1, .tv_nsec: 1 }, rmtp: 0x7ffc091f4090) = 0
$ strace -e clock_nanosleep -- sleep 1
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=1, tv_nsec=1}, 0x7ffe51f3cd00) = 0
+++ exited with 0 +++
```

Thanks,
Ian

>
> Thanks,
> Howard

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

[Arnaldo Carvalho de Melo]

On Mon, May 19, 2025 at 12:58:34PM -0700, Ian Rogers wrote:
> On Mon, May 19, 2025 at 12:28 PM Howard Chu <howardchu95@gmail.com> wrote:
> > On Mon, May 19, 2025 at 10:00 AM Ian Rogers <irogers@google.com> wrote:
> > My bad, I have just realized this is because of the data in the
> > timespec, nothing to do with libbpf... The tv_nsec has a value of 1. I
> > think the 'sleep' on your machine has a different implementation. On
> > my machine, the second member has a value of 0, see below:
> > ~~~
> > $ sudo /tmp/perf/perf trace -e clock_nanosleep -- sleep 1
> >      0.000 (1000.196 ms): sleep/54261 clock_nanosleep(rqtp: { .tv_sec:
> > 1, .tv_nsec: 0 }, rmtp: 0x7ffe13529550) = 0
> >
> > $ strace -e clock_nanosleep -- sleep 1
> > clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=1, tv_nsec=0}, 0x7fff859365a0) = 0
> > +++ exited with 0 +++
> > ~~~

> > Can you please run any of the commands above and see what
> > happens(please change the perf executable path)? If you get 'rqtp: {
> > .tv_sec: 1, .tv_nsec: 1 }' then I will just make the regex less
> > strict, because it differs between different 'sleep' implementations
> > instead of having anything to do with perf itself.
 
> Ack. Here is the output:
> ```
> $ sudo /tmp/perf/perf trace -e clock_nanosleep -- sleep 1
>     0.000 (1000.208 ms): sleep/1710732 clock_nanosleep(rqtp: {
> .tv_sec: 1, .tv_nsec: 1 }, rmtp: 0x7ffc091f4090) = 0
> $ strace -e clock_nanosleep -- sleep 1
> clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=1, tv_nsec=1}, 0x7ffe51f3cd00) = 0
> +++ exited with 0 +++
> ```

With what is now in tmp.perf-tools-next:

root@number:~# uname -a
Linux number 6.14.6-300.fc42.x86_64 #1 SMP PREEMPT_DYNAMIC Fri May  9 20:11:19 UTC 2025 x86_64 GNU/Linux
root@number:~# rpm -q glibc
glibc-2.41-5.fc42.x86_64
root@number:~# perf trace -e clock_nanosleep -- sleep 1.0000000001
     0.000 (1000.058 ms): sleep/665955 clock_nanosleep(rqtp: { .tv_sec: 1, .tv_nsec: 1 }, rmtp: 0x7ffcff002730) = 0
root@number:~# perf trace -e clock_nanosleep -- sleep 1.0000000001
     0.000 (1000.070 ms): sleep/665969 clock_nanosleep(rqtp: { .tv_sec: 1, .tv_nsec: 1 }, rmtp: 0x7fff91df9de0) = 0
root@number:~# perf trace -e clock_nanosleep -- sleep 1.0000000001
     0.000 (1000.068 ms): sleep/665971 clock_nanosleep(rqtp: { .tv_sec: 1, .tv_nsec: 1 }, rmtp: 0x7fffe593b0e0) = 0
root@number:~# perf trace -e clock_nanosleep -- sleep 1.0000000001
     0.000 (1000.056 ms): sleep/665973 clock_nanosleep(rqtp: { .tv_sec: 1, .tv_nsec: 1 }, rmtp: 0x7ffdcf948c80) = 0
root@number:~# perf trace -e clock_nanosleep -- sleep 1.0000000001
     0.000 (1000.057 ms): sleep/665978 clock_nanosleep(rqtp: { .tv_sec: 1, .tv_nsec: 1 }, rmtp: 0x7fff56af7560) = 0
root@number:~# perf test "perf trace"
108: perf trace enum augmentation tests                              : FAILED!
109: perf trace BTF general tests                                    : Ok
110: perf trace exit race                                            : Ok
111: perf trace record and replay                                    : Ok
137: Check open filename arg using perf trace + vfs_getname          : Ok
138: perf trace summary                                              : Ok
root@number:~# perf test -S "perf trace"
108: perf trace enum augmentation tests                              : FAILED!
109: perf trace BTF general tests                                    : Ok
110: perf trace exit race                                            : Ok
111: perf trace record and replay                                    : Ok
137: Check open filename arg using perf trace + vfs_getname          : FAILED!
138: perf trace summary                                              : Ok
root@number:~# perf test 108
108: perf trace enum augmentation tests                              : FAILED!
root@number:~# perf test -v 108
--- start ---
test child forked, pid 666496
Checking if vmlinux exists
Tracing syscall landlock_add_rule
Tracing non-syscall tracepoint syscall
---- end(-1) ----
108: perf trace enum augmentation tests                              : FAILED!
root@number:~# perf test -vv 108
108: perf trace enum augmentation tests:
--- start ---
test child forked, pid 666512
Checking if vmlinux exists
Tracing syscall landlock_add_rule
Tracing non-syscall tracepoint syscall
---- end(-1) ----
108: perf trace enum augmentation tests                              : FAILED!
root@number:~# perf test -vvv 108
108: perf trace enum augmentation tests:
--- start ---
test child forked, pid 666544
Checking if vmlinux exists
Tracing syscall landlock_add_rule
Tracing non-syscall tracepoint syscall
---- end(-1) ----
108: perf trace enum augmentation tests                              : FAILED!
root@number:~# strace -e landlock_add_rule perf test -vvv 108
108: perf trace enum augmentation tests:
108: perf trace enum augmentation tests                              : Running (1 active)
--- start ---
test child forked, pid 666623
Checking if vmlinux exists
Tracing syscall landlock_add_rule
Tracing non-syscall tracepoint syscall
---- end(-1) ----
108: perf trace enum augmentation tests                              : FAILED!
+++ exited with 0 +++
root@number:~# strace -f -e landlock_add_rule perf test -vvv 108
strace: Process 666728 attached
108: perf trace enum augmentation tests:
108: perf trace enum augmentation tests                              : Running (1 active)
strace: Process 666729 attached
strace: Process 666730 attached
[pid 666730] +++ exited with 0 +++
[pid 666729] --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=666730, si_uid=0, si_status=0, si_utime=0, si_stime=0} ---
strace: Process 666731 attached
strace: Process 666732 attached
[pid 666731] +++ exited with 129 +++
[pid 666732] +++ exited with 1 +++
[pid 666729] --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=666731, si_uid=0, si_status=129, si_utime=0, si_stime=0} ---
strace: Process 666733 attached
[pid 666733] +++ exited with 0 +++
[pid 666729] --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=666733, si_uid=0, si_status=0, si_utime=0, si_stime=0} ---
strace: Process 666734 attached
[pid 666734] +++ exited with 0 +++
[pid 666729] --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=666734, si_uid=0, si_status=0, si_utime=0, si_stime=0} ---
strace: Process 666735 attached
strace: Process 666736 attached
strace: Process 666749 attached
[pid 666749] landlock_add_rule(11, LANDLOCK_RULE_PATH_BENEATH, {allowed_access=LANDLOCK_ACCESS_FS_READ_FILE, parent_fd=14}, 0x2d) = -1 EINVAL (Invalid argument)
[pid 666749] landlock_add_rule(11, LANDLOCK_RULE_NET_PORT, {allowed_access=LANDLOCK_ACCESS_NET_CONNECT_TCP, port=19}, 0x2d) = -1 EINVAL (Invalid argument)
[pid 666749] +++ exited with 0 +++
[pid 666735] --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=666749, si_uid=0, si_status=0, si_utime=0, si_stime=0} ---
[pid 666736] +++ exited with 0 +++
[pid 666735] --- SIGPIPE {si_signo=SIGPIPE, si_code=SI_USER, si_pid=666735, si_uid=0} ---
[pid 666735] +++ killed by SIGPIPE +++
[pid 666729] --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=666736, si_uid=0, si_status=0, si_utime=0, si_stime=0} ---
strace: Process 666750 attached
strace: Process 666751 attached
strace: Process 666753 attached
[pid 666753] landlock_add_rule(11, LANDLOCK_RULE_PATH_BENEATH, {allowed_access=LANDLOCK_ACCESS_FS_READ_FILE, parent_fd=14}, 0x2d) = -1 EINVAL (Invalid argument)
[pid 666753] landlock_add_rule(11, LANDLOCK_RULE_NET_PORT, {allowed_access=LANDLOCK_ACCESS_NET_CONNECT_TCP, port=19}, 0x2d) = -1 EINVAL (Invalid argument)
[pid 666753] +++ exited with 0 +++
[pid 666750] --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=666753, si_uid=0, si_status=0, si_utime=0, si_stime=0} ---
[pid 666751] +++ exited with 0 +++
[pid 666750] +++ exited with 0 +++
[pid 666729] --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=666751, si_uid=0, si_status=0, si_utime=0, si_stime=0} ---
strace: Process 666754 attached
strace: Process 666755 attached
[pid 666754] +++ exited with 129 +++
[pid 666755] +++ exited with 1 +++
[pid 666729] --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=666754, si_uid=0, si_status=129, si_utime=0, si_stime=0} ---
[pid 666729] +++ exited with 1 +++
[pid 666728] --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=666729, si_uid=0, si_status=1, si_utime=0, si_stime=0} ---
[pid 666728] +++ exited with 1 +++
--- start ---
test child forked, pid 666728
Checking if vmlinux exists
Tracing syscall landlock_add_rule
Tracing non-syscall tracepoint syscall
---- end(-1) ----
108: perf trace enum augmentation tests                              : FAILED!
+++ exited with 0 +++
root@number:~# 


root@number:~# strace -e clock_nanosleep -- sleep 1
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=1, tv_nsec=0}, 0x7ffda83143a0) = 0
+++ exited with 0 +++
root@number:~# strace -e clock_nanosleep -- sleep 1
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=1, tv_nsec=0}, 0x7ffecc3098e0) = 0
+++ exited with 0 +++
root@number:~#

- Arnaldo

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

[Howard Chu]

Hello Ian,

On Sun, May 18, 2025 at 3:18 PM Ian Rogers <irogers@google.com> wrote:
>
> On Sun, May 18, 2025 at 12:10 PM Howard Chu <howardchu95@gmail.com> wrote:
> >
> > 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!
> >
> > Changes in v2:
> > - Add an extra newline after error messages
> > - Rename the title of patch 3 to 'Stop tracing hrtimer_setup...'
> > - Take the debug diff for explanation out of patch 5 to make it apply
> >   normally
> > - Add base-commit in this cover letter
>
> Thanks Howard! I did some testing but see failures that may be
> pre-existing issues:

Again, thank you for spending time testing this series! It has been
some time... But hopefully this: [1] along with the BTF test v3: [2]
can resolve the issues.

[1]: https://lore.kernel.org/linux-perf-users/20250529065537.529937-1-howardchu95@gmail.com/T/#u
[2]: https://lore.kernel.org/linux-perf-users/20250528191148.89118-1-howardchu95@gmail.com/T/#t

Thanks,
Howard