Question about ARM function graph tracing

Question about ARM function graph tracing

[Tim Bird]

Vincent,

I sheepishly admit that I haven't been following mainline very
well.  I was happily surprised to see you have mainlined ARM
function graph tracing.  I gave it a test on my old OMAP
OSK board, with the results shown below.

My quick questions, before I dive into this, are:
1) what targets did you test with?
2) Did you test with and without dynamic tracing?
3) what version of compiler did you use?

I'm just checking, to narrow down the search space for
debugging through this.

Thanks,
 -- Tim


Kernel is version 2.6.38-rc3

I compiled the kernel with:
CONFIG_STACKTRACE_SUPPORT=y
CONFIG_TRACE_IRQFLAGS_SUPPORT=y
# CONFIG_RCU_TRACE is not set
# CONFIG_TREE_RCU_TRACE is not set
CONFIG_TRACEPOINTS=y
CONFIG_STACKTRACE=y
# CONFIG_BACKTRACE_SELF_TEST is not set
CONFIG_NOP_TRACER=y
CONFIG_HAVE_FUNCTION_TRACER=y
CONFIG_HAVE_FUNCTION_GRAPH_TRACER=y
CONFIG_HAVE_DYNAMIC_FTRACE=y
CONFIG_HAVE_FTRACE_MCOUNT_RECORD=y
CONFIG_TRACER_MAX_TRACE=y
CONFIG_CONTEXT_SWITCH_TRACER=y
CONFIG_GENERIC_TRACER=y
CONFIG_FTRACE=y
CONFIG_FUNCTION_TRACER=y
CONFIG_FUNCTION_GRAPH_TRACER=y
# CONFIG_IRQSOFF_TRACER is not set
# CONFIG_PREEMPT_TRACER is not set
CONFIG_SCHED_TRACER=y
# CONFIG_STACK_TRACER is not set
# CONFIG_BLK_DEV_IO_TRACE is not set
# CONFIG_DYNAMIC_FTRACE is not set
# CONFIG_FTRACE_STARTUP_TEST is not set

The kernel compiles and runs.  Function tracing works OK

Function graph tracing hangs the kernel, when it is enabled:

/debug/tracing # echo function_graph >current_tracer
Unable to handle kernel NULL pointer dereference at virtual address 0000033c
pgd = c1a4e578
[0000033c] *pgd=0000033c
Unable to handle kernel paging request at virtual address b0000000
pgd = c1a4e578
[b0000000] *pgd=c1a51210
Unable to handle kernel paging request at virtual address 71a51000
pgd = c1a4e578
[71a51000] *pgd=00000001
Unable to handle kernel paging request at virtual address b0000144
pgd = c1a4e578
[b0000144] *pgd=c1a51210
Unable to handle kernel paging request at virtual address 71a51000
pgd = c1a4e578
[71a51000] *pgd=00000001
Unable to handle kernel paging request at virtual address b0000144
pgd = c1a4e578
...

=============================
Tim Bird
Architecture Group Chair, CE Linux Forum
Senior Staff Engineer, Sony Network Entertainment
=============================

Question about ARM function graph tracing

[Rabin Vincent]

On Fri, Feb 4, 2011 at 05:12, Tim Bird <tim.bird@am.sony.com> wrote:
> I sheepishly admit that I haven't been following mainline very
> well. ?I was happily surprised to see you have mainlined ARM
> function graph tracing. ?I gave it a test on my old OMAP
> OSK board, with the results shown below.

OMAP is missing a notrace annotation on omap_readl():

http://www.mail-archive.com/linux-omap at vger.kernel.org/msg38911.html

Part of that patch was merged through rmk's work, but the
omap_readl() annotation seems to have been missed.

Also, if this is OMAP1 and not latest mainline, I think you
will need  a notrace on omap_rev() also (called from inside
omap_readl() until recently).

I think this is most probably what is wrong, since IIRC I saw
crashes like this on BeagleBoard before I added the notrace on
omap_readl.  Could you please try with these changes?

Rabin

Question about ARM function graph tracing

[Tim Bird]

Rabin,

For a quick update, see below.

On 02/03/2011 08:07 PM, Rabin Vincent wrote:
> On Fri, Feb 4, 2011 at 05:12, Tim Bird <tim.bird@am.sony.com> wrote:
>> I sheepishly admit that I haven't been following mainline very
>> well. ?I was happily surprised to see you have mainlined ARMj
>> function graph tracing. ?I gave it a test on my old OMAP
>> OSK board, with the results shown below.
> 
> OMAP is missing a notrace annotation on omap_readl():
> 
> http://www.mail-archive.com/linux-omap at vger.kernel.org/msg38911.html
> 
> Part of that patch was merged through rmk's work, but the
> omap_readl() annotation seems to have been missed.
Yep.  It's missing in 2.6.38-rc3.

> Also, if this is OMAP1 and not latest mainline, I think you
> will need  a notrace on omap_rev() also (called from inside
> omap_readl() until recently).

I couldn't find that in the sched_clock code paths, but
I 'notrace'd it anyways.

> 
> I think this is most probably what is wrong, since IIRC I saw
> crashes like this on BeagleBoard before I added the notrace on
> omap_readl.  Could you please try with these changes?

I have sprinkled 'notrace's liberally throughout the sched_clock
code (including omap_readl() and omap_rev()), and I'm still
seeing problems.  I put a recursion guard in
prepare_ftrace_return, and I'm seeing lots of recursion.  So
there's still a notrace missing somewhere.

I'm sure this is the problem, so thanks for pointing me in the
right direction.  I'll keep trying to pin it down, and let
you know what I find.
 -- Tim

=============================
Tim Bird
Architecture Group Chair, CE Linux Forum
Senior Staff Engineer, Sony Network Entertainment
=============================

Question about ARM function graph tracing

[Tim Bird]

On 02/04/2011 12:29 PM, Tim Bird wrote:
>> OMAP is missing a notrace annotation on omap_readl():
>>
>> http://www.mail-archive.com/linux-omap at vger.kernel.org/msg38911.html
>>
>> Part of that patch was merged through rmk's work, but the
>> omap_readl() annotation seems to have been missed.
> Yep.  It's missing in 2.6.38-rc3.
> 
>> Also, if this is OMAP1 and not latest mainline, I think you
>> will need  a notrace on omap_rev() also (called from inside
>> omap_readl() until recently).
> 
> I couldn't find that in the sched_clock code paths, but
> I 'notrace'd it anyways.
> 
>>
>> I think this is most probably what is wrong, since IIRC I saw
>> crashes like this on BeagleBoard before I added the notrace on
>> omap_readl.  Could you please try with these changes?
> 
> I have sprinkled 'notrace's liberally throughout the sched_clock
> code (including omap_readl() and omap_rev()), and I'm still
> seeing problems.  I put a recursion guard in
> prepare_ftrace_return, and I'm seeing lots of recursion.  So
> there's still a notrace missing somewhere.

OK.  The notrace was indeed missing fro omap_readl(), but fixing
this did not completely fix the problem.  I put the following
(crude) recursion guard in arch/arm/kernel/ftrace.c:prepare_ftrace_return:

diff --git a/arch/arm/kernel/ftrace.c b/arch/arm/kernel/ftrace.c
index c0062ad..5872c25 100644
--- a/arch/arm/kernel/ftrace.c
+++ b/arch/arm/kernel/ftrace.c
@@ -209,6 +209,8 @@ int __init ftrace_dyn_arch_init(void *data)
 #endif /* CONFIG_DYNAMIC_FTRACE */

 #ifdef CONFIG_FUNCTION_GRAPH_TRACER
+static int already_here = 0;
+
 void prepare_ftrace_return(unsigned long *parent, unsigned long self_addr,
                           unsigned long frame_pointer)
 {
@@ -217,8 +219,16 @@ void prepare_ftrace_return(unsigned long *parent, unsigned long self_a
        unsigned long old;
        int err;

-       if (unlikely(atomic_read(&current->tracing_graph_pause)))
+       if(unlikely(already_here)) {
                return;
+       } else {
+               already_here=1;
+       }
+
+       if (unlikely(atomic_read(&current->tracing_graph_pause))) {
+               already_here=0;
+               return;
+       }

        old = *parent;
        *parent = return_hooker;
@@ -227,6 +237,7 @@ void prepare_ftrace_return(unsigned long *parent, unsigned long self_ad
                                       frame_pointer);
        if (err == -EBUSY) {
                *parent = old;
+               already_here=0;
                return;
        }

@@ -237,6 +248,7 @@ void prepare_ftrace_return(unsigned long *parent, unsigned long self_ad
                current->curr_ret_stack--;
                *parent = old;
        }
+       already_here=0;
 }

 #ifdef CONFIG_DYNAMIC_FTRACE

Without this, the system hangs for long periods of time after starting
the function graph tracer (echo function_graph >/debug/tracing/current_tracer)
Sometimes the system comes back and sometimes it doesn't.  With the above
code, the system works, and I can get traces (but obviously I'm dumping
a bunch of tracepoints whenever the tracer nests.)

I put some extra instrumentation in, and MOST of the time, the item
causing nesting is asm_do_IRQ(), which is to be expected.  However,
I have seen a recursion from preempt_schedule(), which I didn't really
expect.  Does the tracer invoke anything that would cause a schedule
from inside the trace-recording code?

Should I try this with CONFIG_PREEMPT off? (It's currently on.)

Any ideas for debugging this would be appreciated.
 -- Tim


=============================
Tim Bird
Architecture Group Chair, CE Linux Forum
Senior Staff Engineer, Sony Network Entertainment
=============================

Question about ARM function graph tracing

[Steven Rostedt]

On Tue, 2011-02-15 at 17:39 -0800, Tim Bird wrote:
> On 02/04/2011 12:29 PM, Tim Bird wrote:
> >> OMAP is missing a notrace annotation on omap_readl():
> >>
> >> http://www.mail-archive.com/linux-omap at vger.kernel.org/msg38911.html
> >>
> >> Part of that patch was merged through rmk's work, but the
> >> omap_readl() annotation seems to have been missed.
> > Yep.  It's missing in 2.6.38-rc3.
> > 
> >> Also, if this is OMAP1 and not latest mainline, I think you
> >> will need  a notrace on omap_rev() also (called from inside
> >> omap_readl() until recently).
> > 
> > I couldn't find that in the sched_clock code paths, but
> > I 'notrace'd it anyways.
> > 
> >>
> >> I think this is most probably what is wrong, since IIRC I saw
> >> crashes like this on BeagleBoard before I added the notrace on
> >> omap_readl.  Could you please try with these changes?
> > 
> > I have sprinkled 'notrace's liberally throughout the sched_clock
> > code (including omap_readl() and omap_rev()), and I'm still
> > seeing problems.  I put a recursion guard in
> > prepare_ftrace_return, and I'm seeing lots of recursion.  So
> > there's still a notrace missing somewhere.

Note, if you find that you need to add "notrace" to most functions in a
file, you can simply make the entire file "notrace" from the make file:

CFLAGS_REMOVE_myfile.o = -pg


> 
> OK.  The notrace was indeed missing fro omap_readl(), but fixing
> this did not completely fix the problem.  I put the following
> (crude) recursion guard in arch/arm/kernel/ftrace.c:prepare_ftrace_return:
> 
> diff --git a/arch/arm/kernel/ftrace.c b/arch/arm/kernel/ftrace.c
> index c0062ad..5872c25 100644
> --- a/arch/arm/kernel/ftrace.c
> +++ b/arch/arm/kernel/ftrace.c
> @@ -209,6 +209,8 @@ int __init ftrace_dyn_arch_init(void *data)
>  #endif /* CONFIG_DYNAMIC_FTRACE */
> 
>  #ifdef CONFIG_FUNCTION_GRAPH_TRACER
> +static int already_here = 0;
> +
>  void prepare_ftrace_return(unsigned long *parent, unsigned long self_addr,
>                            unsigned long frame_pointer)
>  {
> @@ -217,8 +219,16 @@ void prepare_ftrace_return(unsigned long *parent, unsigned long self_a
>         unsigned long old;
>         int err;
> 
> -       if (unlikely(atomic_read(&current->tracing_graph_pause)))
> +       if(unlikely(already_here)) {
>                 return;
> +       } else {
> +               already_here=1;
> +       }

Um, single cpu ?


> +
> +       if (unlikely(atomic_read(&current->tracing_graph_pause))) {
> +               already_here=0;
> +               return;
> +       }
> 
>         old = *parent;
>         *parent = return_hooker;
> @@ -227,6 +237,7 @@ void prepare_ftrace_return(unsigned long *parent, unsigned long self_ad
>                                        frame_pointer);
>         if (err == -EBUSY) {
>                 *parent = old;
> +               already_here=0;
>                 return;
>         }
> 
> @@ -237,6 +248,7 @@ void prepare_ftrace_return(unsigned long *parent, unsigned long self_ad
>                 current->curr_ret_stack--;
>                 *parent = old;
>         }
> +       already_here=0;
>  }
> 
>  #ifdef CONFIG_DYNAMIC_FTRACE
> 
> Without this, the system hangs for long periods of time after starting
> the function graph tracer (echo function_graph >/debug/tracing/current_tracer)
> Sometimes the system comes back and sometimes it doesn't.  With the above
> code, the system works, and I can get traces (but obviously I'm dumping
> a bunch of tracepoints whenever the tracer nests.)
> 
> I put some extra instrumentation in, and MOST of the time, the item
> causing nesting is asm_do_IRQ(), which is to be expected.  However,
> I have seen a recursion from preempt_schedule(), which I didn't really
> expect.  Does the tracer invoke anything that would cause a schedule
> from inside the trace-recording code?
> 
> Should I try this with CONFIG_PREEMPT off? (It's currently on.)
> 
> Any ideas for debugging this would be appreciated.

I've had to debug things that broke in the function graph tracer like
this before. Is dynamic ftrace available in arm?

Hmm, from arch/arm/Kconfig:

	select HAVE_DYNAMIC_FTRACE if (!XIP_KERNEL)


I guess so. If you are running something other than this XIP_KERNEL, I
would suggest using the dynamic functions to binary search the issue.

cat available_filter_functions > /tmp/funcs

Then copy half the funcs to /tmp/funcs1 and the other half
to /tmp/funcs2

cat /tmp/funcs1 > set_ftrace_filter

This may take a while, as setting the filter one by one is slow.

then run the function graph tracer. If it locks up, try it again
with /tmp/funcs2. If it locks up, you may have two issues or it could be
something wrong with the function graph tracer itself. But I'm betting
one will work and one wont.

Then just keep chopping these funcs files until you get down to a set of
functions that are causing issues. Then it should point out the problem.

This is the procedure I used to find out why a kvm guest was locking up
with function graph tracer.

See commit:

258af47479980d8238a04568b94a4e55aa1cb537

Something tells me you may have a similar issue ;)

-- Steve

Question about ARM function graph tracing

[Frederic Weisbecker]

On Tue, Feb 15, 2011 at 09:05:45PM -0500, Steven Rostedt wrote:
> On Tue, 2011-02-15 at 17:39 -0800, Tim Bird wrote:
> I've had to debug things that broke in the function graph tracer like
> this before. Is dynamic ftrace available in arm?
> 
> Hmm, from arch/arm/Kconfig:
> 
> 	select HAVE_DYNAMIC_FTRACE if (!XIP_KERNEL)
> 
> 
> I guess so. If you are running something other than this XIP_KERNEL, I
> would suggest using the dynamic functions to binary search the issue.
> 
> cat available_filter_functions > /tmp/funcs
> 
> Then copy half the funcs to /tmp/funcs1 and the other half
> to /tmp/funcs2
> 
> cat /tmp/funcs1 > set_ftrace_filter
> 
> This may take a while, as setting the filter one by one is slow.
> 
> then run the function graph tracer. If it locks up, try it again
> with /tmp/funcs2. If it locks up, you may have two issues or it could be
> something wrong with the function graph tracer itself. But I'm betting
> one will work and one wont.
> 
> Then just keep chopping these funcs files until you get down to a set of
> functions that are causing issues. Then it should point out the problem.
> 
> This is the procedure I used to find out why a kvm guest was locking up
> with function graph tracer.
> 
> See commit:
> 
> 258af47479980d8238a04568b94a4e55aa1cb537
> 
> Something tells me you may have a similar issue ;)


That's a very nice idea to debug ftrace recursions!

As a last resort, in case the binary search doesn't work, you can try:

1) do a local_irq_save() in asm (to avoid possible recursions with common funcs)
2) test recursion, if so, printk_once() the traced func
3) exit recursion
3) local_irq_restore() in asm