tracing, function graph: Remove the noisy output when use function graph filter

PATCH In review Lai Jiangshan 2 participants 2 messages Jun 18, 2010 Tracing

Share & tools

Lai Jiangshan

author

2010-06-18 08:15 UTC #0 lore raw

PATCH v2 1/1 tracing, function graph: Remove the noisy output when use function graph filter

If we use function graph filter(echo some_functions >> set_graph_function) we are only interested in the graph of some_functions.

But if a interrupt occurs when these functions are being traced(or preparing), the graphs of the handlers of this interrupt are also recorded. These events that we aren't interested in are totally noisy.

This patch skip the noise when TRACE_GRAPH_FILTER_SKIP_INTR flag is on (very very seldom noise is still left, It's OK for tracing, doesn't it?).

changed from v1:
Add a TRACE_GRAPH_FILTER_SKIP_INTR flag which is default off to control it.

Signed-off-by Lai Jiangshan <[email protected]>

---

kernel/trace/trace_functions_graph.c +16 -2

index 79f4bac..d4fa4a4 100644
@@ -12,6 +12,8 @@
 #include <linux/slab.h>
 #include <linux/fs.h>
 
+#include <asm/irq_regs.h>
+
 #include "trace.h"
 #include "trace_output.h"

@@ -41,6 +43,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_FILTER_SKIP_INTR	0x40
 
 static struct tracer_opt trace_opts[] = {
 	/* Display overruns? (for self-debug purpose) */

@@ -55,6 +58,8 @@ 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) },
+	/* Skip the graph nested in interrupts when funcgraph filter enabled */
+	{ TRACER_OPT(funcgraph-filter-skip-intr, TRACE_GRAPH_FILTER_SKIP_INTR) },
 	{ } /* Empty entry */
 };

@@ -213,13 +218,22 @@ int trace_graph_entry(struct ftrace_graph_ent *trace)
 	int ret;
 	int cpu;
 	int pc;
+	int depth = trace->depth;
+	unsigned long long cntxt = (unsigned long)(void *)get_irq_regs();
 
 	if (!ftrace_trace_task(current))
 		return 0;
 
 	/* trace it when it is-nested-in or is a function enabled. */
-	if (!(trace->depth || ftrace_graph_addr(trace->func)))
-		return 0;
+	if (!ftrace_graph_addr(trace->func)) {
+		if (!depth)
+			return 0;
+		if ((tracer_flags.val & TRACE_GRAPH_FILTER_SKIP_INTR)
+		    && (current->ret_stack[depth - 1].subtime != cntxt))
+			return 0;
+	}
+	/* We don't use subtime here, reuse it to save context. */
+	current->ret_stack[depth].subtime = cntxt;
 
 	local_irq_save(flags);
 	cpu = raw_smp_processor_id();

Steven Rostedt

maintainer

2010-06-18 15:16 UTC #1 lore raw

Quoted 52 lines · Lai Jiangshan

If we use function graph filter(echo some_functions >> set_graph_function) we are only interested in the graph of some_functions.
But if a interrupt occurs when these functions are being traced(or preparing), the graphs of the handlers of this interrupt are also recorded. These events that we aren't interested in are totally noisy.
This patch skip the noise when TRACE_GRAPH_FILTER_SKIP_INTR flag is on (very very seldom noise is still left, It's OK for tracing, doesn't it?).
changed from v1:
Add a TRACE_GRAPH_FILTER_SKIP_INTR flag which is default off to control it.
Signed-off-by Lai Jiangshan <[email protected]>
---
kernel/trace/trace_functions_graph.c +7 -0
index 79f4bac..d4fa4a4 100644
@@ -12,6 +12,8 @@
 #include <linux/slab.h>
 #include <linux/fs.h>
 
+#include <asm/irq_regs.h>
+
 #include "trace.h"
 #include "trace_output.h"
 
@@ -41,6 +43,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_FILTER_SKIP_INTR	0x40
 
 static struct tracer_opt trace_opts[] = {
 	/* Display overruns? (for self-debug purpose) */
@@ -55,6 +58,8 @@ 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) },
+	/* Skip the graph nested in interrupts when funcgraph filter enabled */
+	{ TRACER_OPT(funcgraph-filter-skip-intr, TRACE_GRAPH_FILTER_SKIP_INTR) },
 	{ } /* Empty entry */
 };
 
@@ -213,13 +218,22 @@ int trace_graph_entry(struct ftrace_graph_ent *trace)
 	int ret;
 	int cpu;
 	int pc;
+	int depth = trace->depth;
+	unsigned long long cntxt = (unsigned long)(void *)get_irq_regs();

kernel/trace/trace_functions_graph.c int trace_graph_entry(struct ftrace_graph_ent *trace) · line 230

Quoted 10 lines

kernel/trace/trace_functions_graph.c +3 -2

 
 	if (!ftrace_trace_task(current))
 		return 0;
 
 	/* trace it when it is-nested-in or is a function enabled. */
-	if (!(trace->depth || ftrace_graph_addr(trace->func)))
-		return 0;
+	if (!ftrace_graph_addr(trace->func)) {
+		if (!depth)
+			return 0;

Note, as I mentioned in my last email, ftrace_graph_addr() is not that cheap of a function. If we can bypass it, then lets do it. The cheap things to check are depth and flags. Do them first.

If depth is set, then there's no reason to do the ftrace_graph_addr() (which is a loop of checking functions!).

The only time we need to do ftrace_graph_addr() is when depth is zero, or flags is set to TRACE_GRAPH_FILTER_SKIP_INTR and the context does not match.

This gets called by _every_function_, it needs to be micro optimized.

kernel/trace/trace_functions_graph.c int trace_graph_entry(struct ftrace_graph_ent *trace) · line 236

Quoted 6 lines

kernel/trace/trace_functions_graph.c +6 -0

+		if ((tracer_flags.val & TRACE_GRAPH_FILTER_SKIP_INTR)
+		    && (current->ret_stack[depth - 1].subtime != cntxt))
+			return 0;
+	}
+	/* We don't use subtime here, reuse it to save context. */
+	current->ret_stack[depth].subtime = cntxt;

I still don't like this double use of subtime. It seems too much of a hack.

What we could also do, which would probably be even better yet, is to have two functions. One for when TRACE_GRAPH_FILTER_SKIP_INTR is set and one when it is not. This will avoid the conditionals. Then just register the proper function with register_ftrace_graph() depending on what the options are.

You can even change the function if the options are set.

-- Steve

Quoted 4 lines

kernel/trace/trace_functions_graph.c +0 -0
 	local_irq_save(flags);
 	cpu = raw_smp_processor_id();
 