Skip to contentSkip to conversation

tracing/latency: Fix header output for latency tracers

PATCH Superseded Jiri Olsa 2 participants 6 messages Sep 13, 2011 – Nov 18, 2011

Subsystems (2)
Tracing Tracing OS noise / latency tracers
lore
Share & tools
lore

Jiri Olsa

author
#0 lore raw

PATCH 1/1 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
#

     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 <[email protected]>
---
 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(-)
kernel/trace/trace.c +12 -0
index e5df02c..7086345 100644
@@ -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;
kernel/trace/trace.h +1 -0
index 616846b..db40865 100644
@@ -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);
kernel/trace/trace_irqsoff.c +12 -1
index 667aa8c..2a0aee6 100644
@@ -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 */
 
 /*
kernel/trace/trace_sched_wakeup.c +12 -1
index e4a70c0..ff791ea 100644
@@ -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 */
 
 /*
Signature · 1 line
1.7.1
author
#1 lore raw

hi,
any feedback on this?

thanks,
jirka

Quoted 176 lines · 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 <[email protected]>
---
 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(-)
kernel/trace/trace.c +12 -0
index e5df02c..7086345 100644
@@ -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;
kernel/trace/trace.h +1 -0
index 616846b..db40865 100644
@@ -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);
kernel/trace/trace_irqsoff.c +12 -1
index 667aa8c..2a0aee6 100644
@@ -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 */
 
 /*
kernel/trace/trace_sched_wakeup.c +12 -1
index e4a70c0..ff791ea 100644
@@ -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 */
 
 /*
Signature · 1 line
1.7.1
maintainer
#2 lore raw
Quoted 3 lines · Jiri Olsa

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

maintainer
#3 lore raw
In reply to Jiri Olsa

Sorry for the late reply, I'm still purging through my Inbox from over the week in Prague.

Quoted 29 lines · 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
#

Quoted 11 lines
  # 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

Quoted 133 lines

* 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 <[email protected]>
---
 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(-)
kernel/trace/trace.c +12 -0
index e5df02c..7086345 100644
@@ -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;
kernel/trace/trace.h +1 -0
index 616846b..db40865 100644
@@ -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);
kernel/trace/trace_irqsoff.c +12 -1
index 667aa8c..2a0aee6 100644
@@ -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 */
 
 /*
kernel/trace/trace_sched_wakeup.c +12 -1
index e4a70c0..ff791ea 100644
@@ -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 */
 
 /*
author
#4 lore raw

PATCH v2 1/1 tracing/latency: Fix header output for latency tracers

Quoted 46 lines · Steven Rostedt

Sorry for the late reply, I'm still purging through my Inbox from over the week in Prague.

Quoted 29 lines · 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
#

Quoted 11 lines
  # 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
Quoted 2 lines

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 <[email protected]>
---
 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(-)
kernel/trace/trace.c +15 -0
index f2bd275..9e158cc 100644
@@ -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;
kernel/trace/trace.h +1 -0
index 092e1f8..f8ec229 100644
@@ -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);
kernel/trace/trace_irqsoff.c +12 -1
index 20dad0d..99d20e9 100644
@@ -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 */
 
 /*
kernel/trace/trace_sched_wakeup.c +12 -1
index e4a70c0..ff791ea 100644
@@ -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 */
 
 /*
Signature · 1 line
1.7.1
author
#5 lore raw
Commit-ID:  7e9a49ef542610609144d1afcd516dc3fafac4d6
Gitweb:     http://git.kernel.org/tip/7e9a49ef542610609144d1afcd516dc3fafac4d6
Author:     Jiri Olsa <[email protected]>
AuthorDate: Mon, 7 Nov 2011 16:08:49 +0100
Committer:  Steven Rostedt <[email protected]>
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/[email protected] open here
Cc Frederic Weisbecker <[email protected]>
Cc Ingo Molnar <[email protected]>
Signed-off-by Jiri Olsa <[email protected]>
Signed-off-by Steven Rostedt <[email protected]>
---
 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(-)
kernel/trace/trace.c +15 -0
index b24a72d..b296186 100644
@@ -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;
kernel/trace/trace.h +1 -0
index 092e1f8..f8ec229 100644
@@ -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);
kernel/trace/trace_irqsoff.c +12 -1
index a1a3359..a248c68 100644
@@ -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 */
 
 /*
kernel/trace/trace_sched_wakeup.c +12 -1
index e4a70c0..ff791ea 100644
@@ -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 */
 
 /*