[PATCH] trace: funcgraph tracer - adding funcgraph-irq option

[PATCH] trace: funcgraph tracer - adding funcgraph-irq option

[Jiri Olsa]

hi,

adding funcgraph-irq option for function graph tracer.

It's handy to be able to disable the irq related output
and not to have to jump over each irq related code, when
you have no interrest in it.

The option is by default enabled, so there's no change to
current behaviour. It affects only the final output, so all
the irq related data stays in the ring buffer.

wbr,
jirka


Signed-off-by: Jiri Olsa <jolsa@redhat.com>
---
 kernel/trace/trace_functions_graph.c |   96 +++++++++++++++++++++++++++++++++-
 1 files changed, 95 insertions(+), 1 deletions(-)

diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index 6bff236..f28476e 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -19,6 +19,7 @@ struct fgraph_cpu_data {
 	pid_t		last_pid;
 	int		depth;
 	int		ignore;
+	unsigned long	irq_entry_addr;
 	unsigned long	enter_funcs[FTRACE_RETFUNC_DEPTH];
 };
 
@@ -41,6 +42,7 @@ struct fgraph_data {
 #define TRACE_GRAPH_PRINT_PROC		0x8
 #define TRACE_GRAPH_PRINT_DURATION	0x10
 #define TRACE_GRAPH_PRINT_ABS_TIME	0x20
+#define TRACE_GRAPH_PRINT_IRQS		0x40
 
 static struct tracer_opt trace_opts[] = {
 	/* Display overruns? (for self-debug purpose) */
@@ -55,13 +57,15 @@ static struct tracer_opt trace_opts[] = {
 	{ TRACER_OPT(funcgraph-duration, TRACE_GRAPH_PRINT_DURATION) },
 	/* Display absolute time of an entry */
 	{ TRACER_OPT(funcgraph-abstime, TRACE_GRAPH_PRINT_ABS_TIME) },
+	/* Display interrupts */
+	{ TRACER_OPT(funcgraph-irqs, TRACE_GRAPH_PRINT_IRQS ) },
 	{ } /* Empty entry */
 };
 
 static struct tracer_flags tracer_flags = {
 	/* Don't display overruns and proc by default */
 	.val = TRACE_GRAPH_PRINT_CPU | TRACE_GRAPH_PRINT_OVERHEAD |
-	       TRACE_GRAPH_PRINT_DURATION,
+	       TRACE_GRAPH_PRINT_DURATION | TRACE_GRAPH_PRINT_IRQS,
 	.opts = trace_opts
 };
 
@@ -847,6 +851,88 @@ print_graph_prologue(struct trace_iterator *iter, struct trace_seq *s,
 	return 0;
 }
 
+/*
+ * Entry check for irq code
+ *
+ * returns 1 if
+ *  - we are inside irq code
+ *  - we just extered irq code
+ *
+ * retunns 0 if
+ *  - funcgraph-interrupts option is set
+ *  - we are not inside irq code
+ */
+static int
+check_irq_entry(struct trace_iterator *iter, u32 flags, unsigned long addr)
+{
+	struct fgraph_data *data = iter->private;
+	int cpu = iter->cpu;
+	unsigned long *irq_entry_addr;
+
+	if (flags & TRACE_GRAPH_PRINT_IRQS)
+		return 0;
+
+	/*
+	 * We are inside the irq code
+	 */
+	irq_entry_addr = &(per_cpu_ptr(data->cpu_data, cpu)->irq_entry_addr);
+	if (*irq_entry_addr)
+		return 1;
+
+	if ((addr < (unsigned long)__irqentry_text_start) ||
+	    (addr >= (unsigned long)__irqentry_text_end))
+		return 0;
+
+	/*
+	 * We are entering irq code.
+	 */
+	*irq_entry_addr = addr;
+	return 1;
+}
+
+/*
+ * Return check for irq code
+ *
+ * returns 1 if
+ *  - we are inside irq code
+ *  - we just left irq code
+ *
+ * returns 0 if
+ *  - funcgraph-interrupts option is set
+ *  - we are not inside irq code
+ */
+static int
+check_irq_return(struct trace_iterator *iter, u32 flags, unsigned long addr)
+{
+	struct fgraph_data *data = iter->private;
+	int cpu = iter->cpu;
+	unsigned long *irq_entry_addr;
+
+	if (flags & TRACE_GRAPH_PRINT_IRQS)
+		return 0;
+
+	/*
+	 * We are not inside the irq code.
+	 */
+	irq_entry_addr = &(per_cpu_ptr(data->cpu_data, cpu)->irq_entry_addr);
+	if (!(*irq_entry_addr))
+		return 0;
+
+	/*
+	 * We are inside the irq code, and this is not the entry.
+	 */
+	if (*irq_entry_addr != addr)
+		return 1;
+
+	/*
+	 * We are inside the irq code, and this is returning entry.
+	 * Let's not trace it and clear the entry address, since
+	 * we are out of irq code.
+	 */
+	*irq_entry_addr = 0;
+	return 1;
+}
+
 static enum print_line_t
 print_graph_entry(struct ftrace_graph_ent_entry *field, struct trace_seq *s,
 			struct trace_iterator *iter, u32 flags)
@@ -857,6 +943,9 @@ print_graph_entry(struct ftrace_graph_ent_entry *field, struct trace_seq *s,
 	static enum print_line_t ret;
 	int cpu = iter->cpu;
 
+	if (check_irq_entry(iter, flags, call->func))
+		return TRACE_TYPE_HANDLED;
+
 	if (print_graph_prologue(iter, s, TRACE_GRAPH_ENT, call->func, flags))
 		return TRACE_TYPE_PARTIAL_LINE;
 
@@ -894,6 +983,9 @@ print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s,
 	int ret;
 	int i;
 
+	if (check_irq_return(iter, flags, trace->func))
+		return TRACE_TYPE_HANDLED;
+
 	if (data) {
 		struct fgraph_cpu_data *cpu_data;
 		int cpu = iter->cpu;
@@ -1202,9 +1294,11 @@ void graph_trace_open(struct trace_iterator *iter)
 		pid_t *pid = &(per_cpu_ptr(data->cpu_data, cpu)->last_pid);
 		int *depth = &(per_cpu_ptr(data->cpu_data, cpu)->depth);
 		int *ignore = &(per_cpu_ptr(data->cpu_data, cpu)->ignore);
+		unsigned long *irq_entry_addr = &(per_cpu_ptr(data->cpu_data, cpu)->irq_entry_addr);
 		*pid = -1;
 		*depth = 0;
 		*ignore = 0;
+		*irq_entry_addr = 0;
 	}
 
 	iter->private = data;

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

[Steven Rostedt]

On Mon, 2010-07-12 at 18:21 +0200, Jiri Olsa wrote:

> +/*
> + * Entry check for irq code
> + *
> + * returns 1 if
> + *  - we are inside irq code
> + *  - we just extered irq code
> + *
> + * retunns 0 if
> + *  - funcgraph-interrupts option is set
> + *  - we are not inside irq code
> + */
> +static int
> +check_irq_entry(struct trace_iterator *iter, u32 flags, unsigned long addr)
> +{
> +	struct fgraph_data *data = iter->private;
> +	int cpu = iter->cpu;
> +	unsigned long *irq_entry_addr;
> +
> +	if (flags & TRACE_GRAPH_PRINT_IRQS)
> +		return 0;
> +
> +	/*
> +	 * We are inside the irq code
> +	 */
> +	irq_entry_addr = &(per_cpu_ptr(data->cpu_data, cpu)->irq_entry_addr);
> +	if (*irq_entry_addr)
> +		return 1;
> +
> +	if ((addr < (unsigned long)__irqentry_text_start) ||
> +	    (addr >= (unsigned long)__irqentry_text_end))
> +		return 0;
> +
> +	/*
> +	 * We are entering irq code.
> +	 */
> +	*irq_entry_addr = addr;
> +	return 1;
> +}
> +
> +/*
> + * Return check for irq code
> + *
> + * returns 1 if
> + *  - we are inside irq code
> + *  - we just left irq code
> + *
> + * returns 0 if
> + *  - funcgraph-interrupts option is set
> + *  - we are not inside irq code
> + */
> +static int
> +check_irq_return(struct trace_iterator *iter, u32 flags, unsigned long addr)
> +{
> +	struct fgraph_data *data = iter->private;
> +	int cpu = iter->cpu;
> +	unsigned long *irq_entry_addr;
> +
> +	if (flags & TRACE_GRAPH_PRINT_IRQS)
> +		return 0;
> +
> +	/*
> +	 * We are not inside the irq code.
> +	 */
> +	irq_entry_addr = &(per_cpu_ptr(data->cpu_data, cpu)->irq_entry_addr);
> +	if (!(*irq_entry_addr))
> +		return 0;
> +
> +	/*
> +	 * We are inside the irq code, and this is not the entry.
> +	 */
> +	if (*irq_entry_addr != addr)
> +		return 1;
> +
> +	/*
> +	 * We are inside the irq code, and this is returning entry.
> +	 * Let's not trace it and clear the entry address, since
> +	 * we are out of irq code.
> +	 */
> +	*irq_entry_addr = 0;
> +	return 1;
> +}
> +
>  static enum print_line_t
>  print_graph_entry(struct ftrace_graph_ent_entry *field, struct trace_seq *s,
>  			struct trace_iterator *iter, u32 flags)
> @@ -857,6 +943,9 @@ print_graph_entry(struct ftrace_graph_ent_entry *field, struct trace_seq *s,
>  	static enum print_line_t ret;
>  	int cpu = iter->cpu;
>  
> +	if (check_irq_entry(iter, flags, call->func))
> +		return TRACE_TYPE_HANDLED;
> +
>  	if (print_graph_prologue(iter, s, TRACE_GRAPH_ENT, call->func, flags))
>  		return TRACE_TYPE_PARTIAL_LINE;
>  
> @@ -894,6 +983,9 @@ print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s,
>  	int ret;
>  	int i;
>  
> +	if (check_irq_return(iter, flags, trace->func))
> +		return TRACE_TYPE_HANDLED;

What happens if we lose the return event? That is, due to buffer
overruns, the return of the trace is lost. Then we lose out on all
events until another event of the same IRQ happens and its return is not
lost.

You should save the depth instead of the function. When you are in a
interrupt, record the depth. Then when the depth is less than or equal
to the recorded depth you can restart printing. This may still suffer
from missed returns, but it would not have as much of a consequence when
it happens.

-- Steve

> +
>  	if (data) {
>  		struct fgraph_cpu_data *cpu_data;
>  		int cpu = iter->cpu;

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

[Jiri Olsa]

On Thu, Jul 22, 2010 at 04:00:21PM -0400, Steven Rostedt wrote:
> On Mon, 2010-07-12 at 18:21 +0200, Jiri Olsa wrote:
> 
SNIP

> 
> What happens if we lose the return event? That is, due to buffer
> overruns, the return of the trace is lost. Then we lose out on all
> events until another event of the same IRQ happens and its return is not
> lost.
> 
> You should save the depth instead of the function. When you are in a
> interrupt, record the depth. Then when the depth is less than or equal
> to the recorded depth you can restart printing. This may still suffer
> from missed returns, but it would not have as much of a consequence when
> it happens.
hi,
you're right, changed patch is attached

thanks,
jirka

---
Adding funcgraph-irq option for function graph tracer.

It's handy to be able to disable the irq related output
and not to have to jump over each irq related code, when
you have no interrest in it.

The option is by default enabled, so there's no change to
current behaviour. It affects only the final output, so all
the irq related data stays in the ring buffer.

wbr,
jirka


Signed-off-by: Jiri Olsa <jolsa@redhat.com>
---
 kernel/trace/trace_functions_graph.c |  101 +++++++++++++++++++++++++++++++++-
 1 files changed, 100 insertions(+), 1 deletions(-)

diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index 6bff236..e66f71f 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		depth_irq;
 	int		ignore;
 	unsigned long	enter_funcs[FTRACE_RETFUNC_DEPTH];
 };
@@ -41,6 +42,7 @@ struct fgraph_data {
 #define TRACE_GRAPH_PRINT_PROC		0x8
 #define TRACE_GRAPH_PRINT_DURATION	0x10
 #define TRACE_GRAPH_PRINT_ABS_TIME	0x20
+#define TRACE_GRAPH_PRINT_IRQS		0x40
 
 static struct tracer_opt trace_opts[] = {
 	/* Display overruns? (for self-debug purpose) */
@@ -55,13 +57,15 @@ static struct tracer_opt trace_opts[] = {
 	{ TRACER_OPT(funcgraph-duration, TRACE_GRAPH_PRINT_DURATION) },
 	/* Display absolute time of an entry */
 	{ TRACER_OPT(funcgraph-abstime, TRACE_GRAPH_PRINT_ABS_TIME) },
+	/* Display interrupts */
+	{ TRACER_OPT(funcgraph-irqs, TRACE_GRAPH_PRINT_IRQS) },
 	{ } /* Empty entry */
 };
 
 static struct tracer_flags tracer_flags = {
 	/* Don't display overruns and proc by default */
 	.val = TRACE_GRAPH_PRINT_CPU | TRACE_GRAPH_PRINT_OVERHEAD |
-	       TRACE_GRAPH_PRINT_DURATION,
+	       TRACE_GRAPH_PRINT_DURATION | TRACE_GRAPH_PRINT_IRQS,
 	.opts = trace_opts
 };
 
@@ -847,6 +851,92 @@ print_graph_prologue(struct trace_iterator *iter, struct trace_seq *s,
 	return 0;
 }
 
+/*
+ * Entry check for irq code
+ *
+ * returns 1 if
+ *  - we are inside irq code
+ *  - we just extered irq code
+ *
+ * retunns 0 if
+ *  - funcgraph-interrupts option is set
+ *  - we are not inside irq code
+ */
+static int
+check_irq_entry(struct trace_iterator *iter, u32 flags,
+		unsigned long addr, int depth)
+{
+	int cpu = iter->cpu;
+	struct fgraph_data *data = iter->private;
+	int *depth_irq = &(per_cpu_ptr(data->cpu_data, cpu)->depth_irq);
+
+	if (flags & TRACE_GRAPH_PRINT_IRQS)
+		return 0;
+
+	/*
+	 * We are inside the irq code
+	 */
+	if (*depth_irq >= 0)
+		return 1;
+
+	if ((addr < (unsigned long)__irqentry_text_start) ||
+	    (addr >= (unsigned long)__irqentry_text_end))
+		return 0;
+
+	/*
+	 * We are entering irq code.
+	 */
+	*depth_irq = depth;
+	return 1;
+}
+
+/*
+ * Return check for irq code
+ *
+ * returns 1 if
+ *  - we are inside irq code
+ *  - we just left irq code
+ *
+ * returns 0 if
+ *  - funcgraph-interrupts option is set
+ *  - we are not inside irq code
+ */
+static int
+check_irq_return(struct trace_iterator *iter, u32 flags, int depth)
+{
+	int cpu = iter->cpu;
+	struct fgraph_data *data = iter->private;
+	int *depth_irq = &(per_cpu_ptr(data->cpu_data, cpu)->depth_irq);
+
+	if (flags & TRACE_GRAPH_PRINT_IRQS)
+		return 0;
+
+	/*
+	 * We are not inside the irq code.
+	 */
+	if (*depth_irq == -1)
+		return 0;
+
+	/*
+	 * We are inside the irq code, and this is returning entry.
+	 * Let's not trace it and clear the entry depth, since
+	 * we are out of irq code.
+	 *
+	 * This condition ensures that we 'leave the irq code' once
+	 * we are out of the entry depth. Thus protecting us from
+	 * the RETURN entry loss.
+	 */
+	if (*depth_irq >= depth) {
+		*depth_irq = -1;
+		return 1;
+	}
+
+	/*
+	 * We are inside the irq code, and this is not the entry.
+	 */
+	return 1;
+}
+
 static enum print_line_t
 print_graph_entry(struct ftrace_graph_ent_entry *field, struct trace_seq *s,
 			struct trace_iterator *iter, u32 flags)
@@ -857,6 +947,9 @@ print_graph_entry(struct ftrace_graph_ent_entry *field, struct trace_seq *s,
 	static enum print_line_t ret;
 	int cpu = iter->cpu;
 
+	if (check_irq_entry(iter, flags, call->func, call->depth))
+		return TRACE_TYPE_HANDLED;
+
 	if (print_graph_prologue(iter, s, TRACE_GRAPH_ENT, call->func, flags))
 		return TRACE_TYPE_PARTIAL_LINE;
 
@@ -894,6 +987,9 @@ print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s,
 	int ret;
 	int i;
 
+	if (check_irq_return(iter, flags, trace->depth))
+		return TRACE_TYPE_HANDLED;
+
 	if (data) {
 		struct fgraph_cpu_data *cpu_data;
 		int cpu = iter->cpu;
@@ -1202,9 +1298,12 @@ void graph_trace_open(struct trace_iterator *iter)
 		pid_t *pid = &(per_cpu_ptr(data->cpu_data, cpu)->last_pid);
 		int *depth = &(per_cpu_ptr(data->cpu_data, cpu)->depth);
 		int *ignore = &(per_cpu_ptr(data->cpu_data, cpu)->ignore);
+		int *depth_irq = &(per_cpu_ptr(data->cpu_data, cpu)->depth_irq);
+
 		*pid = -1;
 		*depth = 0;
 		*ignore = 0;
+		*depth_irq = -1;
 	}
 
 	iter->private = data;

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

[Jiri Olsa]

On Tue, Sep 07, 2010 at 09:44:17AM -0400, Steven Rostedt wrote:
> On Tue, 2010-09-07 at 13:31 +0200, Jiri Olsa wrote:
> 
> > I messed up when I was reminding myself... :) it's the graph output
> > for wakeup tracer (earlier email) and this one..
> 
> Could you resend the patch(es) that are needed. And could you rebase it
> against mainline.
> 
> Thanks,
> 
> -- Steve
> 
> 

hi,
attached updated patch for funcgraph-irq option.

I'll have a look on the wakeup tracer stuff based
on the comments I got from Frederic and resend later.

thanks,
jirka

---
Adding funcgraph-irq option for function graph tracer.

It's handy to be able to disable the irq related output
and not to have to jump over each irq related code, when
you have no interrest in it.

The option is by default enabled, so there's no change to
current behaviour. It affects only the final output, so all
the irq related data stay in the ring buffer.


Signed-off-by: Jiri Olsa <jolsa@redhat.com>
---
diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index c93bcb2..8674750 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		depth_irq;
 	int		ignore;
 	unsigned long	enter_funcs[FTRACE_RETFUNC_DEPTH];
 };
@@ -41,6 +42,7 @@ struct fgraph_data {
 #define TRACE_GRAPH_PRINT_PROC		0x8
 #define TRACE_GRAPH_PRINT_DURATION	0x10
 #define TRACE_GRAPH_PRINT_ABS_TIME	0x20
+#define TRACE_GRAPH_PRINT_IRQS		0x40
 
 static struct tracer_opt trace_opts[] = {
 	/* Display overruns? (for self-debug purpose) */
@@ -55,13 +57,15 @@ static struct tracer_opt trace_opts[] = {
 	{ TRACER_OPT(funcgraph-duration, TRACE_GRAPH_PRINT_DURATION) },
 	/* Display absolute time of an entry */
 	{ TRACER_OPT(funcgraph-abstime, TRACE_GRAPH_PRINT_ABS_TIME) },
+	/* Display interrupts */
+	{ TRACER_OPT(funcgraph-irqs, TRACE_GRAPH_PRINT_IRQS) },
 	{ } /* Empty entry */
 };
 
 static struct tracer_flags tracer_flags = {
 	/* Don't display overruns and proc by default */
 	.val = TRACE_GRAPH_PRINT_CPU | TRACE_GRAPH_PRINT_OVERHEAD |
-	       TRACE_GRAPH_PRINT_DURATION,
+	       TRACE_GRAPH_PRINT_DURATION | TRACE_GRAPH_PRINT_IRQS,
 	.opts = trace_opts
 };
 
@@ -855,6 +859,92 @@ print_graph_prologue(struct trace_iterator *iter, struct trace_seq *s,
 	return 0;
 }
 
+/*
+ * Entry check for irq code
+ *
+ * returns 1 if
+ *  - we are inside irq code
+ *  - we just extered irq code
+ *
+ * retunns 0 if
+ *  - funcgraph-interrupts option is set
+ *  - we are not inside irq code
+ */
+static int
+check_irq_entry(struct trace_iterator *iter, u32 flags,
+		unsigned long addr, int depth)
+{
+	int cpu = iter->cpu;
+	struct fgraph_data *data = iter->private;
+	int *depth_irq = &(per_cpu_ptr(data->cpu_data, cpu)->depth_irq);
+
+	if (flags & TRACE_GRAPH_PRINT_IRQS)
+		return 0;
+
+	/*
+	 * We are inside the irq code
+	 */
+	if (*depth_irq >= 0)
+		return 1;
+
+	if ((addr < (unsigned long)__irqentry_text_start) ||
+	    (addr >= (unsigned long)__irqentry_text_end))
+		return 0;
+
+	/*
+	 * We are entering irq code.
+	 */
+	*depth_irq = depth;
+	return 1;
+}
+
+/*
+ * Return check for irq code
+ *
+ * returns 1 if
+ *  - we are inside irq code
+ *  - we just left irq code
+ *
+ * returns 0 if
+ *  - funcgraph-interrupts option is set
+ *  - we are not inside irq code
+ */
+static int
+check_irq_return(struct trace_iterator *iter, u32 flags, int depth)
+{
+	int cpu = iter->cpu;
+	struct fgraph_data *data = iter->private;
+	int *depth_irq = &(per_cpu_ptr(data->cpu_data, cpu)->depth_irq);
+
+	if (flags & TRACE_GRAPH_PRINT_IRQS)
+		return 0;
+
+	/*
+	 * We are not inside the irq code.
+	 */
+	if (*depth_irq == -1)
+		return 0;
+
+	/*
+	 * We are inside the irq code, and this is returning entry.
+	 * Let's not trace it and clear the entry depth, since
+	 * we are out of irq code.
+	 *
+	 * This condition ensures that we 'leave the irq code' once
+	 * we are out of the entry depth. Thus protecting us from
+	 * the RETURN entry loss.
+	 */
+	if (*depth_irq >= depth) {
+		*depth_irq = -1;
+		return 1;
+	}
+
+	/*
+	 * We are inside the irq code, and this is not the entry.
+	 */
+	return 1;
+}
+
 static enum print_line_t
 print_graph_entry(struct ftrace_graph_ent_entry *field, struct trace_seq *s,
 			struct trace_iterator *iter, u32 flags)
@@ -865,6 +955,9 @@ print_graph_entry(struct ftrace_graph_ent_entry *field, struct trace_seq *s,
 	static enum print_line_t ret;
 	int cpu = iter->cpu;
 
+	if (check_irq_entry(iter, flags, call->func, call->depth))
+		return TRACE_TYPE_HANDLED;
+
 	if (print_graph_prologue(iter, s, TRACE_GRAPH_ENT, call->func, flags))
 		return TRACE_TYPE_PARTIAL_LINE;
 
@@ -902,6 +995,9 @@ print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s,
 	int ret;
 	int i;
 
+	if (check_irq_return(iter, flags, trace->depth))
+		return TRACE_TYPE_HANDLED;
+
 	if (data) {
 		struct fgraph_cpu_data *cpu_data;
 		int cpu = iter->cpu;
@@ -1210,9 +1306,12 @@ void graph_trace_open(struct trace_iterator *iter)
 		pid_t *pid = &(per_cpu_ptr(data->cpu_data, cpu)->last_pid);
 		int *depth = &(per_cpu_ptr(data->cpu_data, cpu)->depth);
 		int *ignore = &(per_cpu_ptr(data->cpu_data, cpu)->ignore);
+		int *depth_irq = &(per_cpu_ptr(data->cpu_data, cpu)->depth_irq);
+
 		*pid = -1;
 		*depth = 0;
 		*ignore = 0;
+		*depth_irq = -1;
 	}
 
 	iter->private = data;

[tip:perf/core] tracing: Add funcgraph-irq option for function graph tracer.

[tip-bot for Jiri Olsa]

Commit-ID:  2bd16212b8eb86f9574e78d6605a5ba9e9aa8c4e
Gitweb:     http://git.kernel.org/tip/2bd16212b8eb86f9574e78d6605a5ba9e9aa8c4e
Author:     Jiri Olsa <jolsa@redhat.com>
AuthorDate: Tue, 7 Sep 2010 16:53:44 +0200
Committer:  Steven Rostedt <rostedt@goodmis.org>
CommitDate: Tue, 14 Sep 2010 20:18:07 -0400

tracing: Add funcgraph-irq option for function graph tracer.

It's handy to be able to disable the irq related output
and not to have to jump over each irq related code, when
you have no interrest in it.

The option is by default enabled, so there's no change to
current behaviour. It affects only the final output, so all
the irq related data stay in the ring buffer.

Signed-off-by: Jiri Olsa <jolsa@redhat.com>
LKML-Reference: <20100907145344.GC1912@jolsa.brq.redhat.com>
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
---
 kernel/trace/trace_functions_graph.c |  101 +++++++++++++++++++++++++++++++++-
 1 files changed, 100 insertions(+), 1 deletions(-)

diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index c93bcb2..8674750 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		depth_irq;
 	int		ignore;
 	unsigned long	enter_funcs[FTRACE_RETFUNC_DEPTH];
 };
@@ -41,6 +42,7 @@ struct fgraph_data {
 #define TRACE_GRAPH_PRINT_PROC		0x8
 #define TRACE_GRAPH_PRINT_DURATION	0x10
 #define TRACE_GRAPH_PRINT_ABS_TIME	0x20
+#define TRACE_GRAPH_PRINT_IRQS		0x40
 
 static struct tracer_opt trace_opts[] = {
 	/* Display overruns? (for self-debug purpose) */
@@ -55,13 +57,15 @@ static struct tracer_opt trace_opts[] = {
 	{ TRACER_OPT(funcgraph-duration, TRACE_GRAPH_PRINT_DURATION) },
 	/* Display absolute time of an entry */
 	{ TRACER_OPT(funcgraph-abstime, TRACE_GRAPH_PRINT_ABS_TIME) },
+	/* Display interrupts */
+	{ TRACER_OPT(funcgraph-irqs, TRACE_GRAPH_PRINT_IRQS) },
 	{ } /* Empty entry */
 };
 
 static struct tracer_flags tracer_flags = {
 	/* Don't display overruns and proc by default */
 	.val = TRACE_GRAPH_PRINT_CPU | TRACE_GRAPH_PRINT_OVERHEAD |
-	       TRACE_GRAPH_PRINT_DURATION,
+	       TRACE_GRAPH_PRINT_DURATION | TRACE_GRAPH_PRINT_IRQS,
 	.opts = trace_opts
 };
 
@@ -855,6 +859,92 @@ print_graph_prologue(struct trace_iterator *iter, struct trace_seq *s,
 	return 0;
 }
 
+/*
+ * Entry check for irq code
+ *
+ * returns 1 if
+ *  - we are inside irq code
+ *  - we just extered irq code
+ *
+ * retunns 0 if
+ *  - funcgraph-interrupts option is set
+ *  - we are not inside irq code
+ */
+static int
+check_irq_entry(struct trace_iterator *iter, u32 flags,
+		unsigned long addr, int depth)
+{
+	int cpu = iter->cpu;
+	struct fgraph_data *data = iter->private;
+	int *depth_irq = &(per_cpu_ptr(data->cpu_data, cpu)->depth_irq);
+
+	if (flags & TRACE_GRAPH_PRINT_IRQS)
+		return 0;
+
+	/*
+	 * We are inside the irq code
+	 */
+	if (*depth_irq >= 0)
+		return 1;
+
+	if ((addr < (unsigned long)__irqentry_text_start) ||
+	    (addr >= (unsigned long)__irqentry_text_end))
+		return 0;
+
+	/*
+	 * We are entering irq code.
+	 */
+	*depth_irq = depth;
+	return 1;
+}
+
+/*
+ * Return check for irq code
+ *
+ * returns 1 if
+ *  - we are inside irq code
+ *  - we just left irq code
+ *
+ * returns 0 if
+ *  - funcgraph-interrupts option is set
+ *  - we are not inside irq code
+ */
+static int
+check_irq_return(struct trace_iterator *iter, u32 flags, int depth)
+{
+	int cpu = iter->cpu;
+	struct fgraph_data *data = iter->private;
+	int *depth_irq = &(per_cpu_ptr(data->cpu_data, cpu)->depth_irq);
+
+	if (flags & TRACE_GRAPH_PRINT_IRQS)
+		return 0;
+
+	/*
+	 * We are not inside the irq code.
+	 */
+	if (*depth_irq == -1)
+		return 0;
+
+	/*
+	 * We are inside the irq code, and this is returning entry.
+	 * Let's not trace it and clear the entry depth, since
+	 * we are out of irq code.
+	 *
+	 * This condition ensures that we 'leave the irq code' once
+	 * we are out of the entry depth. Thus protecting us from
+	 * the RETURN entry loss.
+	 */
+	if (*depth_irq >= depth) {
+		*depth_irq = -1;
+		return 1;
+	}
+
+	/*
+	 * We are inside the irq code, and this is not the entry.
+	 */
+	return 1;
+}
+
 static enum print_line_t
 print_graph_entry(struct ftrace_graph_ent_entry *field, struct trace_seq *s,
 			struct trace_iterator *iter, u32 flags)
@@ -865,6 +955,9 @@ print_graph_entry(struct ftrace_graph_ent_entry *field, struct trace_seq *s,
 	static enum print_line_t ret;
 	int cpu = iter->cpu;
 
+	if (check_irq_entry(iter, flags, call->func, call->depth))
+		return TRACE_TYPE_HANDLED;
+
 	if (print_graph_prologue(iter, s, TRACE_GRAPH_ENT, call->func, flags))
 		return TRACE_TYPE_PARTIAL_LINE;
 
@@ -902,6 +995,9 @@ print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s,
 	int ret;
 	int i;
 
+	if (check_irq_return(iter, flags, trace->depth))
+		return TRACE_TYPE_HANDLED;
+
 	if (data) {
 		struct fgraph_cpu_data *cpu_data;
 		int cpu = iter->cpu;
@@ -1210,9 +1306,12 @@ void graph_trace_open(struct trace_iterator *iter)
 		pid_t *pid = &(per_cpu_ptr(data->cpu_data, cpu)->last_pid);
 		int *depth = &(per_cpu_ptr(data->cpu_data, cpu)->depth);
 		int *ignore = &(per_cpu_ptr(data->cpu_data, cpu)->ignore);
+		int *depth_irq = &(per_cpu_ptr(data->cpu_data, cpu)->depth_irq);
+
 		*pid = -1;
 		*depth = 0;
 		*ignore = 0;
+		*depth_irq = -1;
 	}
 
 	iter->private = data;

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

[Steven Rostedt]

Johannes,

I think it was you that was testing this patch. Could you give me a
"Tested-by" if you have, and it worked out for you.

-- Steve


On Fri, 2010-07-23 at 15:19 +0200, Jiri Olsa wrote:
> On Thu, Jul 22, 2010 at 04:00:21PM -0400, Steven Rostedt wrote:
> > On Mon, 2010-07-12 at 18:21 +0200, Jiri Olsa wrote:
> > 
> SNIP
> 
> > 
> > What happens if we lose the return event? That is, due to buffer
> > overruns, the return of the trace is lost. Then we lose out on all
> > events until another event of the same IRQ happens and its return is not
> > lost.
> > 
> > You should save the depth instead of the function. When you are in a
> > interrupt, record the depth. Then when the depth is less than or equal
> > to the recorded depth you can restart printing. This may still suffer
> > from missed returns, but it would not have as much of a consequence when
> > it happens.
> hi,
> you're right, changed patch is attached
> 
> thanks,
> jirka
> 
> ---
> Adding funcgraph-irq option for function graph tracer.
> 
> It's handy to be able to disable the irq related output
> and not to have to jump over each irq related code, when
> you have no interrest in it.
> 
> The option is by default enabled, so there's no change to
> current behaviour. It affects only the final output, so all
> the irq related data stays in the ring buffer.
> 
> wbr,
> jirka
> 
> 
> Signed-off-by: Jiri Olsa <jolsa@redhat.com>
> ---
>  kernel/trace/trace_functions_graph.c |  101 +++++++++++++++++++++++++++++++++-
>  1 files changed, 100 insertions(+), 1 deletions(-)
> 
> diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
> index 6bff236..e66f71f 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		depth_irq;
>  	int		ignore;
>  	unsigned long	enter_funcs[FTRACE_RETFUNC_DEPTH];
>  };
> @@ -41,6 +42,7 @@ struct fgraph_data {
>  #define TRACE_GRAPH_PRINT_PROC		0x8
>  #define TRACE_GRAPH_PRINT_DURATION	0x10
>  #define TRACE_GRAPH_PRINT_ABS_TIME	0x20
> +#define TRACE_GRAPH_PRINT_IRQS		0x40
>  
>  static struct tracer_opt trace_opts[] = {
>  	/* Display overruns? (for self-debug purpose) */
> @@ -55,13 +57,15 @@ static struct tracer_opt trace_opts[] = {
>  	{ TRACER_OPT(funcgraph-duration, TRACE_GRAPH_PRINT_DURATION) },
>  	/* Display absolute time of an entry */
>  	{ TRACER_OPT(funcgraph-abstime, TRACE_GRAPH_PRINT_ABS_TIME) },
> +	/* Display interrupts */
> +	{ TRACER_OPT(funcgraph-irqs, TRACE_GRAPH_PRINT_IRQS) },
>  	{ } /* Empty entry */
>  };
>  
>  static struct tracer_flags tracer_flags = {
>  	/* Don't display overruns and proc by default */
>  	.val = TRACE_GRAPH_PRINT_CPU | TRACE_GRAPH_PRINT_OVERHEAD |
> -	       TRACE_GRAPH_PRINT_DURATION,
> +	       TRACE_GRAPH_PRINT_DURATION | TRACE_GRAPH_PRINT_IRQS,
>  	.opts = trace_opts
>  };
>  
> @@ -847,6 +851,92 @@ print_graph_prologue(struct trace_iterator *iter, struct trace_seq *s,
>  	return 0;
>  }
>  
> +/*
> + * Entry check for irq code
> + *
> + * returns 1 if
> + *  - we are inside irq code
> + *  - we just extered irq code
> + *
> + * retunns 0 if
> + *  - funcgraph-interrupts option is set
> + *  - we are not inside irq code
> + */
> +static int
> +check_irq_entry(struct trace_iterator *iter, u32 flags,
> +		unsigned long addr, int depth)
> +{
> +	int cpu = iter->cpu;
> +	struct fgraph_data *data = iter->private;
> +	int *depth_irq = &(per_cpu_ptr(data->cpu_data, cpu)->depth_irq);
> +
> +	if (flags & TRACE_GRAPH_PRINT_IRQS)
> +		return 0;
> +
> +	/*
> +	 * We are inside the irq code
> +	 */
> +	if (*depth_irq >= 0)
> +		return 1;
> +
> +	if ((addr < (unsigned long)__irqentry_text_start) ||
> +	    (addr >= (unsigned long)__irqentry_text_end))
> +		return 0;
> +
> +	/*
> +	 * We are entering irq code.
> +	 */
> +	*depth_irq = depth;
> +	return 1;
> +}
> +
> +/*
> + * Return check for irq code
> + *
> + * returns 1 if
> + *  - we are inside irq code
> + *  - we just left irq code
> + *
> + * returns 0 if
> + *  - funcgraph-interrupts option is set
> + *  - we are not inside irq code
> + */
> +static int
> +check_irq_return(struct trace_iterator *iter, u32 flags, int depth)
> +{
> +	int cpu = iter->cpu;
> +	struct fgraph_data *data = iter->private;
> +	int *depth_irq = &(per_cpu_ptr(data->cpu_data, cpu)->depth_irq);
> +
> +	if (flags & TRACE_GRAPH_PRINT_IRQS)
> +		return 0;
> +
> +	/*
> +	 * We are not inside the irq code.
> +	 */
> +	if (*depth_irq == -1)
> +		return 0;
> +
> +	/*
> +	 * We are inside the irq code, and this is returning entry.
> +	 * Let's not trace it and clear the entry depth, since
> +	 * we are out of irq code.
> +	 *
> +	 * This condition ensures that we 'leave the irq code' once
> +	 * we are out of the entry depth. Thus protecting us from
> +	 * the RETURN entry loss.
> +	 */
> +	if (*depth_irq >= depth) {
> +		*depth_irq = -1;
> +		return 1;
> +	}
> +
> +	/*
> +	 * We are inside the irq code, and this is not the entry.
> +	 */
> +	return 1;
> +}
> +
>  static enum print_line_t
>  print_graph_entry(struct ftrace_graph_ent_entry *field, struct trace_seq *s,
>  			struct trace_iterator *iter, u32 flags)
> @@ -857,6 +947,9 @@ print_graph_entry(struct ftrace_graph_ent_entry *field, struct trace_seq *s,
>  	static enum print_line_t ret;
>  	int cpu = iter->cpu;
>  
> +	if (check_irq_entry(iter, flags, call->func, call->depth))
> +		return TRACE_TYPE_HANDLED;
> +
>  	if (print_graph_prologue(iter, s, TRACE_GRAPH_ENT, call->func, flags))
>  		return TRACE_TYPE_PARTIAL_LINE;
>  
> @@ -894,6 +987,9 @@ print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s,
>  	int ret;
>  	int i;
>  
> +	if (check_irq_return(iter, flags, trace->depth))
> +		return TRACE_TYPE_HANDLED;
> +
>  	if (data) {
>  		struct fgraph_cpu_data *cpu_data;
>  		int cpu = iter->cpu;
> @@ -1202,9 +1298,12 @@ void graph_trace_open(struct trace_iterator *iter)
>  		pid_t *pid = &(per_cpu_ptr(data->cpu_data, cpu)->last_pid);
>  		int *depth = &(per_cpu_ptr(data->cpu_data, cpu)->depth);
>  		int *ignore = &(per_cpu_ptr(data->cpu_data, cpu)->ignore);
> +		int *depth_irq = &(per_cpu_ptr(data->cpu_data, cpu)->depth_irq);
> +
>  		*pid = -1;
>  		*depth = 0;
>  		*ignore = 0;
> +		*depth_irq = -1;
>  	}
>  
>  	iter->private = data;

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

[Johannes Weiner]

Hi Steven,

On Tue, Sep 07, 2010 at 12:28:40PM -0400, Steven Rostedt wrote:
> Johannes,
> 
> I think it was you that was testing this patch. Could you give me a
> "Tested-by" if you have, and it worked out for you.

Yes, sure.  I haven't come around to it yet, but I will try within the
next few days and let you know.

	Hannes

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

[Johannes Weiner]

Hi Guys,

On Tue, Sep 07, 2010 at 12:28:40PM -0400, Steven Rostedt wrote:
> On Fri, 2010-07-23 at 15:19 +0200, Jiri Olsa wrote:
> > On Thu, Jul 22, 2010 at 04:00:21PM -0400, Steven Rostedt wrote:
> > > On Mon, 2010-07-12 at 18:21 +0200, Jiri Olsa wrote:
> > > 
> > SNIP
> > 
> > > 
> > > What happens if we lose the return event? That is, due to buffer
> > > overruns, the return of the trace is lost. Then we lose out on all
> > > events until another event of the same IRQ happens and its return is not
> > > lost.
> > > 
> > > You should save the depth instead of the function. When you are in a
> > > interrupt, record the depth. Then when the depth is less than or equal
> > > to the recorded depth you can restart printing. This may still suffer
> > > from missed returns, but it would not have as much of a consequence when
> > > it happens.
> > hi,
> > you're right, changed patch is attached
> > 
> > thanks,
> > jirka
> > 
> > ---
> > Adding funcgraph-irq option for function graph tracer.
> > 
> > It's handy to be able to disable the irq related output
> > and not to have to jump over each irq related code, when
> > you have no interrest in it.

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();

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

[Jiri Olsa]

On Thu, Sep 09, 2010 at 04:44:30PM +0200, Johannes Weiner wrote:
> Hi Guys,
> 
> On Tue, Sep 07, 2010 at 12:28:40PM -0400, Steven Rostedt wrote:
> > On Fri, 2010-07-23 at 15:19 +0200, Jiri Olsa wrote:
> > > On Thu, Jul 22, 2010 at 04:00:21PM -0400, Steven Rostedt wrote:
> > > > On Mon, 2010-07-12 at 18:21 +0200, Jiri Olsa wrote:
> > > > 
> > > SNIP
> > > 
> > > > 
> > > > What happens if we lose the return event? That is, due to buffer
> > > > overruns, the return of the trace is lost. Then we lose out on all
> > > > events until another event of the same IRQ happens and its return is not
> > > > lost.
> > > > 
> > > > You should save the depth instead of the function. When you are in a
> > > > interrupt, record the depth. Then when the depth is less than or equal
> > > > to the recorded depth you can restart printing. This may still suffer
> > > > from missed returns, but it would not have as much of a consequence when
> > > > it happens.
> > > hi,
> > > you're right, changed patch is attached
> > > 
> > > thanks,
> > > jirka
> > > 
> > > ---
> > > Adding funcgraph-irq option for function graph tracer.
> > > 
> > > It's handy to be able to disable the irq related output
> > > and not to have to jump over each irq related code, when
> > > you have no interrest in it.
> 
> 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();
>
hi,

both smp_invalidate_interrupt and native_apic_mem_write are not put
into __irqentry_text code location, so the logic misses them.

I'm not sure how such functions could be caught besides function
pointer check..

It looks like smp_invalidate_interrupt is used for TLB mainating,
which I know nothing about.. :) anyone knows wether it would make
sense to put those function to __irqentry_text area?

thanks,
jirka

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