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.
On Wed, 01 Mar 2017 18:01:31 -0800
Todd Brandt <[email protected]> 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
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
On Wed, 1 Mar 2017 22:47:30 -0500
Steven Rostedt <[email protected]> wrote:
> 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
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 */
Namhyung,
Just an FYI...
-- Steve
On Thu, 2 Mar 2017 12:49:40 -0500
Steven Rostedt <[email protected]> wrote:
> On Wed, 1 Mar 2017 22:47:30 -0500
> Steven Rostedt <[email protected]> wrote:
>
> > 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
>
> 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 */
>
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 <[email protected]> wrote:
>
> > On Wed, 1 Mar 2017 22:47:30 -0500
> > Steven Rostedt <[email protected]> wrote:
> >
> > > 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!
> >
> > -- 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 */
> >
>
On Thu, 02 Mar 2017 12:26:42 -0800
Todd Brandt <[email protected]> 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 <[email protected]> wrote:
> >
> > > On Wed, 1 Mar 2017 22:47:30 -0500
> > > Steven Rostedt <[email protected]> wrote:
> > >
> > > > 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 for testing!
I'll add a Reported-by and Tested-by from you.
-- Steve
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 <[email protected]> wrote:
>
> > On Wed, 1 Mar 2017 22:47:30 -0500
> > Steven Rostedt <[email protected]> wrote:
> >
> > > 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
> >
> > 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 */
> >
>