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

[ts <tatsuya.s2862@gmail.com>]

On 9/30/24 8:51 AM, Masami Hiramatsu (Google) wrote:
> On Thu, 26 Sep 2024 15:13:07 +0900
> Tatsuya S<tatsuya.s2862@gmail.com> 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@gmail.com>
>> ---
>>   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.

So I will change the place to increment skip number.

> Thank you,
>
>>   
>>   	preempt_disable_notrace();
>>   
>> -- 
>> 2.46.1
>>
Thank you,