* [PATCH][GIT PULL] ftrace: Add function names to dangling } in function graph tracer
@ 2010-02-27 0:27 Steven Rostedt
2010-02-27 9:43 ` Ingo Molnar
2010-02-27 10:02 ` Frederic Weisbecker
0 siblings, 2 replies; 7+ messages in thread
From: Steven Rostedt @ 2010-02-27 0:27 UTC (permalink / raw)
To: LKML; +Cc: Ingo Molnar, Frederic Weisbecker, Tim Bird
Ingo,
Please pull the latest tip/tracing/core tree, which can be found at:
git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-2.6-trace.git
tip/tracing/core
Steven Rostedt (1):
ftrace: Add function names to dangling } in function graph tracer
----
kernel/trace/trace_functions_graph.c | 52 ++++++++++++++++++++++++++++------
1 files changed, 43 insertions(+), 9 deletions(-)
---------------------------
commit f1c7f517a5dc23bce07efa5ed55e2c074ed9d4ba
Author: Steven Rostedt <srostedt@redhat.com>
Date: Fri Feb 26 17:08:16 2010 -0500
ftrace: Add function names to dangling } in function graph tracer
The function graph tracer is currently the most invasive tracer
in the ftrace family. It can easily overflow the buffer even with
10megs per CPU. This means that events can often be lost.
On start up, or after events are lost, if the function return is
recorded but the function enter was lost, all we get to see is the
exiting '}'.
Here is how a typical trace output starts:
[tracing] cat trace
# tracer: function_graph
#
# CPU DURATION FUNCTION CALLS
# | | | | | | |
0) + 91.897 us | }
0) ! 567.961 us | }
0) <========== |
0) ! 579.083 us | _raw_spin_lock_irqsave();
0) 4.694 us | _raw_spin_unlock_irqrestore();
0) ! 594.862 us | }
0) ! 603.361 us | }
0) ! 613.574 us | }
0) ! 623.554 us | }
0) 3.653 us | fget_light();
0) | sock_poll() {
There are a series of '}' with no matching "func() {". There's no information
to what functions these ending brackets belong to.
This patch adds a stack on the per cpu structure used in outputting
the function graph tracer to keep track of what function was outputted.
Then on a function exit event, it checks the depth to see if the
function exit has a matching entry event. If it does, then it only
prints the '}', otherwise it adds the function name after the '}'.
This allows function exit events to show what function they belong to
at trace output startup, when the entry was lost due to ring buffer
overflow, or even after a new task is scheduled in.
Here is what the above trace will look like after this patch:
[tracing] cat trace
# tracer: function_graph
#
# CPU DURATION FUNCTION CALLS
# | | | | | | |
0) + 91.897 us | } (irq_exit)
0) ! 567.961 us | } (smp_apic_timer_interrupt)
0) <========== |
0) ! 579.083 us | _raw_spin_lock_irqsave();
0) 4.694 us | _raw_spin_unlock_irqrestore();
0) ! 594.862 us | } (add_wait_queue)
0) ! 603.361 us | } (__pollwait)
0) ! 613.574 us | } (tcp_poll)
0) ! 623.554 us | } (sock_poll)
0) 3.653 us | fget_light();
0) | sock_poll() {
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index 112561d..e998a82 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -18,6 +18,7 @@ struct fgraph_cpu_data {
pid_t last_pid;
int depth;
int ignore;
+ unsigned long enter_funcs[FTRACE_RETFUNC_DEPTH];
};
struct fgraph_data {
@@ -670,15 +671,21 @@ print_graph_entry_leaf(struct trace_iterator *iter,
duration = graph_ret->rettime - graph_ret->calltime;
if (data) {
+ struct fgraph_cpu_data *cpu_data;
int cpu = iter->cpu;
- int *depth = &(per_cpu_ptr(data->cpu_data, cpu)->depth);
+
+ cpu_data = per_cpu_ptr(data->cpu_data, cpu);
/*
* Comments display at + 1 to depth. Since
* this is a leaf function, keep the comments
* equal to this depth.
*/
- *depth = call->depth - 1;
+ cpu_data->depth = call->depth - 1;
+
+ /* No need to keep this function around for this depth */
+ if (call->depth < FTRACE_RETFUNC_DEPTH)
+ cpu_data->enter_funcs[call->depth] = 0;
}
/* Overhead */
@@ -718,10 +725,15 @@ print_graph_entry_nested(struct trace_iterator *iter,
int i;
if (data) {
+ struct fgraph_cpu_data *cpu_data;
int cpu = iter->cpu;
- int *depth = &(per_cpu_ptr(data->cpu_data, cpu)->depth);
- *depth = call->depth;
+ cpu_data = per_cpu_ptr(data->cpu_data, cpu);
+ cpu_data->depth = call->depth;
+
+ /* Save this function pointer to see if the exit matches */
+ if (call->depth < FTRACE_RETFUNC_DEPTH)
+ cpu_data->enter_funcs[call->depth] = call->func;
}
/* No overhead */
@@ -851,18 +863,28 @@ print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s,
struct fgraph_data *data = iter->private;
pid_t pid = ent->pid;
int cpu = iter->cpu;
+ int func_match = 1;
int ret;
int i;
if (data) {
- int *depth = &(per_cpu_ptr(data->cpu_data, cpu)->depth);
+ struct fgraph_cpu_data *cpu_data;
+ int cpu = iter->cpu;
+
+ cpu_data = per_cpu_ptr(data->cpu_data, cpu);
/*
* Comments display at + 1 to depth. This is the
* return from a function, we now want the comments
* to display at the same level of the bracket.
*/
- *depth = trace->depth - 1;
+ cpu_data->depth = trace->depth - 1;
+
+ if (trace->depth < FTRACE_RETFUNC_DEPTH) {
+ if (cpu_data->enter_funcs[trace->depth] != trace->func)
+ func_match = 0;
+ cpu_data->enter_funcs[trace->depth] = 0;
+ }
}
if (print_graph_prologue(iter, s, 0, 0))
@@ -887,9 +909,21 @@ print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s,
return TRACE_TYPE_PARTIAL_LINE;
}
- ret = trace_seq_printf(s, "}\n");
- if (!ret)
- return TRACE_TYPE_PARTIAL_LINE;
+ /*
+ * If the return function does not have a matching entry,
+ * then the entry was lost. Instead of just printing
+ * the '}' and letting the user guess what function this
+ * belongs to, write out the function name.
+ */
+ if (func_match) {
+ ret = trace_seq_printf(s, "}\n");
+ if (!ret)
+ return TRACE_TYPE_PARTIAL_LINE;
+ } else {
+ ret = trace_seq_printf(s, "} (%ps)\n", (void *)trace->func);
+ if (!ret)
+ return TRACE_TYPE_PARTIAL_LINE;
+ }
/* Overrun */
if (tracer_flags.val & TRACE_GRAPH_PRINT_OVERRUN) {
^ permalink raw reply related [flat|nested] 7+ messages in thread* Re: [PATCH][GIT PULL] ftrace: Add function names to dangling } in function graph tracer
2010-02-27 0:27 [PATCH][GIT PULL] ftrace: Add function names to dangling } in function graph tracer Steven Rostedt
@ 2010-02-27 9:43 ` Ingo Molnar
2010-02-27 10:04 ` Frederic Weisbecker
2010-02-27 19:19 ` Steven Rostedt
2010-02-27 10:02 ` Frederic Weisbecker
1 sibling, 2 replies; 7+ messages in thread
From: Ingo Molnar @ 2010-02-27 9:43 UTC (permalink / raw)
To: Steven Rostedt; +Cc: LKML, Frederic Weisbecker, Tim Bird
* Steven Rostedt <rostedt@goodmis.org> wrote:
>
> Ingo,
>
> Please pull the latest tip/tracing/core tree, which can be found at:
>
> git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-2.6-trace.git
> tip/tracing/core
>
>
> Steven Rostedt (1):
> ftrace: Add function names to dangling } in function graph tracer
>
> ----
> kernel/trace/trace_functions_graph.c | 52 ++++++++++++++++++++++++++++------
> 1 files changed, 43 insertions(+), 9 deletions(-)
Pulled, thanks Steve!
> [tracing] cat trace
> # tracer: function_graph
> #
> # CPU DURATION FUNCTION CALLS
> # | | | | | | |
> 0) + 91.897 us | } (irq_exit)
> 0) ! 567.961 us | } (smp_apic_timer_interrupt)
> 0) <========== |
> 0) ! 579.083 us | _raw_spin_lock_irqsave();
> 0) 4.694 us | _raw_spin_unlock_irqrestore();
> 0) ! 594.862 us | } (add_wait_queue)
> 0) ! 603.361 us | } (__pollwait)
> 0) ! 613.574 us | } (tcp_poll)
> 0) ! 623.554 us | } (sock_poll)
> 0) 3.653 us | fget_light();
> 0) | sock_poll() {
Neat! I think it would read even more C-ish if it was something non-syntactic,
like:
> 0) ! 594.862 us | } /* add_wait_queue */
> 0) ! 603.361 us | } /* __pollwait */
> 0) ! 613.574 us | } /* tcp_poll */
> 0) ! 623.554 us | } /* sock_poll */
hm?
Ingo
^ permalink raw reply [flat|nested] 7+ messages in thread* Re: [PATCH][GIT PULL] ftrace: Add function names to dangling } in function graph tracer
2010-02-27 9:43 ` Ingo Molnar
@ 2010-02-27 10:04 ` Frederic Weisbecker
2010-02-27 19:19 ` Steven Rostedt
1 sibling, 0 replies; 7+ messages in thread
From: Frederic Weisbecker @ 2010-02-27 10:04 UTC (permalink / raw)
To: Ingo Molnar; +Cc: Steven Rostedt, LKML, Tim Bird
On Sat, Feb 27, 2010 at 10:43:01AM +0100, Ingo Molnar wrote:
> > [tracing] cat trace
> > # tracer: function_graph
> > #
> > # CPU DURATION FUNCTION CALLS
> > # | | | | | | |
> > 0) + 91.897 us | } (irq_exit)
> > 0) ! 567.961 us | } (smp_apic_timer_interrupt)
> > 0) <========== |
> > 0) ! 579.083 us | _raw_spin_lock_irqsave();
> > 0) 4.694 us | _raw_spin_unlock_irqrestore();
> > 0) ! 594.862 us | } (add_wait_queue)
> > 0) ! 603.361 us | } (__pollwait)
> > 0) ! 613.574 us | } (tcp_poll)
> > 0) ! 623.554 us | } (sock_poll)
> > 0) 3.653 us | fget_light();
> > 0) | sock_poll() {
>
> Neat! I think it would read even more C-ish if it was something non-syntactic,
> like:
>
> > 0) ! 594.862 us | } /* add_wait_queue */
> > 0) ! 603.361 us | } /* __pollwait */
> > 0) ! 613.574 us | } /* tcp_poll */
> > 0) ! 623.554 us | } /* sock_poll */
>
> hm?
Agreed. It won't even be confusing with other events that are
printed as comments, since we have the closing brace before.
>
> Ingo
^ permalink raw reply [flat|nested] 7+ messages in thread* Re: [PATCH][GIT PULL] ftrace: Add function names to dangling } in function graph tracer
2010-02-27 9:43 ` Ingo Molnar
2010-02-27 10:04 ` Frederic Weisbecker
@ 2010-02-27 19:19 ` Steven Rostedt
1 sibling, 0 replies; 7+ messages in thread
From: Steven Rostedt @ 2010-02-27 19:19 UTC (permalink / raw)
To: Ingo Molnar; +Cc: LKML, Frederic Weisbecker, Tim Bird
On Sat, 2010-02-27 at 10:43 +0100, Ingo Molnar wrote:
> * Steven Rostedt <rostedt@goodmis.org> wrote:
>
>
> Neat! I think it would read even more C-ish if it was something non-syntactic,
> like:
>
> > 0) ! 594.862 us | } /* add_wait_queue */
> > 0) ! 603.361 us | } /* __pollwait */
> > 0) ! 613.574 us | } /* tcp_poll */
> > 0) ! 623.554 us | } /* sock_poll */
>
Yeah, that looks better. I'll write up a patch when I get a chance.
Thanks,
-- Steve
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: [PATCH][GIT PULL] ftrace: Add function names to dangling } in function graph tracer
2010-02-27 0:27 [PATCH][GIT PULL] ftrace: Add function names to dangling } in function graph tracer Steven Rostedt
2010-02-27 9:43 ` Ingo Molnar
@ 2010-02-27 10:02 ` Frederic Weisbecker
2010-02-27 19:25 ` Steven Rostedt
1 sibling, 1 reply; 7+ messages in thread
From: Frederic Weisbecker @ 2010-02-27 10:02 UTC (permalink / raw)
To: Steven Rostedt; +Cc: LKML, Ingo Molnar, Tim Bird
On Fri, Feb 26, 2010 at 07:27:19PM -0500, Steven Rostedt wrote:
> commit f1c7f517a5dc23bce07efa5ed55e2c074ed9d4ba
> Author: Steven Rostedt <srostedt@redhat.com>
> Date: Fri Feb 26 17:08:16 2010 -0500
>
> ftrace: Add function names to dangling } in function graph tracer
>
> The function graph tracer is currently the most invasive tracer
> in the ftrace family. It can easily overflow the buffer even with
> 10megs per CPU. This means that events can often be lost.
>
> On start up, or after events are lost, if the function return is
> recorded but the function enter was lost, all we get to see is the
> exiting '}'.
>
> Here is how a typical trace output starts:
>
> [tracing] cat trace
> # tracer: function_graph
> #
> # CPU DURATION FUNCTION CALLS
> # | | | | | | |
> 0) + 91.897 us | }
> 0) ! 567.961 us | }
> 0) <========== |
> 0) ! 579.083 us | _raw_spin_lock_irqsave();
> 0) 4.694 us | _raw_spin_unlock_irqrestore();
> 0) ! 594.862 us | }
> 0) ! 603.361 us | }
> 0) ! 613.574 us | }
> 0) ! 623.554 us | }
> 0) 3.653 us | fget_light();
> 0) | sock_poll() {
>
> There are a series of '}' with no matching "func() {". There's no information
> to what functions these ending brackets belong to.
>
> This patch adds a stack on the per cpu structure used in outputting
> the function graph tracer to keep track of what function was outputted.
> Then on a function exit event, it checks the depth to see if the
> function exit has a matching entry event. If it does, then it only
> prints the '}', otherwise it adds the function name after the '}'.
>
> This allows function exit events to show what function they belong to
> at trace output startup, when the entry was lost due to ring buffer
> overflow, or even after a new task is scheduled in.
>
> Here is what the above trace will look like after this patch:
>
> [tracing] cat trace
> # tracer: function_graph
> #
> # CPU DURATION FUNCTION CALLS
> # | | | | | | |
> 0) + 91.897 us | } (irq_exit)
> 0) ! 567.961 us | } (smp_apic_timer_interrupt)
> 0) <========== |
> 0) ! 579.083 us | _raw_spin_lock_irqsave();
> 0) 4.694 us | _raw_spin_unlock_irqrestore();
> 0) ! 594.862 us | } (add_wait_queue)
> 0) ! 603.361 us | } (__pollwait)
> 0) ! 613.574 us | } (tcp_poll)
> 0) ! 623.554 us | } (sock_poll)
> 0) 3.653 us | fget_light();
> 0) | sock_poll() {
That's a good idea.
>
> Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
>
> diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
> index 112561d..e998a82 100644
> --- a/kernel/trace/trace_functions_graph.c
> +++ b/kernel/trace/trace_functions_graph.c
> @@ -18,6 +18,7 @@ struct fgraph_cpu_data {
> pid_t last_pid;
> int depth;
> int ignore;
> + unsigned long enter_funcs[FTRACE_RETFUNC_DEPTH];
> };
>
> struct fgraph_data {
> @@ -670,15 +671,21 @@ print_graph_entry_leaf(struct trace_iterator *iter,
> duration = graph_ret->rettime - graph_ret->calltime;
>
> if (data) {
> + struct fgraph_cpu_data *cpu_data;
> int cpu = iter->cpu;
> - int *depth = &(per_cpu_ptr(data->cpu_data, cpu)->depth);
> +
> + cpu_data = per_cpu_ptr(data->cpu_data, cpu);
>
> /*
> * Comments display at + 1 to depth. Since
> * this is a leaf function, keep the comments
> * equal to this depth.
> */
> - *depth = call->depth - 1;
> + cpu_data->depth = call->depth - 1;
> +
> + /* No need to keep this function around for this depth */
> + if (call->depth < FTRACE_RETFUNC_DEPTH)
Do you really need to check that? call->depth >= FTRACE_RETFUNC_DEPTH
are not recorded.
> + cpu_data->enter_funcs[call->depth] = 0;
> }
>
> /* Overhead */
> @@ -718,10 +725,15 @@ print_graph_entry_nested(struct trace_iterator *iter,
> int i;
>
> if (data) {
> + struct fgraph_cpu_data *cpu_data;
> int cpu = iter->cpu;
> - int *depth = &(per_cpu_ptr(data->cpu_data, cpu)->depth);
>
> - *depth = call->depth;
> + cpu_data = per_cpu_ptr(data->cpu_data, cpu);
> + cpu_data->depth = call->depth;
> +
> + /* Save this function pointer to see if the exit matches */
> + if (call->depth < FTRACE_RETFUNC_DEPTH)
> + cpu_data->enter_funcs[call->depth] = call->func;
> }
>
> /* No overhead */
> @@ -851,18 +863,28 @@ print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s,
> struct fgraph_data *data = iter->private;
> pid_t pid = ent->pid;
> int cpu = iter->cpu;
> + int func_match = 1;
> int ret;
> int i;
>
> if (data) {
> - int *depth = &(per_cpu_ptr(data->cpu_data, cpu)->depth);
> + struct fgraph_cpu_data *cpu_data;
> + int cpu = iter->cpu;
> +
> + cpu_data = per_cpu_ptr(data->cpu_data, cpu);
>
> /*
> * Comments display at + 1 to depth. This is the
> * return from a function, we now want the comments
> * to display at the same level of the bracket.
> */
> - *depth = trace->depth - 1;
> + cpu_data->depth = trace->depth - 1;
> +
> + if (trace->depth < FTRACE_RETFUNC_DEPTH) {
> + if (cpu_data->enter_funcs[trace->depth] != trace->func)
> + func_match = 0;
> + cpu_data->enter_funcs[trace->depth] = 0;
> + }
> }
>
> if (print_graph_prologue(iter, s, 0, 0))
> @@ -887,9 +909,21 @@ print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s,
> return TRACE_TYPE_PARTIAL_LINE;
> }
>
> - ret = trace_seq_printf(s, "}\n");
> - if (!ret)
> - return TRACE_TYPE_PARTIAL_LINE;
> + /*
> + * If the return function does not have a matching entry,
> + * then the entry was lost. Instead of just printing
> + * the '}' and letting the user guess what function this
> + * belongs to, write out the function name.
> + */
> + if (func_match) {
> + ret = trace_seq_printf(s, "}\n");
> + if (!ret)
> + return TRACE_TYPE_PARTIAL_LINE;
> + } else {
> + ret = trace_seq_printf(s, "} (%ps)\n", (void *)trace->func);
> + if (!ret)
> + return TRACE_TYPE_PARTIAL_LINE;
> + }
>
> /* Overrun */
> if (tracer_flags.val & TRACE_GRAPH_PRINT_OVERRUN) {
>
>
Very nice!
^ permalink raw reply [flat|nested] 7+ messages in thread* Re: [PATCH][GIT PULL] ftrace: Add function names to dangling } in function graph tracer
2010-02-27 10:02 ` Frederic Weisbecker
@ 2010-02-27 19:25 ` Steven Rostedt
2010-02-28 18:16 ` Frederic Weisbecker
0 siblings, 1 reply; 7+ messages in thread
From: Steven Rostedt @ 2010-02-27 19:25 UTC (permalink / raw)
To: Frederic Weisbecker; +Cc: LKML, Ingo Molnar, Tim Bird
On Sat, 2010-02-27 at 11:02 +0100, Frederic Weisbecker wrote:
> > /*
> > * Comments display at + 1 to depth. Since
> > * this is a leaf function, keep the comments
> > * equal to this depth.
> > */
> > - *depth = call->depth - 1;
> > + cpu_data->depth = call->depth - 1;
> > +
> > + /* No need to keep this function around for this depth */
> > + if (call->depth < FTRACE_RETFUNC_DEPTH)
>
>
>
> Do you really need to check that? call->depth >= FTRACE_RETFUNC_DEPTH
> are not recorded.
>
>
Call me paranoid, but working inside the kernel makes me paranoid. If
for some reason a trace gets corrupted here, not doing this check can
cause a kernel oops.
>
> > + cpu_data->enter_funcs[call->depth] = 0;
cpu_data->enter_funcs[102340320211] = 0;
would be bad ;-)
Hmm, I should also make sure depth is not less than zero. I'll send a
new patch to do that too.
-- Steve
> > }
> >
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: [PATCH][GIT PULL] ftrace: Add function names to dangling } in function graph tracer
2010-02-27 19:25 ` Steven Rostedt
@ 2010-02-28 18:16 ` Frederic Weisbecker
0 siblings, 0 replies; 7+ messages in thread
From: Frederic Weisbecker @ 2010-02-28 18:16 UTC (permalink / raw)
To: Steven Rostedt; +Cc: LKML, Ingo Molnar, Tim Bird
On Sat, Feb 27, 2010 at 02:25:03PM -0500, Steven Rostedt wrote:
> On Sat, 2010-02-27 at 11:02 +0100, Frederic Weisbecker wrote:
>
> > > /*
> > > * Comments display at + 1 to depth. Since
> > > * this is a leaf function, keep the comments
> > > * equal to this depth.
> > > */
> > > - *depth = call->depth - 1;
> > > + cpu_data->depth = call->depth - 1;
> > > +
> > > + /* No need to keep this function around for this depth */
> > > + if (call->depth < FTRACE_RETFUNC_DEPTH)
> >
> >
> >
> > Do you really need to check that? call->depth >= FTRACE_RETFUNC_DEPTH
> > are not recorded.
> >
> >
>
> Call me paranoid, but working inside the kernel makes me paranoid. If
> for some reason a trace gets corrupted here, not doing this check can
> cause a kernel oops.
Ok but this may also hide a bug.
Could it be a WARN_ON_ONCE?
> >
> > > + cpu_data->enter_funcs[call->depth] = 0;
>
> cpu_data->enter_funcs[102340320211] = 0;
>
> would be bad ;-)
>
>
> Hmm, I should also make sure depth is not less than zero. I'll send a
> new patch to do that too.
With a WARN_ON_ONCE? :)
Thanks.
^ permalink raw reply [flat|nested] 7+ messages in thread
end of thread, other threads:[~2010-02-28 18:16 UTC | newest]
Thread overview: 7+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2010-02-27 0:27 [PATCH][GIT PULL] ftrace: Add function names to dangling } in function graph tracer Steven Rostedt
2010-02-27 9:43 ` Ingo Molnar
2010-02-27 10:04 ` Frederic Weisbecker
2010-02-27 19:19 ` Steven Rostedt
2010-02-27 10:02 ` Frederic Weisbecker
2010-02-27 19:25 ` Steven Rostedt
2010-02-28 18:16 ` Frederic Weisbecker
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.