Re: [PATCH 0/3] tracing/function-graph-tracer: signal interrupt triggering on output

Re: [PATCH 0/3] tracing/function-graph-tracer: signal interrupt triggering on output

[Frederic Weisbecker]

Frederic Weisbecker wrote:
> This patchset adds all the features to draw hardirq triggering on output
> for the function graph tracer.
> An example is given on the third patch.
> 
> Just one question, on recordmcount.pl:
> 
> my %text_sections = (
>       ".text" => 1,
>       ".sched.text" => 1,
>       ".spinlock.text" => 1,
> 
> The .sched.text section is included inside .text, it's a subsection, I'm not sure
> it's necessary to add it in text_sections. In doubt I added the new .irqentry.text
> 
> The stat of the patchset:
> 
>  arch/x86/kernel/apic.c               |    3 +-
>  arch/x86/kernel/irq_64.c             |    3 +-
>  arch/x86/kernel/vmlinux_64.lds.S     |    1 +
>  include/asm-generic/vmlinux.lds.h    |   10 +++++
>  include/linux/ftrace.h               |   11 ++++++
>  kernel/trace/trace_functions_graph.c |   66 +++++++++++++++++++++++++++++++--
>  scripts/recordmcount.pl              |    1 +
>  7 files changed, 89 insertions(+), 6 deletions(-)
> 
> 

Sorry, forgot to cc LKML on this one.

Re: [PATCH 0/3] tracing/function-graph-tracer: signal interrupt triggering on output

[Steven Rostedt]

On Tue, 9 Dec 2008, Frederic Weisbecker wrote:

> This patchset adds all the features to draw hardirq triggering on output
> for the function graph tracer.
> An example is given on the third patch.
> 
> Just one question, on recordmcount.pl:
> 
> my %text_sections = (
>       ".text" => 1,
>       ".sched.text" => 1,
>       ".spinlock.text" => 1,
> 
> The .sched.text section is included inside .text, it's a subsection, I'm not sure
> it's necessary to add it in text_sections. In doubt I added the new .irqentry.text
> 

Matters what objdump -dr shows.

$ objdump -dr kernel/sched.o | grep 'Disassembly'
Disassembly of section .text:
Disassembly of section .cpuinit.text:
Disassembly of section .init.text:
Disassembly of section .sched.text:

Yep, .sched.text is needed.  It is not about what gets linked by the 
linker. It is about what objdump shows, which is what recordmcount.pl uses 
to determine whether or not to record the mcount callers in that section.

-- Steve

Re: [PATCH 0/3] tracing/function-graph-tracer: signal interrupt triggering on output

[Frédéric Weisbecker]

2008/12/10 Steven Rostedt <rostedt@goodmis.org>:
>
> On Tue, 9 Dec 2008, Frederic Weisbecker wrote:
>
>> This patchset adds all the features to draw hardirq triggering on output
>> for the function graph tracer.
>> An example is given on the third patch.
>>
>> Just one question, on recordmcount.pl:
>>
>> my %text_sections = (
>>       ".text" => 1,
>>       ".sched.text" => 1,
>>       ".spinlock.text" => 1,
>>
>> The .sched.text section is included inside .text, it's a subsection, I'm not sure
>> it's necessary to add it in text_sections. In doubt I added the new .irqentry.text
>>
>
> Matters what objdump -dr shows.
>
> $ objdump -dr kernel/sched.o | grep 'Disassembly'
> Disassembly of section .text:
> Disassembly of section .cpuinit.text:
> Disassembly of section .init.text:
> Disassembly of section .sched.text:
>
> Yep, .sched.text is needed.  It is not about what gets linked by the
> linker. It is about what objdump shows, which is what recordmcount.pl uses
> to determine whether or not to record the mcount callers in that section.


Ok. I looked at a disassembly objdump on vmlinux to find those
subsections and didn't find it.
But I didn't see that recordmcount did its work on each build folder,
I guess that these sections are
visible on the objects found in the subdirectories....

Thanks.

Re: [PATCH 0/3] tracing/function-graph-tracer: signal interrupt triggering on output

[Wang Liming]

Frédéric Weisbecker wrote:
> 2008/12/10 Steven Rostedt <rostedt@goodmis.org>:
>> On Tue, 9 Dec 2008, Frederic Weisbecker wrote:
>>
>>> This patchset adds all the features to draw hardirq triggering on output
>>> for the function graph tracer.
>>> An example is given on the third patch.
>>>
>>> Just one question, on recordmcount.pl:
>>>
>>> my %text_sections = (
>>>       ".text" => 1,
>>>       ".sched.text" => 1,
>>>       ".spinlock.text" => 1,
>>>
>>> The .sched.text section is included inside .text, it's a subsection, I'm not sure
>>> it's necessary to add it in text_sections. In doubt I added the new .irqentry.text
>>>
>> Matters what objdump -dr shows.
>>
>> $ objdump -dr kernel/sched.o | grep 'Disassembly'
>> Disassembly of section .text:
>> Disassembly of section .cpuinit.text:
>> Disassembly of section .init.text:
>> Disassembly of section .sched.text:
>>
>> Yep, .sched.text is needed.  It is not about what gets linked by the
>> linker. It is about what objdump shows, which is what recordmcount.pl uses
>> to determine whether or not to record the mcount callers in that section.
> 
> 
> Ok. I looked at a disassembly objdump on vmlinux to find those
> subsections and didn't find it.
> But I didn't see that recordmcount did its work on each build folder,
You can see "scripts/Makefile.build" file, which uses recordmcount.pl to deal 
with each .o file when building.

Liming Wang
> I guess that these sections are
> visible on the objects found in the subdirectories....
> 
> Thanks.
> --
> To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at  http://www.tux.org/lkml/
> 

Re: [PATCH 0/3] tracing/function-graph-tracer: signal interrupt triggering on output

[Ingo Molnar]

* Frederic Weisbecker <fweisbec@gmail.com> wrote:

> Frederic Weisbecker wrote:
> > This patchset adds all the features to draw hardirq triggering on output
> > for the function graph tracer.
> > An example is given on the third patch.
> > 
> > Just one question, on recordmcount.pl:
> > 
> > my %text_sections = (
> >       ".text" => 1,
> >       ".sched.text" => 1,
> >       ".spinlock.text" => 1,
> > 
> > The .sched.text section is included inside .text, it's a subsection, I'm not sure
> > it's necessary to add it in text_sections. In doubt I added the new .irqentry.text
> > 
> > The stat of the patchset:
> > 
> >  arch/x86/kernel/apic.c               |    3 +-
> >  arch/x86/kernel/irq_64.c             |    3 +-
> >  arch/x86/kernel/vmlinux_64.lds.S     |    1 +
> >  include/asm-generic/vmlinux.lds.h    |   10 +++++
> >  include/linux/ftrace.h               |   11 ++++++
> >  kernel/trace/trace_functions_graph.c |   66 +++++++++++++++++++++++++++++++--
> >  scripts/recordmcount.pl              |    1 +
> >  7 files changed, 89 insertions(+), 6 deletions(-)

applied to tip/tracing/function-graph-tracer, thanks Frederic!

The output looks really nice.

	Ingo

Re: [PATCH 0/3] tracing/function-graph-tracer: signal interrupt triggering on output

[Frédéric Weisbecker]

2008/12/12 Ingo Molnar <mingo@elte.hu>:
>
> * Frederic Weisbecker <fweisbec@gmail.com> wrote:
>
>> Frederic Weisbecker wrote:
>> > This patchset adds all the features to draw hardirq triggering on output
>> > for the function graph tracer.
>> > An example is given on the third patch.
>> >
>> > Just one question, on recordmcount.pl:
>> >
>> > my %text_sections = (
>> >       ".text" => 1,
>> >       ".sched.text" => 1,
>> >       ".spinlock.text" => 1,
>> >
>> > The .sched.text section is included inside .text, it's a subsection, I'm not sure
>> > it's necessary to add it in text_sections. In doubt I added the new .irqentry.text
>> >
>> > The stat of the patchset:
>> >
>> >  arch/x86/kernel/apic.c               |    3 +-
>> >  arch/x86/kernel/irq_64.c             |    3 +-
>> >  arch/x86/kernel/vmlinux_64.lds.S     |    1 +
>> >  include/asm-generic/vmlinux.lds.h    |   10 +++++
>> >  include/linux/ftrace.h               |   11 ++++++
>> >  kernel/trace/trace_functions_graph.c |   66 +++++++++++++++++++++++++++++++--
>> >  scripts/recordmcount.pl              |    1 +
>> >  7 files changed, 89 insertions(+), 6 deletions(-)
>
> applied to tip/tracing/function-graph-tracer, thanks Frederic!
>
> The output looks really nice.
>
>        Ingo
>

Thanks :-)

If anyone  has other needs or suggestions about this tracer, don't
hesitate to request it.
I remember Peter suggested that the preempt count could be output.
Actually, to make the things more humans, I would suggest to simply
output the fact that preempt is disabled or not.

I could for example give three more fields with one letter for each
(as a default-off trace option):

_interrupt disabled
_preempt disabled
_in atomic context

I guess those could help for the -rt tree for example.
What do you think?

When I worked on this hardirq signal, I wanted to print the current
code context for each function:

Interrupt:
_ Hardirq
_ Softirq (with subclasses like tasklets)
_ Nmi (not yet traced, if there are still plans for the ring buffer to
be lockless, that will be easy).

Task:
_Syscall
_Workqueue
_kernel thread

But actually, those things are easy to find if the current task/pid is
output. "ksoftirqd", "events" are here to give
the hints about the softirq and workqueue context. Syscalls are easy
to find along the code flow. Kernel threads are
recognized through their name. And hardirqs have their arrows....

But if you think such a column could be useful for you or anyone, just tell me.

There is still some work remaining, the braces on leaf functions have
to disappear on the trace_pipe (but it requires
to read the ring-buffer on more than one entry forward, just two actually).

And a port to other archs. I will try to acquire a low cost arm board
if I can (I wouldn't feel comfortable with qemu).

Anyway, most of these things will be for 2.6.30 I guess :-)

Re: [PATCH 0/3] tracing/function-graph-tracer: signal interrupt triggering on output

[Ingo Molnar]

* Frédéric Weisbecker <fweisbec@gmail.com> wrote:

> > applied to tip/tracing/function-graph-tracer, thanks Frederic!
> >
> > The output looks really nice.
> >
> >        Ingo
> >
> 
> Thanks :-)
> 
> If anyone  has other needs or suggestions about this tracer, don't
> hesitate to request it.
> I remember Peter suggested that the preempt count could be output.

that reminds me ... did you know about hardirq_count()? We could use it 
to detect IRQ entries in a more generic way, instead of the section 
trick?

Another thing, i just noticed that ftrace_print() is broken in certain 
situations, for example a plain newline:

        ftrace_printk("\n");

printed via trace_pipe will print some weirdly concatenated line:

           <...>-2994  [007]   406.498986: debug_show:          <...>-2994  [007]   406.498986:            <...>-2994  [007]   406.498986: debug_show: 

not via a separate, standalone, empty line.

Another thing: it would be nice to have a trace_option to leave out this 
preamble:

           <...>-2994  [007]   406.498986: debug_show:  test printk

and just give this output:

 test printk

i.e. some 'printk compatibility' mode. That way i could use 
ftrace_printk() as a pure replacement for printk, during development.

	Ingo

Re: [PATCH 0/3] tracing/function-graph-tracer: signal interrupt triggering on output

[Frédéric Weisbecker]

2008/12/13 Ingo Molnar <mingo@elte.hu>:
> that reminds me ... did you know about hardirq_count()? We could use it
> to detect IRQ entries in a more generic way, instead of the section
> trick?


No I didn't know it but thought about it indirectly.
This counter is inc/dec on irq_enter and irq_exit. I wanted first to
send some special events
while entering irq_enter/exit to notice interrupt events. The problem
is that the irq is raised a bit sooner.
If I used I would have:

    foo() {
        smp_apic_timer_interrupt() {
            irq_enter() {
                 ===> //hardirq_count() is incremented here
            }
        }
    }

We would loose so the sense of the arrow here. Its role is to explain
the breakage into
the code flow by the interrupt. The role of the arrow is to explain
that smp_apic_timer_interrupt is not called
by foo().

One thing I would suggest would be to move these irq_enter/exit on entry_xx.S

> Another thing, i just noticed that ftrace_print() is broken in certain
> situations, for example a plain newline:
>
>        ftrace_printk("\n");
>
> printed via trace_pipe will print some weirdly concatenated line:
>
>           <...>-2994  [007]   406.498986: debug_show:          <...>-2994  [007]   406.498986:            <...>-2994  [007]   406.498986: debug_show:
>
> not via a separate, standalone, empty line.

Ok, I will send a patch.

>
> Another thing: it would be nice to have a trace_option to leave out this
> preamble:
>
>           <...>-2994  [007]   406.498986: debug_show:  test printk
>
> and just give this output:
>
>  test printk
>
> i.e. some 'printk compatibility' mode. That way i could use
> ftrace_printk() as a pure replacement for printk, during development.
>
>        Ingo
>

Ok. I will add a flag for that too.

Re: [PATCH 0/3] tracing/function-graph-tracer: signal interrupt triggering on output

[Frédéric Weisbecker]

2008/12/13 Ingo Molnar <mingo@elte.hu>:
> Another thing, i just noticed that ftrace_print() is broken in certain
> situations, for example a plain newline:
>
>        ftrace_printk("\n");
>
> printed via trace_pipe will print some weirdly concatenated line:
>
>           <...>-2994  [007]   406.498986: debug_show:          <...>-2994  [007]   406.498986:            <...>-2994  [007]   406.498986: debug_show:
>
> not via a separate, standalone, empty line.

I just tested with latest -tip and I don't any problem with it.
With a single ftrace_printk("\n") on might_sleep() I get:

           <...>-2739  [000]   145.692153: __might_sleep:
           <...>-2739  [000]   145.692155: __might_sleep:
           <...>-2739  [000]   145.692157: __might_sleep:
           <...>-2739  [000]   145.692158: __might_sleep:

with trace or trace_iter file.
Does it always occur or in rare situations?

Re: [PATCH 0/3] tracing/function-graph-tracer: signal interrupt triggering on output

[Peter Zijlstra]

On Sat, 2008-12-13 at 08:49 +0100, Ingo Molnar wrote:
> * Frédéric Weisbecker <fweisbec@gmail.com> wrote:
> 
> > > applied to tip/tracing/function-graph-tracer, thanks Frederic!
> > >
> > > The output looks really nice.
> > >
> > >        Ingo
> > >
> > 
> > Thanks :-)
> > 
> > If anyone  has other needs or suggestions about this tracer, don't
> > hesitate to request it.
> > I remember Peter suggested that the preempt count could be output.
> 
> that reminds me ... did you know about hardirq_count()? We could use it 
> to detect IRQ entries in a more generic way, instead of the section 
> trick?

hardirq_count() is set from __irq_enter(), which is too late, we've
already had all the ARCH irq code before that.

Re: [PATCH 0/3] tracing/function-graph-tracer: signal interrupt triggering on output

[Ingo Molnar]

* Frédéric Weisbecker <fweisbec@gmail.com> wrote:

> 2008/12/13 Ingo Molnar <mingo@elte.hu>:
> > Another thing, i just noticed that ftrace_print() is broken in certain
> > situations, for example a plain newline:
> >
> >        ftrace_printk("\n");
> >
> > printed via trace_pipe will print some weirdly concatenated line:
> >
> >           <...>-2994  [007]   406.498986: debug_show:          <...>-2994  [007]   406.498986:            <...>-2994  [007]   406.498986: debug_show:
> >
> > not via a separate, standalone, empty line.
> 
> I just tested with latest -tip and I don't any problem with it.
> With a single ftrace_printk("\n") on might_sleep() I get:
> 
>            <...>-2739  [000]   145.692153: __might_sleep:
>            <...>-2739  [000]   145.692155: __might_sleep:
>            <...>-2739  [000]   145.692157: __might_sleep:
>            <...>-2739  [000]   145.692158: __might_sleep:
> 
> with trace or trace_iter file.
> Does it always occur or in rare situations?

it seemed to occur all the time. Will investigate it if i see it again.

	Ingo