preemption latency trace v1.1.4 on 2.6.11-rc4-RT-V0.7.39-02
--------------------------------------------------------------------
 latency: 327 µs, #22/22, CPU#0 | (M:preempt VP:0, KP:1, SP:1 HP:1 #P:1)
    -----------------
    | task: ksoftirqd/0-2 (uid:0 nice:-10 policy:0 rt_prio:0)
    -----------------

                 _------=> CPU#            
                / _-----=> irqs-off        
               | / _----=> need-resched    
               || / _---=> hardirq/softirq 
               ||| / _--=> preempt-depth   
               |||| /                      
               |||||     delay             
   cmd     pid ||||| time  |   caller      
      \   /    |||||   \   |   /           
(T1/#0)             dpkg 16229 0 9 00000002 00000000 [0034184390920878] 0.000ms (+3535970.095ms): <676b7064> (<00746500>)
(T1/#2)             dpkg 16229 0 9 00000002 00000002 [0034184390921351] 0.000ms (+0.000ms): __trace_start_sched_wakeup+0x96/0xc0 <c012cbe6> (try_to_wake_up+0x81/0x150 <c010f911>)
(T1/#3)             dpkg 16229 0 9 00000000 00000003 [0034184390921935] 0.001ms (+0.000ms): wake_up_process+0x1c/0x30 <c010f9fc> (do_softirq+0x4b/0x60 <c01042fb>)
(T6/#4)     dpkg-16229 0dn.2    2µs!< (1)
(T1/#5)             dpkg 16229 0 2 00000001 00000005 [0034184391106965] 0.310ms (+0.000ms): preempt_schedule+0xa/0x70 <c027d0ca> (copy_pte_range+0xb7/0x1c0 <c0142ad7>)
(T1/#6)             dpkg 16229 0 2 00000001 00000006 [0034184391107405] 0.310ms (+0.000ms): __cond_resched_raw_spinlock+0x8/0x50 <c0111398> (copy_pte_range+0xa7/0x1c0 <c0142ac7>)
(T1/#7)             dpkg 16229 0 2 00000000 00000007 [0034184391107918] 0.311ms (+0.001ms): __cond_resched+0x9/0x70 <c0111329> (__cond_resched_raw_spinlock+0x3d/0x50 <c01113cd>)
(T1/#8)             dpkg 16229 0 3 00000000 00000008 [0034184391108602] 0.312ms (+0.000ms): __schedule+0xe/0x630 <c027c98e> (__cond_resched+0x45/0x70 <c0111365>)
(T1/#9)             dpkg 16229 0 3 00000000 00000009 [0034184391109088] 0.313ms (+0.000ms): profile_hit+0x9/0x50 <c0115749> (__schedule+0x3a/0x630 <c027c9ba>)
(T1/#10)             dpkg 16229 0 3 00000001 0000000a [0034184391109573] 0.314ms (+0.001ms): sched_clock+0xe/0xe0 <c010c3ae> (__schedule+0x62/0x630 <c027c9e2>)
(T1/#11)             dpkg 16229 0 3 00000002 0000000b [0034184391110546] 0.316ms (+0.000ms): dequeue_task+0xa/0x50 <c010f4ea> (__schedule+0x1ab/0x630 <c027cb2b>)
(T1/#12)             dpkg 16229 0 3 00000002 0000000c [0034184391110969] 0.316ms (+0.000ms): recalc_task_prio+0xc/0x1a0 <c010f64c> (__schedule+0x1c5/0x630 <c027cb45>)
(T1/#13)             dpkg 16229 0 3 00000002 0000000d [0034184391111383] 0.317ms (+0.000ms): effective_prio+0x8/0x50 <c010f5f8> (recalc_task_prio+0xa6/0x1a0 <c010f6e6>)
(T1/#14)             dpkg 16229 0 3 00000002 0000000e [0034184391111775] 0.318ms (+0.001ms): enqueue_task+0xa/0x80 <c010f53a> (__schedule+0x1cc/0x630 <c027cb4c>)
(T4/#15) [ =>             dpkg ] 0.319ms (+0.001ms)
(T1/#16)            <...>     2 0 1 00000002 00000010 [0034184391113480] 0.321ms (+0.001ms): __switch_to+0xb/0x1a0 <c0100f5b> (__schedule+0x2bd/0x630 <c027cc3d>)
(T3/#17)    <...>-2     0d..2  322µs : __schedule+0x2ea/0x630 <c027cc6a> <dpkg-16229> (74 69): 
(T1/#18)            <...>     2 0 1 00000002 00000012 [0034184391114743] 0.323ms (+0.000ms): finish_task_switch+0xc/0x90 <c010fdec> (__schedule+0x2f6/0x630 <c027cc76>)
(T1/#19)            <...>     2 0 1 00000001 00000013 [0034184391115178] 0.323ms (+0.000ms): trace_stop_sched_switched+0xa/0x150 <c012cc1a> (finish_task_switch+0x43/0x90 <c010fe23>)
(T3/#20)    <...>-2     0d..1  324µs : trace_stop_sched_switched+0x42/0x150 <c012cc52> <<...>-2> (69 0): 
(T1/#21)            <...>     2 0 1 00000001 00000015 [0034184391116385] 0.325ms (+0.000ms): trace_stop_sched_switched+0xfe/0x150 <c012cd0e> (finish_task_switch+0x43/0x90 <c010fe23>)


vim:ft=help