ftrace_graph_filter not working correctly since v4.10

DISCUSSION Todd Brandt 3 participants 8 messages Mar 2, 2017 – Mar 3, 2017

Subsystems (2)

Tracing ftrace

lore

Share & tools

lore

Todd Brandt

author

2017-03-02 02:01 UTC #0 lore raw

I've been using early boot trace to gather callgraph data on filtered functions but something appears to have broken it in v10.0. The graph trace worked fine in v4.10-rc8, so something changed since the release.

Issue:
Using the ftrace_graph_filter kernel parameter to filter on a specific function produces no data (msleep for instance). The graph trace also continues to produce nothing even after reconfiguring it through debugfs. It worked fine in v4.10-rc8 but fails in v4.10.

To reproduce:
GRUB_CMDLINE_LINUX_DEFAULT="initcall_debug \
log_buf_len=32M \
trace_options=nooverwrite,\
funcgraph-abstime,\
funcgraph-cpu,\
funcgraph-duration,\
funcgraph-proc,\
funcgraph-tail,\
nofuncgraph-overhead,\
context-info,\
graph-time \
ftrace=function_graph \
ftrace_graph_filter=msleep"

The trace output is this:
# tracer: function_graph
#
# TIME CPU TASK/PID DURATION
FUNCTION CALLS
# | | | | | | | |
| |

After boot you can also run analyze_suspend to capture a callgraph and it fails to get any callgraph data. It still gets trace marker data, but not callgraph.

# suspend-030117-172549 ivybridge mem 4.10.0+
# fwsuspend 0 fwresume 0
# tracer: function_graph
#
#     TIME        CPU  TASK/PID         DURATION
FUNCTION CALLS
#      |          |     |    |           |   |                     |   |
|   |
  688.257880 |    1)  analyze-1713  |               |  /* SUSPEND START
*/
  688.257901 |    1)  analyze-1713  |               |  /*
suspend_resume: suspend_enter[3] begin */
  688.257902 |    1)  analyze-1713  |               |  /*
suspend_resume: sync_filesystems[0] begin */
  688.259559 |    0)  analyze-1713  |               |  /*
suspend_resume: sync_filesystems[0] end */
  688.260093 |    0)  analyze-1713  |               |  /*
suspend_resume: freeze_processes[0] begin */
  708.279172 |    2)  analyze-1713  |               |  /*
suspend_resume: thaw_processes[0] begin */
  708.282884 |    0)  analyze-1713  |               |  /*
suspend_resume: thaw_processes[0] end */
  708.282888 |    0)  analyze-1713  |               |  /*
suspend_resume: freeze_processes[0] end */
  708.374517 |    0)  analyze-1713  |               |  /* RESUME
COMPLETE */

It seems to work ok if I don't set the ftrace_graph_filter. Has something changed in the kernel params that I missed?

I'll dig a but further to see if I can track down the specific commit, but I just wanted to see if anyone else experienced this.

Steven Rostedt

maintainer

2017-03-02 03:28 UTC #1 lore raw

Quoted 10 lines · On Wed, 01 Mar 2017 18:01:31 -0800 Todd Brandt <[email protected]>…

I've been using early boot trace to gather callgraph data on filtered functions but something appears to have broken it in v10.0. The graph trace worked fine in v4.10-rc8, so something changed since the release.
Issue:
Using the ftrace_graph_filter kernel parameter to filter on a specific function produces no data (msleep for instance). The graph trace also continues to produce nothing even after reconfiguring it through debugfs. It worked fine in v4.10-rc8 but fails in v4.10.

4.10 is fine. It's what has been merged for 4.11 that's broken. I'm doing a bisect now to see what broke it. Yes, lots of commits touched that code recently.

I'll have to add this command line as one of my tests I perform.

Thanks!

-- Steve

Steven Rostedt

maintainer

2017-03-02 03:59 UTC #2 lore raw

Quoted 4 lines · On Wed, 1 Mar 2017 22:28:43 -0500 Steven Rostedt <[email protected]> wrote:

4.10 is fine. It's what has been merged for 4.11 that's broken. I'm doing a bisect now to see what broke it. Yes, lots of commits touched that code recently.

I found the bad commit. I'll have a patch for you to test tomorrow.

-- Steve

Steven Rostedt

maintainer

2017-03-02 17:50 UTC #3 lore raw

Quoted 9 lines · On Wed, 1 Mar 2017 22:47:30 -0500 Steven Rostedt <[email protected]> wrote:

Quoted 4 lines · On Wed, 1 Mar 2017 22:28:43 -0500 Steven Rostedt <[email protected]> wrote:
4.10 is fine. It's what has been merged for 4.11 that's broken. I'm doing a bisect now to see what broke it. Yes, lots of commits touched that code recently.
I found the bad commit. I'll have a patch for you to test tomorrow.

Can you test this patch please.

-- Steve

kernel/trace/ftrace.c +8 -4

index 2d554a0..1b33a41 100644
@@ -4403,10 +4403,9 @@ static void __init set_ftrace_early_graph(char *buf, int enable)
 	char *func;
 	struct ftrace_hash *hash;
 
-	if (enable)
-		hash = ftrace_graph_hash;
-	else
-		hash = ftrace_graph_notrace_hash;
+	hash = alloc_ftrace_hash(FTRACE_HASH_DEFAULT_BITS);
+	if (WARN_ON(!hash))
+		return;
 
 	while (buf) {
 		func = strsep(&buf, ",");

@@ -4416,6 +4415,11 @@ static void __init set_ftrace_early_graph(char *buf, int enable)
 			printk(KERN_DEBUG "ftrace: function %s not "
 					  "traceable\n", func);
 	}
+
+	if (enable)
+		ftrace_graph_hash = hash;
+	else
+		ftrace_graph_notrace_hash = hash;
 }
 #endif /* CONFIG_FUNCTION_GRAPH_TRACER */

Steven Rostedt

maintainer

2017-03-02 18:16 UTC #4 lore raw

Namhyung,

Just an FYI...

-- Steve

Quoted 47 lines · On Thu, 2 Mar 2017 12:49:40 -0500 Steven Rostedt <[email protected]> wrote:

Quoted 9 lines · On Wed, 1 Mar 2017 22:47:30 -0500 Steven Rostedt <[email protected]> wrote:
Quoted 4 lines · On Wed, 1 Mar 2017 22:28:43 -0500 Steven Rostedt <[email protected]> wrote:
4.10 is fine. It's what has been merged for 4.11 that's broken. I'm doing a bisect now to see what broke it. Yes, lots of commits touched that code recently.
I found the bad commit. I'll have a patch for you to test tomorrow.
Can you test this patch please.
-- Steve
kernel/trace/ftrace.c +8 -4
index 2d554a0..1b33a41 100644
@@ -4403,10 +4403,9 @@ static void __init set_ftrace_early_graph(char *buf, int enable)
 	char *func;
 	struct ftrace_hash *hash;
 
-	if (enable)
-		hash = ftrace_graph_hash;
-	else
-		hash = ftrace_graph_notrace_hash;
+	hash = alloc_ftrace_hash(FTRACE_HASH_DEFAULT_BITS);
+	if (WARN_ON(!hash))
+		return;
 
 	while (buf) {
 		func = strsep(&buf, ",");
@@ -4416,6 +4415,11 @@ static void __init set_ftrace_early_graph(char *buf, int enable)
 			printk(KERN_DEBUG "ftrace: function %s not "
 					  "traceable\n", func);
 	}
+
+	if (enable)
+		ftrace_graph_hash = hash;
+	else
+		ftrace_graph_notrace_hash = hash;
 }
 #endif /* CONFIG_FUNCTION_GRAPH_TRACER */
 

Todd Brandt

author

2017-03-02 20:27 UTC #5 lore raw

Quoted 24 lines · Steven Rostedt

Namhyung,
Just an FYI...
-- Steve
Quoted 14 lines · On Thu, 2 Mar 2017 12:49:40 -0500 Steven Rostedt <[email protected]> wrote:
Quoted 9 lines · On Wed, 1 Mar 2017 22:47:30 -0500 Steven Rostedt <[email protected]> wrote:
Quoted 4 lines · On Wed, 1 Mar 2017 22:28:43 -0500 Steven Rostedt <[email protected]> wrote:
4.10 is fine. It's what has been merged for 4.11 that's broken. I'm doing a bisect now to see what broke it. Yes, lots of commits touched that code recently.
I found the bad commit. I'll have a patch for you to test tomorrow.
Can you test this patch please.

Awesome, seems to work fine now.

I applied and tested it on bleeding edge:

commit 4977ab6e92e267afe9d8f78438c3db330ca8434c
Date: Wed Mar 1 17:04:50 2017 -0800

and it works on both msleep and do_one_initcall.

Thanks!

Quoted 34 lines

Quoted 33 lines

-- Steve

kernel/trace/ftrace.c +8 -4

index 2d554a0..1b33a41 100644
@@ -4403,10 +4403,9 @@ static void __init set_ftrace_early_graph(char *buf, int enable)
 	char *func;
 	struct ftrace_hash *hash;
 
-	if (enable)
-		hash = ftrace_graph_hash;
-	else
-		hash = ftrace_graph_notrace_hash;
+	hash = alloc_ftrace_hash(FTRACE_HASH_DEFAULT_BITS);
+	if (WARN_ON(!hash))
+		return;
 
 	while (buf) {
 		func = strsep(&buf, ",");

@@ -4416,6 +4415,11 @@ static void __init set_ftrace_early_graph(char *buf, int enable)
 			printk(KERN_DEBUG "ftrace: function %s not "
 					  "traceable\n", func);
 	}
+
+	if (enable)
+		ftrace_graph_hash = hash;
+	else
+		ftrace_graph_notrace_hash = hash;
 }
 #endif /* CONFIG_FUNCTION_GRAPH_TRACER */

Steven Rostedt

maintainer

2017-03-02 20:51 UTC #6 lore raw

Quoted 25 lines · On Thu, 02 Mar 2017 12:26:42 -0800 Todd Brandt <[email protected]>…

Quoted 24 lines · Steven Rostedt
Namhyung,
Just an FYI...
-- Steve
Quoted 14 lines · On Thu, 2 Mar 2017 12:49:40 -0500 Steven Rostedt <[email protected]> wrote:
Quoted 9 lines · On Wed, 1 Mar 2017 22:47:30 -0500 Steven Rostedt <[email protected]> wrote:
Quoted 4 lines · On Wed, 1 Mar 2017 22:28:43 -0500 Steven Rostedt <[email protected]> wrote:
4.10 is fine. It's what has been merged for 4.11 that's broken. I'm doing a bisect now to see what broke it. Yes, lots of commits touched that code recently.
I found the bad commit. I'll have a patch for you to test tomorrow.
Can you test this patch please.

Quoted 9 lines

Awesome, seems to work fine now.
I applied and tested it on bleeding edge:
commit 4977ab6e92e267afe9d8f78438c3db330ca8434c
Date: Wed Mar 1 17:04:50 2017 -0800
and it works on both msleep and do_one_initcall.

Thanks for testing!

I'll add a Reported-by and Tested-by from you.

-- Steve

Namhyung Kim

2017-03-03 01:15 UTC #7 lore raw

In reply to Steven Rostedt

Quoted 4 lines · Steven Rostedt

Namhyung,
Just an FYI...

Thanks, Steve.

I'll do more testing next time..

Namhyung

Quoted 53 lines

Quoted 47 lines · On Thu, 2 Mar 2017 12:49:40 -0500 Steven Rostedt <[email protected]> wrote:
Quoted 9 lines · On Wed, 1 Mar 2017 22:47:30 -0500 Steven Rostedt <[email protected]> wrote:
Quoted 4 lines · On Wed, 1 Mar 2017 22:28:43 -0500 Steven Rostedt <[email protected]> wrote:
4.10 is fine. It's what has been merged for 4.11 that's broken. I'm doing a bisect now to see what broke it. Yes, lots of commits touched that code recently.
I found the bad commit. I'll have a patch for you to test tomorrow.
Can you test this patch please.
-- Steve
kernel/trace/ftrace.c +8 -4
index 2d554a0..1b33a41 100644
@@ -4403,10 +4403,9 @@ static void __init set_ftrace_early_graph(char *buf, int enable)
 	char *func;
 	struct ftrace_hash *hash;
 
-	if (enable)
-		hash = ftrace_graph_hash;
-	else
-		hash = ftrace_graph_notrace_hash;
+	hash = alloc_ftrace_hash(FTRACE_HASH_DEFAULT_BITS);
+	if (WARN_ON(!hash))
+		return;
 
 	while (buf) {
 		func = strsep(&buf, ",");
@@ -4416,6 +4415,11 @@ static void __init set_ftrace_early_graph(char *buf, int enable)
 			printk(KERN_DEBUG "ftrace: function %s not "
 					  "traceable\n", func);
 	}
+
+	if (enable)
+		ftrace_graph_hash = hash;
+	else
+		ftrace_graph_notrace_hash = hash;
 }
 #endif /* CONFIG_FUNCTION_GRAPH_TRACER */
 