title: Linux kernel ftrace irqsoff tracer generates strange output
body: <p>I was analyzing the interrupt latency in my system( Freescale ARM MX6Q with linux kernel version 3.0.35), I am using the irqsoff tracer, and this is the output I'm getting for the biggest irq off latency:</p>
  
  <pre><code># tracer: irqsoff
  #
  # irqsoff latency trace v1.1.5
  # --------------------------------------------------------------------
  # latency: 2770 us, #89/89, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
  #    -----------------
  #    | task: swapper-0 (uid:0 nice:0 policy:0 rt_prio:0)
  #    -----------------
  #  =&gt; started at: tick_oneshot_mode_active
  #  =&gt; ended at:   default_idle
  #
  #
  #                  _------=&gt; CPU#            
  #                 / _-----=&gt; irqs-off        
  #                | / _----=&gt; need-resched    
  #                || / _---=&gt; hardirq/softirq 
  #                ||| / _--=&gt; preempt-depth   
  #                |||| /     delay             
  #  cmd     pid   ||||| time  |   caller      
  #     \   /      |||||  \    |   /           
    &lt;idle&gt;-0       0d..1    1us : tick_oneshot_mode_active
    &lt;idle&gt;-0       0d..1    2us : clockevents_notify &lt;-arch_idle
    &lt;idle&gt;-0       0d..1    3us : _raw_spin_lock_irqsave &lt;-clockevents_notify
    &lt;idle&gt;-0       0d..1    5us : __raw_spin_lock_irqsave &lt;-_raw_spin_lock_irqsave
    &lt;idle&gt;-0       0d..1    6us : add_preempt_count &lt;-__raw_spin_lock_irqsave
    &lt;idle&gt;-0       0d..2    7us : clockevents_do_notify &lt;-clockevents_notify
    &lt;idle&gt;-0       0d..2    8us : raw_notifier_call_chain &lt;-clockevents_do_notify
    &lt;idle&gt;-0       0d..2   10us : __raw_notifier_call_chain &lt;-raw_notifier_call_chain
    &lt;idle&gt;-0       0d..2   11us : notifier_call_chain &lt;-__raw_notifier_call_chain
    &lt;idle&gt;-0       0d..2   12us : tick_notify &lt;-notifier_call_chain
    &lt;idle&gt;-0       0d..2   13us : tick_broadcast_oneshot_control &lt;-tick_notify
    &lt;idle&gt;-0       0d..2   15us : _raw_spin_lock_irqsave &lt;-tick_broadcast_oneshot_control
    &lt;idle&gt;-0       0d..2   16us : __raw_spin_lock_irqsave &lt;-_raw_spin_lock_irqsave
    &lt;idle&gt;-0       0d..2   17us+: add_preempt_count &lt;-__raw_spin_lock_irqsave
    &lt;idle&gt;-0       0d..3   19us : clockevents_set_mode &lt;-tick_broadcast_oneshot_control
    &lt;idle&gt;-0       0d..3   20us : twd_set_mode &lt;-clockevents_set_mode
    &lt;idle&gt;-0       0d..3   21us : irq_modify_status &lt;-gic_disable_ppi
    &lt;idle&gt;-0       0d..3   22us : __irq_get_desc_lock &lt;-irq_modify_status
    &lt;idle&gt;-0       0d..3   24us : irq_to_desc &lt;-__irq_get_desc_lock
    &lt;idle&gt;-0       0d..3   25us : _raw_spin_lock_irqsave &lt;-__irq_get_desc_lock
    &lt;idle&gt;-0       0d..3   26us : __raw_spin_lock_irqsave &lt;-_raw_spin_lock_irqsave
    &lt;idle&gt;-0       0d..3   27us : add_preempt_count &lt;-__raw_spin_lock_irqsave
    &lt;idle&gt;-0       0d..4   29us : __irq_put_desc_unlock &lt;-irq_modify_status
    &lt;idle&gt;-0       0d..4   30us : _raw_spin_unlock_irqrestore &lt;-__irq_put_desc_unlock
    &lt;idle&gt;-0       0d..4   31us : sub_preempt_count &lt;-_raw_spin_unlock_irqrestore
    &lt;idle&gt;-0       0d..3   32us : irq_get_irq_data &lt;-gic_disable_ppi
    &lt;idle&gt;-0       0d..3   34us : irq_to_desc &lt;-irq_get_irq_data
    &lt;idle&gt;-0       0d..3   35us : gic_mask_irq &lt;-gic_disable_ppi
    &lt;idle&gt;-0       0d..3   36us : _raw_spin_lock &lt;-gic_mask_irq
    &lt;idle&gt;-0       0d..3   37us : __raw_spin_lock &lt;-_raw_spin_lock
    &lt;idle&gt;-0       0d..3   39us : add_preempt_count &lt;-__raw_spin_lock
    &lt;idle&gt;-0       0d..4   40us : _raw_spin_unlock &lt;-gic_mask_irq
    &lt;idle&gt;-0       0d..4   41us+: sub_preempt_count &lt;-_raw_spin_unlock
    &lt;idle&gt;-0       0d..3   43us : _raw_spin_unlock_irqrestore &lt;-tick_broadcast_oneshot_control
    &lt;idle&gt;-0       0d..3   44us : sub_preempt_count &lt;-_raw_spin_unlock_irqrestore
    &lt;idle&gt;-0       0d..2   45us+: _raw_spin_unlock_irqrestore &lt;-clockevents_notify
    &lt;idle&gt;-0       0d..2   47us : sub_preempt_count &lt;-_raw_spin_unlock_irqrestore
    &lt;idle&gt;-0       0d..1   48us+: mxc_cpu_lp_set &lt;-arch_idle
    &lt;idle&gt;-0       0d..1   50us+: gpc_mask_single_irq &lt;-mxc_cpu_lp_set
    &lt;idle&gt;-0       0d..1   51us+: gpc_mask_single_irq &lt;-mxc_cpu_lp_set
    &lt;idle&gt;-0       0d..1   53us+: arch_idle_multi_core &lt;-arch_idle
    &lt;idle&gt;-0       0d..1   55us!: ca9_do_idle &lt;-arch_idle_multi_core
    &lt;idle&gt;-0       0d..1 2709us : clockevents_notify &lt;-arch_idle
    &lt;idle&gt;-0       0d..1 2710us : _raw_spin_lock_irqsave &lt;-clockevents_notify
    &lt;idle&gt;-0       0d..1 2711us : __raw_spin_lock_irqsave &lt;-_raw_spin_lock_irqsave
    &lt;idle&gt;-0       0d..1 2712us+: add_preempt_count &lt;-__raw_spin_lock_irqsave
    &lt;idle&gt;-0       0d..2 2714us : clockevents_do_notify &lt;-clockevents_notify
    &lt;idle&gt;-0       0d..2 2715us : raw_notifier_call_chain &lt;-clockevents_do_notify
    &lt;idle&gt;-0       0d..2 2716us : __raw_notifier_call_chain &lt;-raw_notifier_call_chain
    &lt;idle&gt;-0       0d..2 2717us : notifier_call_chain &lt;-__raw_notifier_call_chain
    &lt;idle&gt;-0       0d..2 2718us : tick_notify &lt;-notifier_call_chain
    &lt;idle&gt;-0       0d..2 2720us : tick_broadcast_oneshot_control &lt;-tick_notify
    &lt;idle&gt;-0       0d..2 2721us : _raw_spin_lock_irqsave &lt;-tick_broadcast_oneshot_control
    &lt;idle&gt;-0       0d..2 2722us : __raw_spin_lock_irqsave &lt;-_raw_spin_lock_irqsave
    &lt;idle&gt;-0       0d..2 2723us : add_preempt_count &lt;-__raw_spin_lock_irqsave
    &lt;idle&gt;-0       0d..3 2725us : clockevents_set_mode &lt;-tick_broadcast_oneshot_control
    &lt;idle&gt;-0       0d..3 2726us : twd_set_mode &lt;-clockevents_set_mode
    &lt;idle&gt;-0       0d..3 2727us : irq_modify_status &lt;-gic_enable_ppi
    &lt;idle&gt;-0       0d..3 2729us : __irq_get_desc_lock &lt;-irq_modify_status
    &lt;idle&gt;-0       0d..3 2730us : irq_to_desc &lt;-__irq_get_desc_lock
    &lt;idle&gt;-0       0d..3 2731us : _raw_spin_lock_irqsave &lt;-__irq_get_desc_lock
    &lt;idle&gt;-0       0d..3 2732us : __raw_spin_lock_irqsave &lt;-_raw_spin_lock_irqsave
    &lt;idle&gt;-0       0d..3 2733us+: add_preempt_count &lt;-__raw_spin_lock_irqsave
    &lt;idle&gt;-0       0d..4 2738us+: __irq_put_desc_unlock &lt;-irq_modify_status
    &lt;idle&gt;-0       0d..4 2739us : _raw_spin_unlock_irqrestore &lt;-__irq_put_desc_unlock
    &lt;idle&gt;-0       0d..4 2741us : sub_preempt_count &lt;-_raw_spin_unlock_irqrestore
    &lt;idle&gt;-0       0d..3 2742us : irq_get_irq_data &lt;-gic_enable_ppi
    &lt;idle&gt;-0       0d..3 2743us : irq_to_desc &lt;-irq_get_irq_data
    &lt;idle&gt;-0       0d..3 2745us : gic_unmask_irq &lt;-gic_enable_ppi
    &lt;idle&gt;-0       0d..3 2746us : _raw_spin_lock &lt;-gic_unmask_irq
    &lt;idle&gt;-0       0d..3 2747us : __raw_spin_lock &lt;-_raw_spin_lock
    &lt;idle&gt;-0       0d..3 2748us+: add_preempt_count &lt;-__raw_spin_lock
    &lt;idle&gt;-0       0d..4 2750us : _raw_spin_unlock &lt;-gic_unmask_irq
    &lt;idle&gt;-0       0d..4 2751us+: sub_preempt_count &lt;-_raw_spin_unlock
    &lt;idle&gt;-0       0d..3 2753us : ktime_get &lt;-tick_broadcast_oneshot_control
    &lt;idle&gt;-0       0d..3 2754us+: clocksource_mmio_readl_up &lt;-ktime_get
    &lt;idle&gt;-0       0d..3 2756us : tick_program_event &lt;-tick_broadcast_oneshot_control
    &lt;idle&gt;-0       0d..3 2757us : tick_dev_program_event &lt;-tick_program_event
    &lt;idle&gt;-0       0d..3 2758us : ktime_get &lt;-tick_dev_program_event
    &lt;idle&gt;-0       0d..3 2759us+: clocksource_mmio_readl_up &lt;-ktime_get
    &lt;idle&gt;-0       0d..3 2761us : clockevents_program_event &lt;-tick_dev_program_event
    &lt;idle&gt;-0       0d..3 2762us : twd_set_next_event &lt;-clockevents_program_event
    &lt;idle&gt;-0       0d..3 2764us : _raw_spin_unlock_irqrestore &lt;-tick_broadcast_oneshot_control
    &lt;idle&gt;-0       0d..3 2765us+: sub_preempt_count &lt;-_raw_spin_unlock_irqrestore
    &lt;idle&gt;-0       0d..2 2767us : _raw_spin_unlock_irqrestore &lt;-clockevents_notify
    &lt;idle&gt;-0       0d..2 2768us : sub_preempt_count &lt;-_raw_spin_unlock_irqrestore
    &lt;idle&gt;-0       0d..1 2769us+: default_idle
    &lt;idle&gt;-0       0d..1 2772us+: trace_hardirqs_on &lt;-default_idle
    &lt;idle&gt;-0       0d..1 2773us : &lt;stack trace&gt;
   =&gt; trace_hardirqs_on
   =&gt; default_idle
   =&gt; cpu_idle
   =&gt; rest_init
   =&gt; start_kernel
   =&gt; 
  </code></pre>
  
  <p>So according to ftrace I have a pretty big latency, it looks as if the interrupts are disabled as long as the CPU is idle. So I thought surely this cannot be true, so I looked more closely at function tick_oneshot_mode_active:</p>
  
  <pre><code>int tick_oneshot_mode_active(void)
  {
      unsigned long flags;
      int ret;
  
      local_irq_save(flags);
      ret = __this_cpu_read(tick_cpu_device.mode) == TICKDEV_MODE_ONESHOT;
      local_irq_restore(flags);
  
      return ret;
  }
  </code></pre>
  
  <p>So in the macro local_irq_save, the interrupts are disabled and the function trace_hardirqs_off() is called which registers that the interrupts were disabled:</p>
  
  <pre><code>#define local_irq_save(flags)               \
      do {                        \
          raw_local_irq_save(flags);      \
          trace_hardirqs_off();           \
      } while (0)
  </code></pre>
  
  <p>After checking the device mode the interrupts are enabled, now here it is strange:</p>
  
  <pre><code>#define local_irq_restore(flags)            \
      do {                        \
          if (raw_irqs_disabled_flags(flags)) {   \
              raw_local_irq_restore(flags);   \
              trace_hardirqs_off();       \
          } else {                \
              trace_hardirqs_on();        \
              raw_local_irq_restore(flags);   \
          }                   \
      } while (0)
  </code></pre>
  
  <p>In my case the code goes over the first branch:</p>
  
  <pre><code>if (raw_irqs_disabled_flags(flags)) {   \
                  raw_local_irq_restore(flags);   \
                  trace_hardirqs_off();       \
  </code></pre>
  
  <p>It looks as if even though the interrupts are enabled back, function trace_hardirqs_on is not called but trace_hardirqs_off(). Why is this happening, do I really have this big latency?</p>