Re: [PATCH v4 2/4] ftrace: Add support for function argument to graph tracer

[Steven Rostedt]

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
 }