On Wed, 9 Apr 2025 23:34:16 +0100
Mark Brown <broonie@xxxxxxxxxx> wrote:
> We've been seeing the PID filters selftest failing for a while on
> several arm64 systems, a bisect I managed to run without running into
> any confounding issues pointed to this patch which is in mainline as
> ff5c9c576e75. It's in the ftrace code, but I'm not immediately seeing
> the relevance. Output from a failing run:
>
> 6190 18:38:41.261255 # not ok 48 ftrace - function pid filters
> 6191 18:38:41.274039 # # execute: /lava-922575/1/tests/2_kselftest-ftrace/automated/linux/kselftest/ftrace/test.d/ftrace/func-filter-pid.tc
> 6192 18:38:41.285261 # # + checkreq /lava-922575/1/tests/2_kselftest-ftrace/automated/linux/kselftest/ftrace/test.d/ftrace/func-filter-pid.tc
> 6193 18:38:41.296551 # # + grep ^#[ t]*requires: /lava-922575/1/tests/2_kselftest-ftrace/automated/linux/kselftest/ftrace/test.d/ftrace/func-filter-pid.tc
> 6194 18:38:41.307877 # # + cut -f2- -d:
> 6195 18:38:41.308157 # # + requires= set_ftrace_pid set_ftrace_filter function:tracer
> 6196 18:38:41.319397 # # + eval check_requires set_ftrace_pid set_ftrace_filter function:tracer
> 6197 18:38:41.319681 # # + check_requires set_ftrace_pid set_ftrace_filter function:tracer
> 6198 18:38:41.319905 # # + p=set_ftrace_pid
> 6199 18:38:41.330653 # # + r=set_ftrace_pid
> 6200 18:38:41.330936 # # + t=set_ftrace_pid
> 6201 18:38:41.331161 # # + [ set_ftrace_pid != set_ftrace_pid ]
> 6202 18:38:41.331367 # # + [ set_ftrace_pid != set_ftrace_pid ]
> 6203 18:38:41.342045 # # + [ set_ftrace_pid != set_ftrace_pid ]
> 6204 18:38:41.342330 # # + [ ! -e set_ftrace_pid ]
> .......
> 6364 18:39:15.411636 # # + grep -v 7190
> 6365 18:39:15.411865 # # + wc -l
> 6366 18:39:15.412073 # # + count_other=3
> 6367 18:39:15.412554 # # + [ 2 -eq 0 -o 3 -ne 0 ]
> 6368 18:39:15.412773 # # + fail PID filtering not working?
> 6369 18:39:15.422776 # # + do_reset
> 6370 18:39:15.423055 # # + [ 1 -eq 1 ]
> 6371 18:39:15.423278 # # + echo nofunction-fork
> 6372 18:39:15.423485 # # + [ 1 -eq 1 ]
> 6373 18:39:15.423681 # # + echo 0
> 6374 18:39:15.423873 # # + echo PID filtering not working?
> 6375 18:39:15.434095 # # PID filtering not working?
> 6376 18:39:15.434377 # # + exit_fail
> 6377 18:39:15.434602 # # + exit 1
Hmm, I wonder if there's junk being added into the trace.
Can you add this patch, and show me the output when it fails again?
-- Steve
diff --git a/tools/testing/selftests/ftrace/test.d/ftrace/func-filter-pid.tc b/tools/testing/selftests/ftrace/test.d/ftrace/func-filter-pid.tc
index 8dcce001881d..0699ec6d7554 100644
--- a/tools/testing/selftests/ftrace/test.d/ftrace/func-filter-pid.tc
+++ b/tools/testing/selftests/ftrace/test.d/ftrace/func-filter-pid.tc
@@ -72,6 +72,7 @@ do_test() {
# count_other should be 0
if [ $count_pid -eq 0 -o $count_other -ne 0 ]; then
+ cat trace
fail "PID filtering not working?"
fi
@@ -79,6 +80,7 @@ do_test() {
clear_trace
if [ $do_function_fork -eq 0 ]; then
+ cat trace
return
fi
@@ -93,6 +95,7 @@ do_test() {
# count_other should NOT be 0
if [ $count_pid -eq 0 -o $count_other -eq 0 ]; then
+ cat trace
fail "PID filtering not following fork?"
fi
}
