linux-kernel - ftrace_graph_filter not working correctly since v4.10

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [thread-next>] [day] [month] [year] [list]

Date:   Wed, 01 Mar 2017 18:01:31 -0800
From:   Todd Brandt <todd.e.brandt@...ux.intel.com>
To:     linux-kernel@...r.kernel.org
Cc:     rostedt@...dmis.org
Subject: ftrace_graph_filter not working correctly since v4.10

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.