ftrace: add ftrace_graph_max_depth kernel parameter

PATCH In review Todd Brandt 2 participants 7 messages Mar 3, 2017

Subsystems (3)

Documentation Tracing ftrace

lore

Share & tools

lore

Todd Brandt

author

2017-03-03 00:16 UTC #0 lore raw

PATCH 1/1 ftrace: add ftrace_graph_max_depth kernel parameter

Early trace callgraphs can be extremely large on systems with several seconds of boot time. The max_depth parameter limits how deep the graph trace goes and reduces the output size. This parameter is the same as the max_graph_depth file in debugfs.

Signed-off-by Todd Brandt <[email protected]>

---
 Documentation/admin-guide/kernel-parameters.txt | 6 ++++++
 kernel/trace/ftrace.c                           | 9 +++++++++
 2 files changed, 15 insertions(+)

Documentation/admin-guide/kernel-parameters.txt +6 -0

index 986e443..1a8575f 100644
@@ -1183,6 +1183,12 @@
 			functions that can be changed at run time by the
 			set_graph_notrace file in the debugfs tracing directory.
 
+	ftrace_graph_max_depth=<uint>
+			[FTRACE] Used with the function graph tracer. This is
+			the max depth it will trace into a function. This value
+			can be changed at run time by the max_graph_depth file
+			in the debugfs tracing directory. default: 0 (no limit)
+
 	gamecon.map[2|3]=
 			[HW,JOY] Multisystem joystick and NES/SNES/PSX pad
 			support via parallel port (up to 5 devices per port)

kernel/trace/ftrace.c +9 -0

index 0c06093..fc6b024 100644
@@ -4415,6 +4415,15 @@ static int __init set_graph_notrace_function(char *str)
 }
 __setup("ftrace_graph_notrace=", set_graph_notrace_function);
 
+static int __init set_graph_max_depth_function(char *str)
+{
+	if (!str)
+		return 0;
+	fgraph_max_depth = simple_strtoul(str, NULL, 0);
+	return 1;
+}
+__setup("ftrace_graph_max_depth=", set_graph_max_depth_function);
+
 static void __init set_ftrace_early_graph(char *buf, int enable)
 {
 	int ret;

Signature · 1 line

2.1.4

Steven Rostedt

maintainer

2017-03-03 01:56 UTC #1 lore raw

Quoted 4 lines · On Thu, 2 Mar 2017 16:12:15 -0800 Todd Brandt <[email protected]>…

Early trace callgraphs can be extremely large on systems with several seconds of boot time. The max_depth parameter limits how deep the graph trace goes and reduces the output size. This parameter is the same as the max_graph_depth file in debugfs.

I'll take this with one modification I'll make. s/debugfs/tracefs/ because it's really the tracefs file system now. It just happens to be automatically mounted in the debugfs file system. But can be by itself in /sys/kernel/tracing/

-- Steve

Quoted 44 lines

Signed-off-by Todd Brandt <[email protected]>

---
 Documentation/admin-guide/kernel-parameters.txt | 6 ++++++
 kernel/trace/ftrace.c                           | 9 +++++++++
 2 files changed, 15 insertions(+)

Documentation/admin-guide/kernel-parameters.txt +6 -0

index 986e443..1a8575f 100644
@@ -1183,6 +1183,12 @@
 			functions that can be changed at run time by the
 			set_graph_notrace file in the debugfs tracing directory.
 
+	ftrace_graph_max_depth=<uint>
+			[FTRACE] Used with the function graph tracer. This is
+			the max depth it will trace into a function. This value
+			can be changed at run time by the max_graph_depth file
+			in the debugfs tracing directory. default: 0 (no limit)
+
 	gamecon.map[2|3]=
 			[HW,JOY] Multisystem joystick and NES/SNES/PSX pad
 			support via parallel port (up to 5 devices per port)

kernel/trace/ftrace.c +9 -0

index 0c06093..fc6b024 100644
@@ -4415,6 +4415,15 @@ static int __init set_graph_notrace_function(char *str)
 }
 __setup("ftrace_graph_notrace=", set_graph_notrace_function);
 
+static int __init set_graph_max_depth_function(char *str)
+{
+	if (!str)
+		return 0;
+	fgraph_max_depth = simple_strtoul(str, NULL, 0);
+	return 1;
+}
+__setup("ftrace_graph_max_depth=", set_graph_max_depth_function);
+
 static void __init set_ftrace_early_graph(char *buf, int enable)
 {
 	int ret;

Steven Rostedt

maintainer

2017-03-03 00:40 UTC #2 lore raw

Quoted 22 lines · On Thu, 2 Mar 2017 19:38:27 -0500 Steven Rostedt <[email protected]> wrote:

Quoted 4 lines · On Thu, 2 Mar 2017 16:12:15 -0800 Todd Brandt <[email protected]>…
Early trace callgraphs can be extremely large on systems with several seconds of boot time. The max_depth parameter limits how deep the graph trace goes and reduces the output size. This parameter is the same as the max_graph_depth file in debugfs.
I'll take this with one modification I'll make. s/debugfs/tracefs/ because it's really the tracefs file system now. It just happens to be automatically mounted in the debugfs file system. But can be by itself in /sys/kernel/tracing/
-- Steve
Quoted 7 lines
Signed-off-by Todd Brandt <[email protected]>
---
 Documentation/admin-guide/kernel-parameters.txt | 6 ++++++
 kernel/trace/ftrace.c                           | 9 +++++++++
 2 files changed, 15 insertions(+)

Quoted 7 lines

Documentation/admin-guide/kernel-parameters.txt line 1184
Quoted 7 lines
Documentation/admin-guide/kernel-parameters.txt +0 -0
index 986e443..1a8575f 100644
@@ -1183,6 +1183,12 @@
 			functions that can be changed at run time by the
 			set_graph_notrace file in the debugfs tracing directory.

I need to make a patch to update the old documentation to reflect this as well. But I'll do that another time.

-- Steve

Todd Brandt

author

2017-03-03 00:58 UTC #3 lore raw

Quoted 11 lines · Steven Rostedt

Quoted 8 lines · On Thu, 2 Mar 2017 19:38:27 -0500 Steven Rostedt <[email protected]> wrote:
Quoted 4 lines · On Thu, 2 Mar 2017 16:12:15 -0800 Todd Brandt <[email protected]>…
Early trace callgraphs can be extremely large on systems with several seconds of boot time. The max_depth parameter limits how deep the graph trace goes and reduces the output size. This parameter is the same as the max_graph_depth file in debugfs.

Quoted 4 lines

Quoted 4 lines
I'll take this with one modification I'll make. s/debugfs/tracefs/ because it's really the tracefs file system now. It just happens to be automatically mounted in the debugfs file system. But can be by itself in /sys/kernel/tracing/

thanks!

BTW I had one other question for you, is it possible to move the ftrace module's initialization further up the queue? ATM it initializes at about 600ms into boot, which is fine since most of the performance issues are happening at 1000ms+. But eventually it might be nice to trace some of the earlier init code.

Quoted 22 lines

Quoted 10 lines
-- Steve
Quoted 7 lines
Signed-off-by Todd Brandt <[email protected]>
---
 Documentation/admin-guide/kernel-parameters.txt | 6 ++++++
 kernel/trace/ftrace.c                           | 9 +++++++++
 2 files changed, 15 insertions(+)
Quoted 7 lines
Documentation/admin-guide/kernel-parameters.txt line 1184
Quoted 7 lines
Documentation/admin-guide/kernel-parameters.txt +0 -0
index 986e443..1a8575f 100644
@@ -1183,6 +1183,12 @@
 			functions that can be changed at run time by the
 			set_graph_notrace file in the debugfs tracing directory.
I need to make a patch to update the old documentation to reflect this as well. But I'll do that another time.
-- Steve

Steven Rostedt

maintainer

2017-03-03 08:16 UTC #4 lore raw

Quoted 5 lines · On Thu, 02 Mar 2017 16:54:57 -0800 Todd Brandt <[email protected]>…

BTW I had one other question for you, is it possible to move the ftrace module's initialization further up the queue? ATM it initializes at about 600ms into boot, which is fine since most of the performance issues are happening at 1000ms+. But eventually it might be nice to trace some of the earlier init code.

module initialization? Or you mean boot up initialization?

For boot up, we have this:

	mm_init();
	sched_init();
	idr_init_cache();
	workqueue_init_early();
	rcu_init();
	trace_init();

Now, going before mm_init() will definitely be quite a pain, as we that would require making the ring buffer out of early boot memory.

We could add a early_trace_init() just before sched_init(), with some limited tracing. Tracepoints require rcu, although we could make hooks to just do hard coded changes (no rcu synchronization) with a flag that denotes that trace_init() hasn't been called yet.

I could toy with the idea, implement it, and see what breaks.

-- Steve

Todd Brandt

author

2017-03-03 01:49 UTC #5 lore raw

Quoted 11 lines · Steven Rostedt

Quoted 5 lines · On Thu, 02 Mar 2017 16:54:57 -0800 Todd Brandt <[email protected]>…
BTW I had one other question for you, is it possible to move the ftrace module's initialization further up the queue? ATM it initializes at about 600ms into boot, which is fine since most of the performance issues are happening at 1000ms+. But eventually it might be nice to trace some of the earlier init code.
module initialization? Or you mean boot up initialization?

oh right, yes.

Quoted 13 lines

For boot up, we have this:
	mm_init();
	sched_init();
	idr_init_cache();
	workqueue_init_early();
	rcu_init();
	trace_init();
Now, going before mm_init() will definitely be quite a pain, as we that would require making the ring buffer out of early boot memory.

Quoted 6 lines

We could add a early_trace_init() just before sched_init(), with some limited tracing. Tracepoints require rcu, although we could make hooks to just do hard coded changes (no rcu synchronization) with a flag that denotes that trace_init() hasn't been called yet.
I could toy with the idea, implement it, and see what breaks.

If it was possible that would be great. The reason I ask is because I've implemented a tool called analyze_boot which I intend to upgrade to use early callgraph trace (it just uses initcall_debug now):

https://marc.info/?l=linux-pm&m=148667508500967&w=2

I'll have it do the same thing for boot that analyze_suspend does for suspend/resume: display the callgraphs for each initcall instance in html. The max_graph_depth param is necessary to keep the html outputs manageable. Most laptop/desktop machines running standard linux seem to take at least 5 seconds for boot, but we've got some servers optimized to boot in less than a second (which means I'd only be able to trace half of the boot timeline or less). The more coverage I can get the better.

P.S. I submitted the analyze_boot tool on the pm list but Raphael didn't think it would fit in the PM tree. Would you be willing to accept this script? (I can resubmit but nothing's changed since the RESEND).

Quoted 2 lines

-- Steve

Steven Rostedt

maintainer

2017-03-03 15:27 UTC #6 lore raw

Quoted 16 lines · On Thu, 02 Mar 2017 17:35:31 -0800 Todd Brandt <[email protected]>…

Quoted 1 line
I could toy with the idea, implement it, and see what breaks.
If it was possible that would be great. The reason I ask is because I've implemented a tool called analyze_boot which I intend to upgrade to use early callgraph trace (it just uses initcall_debug now):
https://marc.info/?l=linux-pm&m=148667508500967&w=2
I'll have it do the same thing for boot that analyze_suspend does for suspend/resume: display the callgraphs for each initcall instance in html. The max_graph_depth param is necessary to keep the html outputs manageable. Most laptop/desktop machines running standard linux seem to take at least 5 seconds for boot, but we've got some servers optimized to boot in less than a second (which means I'd only be able to trace half of the boot timeline or less). The more coverage I can get the better.

Quoted 3 lines

P.S. I submitted the analyze_boot tool on the pm list but Raphael didn't think it would fit in the PM tree. Would you be willing to accept this script? (I can resubmit but nothing's changed since the RESEND).

That may be something to ask Andrew about. He's sorta the one to dump changes to that don't seem to fit anywhere else.

-- Steve