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(-)
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
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
>
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
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
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
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
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
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
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
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
© 2016 - 2025 Red Hat, Inc.