From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1754970Ab0CXHQq (ORCPT ); Wed, 24 Mar 2010 03:16:46 -0400 Received: from mx1.redhat.com ([209.132.183.28]:61985 "EHLO mx1.redhat.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1754943Ab0CXHQn (ORCPT ); Wed, 24 Mar 2010 03:16:43 -0400 Date: Wed, 24 Mar 2010 08:16:38 +0100 From: Jiri Olsa To: Steven Rostedt Cc: linux-kernel@vger.kernel.org Subject: Re: [PATCHv2 2/4] tracing: graph output support for irqsoff tracer Message-ID: <20100324071638.GA1979@jolsa.lab.eng.brq.redhat.com> References: <1268207470-2880-1-git-send-email-jolsa@redhat.com> <1268207470-2880-3-git-send-email-jolsa@redhat.com> <1269393556.2957.1823.camel@gandalf.stny.rr.com> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <1269393556.2957.1823.camel@gandalf.stny.rr.com> User-Agent: Mutt/1.5.20 (2009-08-17) Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On Tue, Mar 23, 2010 at 09:19:16PM -0400, Steven Rostedt wrote: > On Wed, 2010-03-10 at 08:51 +0100, Jiri Olsa wrote: > > > @@ -993,14 +991,6 @@ print_graph_comment(struct trace_seq *s, struct trace_entry *ent, > > if (ret != TRACE_TYPE_HANDLED) > > return ret; > > break; > > - default: > > - event = ftrace_find_event(ent->type); > > - if (!event) > > - return TRACE_TYPE_UNHANDLED; > > - > > - ret = event->trace(iter, sym_flags); > > - if (ret != TRACE_TYPE_HANDLED) > > - return ret; > > } > > > > This has the same effect as the problem with the first patch: > > was: > > 2) | _raw_spin_unlock_irqrestore() { > 2) | /* lock_release: ffffffff816969a8 random_read_wait.lock */ > 2) 6.022 us | } > 2) + 27.632 us | } > 2) 2.939 us | kill_fasync(); > 2) | _raw_spin_unlock_irqrestore() { > 2) | /* lock_release: ffffffff816967f0 &input_pool.lock */ > 2) 5.471 us | } > 2) + 56.740 us | } > 2) + 88.357 us | } > 2) + 94.026 us | } > > > is now: > > 2) | _raw_spin_unlock_irqrestore() { > -0 [002] 411.798721: lock_release: ffffffff816969a8 random_read_wait.lock > 2) 6.022 us | } > 2) + 27.632 us | } > 2) 2.939 us | kill_fasync(); > 2) | _raw_spin_unlock_irqrestore() { > -0 [002] 411.798741: lock_release: ffffffff816967f0 &input_pool.lock > 2) 5.471 us | } > 2) + 56.740 us | } > 2) + 88.357 us | } > 2) + 94.026 us | } > > > Please, before you apply any patch do the following: > > (assuming debugfs is at /debug) > > # echo 1 > /debug/tracing/events/enable > # echo function_graph > /debug/tracing/current_tracer > # cat /debug/tracing/trace > > Examine what you see. > > Then apply all your patches, and repeat the above. Make sure the > formatting is the same. hi, shoot, looks like I forgot about comments... sending new version soon :) thanks, jirka > > Thanks, > > -- Steve > > > > /* Strip ending newline */ > > @@ -1066,8 +1056,11 @@ print_graph_function(struct trace_iterator *iter) > > trace_assign_type(field, entry); > > return print_graph_return(&field->ret, s, entry, iter); > > } > > - default: > > + case TRACE_BPRINT: > > + case TRACE_PRINT: > > return print_graph_comment(s, entry, iter); > > + default: > > + return TRACE_TYPE_UNHANDLED; > > } > > > > return TRACE_TYPE_HANDLED; > > @@ -1101,7 +1094,7 @@ static void print_lat_header(struct seq_file *s) > > seq_printf(s, "#%.*s|||| / \n", size, spaces); > > } > > > > -static void print_graph_headers(struct seq_file *s) > > +void print_graph_headers(struct seq_file *s) > > { > > int lat = trace_flags & TRACE_ITER_LATENCY_FMT; > > > > @@ -1137,7 +1130,7 @@ static void print_graph_headers(struct seq_file *s) > > seq_printf(s, " | | | |\n"); > > } > > > > -static void graph_trace_open(struct trace_iterator *iter) > > +void graph_trace_open(struct trace_iterator *iter) > > { > > /* pid and depth on the last trace processed */ > > struct fgraph_data *data; > > @@ -1172,7 +1165,7 @@ static void graph_trace_open(struct trace_iterator *iter) > > pr_warning("function graph tracer: not enough memory\n"); > > } > > > > -static void graph_trace_close(struct trace_iterator *iter) > > +void graph_trace_close(struct trace_iterator *iter) > > { > > struct fgraph_data *data = iter->private; > > > > diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c > > index 2974bc7..d0c6d6c 100644 > > --- a/kernel/trace/trace_irqsoff.c > > +++ b/kernel/trace/trace_irqsoff.c > > @@ -34,6 +34,9 @@ static int trace_type __read_mostly; > > > > static int save_lat_flag; > > > > +static void stop_irqsoff_tracer(struct trace_array *tr, int graph); > > +static int start_irqsoff_tracer(struct trace_array *tr, int graph); > > + > > #ifdef CONFIG_PREEMPT_TRACER > > static inline int > > preempt_trace(void) > > @@ -55,6 +58,23 @@ irq_trace(void) > > # define irq_trace() (0) > > #endif > > > > +#define TRACE_DISPLAY_GRAPH 1 > > + > > +static struct tracer_opt trace_opts[] = { > > +#ifdef CONFIG_FUNCTION_GRAPH_TRACER > > + /* display latency trace as call graph */ > > + { TRACER_OPT(display-graph, TRACE_DISPLAY_GRAPH) }, > > +#endif > > + { } /* Empty entry */ > > +}; > > + > > +static struct tracer_flags tracer_flags = { > > + .val = 0, > > + .opts = trace_opts, > > +}; > > + > > +#define is_graph() (tracer_flags.val & TRACE_DISPLAY_GRAPH) > > + > > /* > > * Sequence count - we record it when starting a measurement and > > * skip the latency if the sequence has changed - some other section > > @@ -108,6 +128,109 @@ static struct ftrace_ops trace_ops __read_mostly = > > }; > > #endif /* CONFIG_FUNCTION_TRACER */ > > > > +#ifdef CONFIG_FUNCTION_GRAPH_TRACER > > +static int irqsoff_set_flag(u32 old_flags, u32 bit, int set) > > +{ > > + int cpu; > > + > > + if (!(bit & TRACE_DISPLAY_GRAPH)) > > + return -EINVAL; > > + > > + if (!(is_graph() ^ set)) > > + return 0; > > + > > + stop_irqsoff_tracer(irqsoff_trace, !set); > > + > > + for_each_possible_cpu(cpu) > > + per_cpu(tracing_cpu, cpu) = 0; > > + > > + tracing_max_latency = 0; > > + tracing_reset_online_cpus(irqsoff_trace); > > + > > + return start_irqsoff_tracer(irqsoff_trace, set); > > +} > > + > > +static int irqsoff_graph_entry(struct ftrace_graph_ent *trace) > > +{ > > + struct trace_array *tr = irqsoff_trace; > > + struct trace_array_cpu *data; > > + unsigned long flags; > > + long disabled; > > + int ret; > > + int cpu; > > + int pc; > > + > > + cpu = raw_smp_processor_id(); > > + if (likely(!per_cpu(tracing_cpu, cpu))) > > + return 0; > > + > > + local_save_flags(flags); > > + /* slight chance to get a false positive on tracing_cpu */ > > + if (!irqs_disabled_flags(flags)) > > + return 0; > > + > > + data = tr->data[cpu]; > > + disabled = atomic_inc_return(&data->disabled); > > + > > + if (likely(disabled == 1)) { > > + pc = preempt_count(); > > + ret = __trace_graph_entry(tr, trace, flags, pc); > > + } else > > + ret = 0; > > + > > + atomic_dec(&data->disabled); > > + return ret; > > +} > > + > > +static void irqsoff_graph_return(struct ftrace_graph_ret *trace) > > +{ > > + struct trace_array *tr = irqsoff_trace; > > + struct trace_array_cpu *data; > > + unsigned long flags; > > + long disabled; > > + int cpu; > > + int pc; > > + > > + cpu = raw_smp_processor_id(); > > + if (likely(!per_cpu(tracing_cpu, cpu))) > > + return; > > + > > + local_save_flags(flags); > > + /* slight chance to get a false positive on tracing_cpu */ > > + if (!irqs_disabled_flags(flags)) > > + return; > > + > > + data = tr->data[cpu]; > > + disabled = atomic_inc_return(&data->disabled); > > + > > + if (likely(disabled == 1)) { > > + pc = preempt_count(); > > + __trace_graph_return(tr, trace, flags, pc); > > + } > > + > > + atomic_dec(&data->disabled); > > +} > > + > > +static void irqsoff_trace_open(struct trace_iterator *iter) > > +{ > > + if (is_graph()) > > + graph_trace_open(iter); > > + > > +} > > + > > +static void irqsoff_trace_close(struct trace_iterator *iter) > > +{ > > + if (iter->private) > > + graph_trace_close(iter); > > +} > > + > > +#else > > +static int irqsoff_set_flag(u32 old_flags, u32 bit, int set) > > +{ > > + return -EINVAL; > > +} > > +#endif /* CONFIG_FUNCTION_GRAPH_TRACER */ > > + > > /* > > * Should this new latency be reported/recorded? > > */ > > @@ -347,19 +470,36 @@ void trace_preempt_off(unsigned long a0, unsigned long a1) > > } > > #endif /* CONFIG_PREEMPT_TRACER */ > > > > -static void start_irqsoff_tracer(struct trace_array *tr) > > +static int start_irqsoff_tracer(struct trace_array *tr, int graph) > > { > > - register_ftrace_function(&trace_ops); > > - if (tracing_is_enabled()) > > + int ret = 0; > > + > > + if (!graph) > > + ret = register_ftrace_function(&trace_ops); > > +#ifdef CONFIG_FUNCTION_GRAPH_TRACER > > + else > > + ret = register_ftrace_graph(&irqsoff_graph_return, > > + &irqsoff_graph_entry); > > +#endif > > + > > + if (!ret && tracing_is_enabled()) > > tracer_enabled = 1; > > else > > tracer_enabled = 0; > > + > > + return ret; > > } > > > > -static void stop_irqsoff_tracer(struct trace_array *tr) > > +static void stop_irqsoff_tracer(struct trace_array *tr, int graph) > > { > > tracer_enabled = 0; > > - unregister_ftrace_function(&trace_ops); > > + > > + if (!graph) > > + unregister_ftrace_function(&trace_ops); > > +#ifdef CONFIG_FUNCTION_GRAPH_TRACER > > + else > > + unregister_ftrace_graph(); > > +#endif > > } > > > > static void __irqsoff_tracer_init(struct trace_array *tr) > > @@ -372,12 +512,14 @@ static void __irqsoff_tracer_init(struct trace_array *tr) > > /* make sure that the tracer is visible */ > > smp_wmb(); > > tracing_reset_online_cpus(tr); > > - start_irqsoff_tracer(tr); > > + > > + if (start_irqsoff_tracer(tr, is_graph())) > > + printk(KERN_ERR "failed to start irqsoff tracer\n"); > > } > > > > static void irqsoff_tracer_reset(struct trace_array *tr) > > { > > - stop_irqsoff_tracer(tr); > > + stop_irqsoff_tracer(tr, is_graph()); > > > > if (!save_lat_flag) > > trace_flags &= ~TRACE_ITER_LATENCY_FMT; > > @@ -409,9 +551,15 @@ static struct tracer irqsoff_tracer __read_mostly = > > .start = irqsoff_tracer_start, > > .stop = irqsoff_tracer_stop, > > .print_max = 1, > > + .flags = &tracer_flags, > > + .set_flag = irqsoff_set_flag, > > #ifdef CONFIG_FTRACE_SELFTEST > > .selftest = trace_selftest_startup_irqsoff, > > #endif > > +#ifdef CONFIG_FUNCTION_GRAPH_TRACER > > + .open = irqsoff_trace_open, > > + .close = irqsoff_trace_close, > > +#endif > > }; > > # define register_irqsoff(trace) register_tracer(&trace) > > #else > >