On Fri, Apr 11, 2025 at 12:45:52PM -0400, Steven Rostedt wrote: > Mark Brown <broo...@kernel.org> wrote: > > On Thu, Apr 10, 2025 at 01:17:45PM -0400, Steven Rostedt wrote:
> > > 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? > Can you show the information before this output, to see what it is actually > testing? Here's a bit more of the context - this is literally just the ftrace selftests so it'll be doing whatever that does, there's a huge amount of log splat generated when enumerating all the triggers. I do note that it appears to assume there's a ping binary which might confusing things, though I'm surprised that'd be a regression rather than something that just never worked: # # + reset_ftrace_filter # # + [ ! -f set_ftrace_filter ] # # + echo # # + grep -v ^# set_ftrace_filter # # + read t # # + disable_events # # + echo 0 # # + clear_dynamic_events # # + again=1 # # + stop=1 # # + [ 1 -eq 1 ] # # + stop=2 # # + [ 2 -gt 10 ] # # + again=2 # # + grep -v ^# dynamic_events # # + read line # # + [ 2 -eq 1 ] # # + [ -f set_event_pid ] # # + echo # # + [ -f set_ftrace_pid ] # # + echo # # + [ -f set_ftrace_notrace ] # # + echo # # + [ -f set_graph_function ] # # + echo # # + tee set_graph_function set_graph_notrace # # # # + [ -f stack_trace_filter ] # # + echo # # + [ -f kprobe_events ] # # + echo # # + [ -f uprobe_events ] # # + echo # # + [ -f synthetic_events ] # # + echo # # + [ -f snapshot ] # # + echo 0 # # + [ -f options/pause-on-trace ] # # + echo 1 # # + clear_trace # # + echo # # + enable_tracing # # + echo 1 # # + . /opt/kselftest/ftrace/test.d/ftrace/func-filter-pid.tc # # + do_function_fork=1 # # + do_funcgraph_proc=1 # # + [ ! -f options/function-fork ] # # + [ ! -f options/funcgraph-proc ] # # + read PID _ # # + [ 1 -eq 1 ] # # + grep function-fork trace_options # # + orig_value=nofunction-fork # # + [ 1 -eq 1 ] # # + cat options/funcgraph-proc # # + orig_value2=0 # # + echo 1 # # + do_test function # # + TRACER=function # # + disable_tracing # # + echo 0 # # + echo do_execve* # # + echo kernel_clone # # + echo 5190 # # + echo function # # + [ 1 -eq 1 ] # # + echo nofunction-fork # # + enable_tracing # # + echo 1 # # + yield # # + ping 127.0.0.1 -c 1 # # ./ftracetest: 179: /opt/kselftest/ftrace/test.d/ftrace/func-filter-pid.tc: ping: not found # # + sleep .001 # # + cat trace # # + grep -v ^# # # + grep 5190 # # + wc -l # # + count_pid=2 # # + cat trace # # + grep -v ^# # # + grep -v 5190 # # + wc -l # # + count_other=0 # # + [ 2 -eq 0 -o 0 -ne 0 ] # # + disable_tracing # # + echo 0 # # + clear_trace # # + echo # # + [ 1 -eq 0 ] # # + echo function-fork # # + enable_tracing # # + echo 1 # # + yield # # + ping 127.0.0.1 -c 1 # # ./ftracetest: 179: /opt/kselftest/ftrace/test.d/ftrace/func-filter-pid.tc: ping: not found # # + sleep .001 # # + cat trace # # + grep -v ^# # # + grep 5190 # # + wc -l # # + count_pid=2 # # + cat trace # # + grep -v ^# # # + grep -v 5190 # # + wc -l # # + count_other=17 # # + [ 2 -eq 0 -o 17 -eq 0 ] # # + grep -s function_graph available_tracers # # function_graph wakeup_dl wakeup_rt wakeup preemptirqsoff preemptoff irqsoff function nop # # + do_test function_graph # # + TRACER=function_graph # # + disable_tracing # # + echo 0 # # + echo do_execve* # # + echo kernel_clone # # + echo 5190 # # + echo function_graph # # + [ 1 -eq 1 ] # # + echo nofunction-fork # # + enable_tracing # # + echo 1 # # + yield # # + ping 127.0.0.1 -c 1 # # ./ftracetest: 179: /opt/kselftest/ftrace/test.d/ftrace/func-filter-pid.tc: ping: not found # # + sleep .001 # # + cat trace # # + grep -v ^# # # + grep 5190 # # + wc -l # # + count_pid=2 # # + cat trace # # + grep -v ^# # # + grep -v 5190 # # + wc -l # # + count_other=3 # # + [ 2 -eq 0 -o 3 -ne 0 ] # # + cat trace # # # tracer: function_graph # # # # # # CPU TASK/PID DURATION FUNCTION CALLS # # # | | | | | | | | | # # 0) ftracet-5190 | ! 537.633 us | kernel_clone(); /* ret=0x1470 */ # # # # 0) ftracet-5190 | ! 508.253 us | kernel_clone(); /* ret=0x1471 */ # # # # 0) ftracet-5190 | ! 215.716 us | kernel_clone(); /* ret=0x1476 */ # # # # 0) ftracet-5190 | ! 493.890 us | kernel_clone(); /* ret=0x147b */ # # # # + fail PID filtering not working? # # + do_reset # # + [ 1 -eq 1 ] # # + echo nofunction-fork # # + [ 1 -eq 1 ] # # + echo 0 # # + echo PID filtering not working? # # PID filtering not working? # # + exit_fail # # + exit 1 > > # # + cat trace > > # # # tracer: function_graph > > # # # > > # # # CPU TASK/PID DURATION FUNCTION CALLS > > # # # | | | | | | | | | > > # # 0) ftracet-12279 | ! 598.118 us | kernel_clone(); /* ret=0x301f */ > > # # > > # # 0) ftracet-12279 | ! 492.539 us | kernel_clone(); /* ret=0x3020 */ > > # # > > # # 0) ftracet-12279 | ! 231.104 us | kernel_clone(); /* ret=0x3025 */ > > # # > > # # 0) ftracet-12279 | ! 555.566 us | kernel_clone(); /* ret=0x302a */ > > # # > > # # + fail PID filtering not working? > Also, is it possible to just enable function_graph tarcing and see if it > adds these blank lines between events? That'll take a bit more arranging, I'm running these tests as batch jobs in CI infrastructure. I'll try to have a look. The only other test that actually failed was: # not ok 25 Checking dynamic events limitations which isn't flagged as a regression (there's some other UNRESOLVED ones).
signature.asc
Description: PGP signature
