[RFC PATCH] ftrace: Fix depth filtering when func_stack is enabled.

[RFC PATCH] ftrace: Fix depth filtering when func_stack is enabled.

[Nikolay Borisov]

The initial implementation of stack tracing to function trace in
536149910130 ("ftrace: add stack trace to function tracer") required
5 call stack entries to be skipped to avoid polluting the resulting
stacks with ftrace functions. Commit 4104d326b670 ("ftrace: Remove
global function list and call function directly") removed some of
these. Additionally be54f69c2619 ("tracing: Skip more functions when
doing stack tracing of events") also added some logic to adjust the
filtering.

The end result of all this shuffling of code is that the magic number
5 in function_stack_trace_call no longer corresponds to reality. This
results in skipping more than we would like. For example without the
this patch tracing vfs_open produces:

trace-cmd stream -p function -l vfs_open --func-stack

<...>-488   [003]    11.356514: function:             vfs_open
<...>-488   [003]    11.356516: kernel_stack:         <stack trace>
=> do_sys_open (ffffffff811a64b7)
=> SyS_open (ffffffff811a65ae)
=> entry_SYSCALL_64_fastpath (ffffffff8180009b)

Where as the correct stack trace should be :

=> vfs_open (ffffffff811a6085)
=> path_openat (ffffffff811b71af)
=> do_filp_open (ffffffff811b8a8a)
=> do_sys_open (ffffffff811a64a7)
=> SyS_open (ffffffff811a659e)
=> entry_SYSCALL_64_fastpath (ffffffff8180009b)

Signed-off-by: Nikolay Borisov <nborisov@suse.com>
---

Strange why __trace_stack and __ftrace_trace_stack are not part of the stack 
and don't need to be filtered, despite not being inlined: 

nm vmlinux | grep save_stack_trace_regs
ffffffff81026fd0 T save_stack_trace_regs

nm vmlinux | grep __save_stack_trace
ffffffff81026e20 t __save_stack_trace

 kernel/trace/trace_functions.c | 7 ++-----
 1 file changed, 2 insertions(+), 5 deletions(-)

diff --git a/kernel/trace/trace_functions.c b/kernel/trace/trace_functions.c
index 27f7ad12c4b1..b721f1f3f3c0 100644
--- a/kernel/trace/trace_functions.c
+++ b/kernel/trace/trace_functions.c
@@ -181,14 +181,11 @@ function_stack_trace_call(unsigned long ip, unsigned long parent_ip,
 		pc = preempt_count();
 		trace_function(tr, ip, parent_ip, flags, pc);
 		/*
-		 * skip over 5 funcs:
-		 *    __ftrace_trace_stack,
-		 *    __trace_stack,
+		 * skip over 2 funcs:
 		 *    function_stack_trace_call
-		 *    ftrace_list_func
 		 *    ftrace_call
 		 */
-		__trace_stack(tr, flags, 5, pc);
+		__trace_stack(tr, flags, 2, pc);
 	}
 
 	atomic_dec(&data->disabled);
-- 
2.7.4

Re: [RFC PATCH] ftrace: Fix depth filtering when func_stack is enabled.

[Steven Rostedt]

On Mon, 22 Jan 2018 15:50:04 +0200
Nikolay Borisov <nborisov@suse.com> wrote:


> diff --git a/kernel/trace/trace_functions.c b/kernel/trace/trace_functions.c
> index 27f7ad12c4b1..b721f1f3f3c0 100644
> --- a/kernel/trace/trace_functions.c
> +++ b/kernel/trace/trace_functions.c
> @@ -181,14 +181,11 @@ function_stack_trace_call(unsigned long ip, unsigned long parent_ip,
>  		pc = preempt_count();
>  		trace_function(tr, ip, parent_ip, flags, pc);
>  		/*
> -		 * skip over 5 funcs:
> -		 *    __ftrace_trace_stack,
> -		 *    __trace_stack,
> +		 * skip over 2 funcs:
>  		 *    function_stack_trace_call
> -		 *    ftrace_list_func

Thanks, but this breaks when you are not using ORC unwinder.

>  		 *    ftrace_call
>  		 */
> -		__trace_stack(tr, flags, 5, pc);
> +		__trace_stack(tr, flags, 2, pc);
>  	}
>  
>  	atomic_dec(&data->disabled);


There's a bit of ORC unwinder breakage that I'm still dealing with. I
also have patches to handle the differences between ORC and FP, in the
__trace_stack() usages. I'm hoping to have this all fixed by tomorrow,
as I'll be traveling after that.

Thanks!

-- Steve

Re: [RFC PATCH] ftrace: Fix depth filtering when func_stack is enabled.

[Nikolay Borisov]

On 23.01.2018 01:16, Steven Rostedt wrote:
> On Mon, 22 Jan 2018 15:50:04 +0200
> Nikolay Borisov <nborisov@suse.com> wrote:
> 
> 
>> diff --git a/kernel/trace/trace_functions.c b/kernel/trace/trace_functions.c
>> index 27f7ad12c4b1..b721f1f3f3c0 100644
>> --- a/kernel/trace/trace_functions.c
>> +++ b/kernel/trace/trace_functions.c
>> @@ -181,14 +181,11 @@ function_stack_trace_call(unsigned long ip, unsigned long parent_ip,
>>  		pc = preempt_count();
>>  		trace_function(tr, ip, parent_ip, flags, pc);
>>  		/*
>> -		 * skip over 5 funcs:
>> -		 *    __ftrace_trace_stack,
>> -		 *    __trace_stack,
>> +		 * skip over 2 funcs:
>>  		 *    function_stack_trace_call
>> -		 *    ftrace_list_func
> 
> Thanks, but this breaks when you are not using ORC unwinder.

Actually I've tested this with the frame_pointer unwinder, I haven't got
ORC to work at all. So this patch fixes the issue where the FP unwinder
prints out shorter stacktraces than required.

> 
>>  		 *    ftrace_call
>>  		 */
>> -		__trace_stack(tr, flags, 5, pc);
>> +		__trace_stack(tr, flags, 2, pc);
>>  	}
>>  
>>  	atomic_dec(&data->disabled);
> 
> 
> There's a bit of ORC unwinder breakage that I'm still dealing with. I
> also have patches to handle the differences between ORC and FP, in the
> __trace_stack() usages. I'm hoping to have this all fixed by tomorrow,
> as I'll be traveling after that.

Great, please CC me on the patches so that I can test them.

> 
> Thanks!
> 
> -- Steve
> 
>