ftrace: entend notrace to notrace called functions
Subsystems (5)
Steven Rostedt
maintainercover ftrace: entend notrace to notrace called functions
On IRC, Thomas complained about the noise/signal ratio of useful traced functions. Although several functions have been disabled via notrace, these notrace functions tend to call other functions and they get traced. Often times they confuse the trace because its hard to know where these functions were called from.
Other times it is just that we really want to ignore functions that have been marked with notrace, and we also don't care about what functions they call.
The problem is that, unlike the function graph tracer, the function tracer does not have the ability to know when a function has returned. Knowing when a function has been called by a function marked as notrace is not trivial, as a lot of notrace functions are completely hidden to ftrace. Searching all functions to see if it is not marked notrace would slow things down even more than the function graph tracer.
The trick I used was to use the function graph tracer's ret_stack, to keep track of the call chain. By checking the parent against the call chain, we can mostly get what functions belong at what depth, and if a parent is not in the call chain, it may be a clue that the parent was a notrace function. There's other times that a parent may not be in the call chain (irqs, and top level calls), but most of the time, we can figure it out.
Note, things called from assembly are just like being called by a notrace function as assembly functions are not traced. For example do_page_fault() and preempt_schedule() are both called from assembly and can be skipped.
To enable this feature, just echo 1 into debug/tracing/options/extend-notrace
I also added a debug/tracing/options/extend-notrace-debug that inverses what gets traced (things that would be ignored by extend-notrace would be traced, and things that would be traced are not). This debug option is a way to see what functions may be ignored by extend-notrace.
This is just a RFC, and was something that I tried to quickly write up (although it took much longer than I wanted it too). As this was a feature request from Thomas who happened to be using ftrace currently as a real debug tool. And this would help him now.
But I'm leaving this as RFC for the time being and going back to working on RT stuff and other things. Maybe I may get some time on libperf!
-- Steve
git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-2.6-trace.git
rfc/trace
Head SHA1: 0011c1566f498e410787fa1173148513153ec443
Steven Rostedt (3):
ftrace: Make ret_stack usable by other than function graph
ftrace: Add extend-notrace to not trace sub funcs of notrace funcs
ftrace: Add extend-notrace-debug to see what is not traced
----
include/linux/ftrace.h | 38 ++++-- include/linux/sched.h | 16 ++- kernel/fork.c | 5 +- kernel/sched.c | 2 +- kernel/trace/ftrace.c | 281 +++++++++++++++++++++++----------------- kernel/trace/trace.c | 5 + kernel/trace/trace.h | 11 ++ kernel/trace/trace_functions.c | 163 +++++++++++++++++++++++- 8 files changed, 380 insertions(+), 141 deletions(-)
Steven Rostedt
maintainerRFC PATCH 1/3 ftrace: Make ret_stack usable by other than function graph
From: Steven Rostedt <[email protected]>
Move the ret_stack code out of the CONFIG_FUNCTION_GRAPH_TRACER macro section to enable it to be usable by other function tracers.
--- include/linux/ftrace.h | 17 ++-- include/linux/sched.h | 10 +- kernel/fork.c | 4 +- kernel/sched.c | 2 +- kernel/trace/ftrace.c | 278 +++++++++++++++++++++++++++--------------------- kernel/trace/trace.h | 6 + 6 files changed, 181 insertions(+), 136 deletions(-)
include/linux/ftrace.h +9 -8
@@ -99,6 +99,10 @@ void clear_ftrace_function(void);extern void ftrace_stub (unsigned long a0,unsigned long a1); +extern void ftrace_init_task (struct task_struct *t); +extern void ftrace_exit_task (struct task_struct *t); +extern void ftrace_init_idle_task (struct task_struct *t,int cpu); +#else /* !CONFIG_FUNCTION_TRACER */ /* * (un)register_ftrace_function must be a macro since the ops parameter
@@ -110,6 +114,11 @@ static inline void clear_ftrace_function(void) { }static inline void ftrace_kill (void ) { }static inline void ftrace_stop (void ) { }static inline void ftrace_start (void ) { } + +static inline void ftrace_init_task (struct task_struct *t) { } +static inline void ftrace_exit_task (struct task_struct *t) { } +static inline void ftrace_init_idle_task (struct task_struct *t,int cpu) { } +#endif /* CONFIG_FUNCTION_TRACER */ #ifdef CONFIG_STACK_TRACER
@@ -443,10 +452,6 @@ extern trace_func_graph_ent_t ftrace_graph_entry;extern void unregister_ftrace_graph (void ); -extern void ftrace_graph_init_task (struct task_struct *t); -extern void ftrace_graph_exit_task (struct task_struct *t); -extern void ftrace_graph_init_idle_task (struct task_struct *t,int cpu); -static inline int task_curr_ret_stack (struct task_struct *t) {return t->curr_ret_stack;
@@ -467,10 +472,6 @@ static inline void unpause_graph_tracing(void)#define __irq_entry#define INIT_FTRACE_GRAPH -static inline void ftrace_graph_init_task (struct task_struct *t) { } -static inline void ftrace_graph_exit_task (struct task_struct *t) { } -static inline void ftrace_graph_init_idle_task (struct task_struct *t,int cpu) { } -static inline int register_ftrace_graph (trace_func_graph_ret_t retfunc,trace_func_graph_ent_t entryfunc) {
include/linux/sched.h +6 -4
@@ -1530,10 +1530,6 @@ struct task_struct {struct list_head *scm_work_list;#ifdef CONFIG_FUNCTION_GRAPH_TRACER -/* Index of current stored address in ret_stack */ -int curr_ret_stack; -/* Stack of return addresses for return function tracing */ -struct ftrace_ret_stack *ret_stack;/* time stamp for last schedule */ unsigned long long ftrace_timestamp;/*
@@ -1544,6 +1540,12 @@ struct task_struct {/* Pause for the tracing */ atomic_t tracing_graph_pause;#endif +#ifdef CONFIG_FUNCTION_TRACER +/* Index of current stored address in ret_stack */ +int curr_ret_stack; +/* Stack of return addresses for return function tracing */ +struct ftrace_ret_stack *ret_stack; +#endif #ifdef CONFIG_TRACING /* state flags for use by tracers */ unsigned long trace;
kernel/fork.c +2 -2
@@ -167,7 +167,7 @@ void free_task(struct task_struct *tsk)account_kernel_stack (tsk->stack,-1 );free_thread_info (tsk->stack);rt_mutex_debug_task_free (tsk); -ftrace_graph_exit_task (tsk); +ftrace_exit_task (tsk);free_task_struct (tsk); }EXPORT_SYMBOL (free_task);
@@ -1095,7 +1095,7 @@ static struct task_struct *copy_process(unsigned long clone_flags,if (!p) goto fork_out; -ftrace_graph_init_task (p); +ftrace_init_task (p);rt_mutex_init_task (p);
kernel/sched.c +1 -1
@@ -5903,7 +5903,7 @@ void __cpuinit init_idle(struct task_struct *idle, int cpu)* The idle tasks have their own, simple scheduling class: */ idle->sched_class = &idle_sched_class; -ftrace_graph_init_idle_task (idle, cpu); +ftrace_init_idle_task (idle, cpu); }/*
kernel/trace/ftrace.c +157 -121
332 lines not on this page · raw message
kernel/trace/trace.h +6 -0
@@ -537,11 +537,17 @@ static inline int ftrace_trace_task(struct task_struct *task) return test_tsk_trace_trace(task); } + +int trace_ret_stack_enable (void ); +void trace_ret_stack_disable (void ); +#else static inline int ftrace_trace_task (struct task_struct *task) {return 1 ; } +static inline int trace_ret_stack_enable (void ) {return -ENODEV ; } +static inline void trace_ret_stack_disable (void ) { }#endif /*
Signature · 1 line
1.7.5.4
Steven Rostedt
maintainerRFC PATCH 2/3 ftrace: Add extend-notrace to not trace sub funcs of notrace funcs
In reply to Steven RostedtFrom: Steven Rostedt <[email protected]>
When debugging the kernel with the function tracer, the trace can trace lots of "noise" functions. That is functions that you do not care about tracing but end up filling the ring buffer and perhaps even causing you to lose what you wanted to trace. The set_ftrace_notrace as well as denoting specific functions in the kernel with 'notrace' is useful to keep these functions down. But sometimes they call functions that you do not want to trace when a notrace function calls them. For this the trace option 'extend-notrace' has been added.
Because the function tracer only records the entering of the function and function graph tracing may be too slow to trace what is needed, being able to recognise notrace functions is a complex problem as there's no good way to know when a function has returned. But to do a "best effort" in this the following is done.
The extend-notrace option uses the function_graph ret_stack to record a call chain to each function. As the function tracer callbacks receive the instruction pointer of both the traced function and the parent that called that function, we can use the parent to help figure out if the function was called by a notrace function or not. If the parent function is in the ret_stack then we know that this function can be traced. If it is not, then it is a candidate to not be traced.
When the parent is not in the ret_stack, care must be taken to know if the current function should be ignored or not. Along with the call chain, the irq context is also recorded. If the last traced function was not in irq context and the current traced function is, then we trace this function.
If nothing is in the ret_stack than we just trace that as well. But because we never know when this top function has exited, we have to have other tricks to find out when we are at the top again.
One is to check the current stack (by referencing the address of a local variable). If it is less than the current top function's stack, then we declare this function as the new top pointer.
Or, if it is greater than 64 words of the kernel stack, then it is assumed to be a sys_call and we start tracing that as the top function as well.
Known issues: Things that are called from assembly are also not traced. That is because assembly is just like a "notrace" statement. This includes do_page_fault() as that is called from a trap, as well as preempt_schedule() which may be called from returning from an interrupt.
--- include/linux/ftrace.h | 21 +++++- include/linux/sched.h | 6 ++ kernel/fork.c | 1 - kernel/trace/ftrace.c | 3 + kernel/trace/trace.c | 4 + kernel/trace/trace.h | 4 + kernel/trace/trace_functions.c | 152 +++++++++++++++++++++++++++++++++++++++- 7 files changed, 186 insertions(+), 5 deletions(-)
include/linux/ftrace.h +19 -2
@@ -406,8 +406,25 @@ typedef int (*trace_func_graph_ent_t)(struct ftrace_graph_ent *); /* entry */struct ftrace_ret_stack {unsigned long ret;unsigned long func; -unsigned long long calltime; -unsigned long long subtime; +/* +* Function graph and function extend notrace +* share this structure. The ret and func above are +* sensitive to function graph and modifying them could +* cause a kernel panic. The calltime and subtime are +* just used for reporting. When function extend notrace +* is active, function graph can not be active, so these +* numbers are ignored anyway. If not, the worse that can +* happen is that we get funny numbers in the output trace, but +* this should never happen. +*/ +union { +unsigned long long calltime; +unsigned long start_ip; + }; +union { +unsigned long long subtime; +unsigned long end_ip; + };unsigned long fp; };
include/linux/sched.h +6 -0
@@ -1543,6 +1543,12 @@ struct task_struct {#ifdef CONFIG_FUNCTION_TRACER /* Index of current stored address in ret_stack */ int curr_ret_stack; +/* +* Index of current stored address in ret_stack. +* Must be separate from function graph curr_ret_stack. +*/ +int curr_trace_stack; +unsigned long trace_start_stack;/* Stack of return addresses for return function tracing */ struct ftrace_ret_stack *ret_stack;#endif
kernel/fork.c +0 -1
@@ -1199,7 +1199,6 @@ static struct task_struct *copy_process(unsigned long clone_flags, p->curr_chain_key =0 ; p->lockdep_recursion =0 ;#endif -#ifdef CONFIG_DEBUG_MUTEXES p->blocked_on =NULL ;/* not blocked yet */ #endif
kernel/trace/ftrace.c +3 -0
@@ -3919,6 +3919,7 @@ trace_init_task(struct task_struct *t, struct ftrace_ret_stack *ret_stack)void ftrace_init_idle_task (struct task_struct *t,int cpu) { t->curr_ret_stack =-1 ; + t->trace_start_stack =0 ;/* * The idle task has no parent, it either has its own * stack or no stack at all.
@@ -3954,6 +3955,7 @@ void ftrace_init_task(struct task_struct *t)/* Make sure we do not use the parent ret_stack */ t->ret_stack =NULL ; t->curr_ret_stack =-1 ; + t->trace_start_stack =0 ;if (ret_stack_active) {struct ftrace_ret_stack *ret_stack;
@@ -4008,6 +4010,7 @@ static int alloc_retstack_tasklist(struct ftrace_ret_stack **ret_stack_list)if (t->ret_stack ==NULL ) { t->curr_ret_stack =-1 ; + t->trace_start_stack =0 ;trace_init_task (t, ret_stack_list[start++]); } }while_each_thread (g, t);
kernel/trace/trace.c +4 -0
@@ -424,6 +424,7 @@ static const char *trace_options[] = {"graph-time" ,"record-cmd" ,"overwrite" , +"extend-notrace" , NULL };
@@ -2540,6 +2541,9 @@ static void set_tracer_flags(unsigned int mask, int enabled)if (mask ==TRACE_ITER_OVERWRITE )ring_buffer_change_overwrite (global_trace.buffer, enabled); + +if (mask ==TRACE_ITER_EXTEND_NOTRACE ) +trace_extend_notrace (enabled); } static ssize_t
kernel/trace/trace.h +4 -0
@@ -540,6 +540,7 @@ static inline int ftrace_trace_task(struct task_struct *task)int trace_ret_stack_enable (void );void trace_ret_stack_disable (void ); +void trace_extend_notrace (int enabled);#else static inline int ftrace_trace_task (struct task_struct *task)
@@ -548,6 +549,7 @@ static inline int ftrace_trace_task(struct task_struct *task) }static inline int trace_ret_stack_enable (void ) {return -ENODEV ; }static inline void trace_ret_stack_disable (void ) { } +static inline void trace_extend_notrace (int enabled) { }#endif /*
@@ -615,6 +617,7 @@ enum trace_iterator_flags {TRACE_ITER_GRAPH_TIME =0x80000 ,TRACE_ITER_RECORD_CMD =0x100000 ,TRACE_ITER_OVERWRITE =0x200000 , + TRACE_ITER_EXTEND_NOTRACE = 0x400000, };/*
@@ -800,6 +803,7 @@ extern const char *__stop___trace_bprintk_fmt[];/* for function tracing recursion */ #define TRACE_INTERNAL_BIT (1<<11)#define TRACE_GLOBAL_BIT (1<<12) +#define TRACE_IN_IRQ (1<<13)#define trace_recursion_set (bit) do { (current)->trace_recursion |= (bit); } while (0)#define trace_recursion_clear (bit) do { (current)->trace_recursion &= ~(bit); } while (0)
kernel/trace/trace_functions.c +150 -2
182 lines not on this page · raw message
Signature · 1 line
1.7.5.4
Peter Zijlstra
maintainerRe: [RFC][PATCH 2/3] ftrace: Add extend-notrace to not trace sub funcs of notrace funcs
Quoted 1 line · Steven Rostedt
Known issues: Things that are called from assembly are also not traced.
We could of course create a gasm CALL macro that adds the mcount hookery and use that for those functions.
/me runs
Steven Rostedt
maintainerRe: [RFC][PATCH 2/3] ftrace: Add extend-notrace to not trace sub funcs of notrace funcs
Quoted 5 lines · Peter Zijlstra
Quoted 1 line · Steven Rostedt
Known issues: Things that are called from assembly are also not traced.
We could of course create a gasm CALL macro that adds the mcount hookery and use that for those functions.
Hmm, that wouldn't be too hard to do. I'll go write up some patches.
Quoted 2 lines
/me runs
/me chases
Steven Rostedt
maintainerRFC PATCH 3/3 ftrace: Add extend-notrace-debug to see what is not traced
In reply to Steven RostedtFrom: Steven Rostedt <[email protected]>
Enabling extend-notrace causes functions not to be traced if it is determined that its calling function is not traced. To be able to debug this, the option extend-notrace-debug is added. It only takes affect when extend-notrace is enabled.
When extend-notrace-debug is enabled, the functions traced when extend-notrace is enabled is only the functions that would have not been traced. In other words, extend-notrace-debug causes extend-notrace to do the inverse of what it usually does. This allows the user to see what functions may be missing when they enable extend-notrace.
It does not enable "notrace" functions themselves. It only traces the functions that would have normally been traced if extend-notrace was not enabled, but were skipped because of extend-notrace.
--- kernel/trace/trace.c | 1 + kernel/trace/trace.h | 1 + kernel/trace/trace_functions.c | 21 ++++++++++++++++----- 3 files changed, 18 insertions(+), 5 deletions(-)
kernel/trace/trace.c +1 -0
@@ -425,6 +425,7 @@ static const char *trace_options[] = {"record-cmd" ,"overwrite" ,"extend-notrace" , +"extend-notrace-debug" , NULL };
kernel/trace/trace.h +1 -0
@@ -618,6 +618,7 @@ enum trace_iterator_flags {TRACE_ITER_RECORD_CMD =0x100000 ,TRACE_ITER_OVERWRITE =0x200000 ,TRACE_ITER_EXTEND_NOTRACE =0x400000 , + TRACE_ITER_DEBUG_EXTEND_NOTRACE = 0x800000, };/*
kernel/trace/trace_functions.c +16 -5
@@ -70,7 +70,7 @@ void trace_extend_notrace(int enable)/* 64 words depth to reset stack */ #define STACK_OFFSET (THREAD_SIZE - (64 * BITS_PER_LONG/8)) -static inline int skip_notrace (unsigned long ip,unsigned long parent_ip) +static int __skip_notrace (unsigned long ip,unsigned long parent_ip) {unsigned long offset;unsigned long size;
@@ -79,10 +79,6 @@ static inline int skip_notrace(unsigned long ip, unsigned long parent_ip)int curr_ret;int i; -/* Optimize for this case to be off */ -if (likely (!(trace_flags &TRACE_ITER_EXTEND_NOTRACE ))) -return 0 ; -/* * We always trace NMIs, and do not update anything. * This code requires interrupts disabled.
@@ -189,6 +185,21 @@ static inline int skip_notrace(unsigned long ip, unsigned long parent_ip)return 0 ; } +static inline int skip_notrace (unsigned long ip,unsigned long parent_ip) +{ +int ret; + +/* Optimize for this case to be off */ +if (likely (!(trace_flags &TRACE_ITER_EXTEND_NOTRACE ))) +return 0 ; + + ret =__skip_notrace (ip, parent_ip); + +if (trace_flags &TRACE_ITER_DEBUG_EXTEND_NOTRACE ) +return !ret; +return ret; +} +static void function_trace_call_preempt_only (unsigned long ip,unsigned long parent_ip) {
Signature · 1 line
1.7.5.4