Skip to content
  • Steven Rostedt's avatar
    ftrace: trace irq disabled critical timings · 81d68a96
    Steven Rostedt authored
    
    
    This patch adds latency tracing for critical timings
    (how long interrupts are disabled for).
    
     "irqsoff" is added to /debugfs/tracing/available_tracers
    
    Note:
      tracing_max_latency
        also holds the max latency for irqsoff (in usecs).
       (default to large number so one must start latency tracing)
    
      tracing_thresh
        threshold (in usecs) to always print out if irqs off
        is detected to be longer than stated here.
        If irq_thresh is non-zero, then max_irq_latency
        is ignored.
    
    Here's an example of a trace with ftrace_enabled = 0
    
    =======
    preemption latency trace v1.1.5 on 2.6.24-rc7
    Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
    --------------------------------------------------------------------
     latency: 100 us, #3/3, CPU#1 | (M:rt VP:0, KP:0, SP:0 HP:0 #P:2)
        -----------------
        | task: swapper-0 (uid:0 nice:0 policy:0 rt_prio:0)
        -----------------
     => started at: _spin_lock_irqsave+0x2a/0xb7
     => ended at:   _spin_unlock_irqrestore+0x32/0x5f
    
                     _------=> CPU#
                    / _-----=> irqs-off
                   | / _----=> need-resched
                   || / _---=> hardirq/softirq
                   ||| / _--=> preempt-depth
                   |||| /
                   |||||     delay
       cmd     pid ||||| time  |   caller
          \   /    |||||   \   |   /
     swapper-0     1d.s3    0us+: _spin_lock_irqsave+0x2a/0xb7 (e1000_update_stats+0x47/0x64c [e1000])
     swapper-0     1d.s3  100us : _spin_unlock_irqrestore+0x32/0x5f (e1000_update_stats+0x641/0x64c [e1000])
     swapper-0     1d.s3  100us : trace_hardirqs_on_caller+0x75/0x89 (_spin_unlock_irqrestore+0x32/0x5f)
    
    vim:ft=help
    =======
    
    And this is a trace with ftrace_enabled == 1
    
    =======
    preemption latency trace v1.1.5 on 2.6.24-rc7
    --------------------------------------------------------------------
     latency: 102 us, #12/12, CPU#1 | (M:rt VP:0, KP:0, SP:0 HP:0 #P:2)
        -----------------
        | task: swapper-0 (uid:0 nice:0 policy:0 rt_prio:0)
        -----------------
     => started at: _spin_lock_irqsave+0x2a/0xb7
     => ended at:   _spin_unlock_irqrestore+0x32/0x5f
    
                     _------=> CPU#
                    / _-----=> irqs-off
                   | / _----=> need-resched
                   || / _---=> hardirq/softirq
                   ||| / _--=> preempt-depth
                   |||| /
                   |||||     delay
       cmd     pid ||||| time  |   caller
          \   /    |||||   \   |   /
     swapper-0     1dNs3    0us+: _spin_lock_irqsave+0x2a/0xb7 (e1000_update_stats+0x47/0x64c [e1000])
     swapper-0     1dNs3   46us : e1000_read_phy_reg+0x16/0x225 [e1000] (e1000_update_stats+0x5e2/0x64c [e1000])
     swapper-0     1dNs3   46us : e1000_swfw_sync_acquire+0x10/0x99 [e1000] (e1000_read_phy_reg+0x49/0x225 [e1000])
     swapper-0     1dNs3   46us : e1000_get_hw_eeprom_semaphore+0x12/0xa6 [e1000] (e1000_swfw_sync_acquire+0x36/0x99 [e1000])
     swapper-0     1dNs3   47us : __const_udelay+0x9/0x47 (e1000_read_phy_reg+0x116/0x225 [e1000])
     swapper-0     1dNs3   47us+: __delay+0x9/0x50 (__const_udelay+0x45/0x47)
     swapper-0     1dNs3   97us : preempt_schedule+0xc/0x84 (__delay+0x4e/0x50)
     swapper-0     1dNs3   98us : e1000_swfw_sync_release+0xc/0x55 [e1000] (e1000_read_phy_reg+0x211/0x225 [e1000])
     swapper-0     1dNs3   99us+: e1000_put_hw_eeprom_semaphore+0x9/0x35 [e1000] (e1000_swfw_sync_release+0x50/0x55 [e1000])
     swapper-0     1dNs3  101us : _spin_unlock_irqrestore+0xe/0x5f (e1000_update_stats+0x641/0x64c [e1000])
     swapper-0     1dNs3  102us : _spin_unlock_irqrestore+0x32/0x5f (e1000_update_stats+0x641/0x64c [e1000])
     swapper-0     1dNs3  102us : trace_hardirqs_on_caller+0x75/0x89 (_spin_unlock_irqrestore+0x32/0x5f)
    
    vim:ft=help
    =======
    
    Signed-off-by: default avatarSteven Rostedt <srostedt@redhat.com>
    Signed-off-by: default avatarIngo Molnar <mingo@elte.hu>
    Signed-off-by: default avatarThomas Gleixner <tglx@linutronix.de>
    81d68a96