ftrace_graph_filter not working correctly since v4.10

From: Todd Brandt
Date: Wed Mar 01 2017 - 21:01:43 EST


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.