preemption latency trace v1.1.3 on 2.6.10-rc2-mm3-V0.7.32-9
--------------------------------------------------------------------
 latency: 39 us, #42/42 | (M:rt VP:0, KP:1, SP:1 HP:1 #P:2)
    -----------------
    | task: IRQ 8-677 (uid:0 nice:-5 policy:1 rt_prio:99)
    -----------------

                 _------=> CPU#            
                / _-----=> irqs-off        
               | / _----=> hardirq         
               || / _---=> softirq         
               ||| / _--=> preempt-depth   
               |||| /                      
               |||||     delay             
   cmd     pid ||||| time  |   caller      
      \   /    |||||   \   |   /           
   amlat-4973  0-h.3    0µs : __trace_start_sched_wakeup (try_to_wake_up)
   amlat-4973  0-h.3    1µs : _raw_spin_unlock (try_to_wake_up)
   amlat-4973  0-h.2    1µs : preempt_schedule (try_to_wake_up)
   amlat-4973  0        2µs : wake_up_process <IRQ 8-677> (0 1): 
   amlat-4973  0-h.2    2µs : try_to_wake_up (wake_up_process)
   amlat-4973  0-h.2    2µs : _raw_spin_unlock (try_to_wake_up)
   amlat-4973  0-h.1    3µs : preempt_schedule (try_to_wake_up)
   amlat-4973  0-h.1    3µs : wake_up_process (redirect_hardirq)
   amlat-4973  0-h.1    4µs : _raw_spin_unlock (__do_IRQ)
   amlat-4973  0-h..    4µs : preempt_schedule (__do_IRQ)
   amlat-4973  0-h..    4µs : irq_exit (do_IRQ)
   amlat-4973  0-h.1    5µs : do_softirq (irq_exit)
   amlat-4973  0-h.1    5µs : __do_softirq (do_softirq)
   amlat-4973  0-h..    6µs : preempt_schedule_irq (need_resched)
   amlat-4973  0-h..    6µs : __schedule (preempt_schedule_irq)
   amlat-4973  0-h.1    7µs : sched_clock (__schedule)
   amlat-4973  0-h.1    8µs : _raw_spin_lock_irq (__schedule)
   amlat-4973  0-h.1    8µs : _raw_spin_lock_irqsave (__schedule)
   amlat-4973  0-h.2   10µs : pull_rt_tasks (__schedule)
   amlat-4973  0-h.2   10µs : find_next_bit (pull_rt_tasks)
   amlat-4973  0-h.2   11µs+: find_next_bit (pull_rt_tasks)
   amlat-4973  0-..2   13µs : trace_array (__schedule)
   amlat-4973  0       14µs : __schedule <IRQ 8-677> (0 1): 
   amlat-4973  0       14µs+: __schedule <amlat-4973> (1 2): 
   amlat-4973  0       18µs+: __schedule <<unknown-792> (39 3a): 
   amlat-4973  0       21µs : __schedule <<unknown-4> (69 6e): 
   amlat-4973  0       21µs : __schedule <<unknown-4854> (73 78): 
   amlat-4973  0-..2   22µs+: trace_array (__schedule)
   IRQ 8-677   0-..2   31µs : __switch_to (__schedule)
   IRQ 8-677   0       32µs : schedule <amlat-4973> (1 0): 
   IRQ 8-677   0-..2   32µs : finish_task_switch (__schedule)
   IRQ 8-677   0-..2   33µs : smp_send_reschedule_allbutself (finish_task_switch)
   IRQ 8-677   0-..2   33µs : __bitmap_weight (smp_send_reschedule_allbutself)
   IRQ 8-677   0-..2   34µs : __send_IPI_shortcut (smp_send_reschedule_allbutself)
   IRQ 8-677   0-..2   35µs : _raw_spin_unlock (finish_task_switch)
   IRQ 8-677   0-..1   35µs : trace_stop_sched_switched (finish_task_switch)
   IRQ 8-677   0       36µs : finish_task_switch <IRQ 8-677> (0 0): 
   IRQ 8-677   0-..1   36µs+: _raw_spin_lock_irqsave (trace_stop_sched_switched)
   IRQ 8-677   0-..1   43µs : trace_stop_sched_switched (finish_task_switch)


vim:ft=help