Re: [PATCHv2] trace: funcgraph tracer - adding funcgraph-irq option

[Steven Rostedt]

Hi Johannes,

On Thu, 2010-09-09 at 16:44 +0200, Johannes Weiner wrote:

> Although greatly reduced, I still see the following noise in the trace
> output with the IRQ filtering enabled:
> 
>  1)               |    wakeup_flusher_threads() {
>  1)   0.205 us    |      __rcu_read_lock();
>  1)   0.271 us    |      bdi_has_dirty_io();
>  1)   0.287 us    |      bdi_has_dirty_io();
>  1)   0.217 us    |      bdi_has_dirty_io();
>  1)               |      bdi_has_dirty_io() {
>  1)               |        smp_invalidate_interrupt() {
>  1)   0.220 us    |          native_apic_mem_write();
>  1)   0.794 us    |        } /* smp_invalidate_interrupt */
>  1)   1.413 us    |      } /* bdi_has_dirty_io */
>  1)   0.218 us    |      bdi_has_dirty_io();
>  1)   0.213 us    |      bdi_has_dirty_io();
>  1)   0.215 us    |      bdi_has_dirty_io();
>  1)               |      smp_invalidate_interrupt() {
>  1)   0.234 us    |        native_apic_mem_write();
>  1)   0.819 us    |      } /* smp_invalidate_interrupt */
>  1)   0.240 us    |      bdi_has_dirty_io();
>  1)   0.259 us    |      bdi_has_dirty_io();


You could also try the below patch. When you set funcgraph-irqs to 0,
the function tracer will stop recording inside interrupts (except for
the part before it calls irq_enter()). But that's still good, because
you can still see where interrupts happened.

Here's how to use it:

# echo 0 > tracing_on
# echo function_graph > current_tracer
# echo 0 > options/funcgraph-irqs
# echo 1 > tracing_on
<run-stuff>

When you cat the trace file, it wont have the irqs on because of Jiri's
patch. But..

 # echo 1 > options/funcgraph-irqs
 # echo 1 > options/latency-format
 # cat trace
# tracer: function_graph
#
#      _-----=> irqs-off        
#     / _----=> need-resched    
#    | / _---=> hardirq/softirq 
#    || / _--=> preempt-depth   
#    ||| / _-=> lock-depth      
#    |||| /                     
# CPU|||||  DURATION                  FUNCTION CALLS
# |  |||||   |   |                     |   |   |   |
 1)  d..1.  3.090 us    |  }
 1)  d..1.              |  mwait_idle() {
 1)   ==========> |
 1)  d..1.              |    smp_apic_timer_interrupt() {
 1)  d..1.  0.483 us    |      native_apic_mem_write();
 1)  d..1.              |      exit_idle() {
 1)  d..1.  0.511 us    |        __rcu_read_lock();
 1)  d..1.  0.445 us    |        __rcu_read_unlock();
 1)  d..1.  3.903 us    |      }
 1)  d..1.              |      irq_enter() {
 1)  d..1.  0.562 us    |        rcu_irq_enter();
 1)  d..1.  0.461 us    |        idle_cpu();
 1)  d.h1.  9.337 us    |      }
 1)  d..2.              |      do_softirq() {
 1)  d..2.              |        __do_softirq() {

That's because it uses "if (in_irq())" which in_irq() returns true after
irq_enter() and set to false again in irq_exit(), which is not shown,
because it was skipping them.  But softirqs are still displayed, and
here it was run from the interrupt context itself before going back to
whatever it interrupted.

-- Steve

diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index 8674750..02c708a 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -15,6 +15,9 @@
 #include "trace.h"
 #include "trace_output.h"
 
+/* When set, irq functions will be ignored */
+static int ftrace_graph_skip_irqs;
+
 struct fgraph_cpu_data {
 	pid_t		last_pid;
 	int		depth;
@@ -208,6 +211,14 @@ int __trace_graph_entry(struct trace_array *tr,
 	return 1;
 }
 
+static inline int ftrace_graph_ignore_irqs(void)
+{
+	if (!ftrace_graph_skip_irqs)
+		return 0;
+
+	return in_irq();
+}
+
 int trace_graph_entry(struct ftrace_graph_ent *trace)
 {
 	struct trace_array *tr = graph_array;
@@ -222,7 +233,8 @@ int trace_graph_entry(struct ftrace_graph_ent *trace)
 		return 0;
 
 	/* trace it when it is-nested-in or is a function enabled. */
-	if (!(trace->depth || ftrace_graph_addr(trace->func)))
+	if (!(trace->depth || ftrace_graph_addr(trace->func)) ||
+	      ftrace_graph_ignore_irqs())
 		return 0;
 
 	local_irq_save(flags);
@@ -1334,6 +1346,14 @@ void graph_trace_close(struct trace_iterator *iter)
 	}
 }
 
+static int func_graph_set_flag(u32 old_flags, u32 bit, int set)
+{
+	if (bit == TRACE_GRAPH_PRINT_IRQS)
+		ftrace_graph_skip_irqs = !set;
+
+	return 0;
+}
+
 static struct trace_event_functions graph_functions = {
 	.trace		= print_graph_function_event,
 };
@@ -1360,6 +1380,7 @@ static struct tracer graph_trace __read_mostly = {
 	.print_line	= print_graph_function,
 	.print_header	= print_graph_headers,
 	.flags		= &tracer_flags,
+	.set_flag	= func_graph_set_flag,
 #ifdef CONFIG_FTRACE_SELFTEST
 	.selftest	= trace_selftest_startup_function_graph,
 #endif


--
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/