Hi,
I am trying to understand why ftrace function graph doesn't work when
using static ftrace on MIPS. So, what happens when I do 'echo
function_graph > current_tracer' is that the ftrace_graph_caller from
mcount.S is executed once. The function that called it is
'core_kernel_data()' from __register_ftrace_function in
kernel/trace/ftrace.c
However, this is the only function that is reported in the trace file
# cat trace
# tracer: function_graph
#
# CPU DURATION FUNCTION CALLS
# | | | | | | |
0) | core_kernel_data() {
0) 0.000 us | } /* core_kernel_data */
The reason that the ftrace_graph_caller is never executed after that is
that the following as far as I understand:
NESTED(_mcount, PT_SIZE, ra)
PTR_LA t1, ftrace_stub
PTR_L t2, ftrace_trace_function /* Prepare t2 for (1) */
bne t1, t2, static_trace
nop
#ifdef CONFIG_FUNCTION_GRAPH_TRACER
PTR_L t3, ftrace_graph_return
bne t1, t3, ftrace_graph_caller
nop
PTR_LA t1, ftrace_graph_entry_stub
PTR_L t3, ftrace_graph_entry
bne t1, t3, ftrace_graph_caller
nop
#endif
The previous 3 conditionals exists in arch/mips/kernel/mcount.S.
Originally, ftrace_trace_function == ftrace_stub, so the first
conditional is not taken and we end up executed the ftrace_graph_caller.
All good.
However, later on, ftrace_trace_function is set to 'ftrace_ops_no_ops',
so the first 'bne' is taken and the ftrace_graph_caller is never
executed after that. It is not clear to me if this behaviour is expected
so I used QEMU to get a backtrace when ftrace_trace_function is set to
ftrace_ops_no_ops.
Old value = (ftrace_func_t) 0x8010fa90 <ftrace_stub>
New value = (ftrace_func_t) 0x801a32f0 <ftrace_ops_no_ops>
0x801a2578 in update_ftrace_function () at kernel/trace/ftrace.c:318
(gdb) bt
#0 0x801a2578 in update_ftrace_function () at kernel/trace/ftrace.c:318
#1 0x801a2ae8 in __register_ftrace_function (ops=0x806fbcb4 <global_ops>)
at kernel/trace/ftrace.c:414
#2 0x801a39ec in register_ftrace_graph (retfunc=0x801b6ab8
<trace_graph_return>,
entryfunc=0x801b67b4 <trace_graph_entry>) at kernel/trace/ftrace.c:5438
#3 0x801b63d0 in graph_trace_init (tr=<optimized out>)
at kernel/trace/trace_functions_graph.c:463
#4 0x801b0b84 in tracer_init (tr=<optimized out>, t=<optimized out>)
at kernel/trace/trace.c:3916
#5 tracing_set_tracer (tr=0x8093e1d8 <global_trace>,
buf=0x8 <error: Cannot access memory at address 0x8>) at
kernel/trace/trace.c:4171
#6 0x801b103c in tracing_set_trace_write (filp=<optimized out>,
ubuf=<optimized out>,
cnt=<optimized out>, ppos=0x82147f00) at kernel/trace/trace.c:4209
#7 0x80212944 in vfs_write (file=0x821fa100,
buf=0x806fbc8c <graph_ops> "\220\372\020\200h0o\200", <incomplete
sequence \340>,
count=<optimized out>, pos=0x82147f00) at fs/read_write.c:532
#8 0x80213164 in SYSC_write (count=<optimized out>, buf=<optimized out>,
fd=<optimized out>) at fs/read_write.c:583
#9 SyS_write (fd=<optimized out>, buf=0x4bdf38, count=0xf) at
fs/read_write.c:575
#10 0x80112f48 in handle_sys () at arch/mips/kernel/scall32-o32.S:99
So, now that the ftrace_trace_function has been set to
'ftrace_ops_no_ops', the previous branch (as I explained before) is
taken and the function graph related functions are not being executed
anymore.
Dynamic tracing is working (or seems it does) because the code does a
'jal ftrace_call' and the returns back and does a 'j
ftrace_graph_caller'. In other words, it always executes the
ftrace_graph_caller no matter what the ftrace_trace_function is.
So any ideas? Do I do something wrong?
--
markos
