preemption latency trace v1.1.4 on 2.6.12-RT-V0.7.50-11-debug
--------------------------------------------------------------------
 latency: 223 us, #76/76, CPU#0 | (M:rt VP:0, KP:1, SP:1 HP:1 #P:2)
    -----------------
    | task: wmfortune-2967 (uid:500 nice:0 policy:0 rt_prio:0)
    -----------------

                 _------=> CPU#            
                / _-----=> irqs-off        
               | / _----=> need-resched    
               || / _---=> hardirq/softirq 
               ||| / _--=> preempt-depth   
               |||| /                      
               |||||     delay             
   cmd     pid ||||| time  |   caller      
      \   /    |||||   \   |   /           
   <...>-3083  1Dnh1    0us : grab_lock (__down_mutex)
softirq--4     0Dnh.    0us : preempt_schedule (__up_mutex)
softirq--4     0Dnh.    0us : irqs_disabled (preempt_schedule)
   <...>-3083  1Dnh1    0us : __down_mutex <<...>-3083> (36 0)
   <...>-3083  1Dnh1    0us : _raw_spin_unlock (__down_mutex)
softirq--4     0Dn..    0us : preempt_schedule (up_mutex)
softirq--4     0Dn..    0us : irqs_disabled (preempt_schedule)
   <...>-3083  1....    0us : __local_save_flags (_spin_lock_irqsave)
softirq--4     0Dnh.    1us : __schedule (preempt_schedule)
   <...>-3083  1....    1us : _spin_unlock_irqrestore (extract_buf)
softirq--4     0Dnh.    1us : profile_hit (__schedule)
   <...>-3083  1....    1us : up_mutex (extract_buf)
   <...>-3083  1....    1us : __up_mutex (up_mutex)
softirq--4     0Dnh1    1us : sched_clock (__schedule)
softirq--4     0Dnh1    2us!: _raw_spin_lock_irq (__schedule)
   <...>-3083  1Dnh.  207us : _raw_spin_lock (__up_mutex)
   <...>-3083  1Dnh1  208us : _raw_spin_unlock (__up_mutex)
softirq--4     0Dnh1  208us : _raw_spin_lock_irqsave (__schedule)
   <...>-3083  1....  208us : sha_transform (extract_buf)
softirq--4     0Dnh2  208us : dependent_sleeper (__schedule)
softirq--4     0Dnh2  209us : _raw_spin_unlock (dependent_sleeper)
softirq--4     0Dnh1  209us : preempt_schedule (dependent_sleeper)
   <...>-3083  1....  209us : __add_entropy_words (extract_buf)
softirq--4     0Dnh1  209us : _raw_spin_lock (dependent_sleeper)
   <...>-3083  1....  209us : _spin_lock_irqsave (__add_entropy_words)
softirq--4     0Dnh2  209us : find_next_bit (dependent_sleeper)
   <...>-3083  1....  210us : __might_sleep (_spin_lock_irqsave)
softirq--4     0Dnh2  210us : _raw_spin_lock (dependent_sleeper)
   <...>-3083  1....  210us : irqs_disabled (__might_sleep)
   <...>-3083  1....  210us : _down_mutex (_spin_lock_irqsave)
softirq--4     0Dnh3  210us : find_next_bit (dependent_sleeper)
   <...>-3083  1....  210us : __down_mutex (_spin_lock_irqsave)
   <...>-3083  1Dnh.  211us : _raw_spin_lock (__down_mutex)
softirq--4     0Dnh3  211us : find_next_bit (dependent_sleeper)
softirq--4     0Dnh3  211us : _raw_spin_unlock (dependent_sleeper)
   <...>-3083  1Dnh1  211us : grab_lock (__down_mutex)
softirq--4     0Dnh2  211us : preempt_schedule (dependent_sleeper)
   <...>-3083  1Dnh1  211us : __down_mutex <<...>-3083> (36 0)
softirq--4     0Dnh2  212us : find_next_bit (dependent_sleeper)
   <...>-3083  1Dnh1  212us : _raw_spin_unlock (__down_mutex)
   <...>-3083  1....  212us : __local_save_flags (_spin_lock_irqsave)
softirq--4     0Dnh2  212us : trace_array (__schedule)
   <...>-3083  1....  212us : _spin_unlock_irqrestore (extract_buf)
   <...>-3083  1....  213us : up_mutex (extract_buf)
   <...>-3083  1....  213us : __up_mutex (up_mutex)
softirq--4     0Dnh2  213us : trace_array <<...>-2967> (34 78)
   <...>-3083  1Dnh.  213us : _raw_spin_lock (__up_mutex)
   <...>-3083  1Dnh1  214us : _raw_spin_unlock (__up_mutex)
   <...>-3083  1....  214us : __add_entropy_words (extract_buf)
softirq--4     0Dnh2  214us : trace_array <softirq--4> (69 6e)
   <...>-3083  1....  214us : _spin_lock_irqsave (__add_entropy_words)
   <...>-3083  1....  214us : __might_sleep (_spin_lock_irqsave)
softirq--4     0Dnh2  215us : trace_array (__schedule)
   <...>-3083  1....  215us : irqs_disabled (__might_sleep)
   <...>-3083  1....  215us : _down_mutex (_spin_lock_irqsave)
   <...>-3083  1....  215us : __down_mutex (_spin_lock_irqsave)
   <...>-3083  1Dnh.  215us : _raw_spin_lock (__down_mutex)
   <...>-3083  1Dnh1  216us : grab_lock (__down_mutex)
   <...>-3083  1Dnh1  216us : __down_mutex <<...>-3083> (36 0)
   <...>-3083  1Dnh1  216us : _raw_spin_unlock (__down_mutex)
   <...>-3083  1....  216us : __local_save_flags (_spin_lock_irqsave)
   <...>-2967  0Dnh2  217us : __switch_to (__schedule)
   <...>-3083  1....  217us : _spin_unlock_irqrestore (extract_buf)
   <...>-3083  1....  217us : up_mutex (extract_buf)
   <...>-2967  0Dnh2  217us : __schedule <softirq--4> (69 34)
   <...>-3083  1....  217us : __up_mutex (up_mutex)
   <...>-2967  0Dnh2  218us : _raw_spin_unlock (__schedule)
   <...>-3083  1Dnh.  218us : _raw_spin_lock (__up_mutex)
   <...>-2967  0Dnh1  218us : trace_stop_sched_switched (__schedule)
   <...>-3083  1Dnh1  218us : _raw_spin_unlock (__up_mutex)
   <...>-2967  0Dnh1  218us : _raw_spin_lock (trace_stop_sched_switched)
   <...>-3083  1....  219us : sha_transform (extract_buf)
   <...>-2967  0Dnh2  219us : trace_stop_sched_switched <<...>-2967> (34 0)
   <...>-2967  0Dnh2  219us : _raw_spin_unlock (trace_stop_sched_switched)
   <...>-2967  0Dnh1  219us : trace_stop_sched_switched (__schedule)


vim:ft=help