preemption latency trace v1.1.4 on 2.6.10-rc2-mm3-V0.7.32-12
--------------------------------------------------------------------
 latency: 46 us, #83/83 | (M:rt VP:0, KP:1, SP:1 HP:1 #P:2)
    -----------------
    | task: su-5646 (uid:500 nice:0 policy:0 rt_prio:0)
    -----------------

                 _------=> CPU#            
                / _-----=> irqs-off        
               | / _----=> hardirq         
               || / _---=> softirq         
               ||| / _--=> preempt-depth   
               |||| /                      
               |||||     delay             
   cmd     pid ||||| time  |   caller      
      \   /    |||||   \   |   /           
    bash-5650  0-h.2    0µs : __trace_start_sched_wakeup (try_to_wake_up)
    bash-5650  0-h.2    0µs : _raw_spin_unlock (try_to_wake_up)
    bash-5650  0-h.1    0µs : preempt_schedule (try_to_wake_up)
    bash-5650  0        1µs : __wake_up_common <su-5646> (74 75): 
    bash-5650  0-h.1    1µs : try_to_wake_up (__wake_up_common)
    bash-5650  0-h.1    1µs : _raw_spin_unlock (try_to_wake_up)
    bash-5650  0-h..    2µs : preempt_schedule (try_to_wake_up)
    bash-5650  0.h..    2µs : _spin_unlock_irqrestore (__wake_up_sync)
    bash-5650  0.h..    2µs : up_mutex (__wake_up_sync)
    bash-5650  0.h..    2µs : __up_mutex (up_mutex)
    bash-5650  0-h..    3µs : _raw_spin_lock (__up_mutex)
    bash-5650  0-h.1    3µs : _raw_spin_lock (__up_mutex)
    bash-5650  0-h.2    3µs : _raw_spin_lock (__up_mutex)
    bash-5650  0-h.3    3µs : mutex_getprio (__up_mutex)
    bash-5650  0        4µs : __up_mutex <bash-5650> (75 75): 
    bash-5650  0-h.3    4µs : _raw_spin_unlock (__up_mutex)
    bash-5650  0-h.2    4µs : preempt_schedule (__up_mutex)
    bash-5650  0-h.2    4µs : _raw_spin_unlock (__up_mutex)
    bash-5650  0-h.1    5µs : preempt_schedule (__up_mutex)
    bash-5650  0-h.1    5µs : _raw_spin_unlock (__up_mutex)
    bash-5650  0-h..    5µs : preempt_schedule (__up_mutex)
    bash-5650  0.h..    5µs : next_thread (__wake_up_parent)
    bash-5650  0.h..    6µs : _spin_is_locked (next_thread)
    bash-5650  0.h..    6µs : rt_mutex_is_locked (next_thread)
    bash-5650  0.h..    6µs : _spin_unlock_irqrestore (do_notify_parent)
    bash-5650  0.h..    6µs : up_mutex (do_notify_parent)
    bash-5650  0.h..    7µs : __up_mutex (up_mutex)
    bash-5650  0-h..    7µs : _raw_spin_lock (__up_mutex)
    bash-5650  0-h.1    7µs : _raw_spin_lock (__up_mutex)
    bash-5650  0-h.2    7µs : _raw_spin_lock (__up_mutex)
    bash-5650  0-h.3    8µs : mutex_getprio (__up_mutex)
    bash-5650  0        8µs : __up_mutex <bash-5650> (75 75): 
    bash-5650  0-h.3    8µs : _raw_spin_unlock (__up_mutex)
    bash-5650  0-h.2    8µs : preempt_schedule (__up_mutex)
    bash-5650  0-h.2    9µs : _raw_spin_unlock (__up_mutex)
    bash-5650  0-h.1    9µs : preempt_schedule (__up_mutex)
    bash-5650  0-h.1    9µs : _raw_spin_unlock (__up_mutex)
    bash-5650  0-h..   10µs : preempt_schedule (__up_mutex)
    bash-5650  0.h..   10µs : _write_unlock_irq (exit_notify)
    bash-5650  0.h..   10µs : up_write_mutex (exit_notify)
    bash-5650  0.h..   11µs : __up_mutex (up_write_mutex)
    bash-5650  0-h..   11µs : _raw_spin_lock (__up_mutex)
    bash-5650  0-h.1   11µs : _raw_spin_lock (__up_mutex)
    bash-5650  0-h.2   12µs : _raw_spin_lock (__up_mutex)
    bash-5650  0-h.3   12µs : mutex_getprio (__up_mutex)
    bash-5650  0       12µs : __up_mutex <bash-5650> (75 75): 
    bash-5650  0-h.3   12µs : _raw_spin_unlock (__up_mutex)
    bash-5650  0-h.2   13µs : preempt_schedule (__up_mutex)
    bash-5650  0-h.2   13µs : _raw_spin_unlock (__up_mutex)
    bash-5650  0-h.1   13µs : preempt_schedule (__up_mutex)
    bash-5650  0-h.1   14µs : _raw_spin_unlock (__up_mutex)
    bash-5650  0-h..   14µs : preempt_schedule (__up_mutex)
    bash-5650  0.h..   14µs : check_no_held_locks (do_exit)
    bash-5650  0-h..   15µs+: _raw_spin_lock (check_no_held_locks)
    bash-5650  0-h.1   22µs : _raw_spin_lock (check_no_held_locks)
    bash-5650  0-h.2   23µs : _raw_spin_unlock (check_no_held_locks)
    bash-5650  0-h.1   23µs : preempt_schedule (check_no_held_locks)
    bash-5650  0-h.1   24µs : _raw_spin_unlock (check_no_held_locks)
    bash-5650  0-h..   24µs : preempt_schedule (check_no_held_locks)
    bash-5650  0.h..   24µs : preempt_schedule (do_exit)
    bash-5650  0-h..   25µs : __schedule (preempt_schedule)
    bash-5650  0-h.1   25µs : sched_clock (__schedule)
    bash-5650  0-h.1   26µs : _raw_spin_lock_irq (__schedule)
    bash-5650  0-h.1   26µs : _raw_spin_lock_irqsave (__schedule)
    bash-5650  0-h.2   27µs : dequeue_task (__schedule)
    bash-5650  0-h.2   27µs : recalc_task_prio (__schedule)
    bash-5650  0-h.2   28µs : effective_prio (recalc_task_prio)
    bash-5650  0-h.2   28µs : enqueue_task (__schedule)
    bash-5650  0-..2   29µs+: trace_array (__schedule)
    bash-5650  0       33µs : __schedule <su-5646> (74 78): 
    bash-5650  0       33µs : __schedule <bash-5650> (75 78): 
    bash-5650  0-..2   34µs+: trace_array (__schedule)
      su-5646  0-..2   41µs : __switch_to (__schedule)
      su-5646  0       42µs : schedule <bash-5650> (75 74): 
      su-5646  0-..2   42µs : finish_task_switch (__schedule)
      su-5646  0-..2   43µs : _raw_spin_unlock (finish_task_switch)
      su-5646  0-..1   43µs : trace_stop_sched_switched (finish_task_switch)
      su-5646  0       44µs : finish_task_switch <su-5646> (74 0): 
      su-5646  0-..1   44µs : _raw_spin_lock_irqsave (trace_stop_sched_switched)
      su-5646  0-..2   45µs : trace_stop_sched_switched (finish_task_switch)


vim:ft=help