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

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives
Hash Suite: Windows password security audit tool. GUI, reports in PDF.
[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]
Message-ID: <1269615239.19685.78.camel@gandalf.stny.rr.com>
Date:	Fri, 26 Mar 2010 10:53:59 -0400
From:	Steven Rostedt <rostedt@...dmis.org>
To:	Jiri Olsa <jolsa@...hat.com>
Cc:	linux-kernel@...r.kernel.org,
	Frederic Weisbecker <fweisbec@...il.com>,
	Ingo Molnar <mingo@...e.hu>
Subject: Re: [PATCHv3 0/2] tracing: function graph output for
 preempt/irqs-off tracers

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(-)


--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@...r.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/