Re: [PATCH v2] ftrace: Hide a extra entry in stack trace

[ts]

On 10/1/24 10:27 PM, ts wrote:
> On 9/30/24 8:51 AM, Masami Hiramatsu (Google) wrote:
> > On Thu, 26 Sep 2024 15:13:07 +0900
> > Tatsuya S<tatsuya.s2862@xxxxxxxxx> wrote:
> >
> > > A extra entry is shown on stack trace(CONFIG_UNWINDER_ORC=y).
> > >
> > >      [003] .....   110.171589: vfs_write <-__x64_sys_write
> > >      [003] .....   110.171600: <stack trace>
> > >   => XXXXXXXXX (Wrong function name)
> > >   => vfs_write
> > >   => __x64_sys_write
> > >   => do_syscall_64
> > >   => entry_SYSCALL_64_after_hwframe
> > OK, I confirmed it;
> >
> > ------
> > echo 1 > options/func_stack_trace
> > echo "vfs_write" >> set_ftrace_filter
> > echo "function" > current_tracer
> > echo > /dev/null
> > cat trace
> >                sh-136     [005] .....   266.884180: vfs_write 
> > <-ksys_write
> >                sh-136     [005] .....   266.884188: <stack trace>
> >   => 0xffffffffa0004099
> >   => vfs_write
> >   => ksys_write
> >   => do_syscall_64
> >   => entry_SYSCALL_64_after_hwframe
> > ------
> >
> > > To resolve this, increment skip in __ftrace_trace_stack().
> > > The reason why skip is incremented in __ftrace_trace_stack()
> > > is because __ftrace_trace_stack() in stack trace is the only function
> > > that wasn't skipped from anywhere.
> > >
> > > Signed-off-by: Tatsuya S<tatsuya.s2862@xxxxxxxxx>
> > > ---
> > >   kernel/trace/trace.c | 4 +---
> > >   1 file changed, 1 insertion(+), 3 deletions(-)
> > >
> > > diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> > > index c3b2c7dfadef..0f2e255f563c 100644
> > > --- a/kernel/trace/trace.c
> > > +++ b/kernel/trace/trace.c
> > > @@ -2916,10 +2916,8 @@ static void __ftrace_trace_stack(struct 
> > > trace_buffer *buffer,
> > >        * Add one, for this function and the call to save_stack_trace()
> > >        * If regs is set, then these functions will not be in the way.
> > >        */
> > Hmm, with this change, the above comment should also be updated.
> >
> >
> > > -#ifndef CONFIG_UNWINDER_ORC
> > > -    if (!regs)
> > > +    if (IS_ENABLED(CONFIG_UNWINDER_ORC) || !regs)
> > >           skip++;
> > > -#endif
> > Also, this solves just one pattern (only enable function tracer) but if
> > there are fprobes (or kprobes) on the same function, it introduces 
> > another issue.
> > e.g. (with this fix)
> >
> > ------
> > echo 1 > options/func_stack_trace
> > echo 1 > options/stacktrace
> > echo "vfs_write" >> set_ftrace_filter
> > echo "function" > current_tracer
> > echo "f:myevent vfs_write" > dynamic_events
> > echo 1 > events/fprobes/myevent/enable
> > echo > /dev/null
> > cat trace
> > ...
> >                sh-140     [001] ...1.    18.352601: myevent: 
> > (vfs_write+0x4/0x560)
> >                sh-140     [001] ...1.    18.352602: <stack trace>
> >   => ksys_write
> >   => do_syscall_64
> >   => entry_SYSCALL_64_after_hwframe
> >                sh-140     [001] ...1.    18.352602: vfs_write 
> > <-ksys_write
> >                sh-140     [001] ...1.    18.352604: <stack trace>
> >   => ftrace_regs_call
> >   => vfs_write
> >   => ksys_write
> >   => do_syscall_64
> >   => entry_SYSCALL_64_after_hwframe
> > ------
> > As you can see, myevent skips "vfs_write".
> > (and function tracer still have ftrace_regs_call() )
>
> Thanks for the other tests. This issue may be function_trace_call() 
> specific problem.
Not function_trace_call(),  function_stack_trace_call().
> So I will change the place to increment skip number.
>
> > Thank you,
> >
> > >         preempt_disable_notrace();
> > >   --
> > > 2.46.1
> Thank you,