Re: [PATCH][GIT PULL] ftrace: Add function names to dangling } infunction graph tracer
From: Frederic Weisbecker
Date: Sat Feb 27 2010 - 05:02:43 EST
On Fri, Feb 26, 2010 at 07:27:19PM -0500, Steven Rostedt wrote:
> commit f1c7f517a5dc23bce07efa5ed55e2c074ed9d4ba
> Author: Steven Rostedt <srostedt@xxxxxxxxxx>
> 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@xxxxxxxxxxx>
>
> 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!
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/