Re: [for-next][PATCH 04/21] ftrace: Optimize function graph to be called directly

Tuomas Tynkkynen
2014-07-10T17:46:01Z

On 03/07/14 19:05, Steven Rostedt wrote:
> From: "Steven Rostedt (Red Hat)"<rostedt@goodmis.org>
>
> Function graph tracing is a bit different than the function tracers, as
> it is processed after either the ftrace_caller or ftrace_regs_caller
> and we only have one place to modify the jump to ftrace_graph_caller,
> the jump needs to happen after the restore of registeres.
>
> The function graph tracer is dependent on the function tracer, where
> even if the function graph tracing is going on by itself, the save and
> restore of registers is still done for function tracing regardless of
> if function tracing is happening, before it calls the function graph
> code.
>
> If there's no function tracing happening, it is possible to just call
> the function graph tracer directly, and avoid the wasted effort to save
> and restore regs for function tracing.
>
> This requires adding new flags to the dyn_ftrace records:
>
> FTRACE_FL_TRAMP
> FTRACE_FL_TRAMP_EN
>
> The first is set if the count for the record is one, and the ftrace_ops
> associated to that record has its own trampoline. That way the mcount code
> can call that trampoline directly.
>
> In the future, trampolines can be added to arbitrary ftrace_ops, where you
> can have two or more ftrace_ops registered to ftrace (like kprobes and perf)
> and if they are not tracing the same functions, then instead of doing a
> loop to check all registered ftrace_ops against their hashes, just call the
> ftrace_ops trampoline directly, which would call the registered ftrace_ops
> function directly.
>
> Without this patch perf showed:
>
> 0.05% hackbench [kernel.kallsyms] [k] ftrace_caller
> 0.05% hackbench [kernel.kallsyms] [k] arch_local_irq_save
> 0.05% hackbench [kernel.kallsyms] [k] native_sched_clock
> 0.04% hackbench [kernel.kallsyms] [k] __buffer_unlock_commit
> 0.04% hackbench [kernel.kallsyms] [k] preempt_trace
> 0.04% hackbench [kernel.kallsyms] [k] prepare_ftrace_return
> 0.04% hackbench [kernel.kallsyms] [k] __this_cpu_preempt_check
> 0.04% hackbench [kernel.kallsyms] [k] ftrace_graph_caller
>
> See that the ftrace_caller took up more time than the ftrace_graph_caller
> did.
>
> With this patch:
>
> 0.05% hackbench [kernel.kallsyms] [k] __buffer_unlock_commit
> 0.04% hackbench [kernel.kallsyms] [k] call_filter_check_discard
> 0.04% hackbench [kernel.kallsyms] [k] ftrace_graph_caller
> 0.04% hackbench [kernel.kallsyms] [k] sched_clock
>
> The ftrace_caller is no where to be found and ftrace_graph_caller still
> takes up the same percentage.
>
> Signed-off-by: Steven Rostedt<rostedt@goodmis.org>
> ---
> arch/x86/kernel/mcount_64.S | 5 +
> include/linux/ftrace.h | 19 +++-
> kernel/trace/ftrace.c | 242 ++++++++++++++++++++++++++++++++++++++++++--
> 3 files changed, 254 insertions(+), 12 deletions(-)
>

This commit (79922b8) breaks the function graph tracer on today's -next.
This is on an ARM Tegra board.

I'm using ftrace with this script:

#!/bin/sh
echo function_graph > /d/tracing/current_tracer
echo clear > /d/tracing/trace
echo $$ > /d/tracing/set_ftrace_pid
exec "$@"

...and a simple './trace.sh ls' crashes with no console output. SysRq is
not responsive either.