Re: [PATCHv3 0/2] tracing: function graph output for preempt/irqs-off tracers

Steven Rostedt
2010-03-26T14:54:06Z

On Fri, 2010-03-26 at 13:32 +0100, Jiri Olsa wrote:
> hi,
>
> I reworked it based on your comments:
>
> - the function_graph tracer should have the same output
> as current version even with events enabled,
> unless I missed something again ;)
>
> - I gave up the idea of function_graph events,
> since it was unsuitable for outputing other
> events as comments "/* */"
>
> - I'm not including the raw function_graph for now
>

Getting better, but I still have some issues ;-)

Without graph, header looks like this: (old way)

# tracer: irqsoff
#
# irqsoff latency trace v1.1.5 on 2.6.34-rc2
# --------------------------------------------------------------------
# latency: 326 us, #73/73, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0
#P:4)
# -----------------
# | task: swapper-0 (uid:0 nice:0 policy:0 rt_prio:0)
# -----------------
# => started at: save_args
# => ended at: __do_softirq
#
#
# _------=> CPU#
# / _-----=> irqs-off
# | / _----=> need-resched
# || / _---=> hardirq/softirq
# ||| / _--=> preempt-depth
# |||| /_--=> lock-depth
# |||||/ delay
# cmd pid |||||| time | caller
# \ / |||||| \ | /
<idle>-0 1d..1. 1us+: trace_hardirqs_off_thunk <-save_args

Lots of good info.

But if I enable the graph:

# trace-cmd start -p irqsoff -O display-graph
# cat /debug/tracing/trace

# tracer: irqsoff
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / _-=> lock-depth
# |||| /
# CPU||||| DURATION FUNCTION CALLS
# | ||||| | | | | | |
trace-cm-3661 0d.s4. 1us+: trace_hardirqs_off_thunk <-save_args
0) ==========> |
0) d.s4. | smp_apic_timer_interrupt() {
0) d.s4. 5.740 us | native_apic_mem_write();
0) d.s4. 6.458 us | exit_idle();
0) d.s4. | irq_enter() {
0) d.s4. 5.391 us | rcu_irq_enter();

I see you are using the function graph output, but you just lost some
important information that was with the original tracer.

Another thing is. If I disable the option after I record, I get this:

# echo 0 > /debug/tracing/tracing_enabled
# echo 0 > /debug/tracing/option/display-graph
# cat /debug/tracing/trace

# tracer: irqsoff
#
# irqsoff latency trace v1.1.5 on 2.6.34-rc2
# --------------------------------------------------------------------
# latency: 1084 us, #210/210, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0
#P:4)
# -----------------
# | task: irqbalance-2672 (uid:0 nice:0 policy:0 rt_prio:0)
# -----------------
# => started at: save_args
# => ended at: __do_softirq
#
#
# _------=> CPU#
# / _-----=> irqs-off
# | / _----=> need-resched
# || / _---=> hardirq/softirq
# ||| / _--=> preempt-depth
# |||| /_--=> lock-depth
# |||||/ delay
# cmd pid |||||| time | caller
# \ / |||||| \ | /
irqbalan-2672 0d..2. 2us+: trace_hardirqs_off_thunk <-save_args
irqbalan-2672 0d..2. 10us+: Unknown type 14
irqbalan-2672 0d..2. 16us+: Unknown type 14
irqbalan-2672 0d..2. 20us+: Unknown type 13
irqbalan-2672 0d..2. 25us+: Unknown type 14
irqbalan-2672 0d..2. 29us+: Unknown type 13
irqbalan-2672 0d..2. 33us+: Unknown type 14
irqbalan-2672 0d..2. 37us+: Unknown type 14
irqbalan-2672 0d..2. 42us+: Unknown type 13
irqbalan-2672 0d..2. 49us+: Unknown type 14
irqbalan-2672 0d..2. 55us+: Unknown type 13
irqbalan-2672 0d.h2. 62us+: Unknown type 13

I think you can still do the "event" part, without effecting the way the
function graph outputs normally. I would not have given up on that
method. You don't need to worry about it processing other events,
because when you register it to write as an event, it will only be
called when a function graph event was found. It will not be processing
other events. Only when the tracer itself overrides the default writing
will it do so.

-- Steve

>
> attached patches:
> - 1/2 graph output support for irqsoff tracer
> - 2/2 graph output support for preemptirqsoff/preemptoff tracers
>
> plz let me know what you think
>
> wbr,
> jirka
> ---
> kernel/trace/trace.c | 31 ++++--
> kernel/trace/trace.h | 10 ++
> kernel/trace/trace_functions_graph.c | 15 ++-
> kernel/trace/trace_irqsoff.c | 200 ++++++++++++++++++++++++++++++++-
> 4 files changed, 233 insertions(+), 23 deletions(-)