preemption latency trace v1.1.4 on 2.6.12-RT-V0.7.50-11-debug
--------------------------------------------------------------------
 latency: 231 us, #88/88, CPU#1 | (M:rt VP:0, KP:1, SP:1 HP:1 #P:2)
    -----------------
    | task: softirq-timer/1-13 (uid:0 nice:-10 policy:0 rt_prio:0)
    -----------------

                 _------=> CPU#            
                / _-----=> irqs-off        
               | / _----=> need-resched    
               || / _---=> hardirq/softirq 
               ||| / _--=> preempt-depth   
               |||| /                      
               |||||     delay             
   cmd     pid ||||| time  |   caller      
      \   /    |||||   \   |   /           
  <idle>-0     1Dnh3    0us : find_next_bit (__trace_start_sched_wakeup)
  <idle>-0     0Dnh1    0us : _raw_spin_unlock (scheduler_tick)
  <idle>-0     1Dnh3    0us : <70617773> (<00726570>)
  <idle>-0     0Dnh.    0us : rebalance_tick (scheduler_tick)
  <idle>-0     1Dnh3    0us : __trace_start_sched_wakeup (try_to_wake_up)
  <idle>-0     1Dnh3    1us : __trace_start_sched_wakeup <<...>-13> (69 1)
  <idle>-0     0Dnh.    1us : softlockup_tick (smp_apic_timer_interrupt)
  <idle>-0     1Dnh3    1us : _raw_spin_unlock (try_to_wake_up)
  <idle>-0     0Dnh.    1us : irq_exit (apic_timer_interrupt)
  <idle>-0     1Dnh2    1us : resched_task (try_to_wake_up)
  <idle>-0     0Dnh1    1us : do_softirq (irq_exit)
  <idle>-0     0Dnh1    2us : __do_softirq (do_softirq)
  <idle>-0     1Dnh2    2us : try_to_wake_up <<...>-13> (69 8c)
  <idle>-0     0Dnh1    2us : trigger_softirqs (do_softirq)
  <idle>-0     1Dnh2    2us : _raw_spin_unlock_irqrestore (try_to_wake_up)
  <idle>-0     0Dnh1    2us : wakeup_softirqd (trigger_softirqs)
  <idle>-0     1Dnh1    2us : preempt_schedule (try_to_wake_up)
  <idle>-0     1Dnh1    3us : wake_up_process (trigger_softirqs)
  <idle>-0     0Dnh1    3us : wake_up_process (trigger_softirqs)
  <idle>-0     0Dnh1    3us : try_to_wake_up (wake_up_process)
  <idle>-0     1Dnh.    3us : preempt_schedule_irq (need_resched)
  <idle>-0     0Dnh1    3us : _raw_spin_lock (try_to_wake_up)
  <idle>-0     1Dnh.    3us : __schedule (preempt_schedule_irq)
  <idle>-0     1Dnh.    4us : profile_hit (__schedule)
  <idle>-0     0Dnh2    4us : wake_idle (try_to_wake_up)
  <idle>-0     1Dnh1    4us : sched_clock (__schedule)
  <idle>-0     0Dnh2    4us : idle_cpu (wake_idle)
  <idle>-0     1Dnh1    5us : _raw_spin_lock_irq (__schedule)
  <idle>-0     0Dnh2    5us : activate_task (try_to_wake_up)
  <idle>-0     1Dnh1    5us : _raw_spin_lock_irqsave (__schedule)
  <idle>-0     0Dnh2    5us : sched_clock (activate_task)
  <idle>-0     0Dnh2    5us : recalc_task_prio (activate_task)
  <idle>-0     1Dnh2    5us : dependent_sleeper (__schedule)
  <idle>-0     0Dnh2    6us : effective_prio (recalc_task_prio)
  <idle>-0     1Dnh2    6us : _raw_spin_unlock (dependent_sleeper)
  <idle>-0     0Dnh2    6us : activate_task <<...>-4> (69 0)
  <idle>-0     1Dnh1    6us : preempt_schedule (dependent_sleeper)
  <idle>-0     0Dnh2    6us : enqueue_task (activate_task)
  <idle>-0     1Dnh1    6us : _raw_spin_lock (dependent_sleeper)
  <idle>-0     0Dnh2    7us : __trace_start_sched_wakeup (try_to_wake_up)
  <idle>-0     1Dnh1    7us : preempt_schedule (_raw_spin_lock)
  <idle>-0     0Dnh2    7us : _raw_spin_lock (__trace_start_sched_wakeup)
  <idle>-0     0Dnh3    7us : _raw_spin_unlock (try_to_wake_up)
  <idle>-0     0Dnh2    7us : resched_task (try_to_wake_up)
  <idle>-0     0Dnh2    8us : try_to_wake_up <<...>-4> (69 8c)
  <idle>-0     0Dnh2    8us : _raw_spin_unlock_irqrestore (try_to_wake_up)
  <idle>-0     1Dnh2    8us : find_next_bit (dependent_sleeper)
  <idle>-0     0Dnh1    8us : preempt_schedule (try_to_wake_up)
  <idle>-0     1Dnh2    8us : _raw_spin_lock (dependent_sleeper)
  <idle>-0     0Dnh1    8us : wake_up_process (trigger_softirqs)
  <idle>-0     1Dnh3    9us : find_next_bit (dependent_sleeper)
  <idle>-0     0Dnh.    9us : preempt_schedule_irq (need_resched)
  <idle>-0     0Dnh.    9us : __schedule (preempt_schedule_irq)
  <idle>-0     1Dnh3    9us : resched_task (dependent_sleeper)
  <idle>-0     0Dnh.   10us : profile_hit (__schedule)
  <idle>-0     1Dnh3   10us : find_next_bit (dependent_sleeper)
  <idle>-0     0Dnh1   10us : sched_clock (__schedule)
  <idle>-0     1Dnh3   10us : _raw_spin_unlock (dependent_sleeper)
  <idle>-0     0Dnh1   10us : _raw_spin_lock_irq (__schedule)
  <idle>-0     1Dnh2   11us : preempt_schedule (dependent_sleeper)
  <idle>-0     0Dnh1   11us : _raw_spin_lock_irqsave (__schedule)
  <idle>-0     1Dnh2   11us : find_next_bit (dependent_sleeper)
  <idle>-0     0Dnh2   11us : dependent_sleeper (__schedule)
  <idle>-0     0Dnh2   11us : _raw_spin_unlock (dependent_sleeper)
  <idle>-0     1Dnh2   11us : dequeue_task (__schedule)
  <idle>-0     0Dnh1   12us : preempt_schedule (dependent_sleeper)
  <idle>-0     1Dnh2   12us : recalc_task_prio (__schedule)
  <idle>-0     0Dnh1   12us : _raw_spin_lock (dependent_sleeper)
  <idle>-0     1Dnh2   12us : effective_prio (recalc_task_prio)
  <idle>-0     0Dnh2   12us : find_next_bit (dependent_sleeper)
  <idle>-0     1Dnh2   12us : enqueue_task (__schedule)
  <idle>-0     0Dnh2   13us : _raw_spin_lock (dependent_sleeper)
  <idle>-0     1Dnh2   13us : trace_array (__schedule)
  <idle>-0     0Dnh2   13us : preempt_schedule (_raw_spin_lock)
  <idle>-0     1Dnh2   14us : trace_array <<...>-13> (69 6e)
  <idle>-0     1Dnh2   15us : trace_array (__schedule)
   <...>-13    1Dnh2   17us : __switch_to (__schedule)
   <...>-13    1Dnh2   17us : __schedule <<idle>-0> (8c 69)
   <...>-13    1Dnh2   17us : _raw_spin_unlock (__schedule)
   <...>-13    1Dnh1   18us : trace_stop_sched_switched (__schedule)
  <idle>-0     0Dnh3   18us!: find_next_bit (dependent_sleeper)
   <...>-13    1Dnh1  229us : _raw_spin_lock (trace_stop_sched_switched)
   <...>-13    1Dnh2  230us : trace_stop_sched_switched <<...>-13> (69 1)
  <idle>-0     0Dnh3  230us : find_next_bit (dependent_sleeper)
   <...>-13    1Dnh2  230us : _raw_spin_unlock (trace_stop_sched_switched)
  <idle>-0     0Dnh3  231us : _raw_spin_unlock (dependent_sleeper)
   <...>-13    1Dnh1  231us : trace_stop_sched_switched (__schedule)


vim:ft=help