* [PATCH] tracing/latency: Fix header output for latency tracers
@ 2011-09-13 14:03 Jiri Olsa
2011-10-18 16:53 ` Jiri Olsa
2011-11-05 2:24 ` Steven Rostedt
0 siblings, 2 replies; 6+ messages in thread
From: Jiri Olsa @ 2011-09-13 14:03 UTC (permalink / raw)
To: rostedt, fweisbec, mingo; +Cc: linux-kernel, Jiri Olsa
In case the the graph tracer (CONFIG_FUNCTION_GRAPH_TRACER) or even the
function tracer (CONFIG_FUNCTION_TRACER) are not set, the latency tracers
do not display proper latency header.
The involved/fixed latency tracers are:
wakeup_rt
wakeup
preemptirqsoff
preemptoff
irqsoff
The patch adds proper handling of tracer configuration options for latency
tracers, and displaying correct header info accordingly.
* The current output (for wakeup tracer) with both graph and function
tracers disabled is:
# tracer: wakeup
#
cat-1163 0d..4 1us : 1163:120:R + [000] 6: 0:R migration/0
cat-1163 0d..4 2us+: ttwu_do_activate.clone.1 <-try_to_wake_up
cat-1163 0d..3 4us : __schedule <-preempt_schedule
cat-1163 0d..3 4us : 1163:120:R ==> [000] 6: 0:R migration/0
* The fixed output is:
# tracer: wakeup
#
# wakeup latency trace v1.1.5 on 3.1.0-rc4-tip+
# --------------------------------------------------------------------
# latency: 91 us, #4/4, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
# -----------------
# | task: watchdog/0-7 (uid:0 nice:0 policy:1 rt_prio:99)
# -----------------
#
<idle>-0 0d.h5 1us : 0:120:R + [000] 7: 0:R watchdog/0
<idle>-0 0d.h5 2us+: ttwu_do_activate.clone.1 <-try_to_wake_up
<idle>-0 0d..3 17us : __schedule <-schedule
<idle>-0 0d..3 17us : 0:120:R ==> [000] 7: 0:R watchdog/0
* There's slightly different output (for wakeup_rt tracer) when function
tracer is enabled, currently:
# tracer: wakeup_rt
#
cat-1168 1d..4 0us : 1168:120:R + [001] 8: 0:R migration/1
cat-1168 1d..4 1us : ttwu_do_activate.clone.1 <-try_to_wake_up
cat-1168 1d..3 1us : check_preempt_curr <-ttwu_do_wakeup
...
* After the fix:
# tracer: wakeup_rt
#
# wakeup_rt latency trace v1.1.5 on 3.1.0-rc4-tip+
# --------------------------------------------------------------------
# latency: 209 us, #113/113, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
# -----------------
# | task: watchdog/0-7 (uid:0 nice:0 policy:1 rt_prio:99)
# -----------------
#
# _------=> CPU#
# / _-----=> irqs-off
# | / _----=> need-resched
# || / _---=> hardirq/softirq
# ||| / _--=> preempt-depth
# |||| / delay
# cmd pid ||||| time | caller
# \ / ||||| \ | /
cat-1168 1d..4 0us : 1168:120:R + [001] 8: 0:R migration/1
cat-1168 1d..4 1us : ttwu_do_activate.clone.1 <-try_to_wake_up
cat-1168 1d..3 1us : check_preempt_curr <-ttwu_do_wakeup
...
Signed-off-by: Jiri Olsa <jolsa@redhat.com>
---
kernel/trace/trace.c | 12 ++++++++++++
kernel/trace/trace.h | 1 +
kernel/trace/trace_irqsoff.c | 13 ++++++++++++-
kernel/trace/trace_sched_wakeup.c | 13 ++++++++++++-
4 files changed, 37 insertions(+), 2 deletions(-)
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index e5df02c..7086345 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -2139,6 +2139,18 @@ enum print_line_t print_trace_line(struct trace_iterator *iter)
return print_trace_fmt(iter);
}
+void trace_latency_header(struct seq_file *m)
+{
+ struct trace_iterator *iter = m->private;
+
+ /* print nothing if the buffers are empty */
+ if (trace_empty(iter))
+ return;
+
+ if (iter->iter_flags & TRACE_FILE_LAT_FMT)
+ print_trace_header(m, iter);
+}
+
void trace_default_header(struct seq_file *m)
{
struct trace_iterator *iter = m->private;
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 616846b..db40865 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -370,6 +370,7 @@ void trace_graph_function(struct trace_array *tr,
unsigned long ip,
unsigned long parent_ip,
unsigned long flags, int pc);
+void trace_latency_header(struct seq_file *m);
void trace_default_header(struct seq_file *m);
void print_trace_header(struct seq_file *m, struct trace_iterator *iter);
int trace_empty(struct trace_iterator *iter);
diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c
index 667aa8c..2a0aee6 100644
--- a/kernel/trace/trace_irqsoff.c
+++ b/kernel/trace/trace_irqsoff.c
@@ -280,9 +280,20 @@ static enum print_line_t irqsoff_print_line(struct trace_iterator *iter)
}
static void irqsoff_graph_return(struct ftrace_graph_ret *trace) { }
-static void irqsoff_print_header(struct seq_file *s) { }
static void irqsoff_trace_open(struct trace_iterator *iter) { }
static void irqsoff_trace_close(struct trace_iterator *iter) { }
+
+#ifdef CONFIG_FUNCTION_TRACER
+static void irqsoff_print_header(struct seq_file *s)
+{
+ trace_default_header(s);
+}
+#else
+static void irqsoff_print_header(struct seq_file *s)
+{
+ trace_latency_header(s);
+}
+#endif /* CONFIG_FUNCTION_TRACER */
#endif /* CONFIG_FUNCTION_GRAPH_TRACER */
/*
diff --git a/kernel/trace/trace_sched_wakeup.c b/kernel/trace/trace_sched_wakeup.c
index e4a70c0..ff791ea 100644
--- a/kernel/trace/trace_sched_wakeup.c
+++ b/kernel/trace/trace_sched_wakeup.c
@@ -280,9 +280,20 @@ static enum print_line_t wakeup_print_line(struct trace_iterator *iter)
}
static void wakeup_graph_return(struct ftrace_graph_ret *trace) { }
-static void wakeup_print_header(struct seq_file *s) { }
static void wakeup_trace_open(struct trace_iterator *iter) { }
static void wakeup_trace_close(struct trace_iterator *iter) { }
+
+#ifdef CONFIG_FUNCTION_TRACER
+static void wakeup_print_header(struct seq_file *s)
+{
+ trace_default_header(s);
+}
+#else
+static void wakeup_print_header(struct seq_file *s)
+{
+ trace_latency_header(s);
+}
+#endif /* CONFIG_FUNCTION_TRACER */
#endif /* CONFIG_FUNCTION_GRAPH_TRACER */
/*
--
1.7.1
^ permalink raw reply related [flat|nested] 6+ messages in thread
* Re: [PATCH] tracing/latency: Fix header output for latency tracers
2011-09-13 14:03 [PATCH] tracing/latency: Fix header output for latency tracers Jiri Olsa
@ 2011-10-18 16:53 ` Jiri Olsa
2011-10-18 17:44 ` Steven Rostedt
2011-11-05 2:24 ` Steven Rostedt
1 sibling, 1 reply; 6+ messages in thread
From: Jiri Olsa @ 2011-10-18 16:53 UTC (permalink / raw)
To: rostedt, fweisbec, mingo; +Cc: linux-kernel
hi,
any feedback on this?
thanks,
jirka
On Tue, Sep 13, 2011 at 04:03:34PM +0200, Jiri Olsa wrote:
> In case the the graph tracer (CONFIG_FUNCTION_GRAPH_TRACER) or even the
> function tracer (CONFIG_FUNCTION_TRACER) are not set, the latency tracers
> do not display proper latency header.
>
> The involved/fixed latency tracers are:
> wakeup_rt
> wakeup
> preemptirqsoff
> preemptoff
> irqsoff
>
> The patch adds proper handling of tracer configuration options for latency
> tracers, and displaying correct header info accordingly.
>
> * The current output (for wakeup tracer) with both graph and function
> tracers disabled is:
>
> # tracer: wakeup
> #
> cat-1163 0d..4 1us : 1163:120:R + [000] 6: 0:R migration/0
> cat-1163 0d..4 2us+: ttwu_do_activate.clone.1 <-try_to_wake_up
> cat-1163 0d..3 4us : __schedule <-preempt_schedule
> cat-1163 0d..3 4us : 1163:120:R ==> [000] 6: 0:R migration/0
>
>
> * The fixed output is:
>
> # tracer: wakeup
> #
> # wakeup latency trace v1.1.5 on 3.1.0-rc4-tip+
> # --------------------------------------------------------------------
> # latency: 91 us, #4/4, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
> # -----------------
> # | task: watchdog/0-7 (uid:0 nice:0 policy:1 rt_prio:99)
> # -----------------
> #
> <idle>-0 0d.h5 1us : 0:120:R + [000] 7: 0:R watchdog/0
> <idle>-0 0d.h5 2us+: ttwu_do_activate.clone.1 <-try_to_wake_up
> <idle>-0 0d..3 17us : __schedule <-schedule
> <idle>-0 0d..3 17us : 0:120:R ==> [000] 7: 0:R watchdog/0
>
>
> * There's slightly different output (for wakeup_rt tracer) when function
> tracer is enabled, currently:
>
> # tracer: wakeup_rt
> #
> cat-1168 1d..4 0us : 1168:120:R + [001] 8: 0:R migration/1
> cat-1168 1d..4 1us : ttwu_do_activate.clone.1 <-try_to_wake_up
> cat-1168 1d..3 1us : check_preempt_curr <-ttwu_do_wakeup
> ...
>
>
> * After the fix:
>
> # tracer: wakeup_rt
> #
> # wakeup_rt latency trace v1.1.5 on 3.1.0-rc4-tip+
> # --------------------------------------------------------------------
> # latency: 209 us, #113/113, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
> # -----------------
> # | task: watchdog/0-7 (uid:0 nice:0 policy:1 rt_prio:99)
> # -----------------
> #
> # _------=> CPU#
> # / _-----=> irqs-off
> # | / _----=> need-resched
> # || / _---=> hardirq/softirq
> # ||| / _--=> preempt-depth
> # |||| / delay
> # cmd pid ||||| time | caller
> # \ / ||||| \ | /
> cat-1168 1d..4 0us : 1168:120:R + [001] 8: 0:R migration/1
> cat-1168 1d..4 1us : ttwu_do_activate.clone.1 <-try_to_wake_up
> cat-1168 1d..3 1us : check_preempt_curr <-ttwu_do_wakeup
> ...
>
>
> Signed-off-by: Jiri Olsa <jolsa@redhat.com>
> ---
> kernel/trace/trace.c | 12 ++++++++++++
> kernel/trace/trace.h | 1 +
> kernel/trace/trace_irqsoff.c | 13 ++++++++++++-
> kernel/trace/trace_sched_wakeup.c | 13 ++++++++++++-
> 4 files changed, 37 insertions(+), 2 deletions(-)
>
> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> index e5df02c..7086345 100644
> --- a/kernel/trace/trace.c
> +++ b/kernel/trace/trace.c
> @@ -2139,6 +2139,18 @@ enum print_line_t print_trace_line(struct trace_iterator *iter)
> return print_trace_fmt(iter);
> }
>
> +void trace_latency_header(struct seq_file *m)
> +{
> + struct trace_iterator *iter = m->private;
> +
> + /* print nothing if the buffers are empty */
> + if (trace_empty(iter))
> + return;
> +
> + if (iter->iter_flags & TRACE_FILE_LAT_FMT)
> + print_trace_header(m, iter);
> +}
> +
> void trace_default_header(struct seq_file *m)
> {
> struct trace_iterator *iter = m->private;
> diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
> index 616846b..db40865 100644
> --- a/kernel/trace/trace.h
> +++ b/kernel/trace/trace.h
> @@ -370,6 +370,7 @@ void trace_graph_function(struct trace_array *tr,
> unsigned long ip,
> unsigned long parent_ip,
> unsigned long flags, int pc);
> +void trace_latency_header(struct seq_file *m);
> void trace_default_header(struct seq_file *m);
> void print_trace_header(struct seq_file *m, struct trace_iterator *iter);
> int trace_empty(struct trace_iterator *iter);
> diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c
> index 667aa8c..2a0aee6 100644
> --- a/kernel/trace/trace_irqsoff.c
> +++ b/kernel/trace/trace_irqsoff.c
> @@ -280,9 +280,20 @@ static enum print_line_t irqsoff_print_line(struct trace_iterator *iter)
> }
>
> static void irqsoff_graph_return(struct ftrace_graph_ret *trace) { }
> -static void irqsoff_print_header(struct seq_file *s) { }
> static void irqsoff_trace_open(struct trace_iterator *iter) { }
> static void irqsoff_trace_close(struct trace_iterator *iter) { }
> +
> +#ifdef CONFIG_FUNCTION_TRACER
> +static void irqsoff_print_header(struct seq_file *s)
> +{
> + trace_default_header(s);
> +}
> +#else
> +static void irqsoff_print_header(struct seq_file *s)
> +{
> + trace_latency_header(s);
> +}
> +#endif /* CONFIG_FUNCTION_TRACER */
> #endif /* CONFIG_FUNCTION_GRAPH_TRACER */
>
> /*
> diff --git a/kernel/trace/trace_sched_wakeup.c b/kernel/trace/trace_sched_wakeup.c
> index e4a70c0..ff791ea 100644
> --- a/kernel/trace/trace_sched_wakeup.c
> +++ b/kernel/trace/trace_sched_wakeup.c
> @@ -280,9 +280,20 @@ static enum print_line_t wakeup_print_line(struct trace_iterator *iter)
> }
>
> static void wakeup_graph_return(struct ftrace_graph_ret *trace) { }
> -static void wakeup_print_header(struct seq_file *s) { }
> static void wakeup_trace_open(struct trace_iterator *iter) { }
> static void wakeup_trace_close(struct trace_iterator *iter) { }
> +
> +#ifdef CONFIG_FUNCTION_TRACER
> +static void wakeup_print_header(struct seq_file *s)
> +{
> + trace_default_header(s);
> +}
> +#else
> +static void wakeup_print_header(struct seq_file *s)
> +{
> + trace_latency_header(s);
> +}
> +#endif /* CONFIG_FUNCTION_TRACER */
> #endif /* CONFIG_FUNCTION_GRAPH_TRACER */
>
> /*
> --
> 1.7.1
>
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: [PATCH] tracing/latency: Fix header output for latency tracers
2011-10-18 16:53 ` Jiri Olsa
@ 2011-10-18 17:44 ` Steven Rostedt
0 siblings, 0 replies; 6+ messages in thread
From: Steven Rostedt @ 2011-10-18 17:44 UTC (permalink / raw)
To: Jiri Olsa; +Cc: fweisbec, mingo, linux-kernel
On Tue, 2011-10-18 at 18:53 +0200, Jiri Olsa wrote:
> hi,
> any feedback on this?
>
Ah, I must have missed this patch. Strange, as I had it highlighted.
Anyway, I'm currently on my way to Prague, I'll see if I get some time
when I'm there to look at it in more detail and perhaps get it ready for
3.2.
Thanks,
-- Steve
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: [PATCH] tracing/latency: Fix header output for latency tracers
2011-09-13 14:03 [PATCH] tracing/latency: Fix header output for latency tracers Jiri Olsa
2011-10-18 16:53 ` Jiri Olsa
@ 2011-11-05 2:24 ` Steven Rostedt
2011-11-07 15:08 ` [PATCHv2] " Jiri Olsa
1 sibling, 1 reply; 6+ messages in thread
From: Steven Rostedt @ 2011-11-05 2:24 UTC (permalink / raw)
To: Jiri Olsa; +Cc: fweisbec, mingo, linux-kernel
Sorry for the late reply, I'm still purging through my Inbox from over
the week in Prague.
On Tue, 2011-09-13 at 16:03 +0200, Jiri Olsa wrote:
> In case the the graph tracer (CONFIG_FUNCTION_GRAPH_TRACER) or even the
> function tracer (CONFIG_FUNCTION_TRACER) are not set, the latency tracers
> do not display proper latency header.
>
> The involved/fixed latency tracers are:
> wakeup_rt
> wakeup
> preemptirqsoff
> preemptoff
> irqsoff
>
> The patch adds proper handling of tracer configuration options for latency
> tracers, and displaying correct header info accordingly.
>
> * The current output (for wakeup tracer) with both graph and function
> tracers disabled is:
>
> # tracer: wakeup
> #
> cat-1163 0d..4 1us : 1163:120:R + [000] 6: 0:R migration/0
> cat-1163 0d..4 2us+: ttwu_do_activate.clone.1 <-try_to_wake_up
> cat-1163 0d..3 4us : __schedule <-preempt_schedule
> cat-1163 0d..3 4us : 1163:120:R ==> [000] 6: 0:R migration/0
>
>
> * The fixed output is:
>
> # tracer: wakeup
> #
> # wakeup latency trace v1.1.5 on 3.1.0-rc4-tip+
> # --------------------------------------------------------------------
> # latency: 91 us, #4/4, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
> # -----------------
> # | task: watchdog/0-7 (uid:0 nice:0 policy:1 rt_prio:99)
> # -----------------
> #
> <idle>-0 0d.h5 1us : 0:120:R + [000] 7: 0:R watchdog/0
> <idle>-0 0d.h5 2us+: ttwu_do_activate.clone.1 <-try_to_wake_up
> <idle>-0 0d..3 17us : __schedule <-schedule
> <idle>-0 0d..3 17us : 0:120:R ==> [000] 7: 0:R watchdog/0
Why the above header? Why not just use the latency header for all of
them?
-- Steve
>
>
> * There's slightly different output (for wakeup_rt tracer) when function
> tracer is enabled, currently:
>
> # tracer: wakeup_rt
> #
> cat-1168 1d..4 0us : 1168:120:R + [001] 8: 0:R migration/1
> cat-1168 1d..4 1us : ttwu_do_activate.clone.1 <-try_to_wake_up
> cat-1168 1d..3 1us : check_preempt_curr <-ttwu_do_wakeup
> ...
>
>
> * After the fix:
>
> # tracer: wakeup_rt
> #
> # wakeup_rt latency trace v1.1.5 on 3.1.0-rc4-tip+
> # --------------------------------------------------------------------
> # latency: 209 us, #113/113, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
> # -----------------
> # | task: watchdog/0-7 (uid:0 nice:0 policy:1 rt_prio:99)
> # -----------------
> #
> # _------=> CPU#
> # / _-----=> irqs-off
> # | / _----=> need-resched
> # || / _---=> hardirq/softirq
> # ||| / _--=> preempt-depth
> # |||| / delay
> # cmd pid ||||| time | caller
> # \ / ||||| \ | /
> cat-1168 1d..4 0us : 1168:120:R + [001] 8: 0:R migration/1
> cat-1168 1d..4 1us : ttwu_do_activate.clone.1 <-try_to_wake_up
> cat-1168 1d..3 1us : check_preempt_curr <-ttwu_do_wakeup
> ...
>
>
> Signed-off-by: Jiri Olsa <jolsa@redhat.com>
> ---
> kernel/trace/trace.c | 12 ++++++++++++
> kernel/trace/trace.h | 1 +
> kernel/trace/trace_irqsoff.c | 13 ++++++++++++-
> kernel/trace/trace_sched_wakeup.c | 13 ++++++++++++-
> 4 files changed, 37 insertions(+), 2 deletions(-)
>
> diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
> index e5df02c..7086345 100644
> --- a/kernel/trace/trace.c
> +++ b/kernel/trace/trace.c
> @@ -2139,6 +2139,18 @@ enum print_line_t print_trace_line(struct trace_iterator *iter)
> return print_trace_fmt(iter);
> }
>
> +void trace_latency_header(struct seq_file *m)
> +{
> + struct trace_iterator *iter = m->private;
> +
> + /* print nothing if the buffers are empty */
> + if (trace_empty(iter))
> + return;
> +
> + if (iter->iter_flags & TRACE_FILE_LAT_FMT)
> + print_trace_header(m, iter);
> +}
> +
> void trace_default_header(struct seq_file *m)
> {
> struct trace_iterator *iter = m->private;
> diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
> index 616846b..db40865 100644
> --- a/kernel/trace/trace.h
> +++ b/kernel/trace/trace.h
> @@ -370,6 +370,7 @@ void trace_graph_function(struct trace_array *tr,
> unsigned long ip,
> unsigned long parent_ip,
> unsigned long flags, int pc);
> +void trace_latency_header(struct seq_file *m);
> void trace_default_header(struct seq_file *m);
> void print_trace_header(struct seq_file *m, struct trace_iterator *iter);
> int trace_empty(struct trace_iterator *iter);
> diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c
> index 667aa8c..2a0aee6 100644
> --- a/kernel/trace/trace_irqsoff.c
> +++ b/kernel/trace/trace_irqsoff.c
> @@ -280,9 +280,20 @@ static enum print_line_t irqsoff_print_line(struct trace_iterator *iter)
> }
>
> static void irqsoff_graph_return(struct ftrace_graph_ret *trace) { }
> -static void irqsoff_print_header(struct seq_file *s) { }
> static void irqsoff_trace_open(struct trace_iterator *iter) { }
> static void irqsoff_trace_close(struct trace_iterator *iter) { }
> +
> +#ifdef CONFIG_FUNCTION_TRACER
> +static void irqsoff_print_header(struct seq_file *s)
> +{
> + trace_default_header(s);
> +}
> +#else
> +static void irqsoff_print_header(struct seq_file *s)
> +{
> + trace_latency_header(s);
> +}
> +#endif /* CONFIG_FUNCTION_TRACER */
> #endif /* CONFIG_FUNCTION_GRAPH_TRACER */
>
> /*
> diff --git a/kernel/trace/trace_sched_wakeup.c b/kernel/trace/trace_sched_wakeup.c
> index e4a70c0..ff791ea 100644
> --- a/kernel/trace/trace_sched_wakeup.c
> +++ b/kernel/trace/trace_sched_wakeup.c
> @@ -280,9 +280,20 @@ static enum print_line_t wakeup_print_line(struct trace_iterator *iter)
> }
>
> static void wakeup_graph_return(struct ftrace_graph_ret *trace) { }
> -static void wakeup_print_header(struct seq_file *s) { }
> static void wakeup_trace_open(struct trace_iterator *iter) { }
> static void wakeup_trace_close(struct trace_iterator *iter) { }
> +
> +#ifdef CONFIG_FUNCTION_TRACER
> +static void wakeup_print_header(struct seq_file *s)
> +{
> + trace_default_header(s);
> +}
> +#else
> +static void wakeup_print_header(struct seq_file *s)
> +{
> + trace_latency_header(s);
> +}
> +#endif /* CONFIG_FUNCTION_TRACER */
> #endif /* CONFIG_FUNCTION_GRAPH_TRACER */
>
> /*
^ permalink raw reply [flat|nested] 6+ messages in thread
* [PATCHv2] tracing/latency: Fix header output for latency tracers
2011-11-05 2:24 ` Steven Rostedt
@ 2011-11-07 15:08 ` Jiri Olsa
2011-11-18 23:14 ` [tip:perf/core] " tip-bot for Jiri Olsa
0 siblings, 1 reply; 6+ messages in thread
From: Jiri Olsa @ 2011-11-07 15:08 UTC (permalink / raw)
To: Steven Rostedt; +Cc: fweisbec, mingo, linux-kernel
On Fri, Nov 04, 2011 at 10:24:46PM -0400, Steven Rostedt wrote:
> Sorry for the late reply, I'm still purging through my Inbox from over
> the week in Prague.
>
>
> On Tue, 2011-09-13 at 16:03 +0200, Jiri Olsa wrote:
> > In case the the graph tracer (CONFIG_FUNCTION_GRAPH_TRACER) or even the
> > function tracer (CONFIG_FUNCTION_TRACER) are not set, the latency tracers
> > do not display proper latency header.
> >
> > The involved/fixed latency tracers are:
> > wakeup_rt
> > wakeup
> > preemptirqsoff
> > preemptoff
> > irqsoff
> >
> > The patch adds proper handling of tracer configuration options for latency
> > tracers, and displaying correct header info accordingly.
> >
> > * The current output (for wakeup tracer) with both graph and function
> > tracers disabled is:
> >
> > # tracer: wakeup
> > #
> > cat-1163 0d..4 1us : 1163:120:R + [000] 6: 0:R migration/0
> > cat-1163 0d..4 2us+: ttwu_do_activate.clone.1 <-try_to_wake_up
> > cat-1163 0d..3 4us : __schedule <-preempt_schedule
> > cat-1163 0d..3 4us : 1163:120:R ==> [000] 6: 0:R migration/0
> >
> >
> > * The fixed output is:
> >
> > # tracer: wakeup
> > #
> > # wakeup latency trace v1.1.5 on 3.1.0-rc4-tip+
> > # --------------------------------------------------------------------
> > # latency: 91 us, #4/4, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
> > # -----------------
> > # | task: watchdog/0-7 (uid:0 nice:0 policy:1 rt_prio:99)
> > # -----------------
> > #
> > <idle>-0 0d.h5 1us : 0:120:R + [000] 7: 0:R watchdog/0
> > <idle>-0 0d.h5 2us+: ttwu_do_activate.clone.1 <-try_to_wake_up
> > <idle>-0 0d..3 17us : __schedule <-schedule
> > <idle>-0 0d..3 17us : 0:120:R ==> [000] 7: 0:R watchdog/0
>
> Why the above header? Why not just use the latency header for all of
> them?
ops, you're right I forgot to call the print_lat_help_header function,
attaching PATCHv2
thanks,
jirka
---
In case the the graph tracer (CONFIG_FUNCTION_GRAPH_TRACER) or even the
function tracer (CONFIG_FUNCTION_TRACER) are not set, the latency tracers
do not display proper latency header.
The involved/fixed latency tracers are:
wakeup_rt
wakeup
preemptirqsoff
preemptoff
irqsoff
The patch adds proper handling of tracer configuration options for latency
tracers, and displaying correct header info accordingly.
* The current output (for wakeup tracer) with both graph and function
tracers disabled is:
# tracer: wakeup
#
<idle>-0 0d.h5 1us+: 0:120:R + [000] 7: 0:R watchdog/0
<idle>-0 0d.h5 3us+: ttwu_do_activate.clone.1 <-try_to_wake_up
...
* The fixed output is:
# tracer: wakeup
#
# wakeup latency trace v1.1.5 on 3.1.0-tip+
# --------------------------------------------------------------------
# latency: 55 us, #4/4, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
# -----------------
# | task: migration/0-6 (uid:0 nice:0 policy:1 rt_prio:99)
# -----------------
#
# _------=> CPU#
# / _-----=> irqs-off
# | / _----=> need-resched
# || / _---=> hardirq/softirq
# ||| / _--=> preempt-depth
# |||| / delay
# cmd pid ||||| time | caller
# \ / ||||| \ | /
cat-1129 0d..4 1us : 1129:120:R + [000] 6: 0:R migration/0
cat-1129 0d..4 2us+: ttwu_do_activate.clone.1 <-try_to_wake_up
* The current output (for wakeup tracer) with only function
tracer enabled is:
# tracer: wakeup
#
cat-1140 0d..4 1us+: 1140:120:R + [000] 6: 0:R migration/0
cat-1140 0d..4 2us : ttwu_do_activate.clone.1 <-try_to_wake_up
* The fixed output is:
# tracer: wakeup
#
# wakeup latency trace v1.1.5 on 3.1.0-tip+
# --------------------------------------------------------------------
# latency: 207 us, #109/109, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
# -----------------
# | task: watchdog/1-12 (uid:0 nice:0 policy:1 rt_prio:99)
# -----------------
#
# _------=> CPU#
# / _-----=> irqs-off
# | / _----=> need-resched
# || / _---=> hardirq/softirq
# ||| / _--=> preempt-depth
# |||| / delay
# cmd pid ||||| time | caller
# \ / ||||| \ | /
<idle>-0 1d.h5 1us+: 0:120:R + [001] 12: 0:R watchdog/1
<idle>-0 1d.h5 3us : ttwu_do_activate.clone.1 <-try_to_wake_up
Signed-off-by: Jiri Olsa <jolsa@redhat.com>
---
kernel/trace/trace.c | 15 +++++++++++++++
kernel/trace/trace.h | 1 +
kernel/trace/trace_irqsoff.c | 13 ++++++++++++-
kernel/trace/trace_sched_wakeup.c | 13 ++++++++++++-
4 files changed, 40 insertions(+), 2 deletions(-)
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index f2bd275..9e158cc 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -2140,6 +2140,21 @@ enum print_line_t print_trace_line(struct trace_iterator *iter)
return print_trace_fmt(iter);
}
+void trace_latency_header(struct seq_file *m)
+{
+ struct trace_iterator *iter = m->private;
+
+ /* print nothing if the buffers are empty */
+ if (trace_empty(iter))
+ return;
+
+ if (iter->iter_flags & TRACE_FILE_LAT_FMT)
+ print_trace_header(m, iter);
+
+ if (!(trace_flags & TRACE_ITER_VERBOSE))
+ print_lat_help_header(m);
+}
+
void trace_default_header(struct seq_file *m)
{
struct trace_iterator *iter = m->private;
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 092e1f8..f8ec229 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -370,6 +370,7 @@ void trace_graph_function(struct trace_array *tr,
unsigned long ip,
unsigned long parent_ip,
unsigned long flags, int pc);
+void trace_latency_header(struct seq_file *m);
void trace_default_header(struct seq_file *m);
void print_trace_header(struct seq_file *m, struct trace_iterator *iter);
int trace_empty(struct trace_iterator *iter);
diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c
index 20dad0d..99d20e9 100644
--- a/kernel/trace/trace_irqsoff.c
+++ b/kernel/trace/trace_irqsoff.c
@@ -280,9 +280,20 @@ static enum print_line_t irqsoff_print_line(struct trace_iterator *iter)
}
static void irqsoff_graph_return(struct ftrace_graph_ret *trace) { }
-static void irqsoff_print_header(struct seq_file *s) { }
static void irqsoff_trace_open(struct trace_iterator *iter) { }
static void irqsoff_trace_close(struct trace_iterator *iter) { }
+
+#ifdef CONFIG_FUNCTION_TRACER
+static void irqsoff_print_header(struct seq_file *s)
+{
+ trace_default_header(s);
+}
+#else
+static void irqsoff_print_header(struct seq_file *s)
+{
+ trace_latency_header(s);
+}
+#endif /* CONFIG_FUNCTION_TRACER */
#endif /* CONFIG_FUNCTION_GRAPH_TRACER */
/*
diff --git a/kernel/trace/trace_sched_wakeup.c b/kernel/trace/trace_sched_wakeup.c
index e4a70c0..ff791ea 100644
--- a/kernel/trace/trace_sched_wakeup.c
+++ b/kernel/trace/trace_sched_wakeup.c
@@ -280,9 +280,20 @@ static enum print_line_t wakeup_print_line(struct trace_iterator *iter)
}
static void wakeup_graph_return(struct ftrace_graph_ret *trace) { }
-static void wakeup_print_header(struct seq_file *s) { }
static void wakeup_trace_open(struct trace_iterator *iter) { }
static void wakeup_trace_close(struct trace_iterator *iter) { }
+
+#ifdef CONFIG_FUNCTION_TRACER
+static void wakeup_print_header(struct seq_file *s)
+{
+ trace_default_header(s);
+}
+#else
+static void wakeup_print_header(struct seq_file *s)
+{
+ trace_latency_header(s);
+}
+#endif /* CONFIG_FUNCTION_TRACER */
#endif /* CONFIG_FUNCTION_GRAPH_TRACER */
/*
--
1.7.1
^ permalink raw reply related [flat|nested] 6+ messages in thread
* [tip:perf/core] tracing/latency: Fix header output for latency tracers
2011-11-07 15:08 ` [PATCHv2] " Jiri Olsa
@ 2011-11-18 23:14 ` tip-bot for Jiri Olsa
0 siblings, 0 replies; 6+ messages in thread
From: tip-bot for Jiri Olsa @ 2011-11-18 23:14 UTC (permalink / raw)
To: linux-tip-commits
Cc: linux-kernel, hpa, mingo, fweisbec, rostedt, tglx, jolsa
Commit-ID: 7e9a49ef542610609144d1afcd516dc3fafac4d6
Gitweb: http://git.kernel.org/tip/7e9a49ef542610609144d1afcd516dc3fafac4d6
Author: Jiri Olsa <jolsa@redhat.com>
AuthorDate: Mon, 7 Nov 2011 16:08:49 +0100
Committer: Steven Rostedt <rostedt@goodmis.org>
CommitDate: Mon, 7 Nov 2011 13:48:35 -0500
tracing/latency: Fix header output for latency tracers
In case the the graph tracer (CONFIG_FUNCTION_GRAPH_TRACER) or even the
function tracer (CONFIG_FUNCTION_TRACER) are not set, the latency tracers
do not display proper latency header.
The involved/fixed latency tracers are:
wakeup_rt
wakeup
preemptirqsoff
preemptoff
irqsoff
The patch adds proper handling of tracer configuration options for latency
tracers, and displaying correct header info accordingly.
* The current output (for wakeup tracer) with both graph and function
tracers disabled is:
# tracer: wakeup
#
<idle>-0 0d.h5 1us+: 0:120:R + [000] 7: 0:R watchdog/0
<idle>-0 0d.h5 3us+: ttwu_do_activate.clone.1 <-try_to_wake_up
...
* The fixed output is:
# tracer: wakeup
#
# wakeup latency trace v1.1.5 on 3.1.0-tip+
# --------------------------------------------------------------------
# latency: 55 us, #4/4, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
# -----------------
# | task: migration/0-6 (uid:0 nice:0 policy:1 rt_prio:99)
# -----------------
#
# _------=> CPU#
# / _-----=> irqs-off
# | / _----=> need-resched
# || / _---=> hardirq/softirq
# ||| / _--=> preempt-depth
# |||| / delay
# cmd pid ||||| time | caller
# \ / ||||| \ | /
cat-1129 0d..4 1us : 1129:120:R + [000] 6: 0:R migration/0
cat-1129 0d..4 2us+: ttwu_do_activate.clone.1 <-try_to_wake_up
* The current output (for wakeup tracer) with only function
tracer enabled is:
# tracer: wakeup
#
cat-1140 0d..4 1us+: 1140:120:R + [000] 6: 0:R migration/0
cat-1140 0d..4 2us : ttwu_do_activate.clone.1 <-try_to_wake_up
* The fixed output is:
# tracer: wakeup
#
# wakeup latency trace v1.1.5 on 3.1.0-tip+
# --------------------------------------------------------------------
# latency: 207 us, #109/109, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
# -----------------
# | task: watchdog/1-12 (uid:0 nice:0 policy:1 rt_prio:99)
# -----------------
#
# _------=> CPU#
# / _-----=> irqs-off
# | / _----=> need-resched
# || / _---=> hardirq/softirq
# ||| / _--=> preempt-depth
# |||| / delay
# cmd pid ||||| time | caller
# \ / ||||| \ | /
<idle>-0 1d.h5 1us+: 0:120:R + [001] 12: 0:R watchdog/1
<idle>-0 1d.h5 3us : ttwu_do_activate.clone.1 <-try_to_wake_up
Link: http://lkml.kernel.org/r/20111107150849.GE1807@m.brq.redhat.com
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Ingo Molnar <mingo@redhat.com>
Signed-off-by: Jiri Olsa <jolsa@redhat.com>
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
kernel/trace/trace.c | 15 +++++++++++++++
kernel/trace/trace.h | 1 +
kernel/trace/trace_irqsoff.c | 13 ++++++++++++-
kernel/trace/trace_sched_wakeup.c | 13 ++++++++++++-
4 files changed, 40 insertions(+), 2 deletions(-)
diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index b24a72d..b296186 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -2140,6 +2140,21 @@ enum print_line_t print_trace_line(struct trace_iterator *iter)
return print_trace_fmt(iter);
}
+void trace_latency_header(struct seq_file *m)
+{
+ struct trace_iterator *iter = m->private;
+
+ /* print nothing if the buffers are empty */
+ if (trace_empty(iter))
+ return;
+
+ if (iter->iter_flags & TRACE_FILE_LAT_FMT)
+ print_trace_header(m, iter);
+
+ if (!(trace_flags & TRACE_ITER_VERBOSE))
+ print_lat_help_header(m);
+}
+
void trace_default_header(struct seq_file *m)
{
struct trace_iterator *iter = m->private;
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 092e1f8..f8ec229 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -370,6 +370,7 @@ void trace_graph_function(struct trace_array *tr,
unsigned long ip,
unsigned long parent_ip,
unsigned long flags, int pc);
+void trace_latency_header(struct seq_file *m);
void trace_default_header(struct seq_file *m);
void print_trace_header(struct seq_file *m, struct trace_iterator *iter);
int trace_empty(struct trace_iterator *iter);
diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c
index a1a3359..a248c68 100644
--- a/kernel/trace/trace_irqsoff.c
+++ b/kernel/trace/trace_irqsoff.c
@@ -280,9 +280,20 @@ static enum print_line_t irqsoff_print_line(struct trace_iterator *iter)
}
static void irqsoff_graph_return(struct ftrace_graph_ret *trace) { }
-static void irqsoff_print_header(struct seq_file *s) { }
static void irqsoff_trace_open(struct trace_iterator *iter) { }
static void irqsoff_trace_close(struct trace_iterator *iter) { }
+
+#ifdef CONFIG_FUNCTION_TRACER
+static void irqsoff_print_header(struct seq_file *s)
+{
+ trace_default_header(s);
+}
+#else
+static void irqsoff_print_header(struct seq_file *s)
+{
+ trace_latency_header(s);
+}
+#endif /* CONFIG_FUNCTION_TRACER */
#endif /* CONFIG_FUNCTION_GRAPH_TRACER */
/*
diff --git a/kernel/trace/trace_sched_wakeup.c b/kernel/trace/trace_sched_wakeup.c
index e4a70c0..ff791ea 100644
--- a/kernel/trace/trace_sched_wakeup.c
+++ b/kernel/trace/trace_sched_wakeup.c
@@ -280,9 +280,20 @@ static enum print_line_t wakeup_print_line(struct trace_iterator *iter)
}
static void wakeup_graph_return(struct ftrace_graph_ret *trace) { }
-static void wakeup_print_header(struct seq_file *s) { }
static void wakeup_trace_open(struct trace_iterator *iter) { }
static void wakeup_trace_close(struct trace_iterator *iter) { }
+
+#ifdef CONFIG_FUNCTION_TRACER
+static void wakeup_print_header(struct seq_file *s)
+{
+ trace_default_header(s);
+}
+#else
+static void wakeup_print_header(struct seq_file *s)
+{
+ trace_latency_header(s);
+}
+#endif /* CONFIG_FUNCTION_TRACER */
#endif /* CONFIG_FUNCTION_GRAPH_TRACER */
/*
^ permalink raw reply related [flat|nested] 6+ messages in thread
end of thread, other threads:[~2011-11-18 23:15 UTC | newest]
Thread overview: 6+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2011-09-13 14:03 [PATCH] tracing/latency: Fix header output for latency tracers Jiri Olsa
2011-10-18 16:53 ` Jiri Olsa
2011-10-18 17:44 ` Steven Rostedt
2011-11-05 2:24 ` Steven Rostedt
2011-11-07 15:08 ` [PATCHv2] " Jiri Olsa
2011-11-18 23:14 ` [tip:perf/core] " tip-bot for Jiri Olsa
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox