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

[Mark Brown]

On Fri, Apr 11, 2025 at 12:45:52PM -0400, Steven Rostedt wrote:
> Mark Brown <broonie@xxxxxxxxxx> 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).

Attachment: signature.asc
Description: PGP signature