* ftrace function graph with static ftrace does not work on MIPS
@ 2014-11-13 9:23 ` Markos Chandras
0 siblings, 0 replies; 8+ messages in thread
From: Markos Chandras @ 2014-11-13 9:23 UTC (permalink / raw)
To: linux-mips@linux-mips.org; +Cc: rostedt, mingo
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
^ permalink raw reply [flat|nested] 8+ messages in thread
* ftrace function graph with static ftrace does not work on MIPS
@ 2014-11-13 9:23 ` Markos Chandras
0 siblings, 0 replies; 8+ messages in thread
From: Markos Chandras @ 2014-11-13 9:23 UTC (permalink / raw)
To: linux-mips@linux-mips.org; +Cc: rostedt, mingo
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
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: ftrace function graph with static ftrace does not work on MIPS
@ 2014-11-20 16:09 ` Steven Rostedt
0 siblings, 0 replies; 8+ messages in thread
From: Steven Rostedt @ 2014-11-20 16:09 UTC (permalink / raw)
To: Markos Chandras; +Cc: linux-mips@linux-mips.org, mingo
On Thu, 13 Nov 2014 09:23:45 +0000
Markos Chandras <Markos.Chandras@imgtec.com> wrote:
> 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.
Looks like the static tracing code in wrong. The function graph code
should be tested every time.
-- Steve
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: ftrace function graph with static ftrace does not work on MIPS
@ 2014-11-20 16:09 ` Steven Rostedt
0 siblings, 0 replies; 8+ messages in thread
From: Steven Rostedt @ 2014-11-20 16:09 UTC (permalink / raw)
To: Markos Chandras; +Cc: linux-mips@linux-mips.org, mingo
On Thu, 13 Nov 2014 09:23:45 +0000
Markos Chandras <Markos.Chandras@imgtec.com> wrote:
> 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.
Looks like the static tracing code in wrong. The function graph code
should be tested every time.
-- Steve
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: ftrace function graph with static ftrace does not work on MIPS
@ 2014-11-21 9:33 ` Markos Chandras
0 siblings, 0 replies; 8+ messages in thread
From: Markos Chandras @ 2014-11-21 9:33 UTC (permalink / raw)
To: Steven Rostedt; +Cc: linux-mips@linux-mips.org, mingo
On 11/20/2014 04:09 PM, Steven Rostedt wrote:
> On Thu, 13 Nov 2014 09:23:45 +0000
> Markos Chandras <Markos.Chandras@imgtec.com> wrote:
>
>> 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.
>
> Looks like the static tracing code in wrong. The function graph code
> should be tested every time.
>
> -- Steve
>
Hi Steven,
I had a look on
https://www.kernel.org/doc/Documentation/trace/ftrace-design.txt
and section "HAVE_FUNCTION_GRAPH_TRACER"
According to the sample code, first we check "ftrace_trace_function !=
ftrace_stub" and if that's true, then we never check the ftrace_graph_*
functions which is exactly what MIPS does. So the graph functions are
not always checked. x86 seems to do something similar in mcount_64.S
--
markos
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: ftrace function graph with static ftrace does not work on MIPS
@ 2014-11-21 9:33 ` Markos Chandras
0 siblings, 0 replies; 8+ messages in thread
From: Markos Chandras @ 2014-11-21 9:33 UTC (permalink / raw)
To: Steven Rostedt; +Cc: linux-mips@linux-mips.org, mingo
On 11/20/2014 04:09 PM, Steven Rostedt wrote:
> On Thu, 13 Nov 2014 09:23:45 +0000
> Markos Chandras <Markos.Chandras@imgtec.com> wrote:
>
>> 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.
>
> Looks like the static tracing code in wrong. The function graph code
> should be tested every time.
>
> -- Steve
>
Hi Steven,
I had a look on
https://www.kernel.org/doc/Documentation/trace/ftrace-design.txt
and section "HAVE_FUNCTION_GRAPH_TRACER"
According to the sample code, first we check "ftrace_trace_function !=
ftrace_stub" and if that's true, then we never check the ftrace_graph_*
functions which is exactly what MIPS does. So the graph functions are
not always checked. x86 seems to do something similar in mcount_64.S
--
markos
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: ftrace function graph with static ftrace does not work on MIPS
@ 2014-11-21 21:31 ` Steven Rostedt
0 siblings, 0 replies; 8+ messages in thread
From: Steven Rostedt @ 2014-11-21 21:31 UTC (permalink / raw)
To: Markos Chandras; +Cc: linux-mips@linux-mips.org, mingo
On Fri, 21 Nov 2014 09:33:44 +0000
Markos Chandras <Markos.Chandras@imgtec.com> wrote:
> Hi Steven,
>
> I had a look on
>
> https://www.kernel.org/doc/Documentation/trace/ftrace-design.txt
>
> and section "HAVE_FUNCTION_GRAPH_TRACER"
>
> According to the sample code, first we check "ftrace_trace_function !=
> ftrace_stub" and if that's true, then we never check the ftrace_graph_*
> functions which is exactly what MIPS does. So the graph functions are
> not always checked. x86 seems to do something similar in mcount_64.S
>
Thanks, I need to update that file.
I don't test static tracing much as I feel it's overhead makes it
almost not worth keeping. I've been even thinking of nuking it, but I
keep it in because it's good for archs adding function tracing to get a
basic test working, as dynamic function tracing is a bit more difficult
to implement.
But yeah, don't go too much by that document. It is out of date, and
when I get time, I'll have to update it. I'll probably do that when I
bring powerpc up to speed with x86 (except for the fentry part).
I want dynamic trampolines for powerpc and such, and when I do that, it
will make all the changes fresh in my mind to go back and tackle the
design documentation.
-- Steve
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: ftrace function graph with static ftrace does not work on MIPS
@ 2014-11-21 21:31 ` Steven Rostedt
0 siblings, 0 replies; 8+ messages in thread
From: Steven Rostedt @ 2014-11-21 21:31 UTC (permalink / raw)
To: Markos Chandras; +Cc: linux-mips@linux-mips.org, mingo
On Fri, 21 Nov 2014 09:33:44 +0000
Markos Chandras <Markos.Chandras@imgtec.com> wrote:
> Hi Steven,
>
> I had a look on
>
> https://www.kernel.org/doc/Documentation/trace/ftrace-design.txt
>
> and section "HAVE_FUNCTION_GRAPH_TRACER"
>
> According to the sample code, first we check "ftrace_trace_function !=
> ftrace_stub" and if that's true, then we never check the ftrace_graph_*
> functions which is exactly what MIPS does. So the graph functions are
> not always checked. x86 seems to do something similar in mcount_64.S
>
Thanks, I need to update that file.
I don't test static tracing much as I feel it's overhead makes it
almost not worth keeping. I've been even thinking of nuking it, but I
keep it in because it's good for archs adding function tracing to get a
basic test working, as dynamic function tracing is a bit more difficult
to implement.
But yeah, don't go too much by that document. It is out of date, and
when I get time, I'll have to update it. I'll probably do that when I
bring powerpc up to speed with x86 (except for the fentry part).
I want dynamic trampolines for powerpc and such, and when I do that, it
will make all the changes fresh in my mind to go back and tackle the
design documentation.
-- Steve
^ permalink raw reply [flat|nested] 8+ messages in thread
end of thread, other threads:[~2014-11-21 21:31 UTC | newest]
Thread overview: 8+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2014-11-13 9:23 ftrace function graph with static ftrace does not work on MIPS Markos Chandras
2014-11-13 9:23 ` Markos Chandras
2014-11-20 16:09 ` Steven Rostedt
2014-11-20 16:09 ` Steven Rostedt
2014-11-21 9:33 ` Markos Chandras
2014-11-21 9:33 ` Markos Chandras
2014-11-21 21:31 ` Steven Rostedt
2014-11-21 21:31 ` Steven Rostedt
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.