• Changbin Du's avatar
    function_graph: Support displaying relative timestamp · 9acd8de6
    Changbin Du authored
    When function_graph is used for latency tracers, relative timestamp
    is more straightforward than absolute timestamp as function trace
    does. This change adds relative timestamp support to function_graph
    and applies to latency tracers (wakeup and irqsoff).
    
    Instead of:
    
     # tracer: irqsoff
     #
     # irqsoff latency trace v1.1.5 on 5.0.0-rc1-test
     # --------------------------------------------------------------------
     # latency: 521 us, #1125/1125, CPU#2 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:8)
     #    -----------------
     #    | task: swapper/2-0 (uid:0 nice:0 policy:0 rt_prio:0)
     #    -----------------
     #  => started at: __schedule
     #  => ended at:   _raw_spin_unlock_irq
     #
     #
     #                                       _-----=> irqs-off
     #                                      / _----=> need-resched
     #                                     | / _---=> hardirq/softirq
     #                                     || / _--=> preempt-depth
     #                                     ||| /
     #     TIME        CPU  TASK/PID       ||||  DURATION                  FUNCTION CALLS
     #      |          |     |    |        ||||   |   |                     |   |   |   |
       124.974306 |   2)  systemd-693   |  d..1  0.000 us    |  __schedule();
       124.974307 |   2)  systemd-693   |  d..1              |    rcu_note_context_switch() {
       124.974308 |   2)  systemd-693   |  d..1  0.487 us    |      rcu_preempt_deferred_qs();
       124.974309 |   2)  systemd-693   |  d..1  0.451 us    |      rcu_qs();
       124.974310 |   2)  systemd-693   |  d..1  2.301 us    |    }
    [..]
       124.974826 |   2)    <idle>-0    |  d..2              |  finish_task_switch() {
       124.974826 |   2)    <idle>-0    |  d..2              |    _raw_spin_unlock_irq() {
       124.974827 |   2)    <idle>-0    |  d..2  0.000 us    |  _raw_spin_unlock_irq();
       124.974828 |   2)    <idle>-0    |  d..2  0.000 us    |  tracer_hardirqs_on();
       <idle>-0       2d..2  552us : <stack trace>
      => __schedule
      => schedule_idle
      => do_idle
      => cpu_startup_entry
      => start_secondary
      => secondary_startup_64
    
    Show:
    
     # tracer: irqsoff
     #
     # irqsoff latency trace v1.1.5 on 5.0.0-rc1-test+
     # --------------------------------------------------------------------
     # latency: 511 us, #1053/1053, CPU#7 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:8)
     #    -----------------
     #    | task: swapper/7-0 (uid:0 nice:0 policy:0 rt_prio:0)
     #    -----------------
     #  => started at: __schedule
     #  => ended at:   _raw_spin_unlock_irq
     #
     #
     #                                       _-----=> irqs-off
     #                                      / _----=> need-resched
     #                                     | / _---=> hardirq/softirq
     #                                     || / _--=> preempt-depth
     #                                     ||| /
     #   REL TIME      CPU  TASK/PID       ||||  DURATION                  FUNCTION CALLS
     #      |          |     |    |        ||||   |   |                     |   |   |   |
             0 us |   7)   sshd-1704    |  d..1  0.000 us    |  __schedule();
             1 us |   7)   sshd-1704    |  d..1              |    rcu_note_context_switch() {
             1 us |   7)   sshd-1704    |  d..1  0.611 us    |      rcu_preempt_deferred_qs();
             2 us |   7)   sshd-1704    |  d..1  0.484 us    |      rcu_qs();
             3 us |   7)   sshd-1704    |  d..1  2.599 us    |    }
    [..]
           509 us |   7)    <idle>-0    |  d..2              |  finish_task_switch() {
           510 us |   7)    <idle>-0    |  d..2              |    _raw_spin_unlock_irq() {
           510 us |   7)    <idle>-0    |  d..2  0.000 us    |  _raw_spin_unlock_irq();
           512 us |   7)    <idle>-0    |  d..2  0.000 us    |  tracer_hardirqs_on();
       <idle>-0       7d..2  543us : <stack trace>
      => __schedule
      => schedule_idle
      => do_idle
      => cpu_startup_entry
      => start_secondary
      => secondary_startup_64
    
    Link: http://lkml.kernel.org/r/20190101154614.8887-2-changbin.du@gmail.comSigned-off-by: default avatarChangbin Du <changbin.du@gmail.com>
    Signed-off-by: default avatarSteven Rostedt (VMware) <rostedt@goodmis.org>
    9acd8de6
trace_irqsoff.c 17.4 KB