Message-ID: <1488420091.7212.17.camel@linux.intel.com>
Subject: ftrace_graph_filter not working correctly since v4.10
From: Todd Brandt <todd.e.brandt@linux.intel.com>
Reply-To: todd.e.brandt@linux.intel.com
To: linux-kernel@vger.kernel.org
Cc: rostedt@goodmis.org
Date: Wed, 01 Mar 2017 18:01:31 -0800
Content-Type: text/plain; charset="UTF-8"
Mime-Version: 1.0
Content-Transfer-Encoding: 7bit
Sender: linux-kernel-owner@vger.kernel.org
Content-Length: 2492
Lines: 70

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.