ftrace_graph_filter not working correctly since v4.10

ftrace_graph_filter not working correctly since v4.10

[Todd Brandt]

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.

Re: ftrace_graph_filter not working correctly since v4.10

[Steven Rostedt]

On Wed, 01 Mar 2017 18:01:31 -0800
Todd Brandt <todd.e.brandt@linux.intel.com> wrote:

> 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

Re: ftrace_graph_filter not working correctly since v4.10

[Steven Rostedt]

On Wed, 1 Mar 2017 22:28:43 -0500
Steven Rostedt <rostedt@goodmis.org> 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

Re: ftrace_graph_filter not working correctly since v4.10

[Steven Rostedt]

On Wed, 1 Mar 2017 22:47:30 -0500
Steven Rostedt <rostedt@goodmis.org> wrote:

> On Wed, 1 Mar 2017 22:28:43 -0500
> Steven Rostedt <rostedt@goodmis.org> 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

diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c
index 2d554a0..1b33a41 100644
--- a/kernel/trace/ftrace.c
+++ b/kernel/trace/ftrace.c
@@ -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 */
 

Re: ftrace_graph_filter not working correctly since v4.10

[Steven Rostedt]

Namhyung,

Just an FYI...

-- Steve


On Thu, 2 Mar 2017 12:49:40 -0500
Steven Rostedt <rostedt@goodmis.org> wrote:

> On Wed, 1 Mar 2017 22:47:30 -0500
> Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> > On Wed, 1 Mar 2017 22:28:43 -0500
> > Steven Rostedt <rostedt@goodmis.org> 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
> 
> diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c
> index 2d554a0..1b33a41 100644
> --- a/kernel/trace/ftrace.c
> +++ b/kernel/trace/ftrace.c
> @@ -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 */
>  

Re: ftrace_graph_filter not working correctly since v4.10

[Todd Brandt]

On Thu, 2017-03-02 at 13:05 -0500, Steven Rostedt wrote:
> Namhyung,
> 
> Just an FYI...
> 
> -- Steve
> 
> 
> On Thu, 2 Mar 2017 12:49:40 -0500
> Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> > On Wed, 1 Mar 2017 22:47:30 -0500
> > Steven Rostedt <rostedt@goodmis.org> wrote:
> > 
> > > On Wed, 1 Mar 2017 22:28:43 -0500
> > > Steven Rostedt <rostedt@goodmis.org> 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!

> > 
> > -- Steve
> > 
> > diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c
> > index 2d554a0..1b33a41 100644
> > --- a/kernel/trace/ftrace.c
> > +++ b/kernel/trace/ftrace.c
> > @@ -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 */
> >  
> 

Re: ftrace_graph_filter not working correctly since v4.10

[Steven Rostedt]

On Thu, 02 Mar 2017 12:26:42 -0800
Todd Brandt <todd.e.brandt@linux.intel.com> wrote:

> On Thu, 2017-03-02 at 13:05 -0500, Steven Rostedt wrote:
> > Namhyung,
> > 
> > Just an FYI...
> > 
> > -- Steve
> > 
> > 
> > On Thu, 2 Mar 2017 12:49:40 -0500
> > Steven Rostedt <rostedt@goodmis.org> wrote:
> >   
> > > On Wed, 1 Mar 2017 22:47:30 -0500
> > > Steven Rostedt <rostedt@goodmis.org> wrote:
> > >   
> > > > On Wed, 1 Mar 2017 22:28:43 -0500
> > > > Steven Rostedt <rostedt@goodmis.org> 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 for testing!

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

-- Steve

Re: ftrace_graph_filter not working correctly since v4.10

[Namhyung Kim]

On Thu, Mar 02, 2017 at 01:05:51PM -0500, Steven Rostedt wrote:
> 
> Namhyung,
> 
> Just an FYI...

Thanks, Steve.

I'll do more testing next time..

Namhyung

  
> 
> 
> On Thu, 2 Mar 2017 12:49:40 -0500
> Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> > On Wed, 1 Mar 2017 22:47:30 -0500
> > Steven Rostedt <rostedt@goodmis.org> wrote:
> > 
> > > On Wed, 1 Mar 2017 22:28:43 -0500
> > > Steven Rostedt <rostedt@goodmis.org> 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
> > 
> > diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c
> > index 2d554a0..1b33a41 100644
> > --- a/kernel/trace/ftrace.c
> > +++ b/kernel/trace/ftrace.c
> > @@ -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 */
> >  
>