Re: [patch] Real-Time Preemption, -RT-2.6.12-rc6-V0.7.48-00
From: William Weston
Date: Wed Jun 22 2005 - 18:24:57 EST
On Thu, 23 Jun 2005, Ingo Molnar wrote:
> these are all the first type of latencies, which seem to be hardware
> related. Could you try to boot the UP kernel, do you see these latencies
> there too? (if yes then please post those too)
On -50-11 UP, the ~200us idle is still showing up in the traces. This
idle time, however, seems to be at random points within the trace. Some
of the traces attached are nearly identical except for where the ~200us
jump happens to fall. Hardware induced latency?
--wwpreemption latency trace v1.1.4 on 2.6.12-RT-V0.7.50-11-up-debug
--------------------------------------------------------------------
latency: 221 us, #29/29, CPU#0 | (M:rt VP:0, KP:1, SP:1 HP:1 #P:1)
-----------------
| task: softirq-timer/0-3 (uid:0 nice:-10 policy:0 rt_prio:0)
-----------------
_------=> CPU#
/ _-----=> irqs-off
| / _----=> need-resched
|| / _---=> hardirq/softirq
||| / _--=> preempt-depth
|||| /
||||| delay
cmd pid ||||| time | caller
\ / ||||| \ | /
cc1-4654 0Dnh3 0us : <00316363> (<66747200>)
cc1-4654 0Dnh3 0us : __trace_start_sched_wakeup (try_to_wake_up)
cc1-4654 0Dnh3 0us : __trace_start_sched_wakeup <<...>-3> (69 0)
cc1-4654 0Dnh2 0us : try_to_wake_up <<...>-3> (69 7b)
cc1-4654 0Dnh1 0us : preempt_schedule (try_to_wake_up)
cc1-4654 0Dnh1 0us : wake_up_process (trigger_softirqs)
cc1-4654 0Dnh. 0us : __schedule (work_resched)
cc1-4654 0Dnh. 0us : profile_hit (__schedule)
cc1-4654 0Dnh1 1us : sched_clock (__schedule)
cc1-4654 0Dnh2 2us : dequeue_task (__schedule)
cc1-4654 0Dnh2 2us : recalc_task_prio (__schedule)
cc1-4654 0Dnh2 2us : effective_prio (recalc_task_prio)
cc1-4654 0Dnh2 2us : enqueue_task (__schedule)
cc1-4654 0Dnh2 2us : trace_array (__schedule)
cc1-4654 0Dnh2 3us : trace_array <<...>-3> (69 6e)
cc1-4654 0Dnh2 3us : trace_array <cc1-4654> (7b 78)
cc1-4654 0Dnh2 3us : trace_array <<...>-3592> (7d 82)
cc1-4654 0Dnh2 4us : trace_array <<...>-3588> (7d 82)
cc1-4654 0Dnh2 4us : trace_array <<...>-3586> (7d 82)
cc1-4654 0Dnh2 4us : trace_array <<...>-3587> (7d 82)
cc1-4654 0Dnh2 4us : trace_array <<...>-3589> (7d 82)
cc1-4654 0Dnh2 5us : trace_array <<...>-3594> (7e 82)
cc1-4654 0Dnh2 5us : trace_array (__schedule)
<...>-3 0Dnh2 7us : __switch_to (__schedule)
<...>-3 0Dnh2 8us : __schedule <cc1-4654> (7b 69)
<...>-3 0Dnh1 8us!: trace_stop_sched_switched (__schedule)
<...>-3 0Dnh2 220us : trace_stop_sched_switched <<...>-3> (69 0)
<...>-3 0Dnh1 221us : trace_stop_sched_switched (__schedule)
vim:ft=help
preemption latency trace v1.1.4 on 2.6.12-RT-V0.7.50-11-up-debug
--------------------------------------------------------------------
latency: 217 us, #29/29, CPU#0 | (M:rt VP:0, KP:1, SP:1 HP:1 #P:1)
-----------------
| task: softirq-timer/0-3 (uid:0 nice:-10 policy:0 rt_prio:0)
-----------------
_------=> CPU#
/ _-----=> irqs-off
| / _----=> need-resched
|| / _---=> hardirq/softirq
||| / _--=> preempt-depth
|||| /
||||| delay
cmd pid ||||| time | caller
\ / ||||| \ | /
X-2790 0Dnh3 0us : <2d6d0058> (<616e6962>)
X-2790 0Dnh3 0us : __trace_start_sched_wakeup (try_to_wake_up)
X-2790 0Dnh3 0us : __trace_start_sched_wakeup <<...>-3> (69 0)
X-2790 0Dnh2 0us : try_to_wake_up <<...>-3> (69 74)
X-2790 0Dnh1 0us!: preempt_schedule (try_to_wake_up)
X-2790 0Dnh1 211us : wake_up_process (trigger_softirqs)
X-2790 0Dnh. 211us : preempt_schedule_irq (need_resched)
X-2790 0Dnh. 211us : __schedule (preempt_schedule_irq)
X-2790 0Dnh. 212us : profile_hit (__schedule)
X-2790 0Dnh1 212us : sched_clock (__schedule)
X-2790 0Dnh2 212us : dequeue_task (__schedule)
X-2790 0Dnh2 212us : recalc_task_prio (__schedule)
X-2790 0Dnh2 212us : effective_prio (recalc_task_prio)
X-2790 0Dnh2 212us : enqueue_task (__schedule)
X-2790 0Dnh2 212us : trace_array (__schedule)
X-2790 0Dnh2 213us : trace_array <<...>-3> (69 6e)
X-2790 0Dnh2 213us : trace_array <X-2790> (74 78)
X-2790 0Dnh2 214us : trace_array <<...>-3588> (7d 82)
X-2790 0Dnh2 214us : trace_array <<...>-3586> (7d 82)
X-2790 0Dnh2 214us : trace_array <<...>-3587> (7d 82)
X-2790 0Dnh2 214us : trace_array <<...>-3589> (7d 82)
X-2790 0Dnh2 214us : trace_array (__schedule)
X-2790 0Dnh2 215us : trace_array <<...>-6004> (7d 78)
<...>-3 0Dnh2 216us : __switch_to (__schedule)
<...>-3 0Dnh2 216us : __schedule <X-2790> (74 69)
<...>-3 0Dnh1 216us : trace_stop_sched_switched (__schedule)
<...>-3 0Dnh2 217us : trace_stop_sched_switched <<...>-3> (69 0)
<...>-3 0Dnh1 217us : trace_stop_sched_switched (__schedule)
vim:ft=help
preemption latency trace v1.1.4 on 2.6.12-RT-V0.7.50-11-up-debug
--------------------------------------------------------------------
latency: 208 us, #30/30, CPU#0 | (M:rt VP:0, KP:1, SP:1 HP:1 #P:1)
-----------------
| task: softirq-timer/0-3 (uid:0 nice:-10 policy:0 rt_prio:0)
-----------------
_------=> CPU#
/ _-----=> irqs-off
| / _----=> need-resched
|| / _---=> hardirq/softirq
||| / _--=> preempt-depth
|||| /
||||| delay
cmd pid ||||| time | caller
\ / ||||| \ | /
vlc-8511 0Dnh3 0us : <00636c76> (<6f000000>)
vlc-8511 0Dnh3 0us : __trace_start_sched_wakeup (try_to_wake_up)
vlc-8511 0Dnh3 0us : __trace_start_sched_wakeup <<...>-3> (69 0)
vlc-8511 0Dnh2 0us : try_to_wake_up <<...>-3> (69 73)
vlc-8511 0Dnh1 0us!: preempt_schedule (try_to_wake_up)
vlc-8511 0Dnh1 200us : wake_up_process (trigger_softirqs)
vlc-8511 0Dnh. 201us : __schedule (work_resched)
vlc-8511 0Dnh. 201us : profile_hit (__schedule)
vlc-8511 0Dnh1 201us : sched_clock (__schedule)
vlc-8511 0Dnh2 201us : dequeue_task (__schedule)
vlc-8511 0Dnh2 201us : recalc_task_prio (__schedule)
vlc-8511 0Dnh2 202us : effective_prio (recalc_task_prio)
vlc-8511 0Dnh2 202us : enqueue_task (__schedule)
vlc-8511 0Dnh2 202us : trace_array (__schedule)
vlc-8511 0Dnh2 203us : trace_array <<...>-3> (69 6e)
vlc-8511 0Dnh2 203us : trace_array <<...>-2790> (73 78)
vlc-8511 0Dnh2 203us : trace_array <vlc-8511> (73 78)
vlc-8511 0Dnh2 203us : trace_array <<...>-8766> (7d 78)
vlc-8511 0Dnh2 203us : trace_array <<...>-3592> (7d 82)
vlc-8511 0Dnh2 204us : trace_array <<...>-3588> (7d 82)
vlc-8511 0Dnh2 204us : trace_array <<...>-3587> (7d 82)
vlc-8511 0Dnh2 204us : trace_array <<...>-3586> (7d 82)
vlc-8511 0Dnh2 204us : trace_array <<...>-3589> (7d 82)
vlc-8511 0Dnh2 205us : trace_array (__schedule)
<...>-3 0Dnh2 206us : __switch_to (__schedule)
<...>-3 0Dnh2 207us : __schedule <vlc-8511> (73 69)
<...>-3 0Dnh1 207us : trace_stop_sched_switched (__schedule)
<...>-3 0Dnh2 208us : trace_stop_sched_switched <<...>-3> (69 0)
<...>-3 0Dnh1 208us : trace_stop_sched_switched (__schedule)
vim:ft=help
preemption latency trace v1.1.4 on 2.6.12-RT-V0.7.50-11-up-debug
--------------------------------------------------------------------
latency: 229 us, #32/32, CPU#0 | (M:rt VP:0, KP:1, SP:1 HP:1 #P:1)
-----------------
| task: IRQ 10-1010 (uid:0 nice:-5 policy:1 rt_prio:41)
-----------------
_------=> CPU#
/ _-----=> irqs-off
| / _----=> need-resched
|| / _---=> hardirq/softirq
||| / _--=> preempt-depth
|||| /
||||| delay
cmd pid ||||| time | caller
\ / ||||| \ | /
vlc-8510 0dnh3 0us : <00636c76> (<6f000000>)
vlc-8510 0dnh3 0us : __trace_start_sched_wakeup (try_to_wake_up)
vlc-8510 0dnh3 0us : __trace_start_sched_wakeup <<...>-1010> (3a 0)
vlc-8510 0dnh2 0us : try_to_wake_up <<...>-1010> (3a 73)
vlc-8510 0dnh1 0us : preempt_schedule (try_to_wake_up)
vlc-8510 0dnh1 0us : wake_up_process (redirect_hardirq)
vlc-8510 0dnh1 0us!: disable_8259A_irq (__do_IRQ)
vlc-8510 0dnh1 223us : preempt_schedule (__do_IRQ)
vlc-8510 0dnh. 223us : preempt_schedule (__do_IRQ)
vlc-8510 0dnh. 223us : local_irq_restore (__do_IRQ)
vlc-8510 0dnh. 223us : check_soft_flags (local_irq_restore)
vlc-8510 0Dnh. 223us : preempt_schedule (__do_IRQ)
vlc-8510 0Dnh. 224us : irq_exit (do_IRQ)
vlc-8510 0Dnh. 224us : __schedule (work_resched)
vlc-8510 0Dnh. 224us : profile_hit (__schedule)
vlc-8510 0Dnh1 224us : sched_clock (__schedule)
vlc-8510 0Dnh2 224us : trace_array (__schedule)
vlc-8510 0Dnh2 225us : trace_array <<...>-1010> (3a 3a)
vlc-8510 0Dnh2 225us : trace_array <vlc-8510> (73 78)
vlc-8510 0Dnh2 226us : trace_array <<...>-8790> (7c 78)
vlc-8510 0Dnh2 226us : trace_array <<...>-3592> (7d 82)
vlc-8510 0Dnh2 226us : trace_array <<...>-3588> (7d 82)
vlc-8510 0Dnh2 226us : trace_array <<...>-3587> (7d 82)
vlc-8510 0Dnh2 226us : trace_array <<...>-3586> (7d 82)
vlc-8510 0Dnh2 226us : trace_array <<...>-3589> (7d 82)
vlc-8510 0Dnh2 226us : trace_array (__schedule)
<...>-1010 0Dnh2 228us : __switch_to (__schedule)
<...>-1010 0Dnh2 228us : __schedule <vlc-8510> (73 3a)
<...>-1010 0Dnh1 228us : trace_stop_sched_switched (__schedule)
<...>-1010 0Dnh2 228us : trace_stop_sched_switched <<...>-1010> (3a 0)
<...>-1010 0Dnh1 229us : trace_stop_sched_switched (__schedule)
vim:ft=help
preemption latency trace v1.1.4 on 2.6.12-RT-V0.7.50-11-up-debug
--------------------------------------------------------------------
latency: 208 us, #33/33, CPU#0 | (M:rt VP:0, KP:1, SP:1 HP:1 #P:1)
-----------------
| task: IRQ 10-1010 (uid:0 nice:-5 policy:1 rt_prio:41)
-----------------
_------=> CPU#
/ _-----=> irqs-off
| / _----=> need-resched
|| / _---=> hardirq/softirq
||| / _--=> preempt-depth
|||| /
||||| delay
cmd pid ||||| time | caller
\ / ||||| \ | /
vlc-8511 0dnh3 0us : <00636c76> (<6f000000>)
vlc-8511 0dnh3 0us : __trace_start_sched_wakeup (try_to_wake_up)
vlc-8511 0dnh3 0us : __trace_start_sched_wakeup <<...>-1010> (3a 0)
vlc-8511 0dnh2 0us : try_to_wake_up <<...>-1010> (3a 73)
vlc-8511 0dnh1 0us : preempt_schedule (try_to_wake_up)
vlc-8511 0dnh1 0us : wake_up_process (redirect_hardirq)
vlc-8511 0dnh1 0us : disable_8259A_irq (__do_IRQ)
vlc-8511 0dnh1 1us : preempt_schedule (__do_IRQ)
vlc-8511 0dnh. 1us : preempt_schedule (__do_IRQ)
vlc-8511 0dnh. 1us : local_irq_restore (__do_IRQ)
vlc-8511 0dnh. 1us : check_soft_flags (local_irq_restore)
vlc-8511 0Dnh. 2us : preempt_schedule (__do_IRQ)
vlc-8511 0Dnh. 2us : irq_exit (do_IRQ)
vlc-8511 0Dnh. 2us : __schedule (work_resched)
vlc-8511 0Dnh. 2us : profile_hit (__schedule)
vlc-8511 0Dnh1 2us : sched_clock (__schedule)
vlc-8511 0Dnh2 2us : trace_array (__schedule)
vlc-8511 0Dnh2 3us : trace_array <<...>-1010> (3a 3a)
vlc-8511 0Dnh2 3us : trace_array <<...>-8039> (73 78)
vlc-8511 0Dnh2 3us : trace_array <vlc-8511> (73 78)
vlc-8511 0Dnh2 4us : trace_array <<...>-9298> (7b 78)
vlc-8511 0Dnh2 4us : trace_array <<...>-3588> (7d 82)
vlc-8511 0Dnh2 4us : trace_array <<...>-3592> (7d 82)
vlc-8511 0Dnh2 4us : trace_array <<...>-3586> (7d 82)
vlc-8511 0Dnh2 4us : trace_array <<...>-3587> (7d 82)
vlc-8511 0Dnh2 4us : trace_array <<...>-3589> (7d 82)
vlc-8511 0Dnh2 4us!: trace_array (__schedule)
<...>-1010 0Dnh2 207us : __switch_to (__schedule)
<...>-1010 0Dnh2 208us : __schedule <vlc-8511> (73 3a)
<...>-1010 0Dnh1 208us : trace_stop_sched_switched (__schedule)
<...>-1010 0Dnh2 208us : trace_stop_sched_switched <<...>-1010> (3a 0)
<...>-1010 0Dnh1 208us : trace_stop_sched_switched (__schedule)
vim:ft=help
preemption latency trace v1.1.4 on 2.6.12-RT-V0.7.50-11-up-debug
--------------------------------------------------------------------
latency: 231 us, #32/32, CPU#0 | (M:rt VP:0, KP:1, SP:1 HP:1 #P:1)
-----------------
| task: softirq-timer/0-3 (uid:0 nice:-10 policy:0 rt_prio:0)
-----------------
_------=> CPU#
/ _-----=> irqs-off
| / _----=> need-resched
|| / _---=> hardirq/softirq
||| / _--=> preempt-depth
|||| /
||||| delay
cmd pid ||||| time | caller
\ / ||||| \ | /
tee-10092 0Dnh3 0us!: <00656574> (<6f000000>)
tee-10092 0Dnh3 222us : __trace_start_sched_wakeup (try_to_wake_up)
tee-10092 0Dnh3 222us : __trace_start_sched_wakeup <<...>-3> (69 0)
tee-10092 0Dnh2 222us : try_to_wake_up <<...>-3> (69 73)
tee-10092 0Dnh1 222us : preempt_schedule (try_to_wake_up)
tee-10092 0Dnh1 222us : wake_up_process (trigger_softirqs)
tee-10092 0Dnh. 223us : preempt_schedule_irq (need_resched)
tee-10092 0Dnh. 223us : __schedule (preempt_schedule_irq)
tee-10092 0Dnh. 223us : profile_hit (__schedule)
tee-10092 0Dnh1 224us : sched_clock (__schedule)
tee-10092 0Dnh2 224us : dequeue_task (__schedule)
tee-10092 0Dnh2 224us : recalc_task_prio (__schedule)
tee-10092 0Dnh2 224us : effective_prio (recalc_task_prio)
tee-10092 0Dnh2 224us : enqueue_task (__schedule)
tee-10092 0Dnh2 224us : trace_array (__schedule)
tee-10092 0Dnh2 226us : trace_array <<...>-3> (69 6e)
tee-10092 0Dnh2 226us : trace_array <tee-10092> (73 78)
tee-10092 0Dnh2 226us : trace_array <<...>-4794> (73 78)
tee-10092 0Dnh2 226us : trace_array <<...>-8283> (73 78)
tee-10092 0Dnh2 227us : trace_array <<...>-4659> (74 78)
tee-10092 0Dnh2 227us : trace_array <<...>-10089> (7b 78)
tee-10092 0Dnh2 227us : trace_array <<...>-3592> (7d 82)
tee-10092 0Dnh2 227us : trace_array <<...>-3588> (7d 82)
tee-10092 0Dnh2 228us : trace_array <<...>-3586> (7d 82)
tee-10092 0Dnh2 228us : trace_array <<...>-3587> (7d 82)
tee-10092 0Dnh2 228us : trace_array (__schedule)
<...>-3 0Dnh2 230us : __switch_to (__schedule)
<...>-3 0Dnh2 230us : __schedule <tee-10092> (73 69)
<...>-3 0Dnh1 230us : trace_stop_sched_switched (__schedule)
<...>-3 0Dnh2 231us : trace_stop_sched_switched <<...>-3> (69 0)
<...>-3 0Dnh1 231us : trace_stop_sched_switched (__schedule)
vim:ft=help
preemption latency trace v1.1.4 on 2.6.12-RT-V0.7.50-11-up-debug
--------------------------------------------------------------------
latency: 208 us, #28/28, CPU#0 | (M:rt VP:0, KP:1, SP:1 HP:1 #P:1)
-----------------
| task: softirq-timer/0-3 (uid:0 nice:-10 policy:0 rt_prio:0)
-----------------
_------=> CPU#
/ _-----=> irqs-off
| / _----=> need-resched
|| / _---=> hardirq/softirq
||| / _--=> preempt-depth
|||| /
||||| delay
cmd pid ||||| time | caller
\ / ||||| \ | /
cc1-11149 0Dnh3 0us : <00316363> (<66747200>)
cc1-11149 0Dnh3 0us : __trace_start_sched_wakeup (try_to_wake_up)
cc1-11149 0Dnh3 0us : __trace_start_sched_wakeup <<...>-3> (69 0)
cc1-11149 0Dnh2 0us : try_to_wake_up <<...>-3> (69 78)
cc1-11149 0Dnh1 0us : preempt_schedule (try_to_wake_up)
cc1-11149 0Dnh1 0us : wake_up_process (trigger_softirqs)
cc1-11149 0Dnh. 0us : __schedule (work_resched)
cc1-11149 0Dnh. 1us : profile_hit (__schedule)
cc1-11149 0Dnh1 1us : sched_clock (__schedule)
cc1-11149 0Dnh2 1us!: dequeue_task (__schedule)
cc1-11149 0Dnh2 202us : recalc_task_prio (__schedule)
cc1-11149 0Dnh2 202us : effective_prio (recalc_task_prio)
cc1-11149 0Dnh2 202us : enqueue_task (__schedule)
cc1-11149 0Dnh2 203us : trace_array (__schedule)
cc1-11149 0Dnh2 204us : trace_array <<...>-3> (69 6e)
cc1-11149 0Dnh2 204us : trace_array <cc1-11149> (78 78)
cc1-11149 0Dnh2 204us : trace_array <<...>-3592> (7d 82)
cc1-11149 0Dnh2 204us : trace_array <<...>-3588> (7d 82)
cc1-11149 0Dnh2 204us : trace_array <<...>-3587> (7d 82)
cc1-11149 0Dnh2 205us : trace_array <<...>-3586> (7d 82)
cc1-11149 0Dnh2 205us : trace_array <<...>-3589> (7d 82)
cc1-11149 0Dnh2 205us : trace_array (__schedule)
<...>-3 0Dnh2 207us : __switch_to (__schedule)
<...>-3 0Dnh2 207us : __schedule <cc1-11149> (78 69)
<...>-3 0Dnh1 207us : trace_stop_sched_switched (__schedule)
<...>-3 0Dnh2 208us : trace_stop_sched_switched <<...>-3> (69 0)
<...>-3 0Dnh1 208us : trace_stop_sched_switched (__schedule)
vim:ft=help
preemption latency trace v1.1.4 on 2.6.12-RT-V0.7.50-11-up-debug
--------------------------------------------------------------------
latency: 213 us, #32/32, CPU#0 | (M:rt VP:0, KP:1, SP:1 HP:1 #P:1)
-----------------
| task: IRQ 14-254 (uid:0 nice:-5 policy:1 rt_prio:45)
-----------------
_------=> CPU#
/ _-----=> irqs-off
| / _----=> need-resched
|| / _---=> hardirq/softirq
||| / _--=> preempt-depth
|||| /
||||| delay
cmd pid ||||| time | caller
\ / ||||| \ | /
softirq--7 0dnh3 0us : <74666f73> (<2d717269>)
softirq--7 0dnh3 0us : __trace_start_sched_wakeup (try_to_wake_up)
softirq--7 0dnh3 0us : __trace_start_sched_wakeup <<...>-254> (36 0)
softirq--7 0dnh2 0us : try_to_wake_up <<...>-254> (36 3a)
softirq--7 0dnh1 0us : preempt_schedule (try_to_wake_up)
softirq--7 0dnh1 0us : wake_up_process (redirect_hardirq)
softirq--7 0dnh1 0us : disable_8259A_irq (__do_IRQ)
softirq--7 0dnh1 1us : preempt_schedule (__do_IRQ)
softirq--7 0dnh. 1us : preempt_schedule (__do_IRQ)
softirq--7 0dnh. 1us : local_irq_restore (__do_IRQ)
softirq--7 0dnh. 1us : check_soft_flags (local_irq_restore)
softirq--7 0Dnh. 1us : preempt_schedule (__do_IRQ)
softirq--7 0Dnh. 1us!: irq_exit (do_IRQ)
softirq--7 0Dnh. 209us : preempt_schedule_irq (need_resched)
softirq--7 0Dnh. 209us : __schedule (preempt_schedule_irq)
softirq--7 0Dnh. 209us : profile_hit (__schedule)
softirq--7 0Dnh1 209us : sched_clock (__schedule)
softirq--7 0Dnh2 210us : trace_array (__schedule)
softirq--7 0Dnh2 210us : trace_array <<...>-254> (36 36)
softirq--7 0Dnh2 210us : trace_array <softirq--7> (3a 6e)
softirq--7 0Dnh2 211us : trace_array <<...>-11476> (7b 78)
softirq--7 0Dnh2 211us : trace_array <<...>-3588> (7d 82)
softirq--7 0Dnh2 211us : trace_array <<...>-3592> (7d 82)
softirq--7 0Dnh2 211us : trace_array <<...>-3586> (7d 82)
softirq--7 0Dnh2 211us : trace_array <<...>-3587> (7d 82)
softirq--7 0Dnh2 211us : trace_array (__schedule)
<...>-254 0Dnh2 213us : __switch_to (__schedule)
<...>-254 0Dnh2 213us : __schedule <softirq--7> (3a 36)
<...>-254 0Dnh1 213us : trace_stop_sched_switched (__schedule)
<...>-254 0Dnh2 213us : trace_stop_sched_switched <<...>-254> (36 0)
<...>-254 0Dnh1 213us : trace_stop_sched_switched (__schedule)
vim:ft=help
preemption latency trace v1.1.4 on 2.6.12-RT-V0.7.50-11-up-debug
--------------------------------------------------------------------
latency: 224 us, #33/33, CPU#0 | (M:rt VP:0, KP:1, SP:1 HP:1 #P:1)
-----------------
| task: IRQ 10-1010 (uid:0 nice:-5 policy:1 rt_prio:41)
-----------------
_------=> CPU#
/ _-----=> irqs-off
| / _----=> need-resched
|| / _---=> hardirq/softirq
||| / _--=> preempt-depth
|||| /
||||| delay
cmd pid ||||| time | caller
\ / ||||| \ | /
vlc-8039 0dnh3 0us : <00636c76> (<6f000000>)
vlc-8039 0dnh3 0us : __trace_start_sched_wakeup (try_to_wake_up)
vlc-8039 0dnh3 0us : __trace_start_sched_wakeup <<...>-1010> (3a 0)
vlc-8039 0dnh2 0us : try_to_wake_up <<...>-1010> (3a 73)
vlc-8039 0dnh1 0us : preempt_schedule (try_to_wake_up)
vlc-8039 0dnh1 0us : wake_up_process (redirect_hardirq)
vlc-8039 0dnh1 0us : disable_8259A_irq (__do_IRQ)
vlc-8039 0dnh1 1us : preempt_schedule (__do_IRQ)
vlc-8039 0dnh. 1us : preempt_schedule (__do_IRQ)
vlc-8039 0dnh. 1us : local_irq_restore (__do_IRQ)
vlc-8039 0dnh. 2us : check_soft_flags (local_irq_restore)
vlc-8039 0Dnh. 2us : preempt_schedule (__do_IRQ)
vlc-8039 0Dnh. 2us : irq_exit (do_IRQ)
vlc-8039 0Dnh. 2us : __schedule (work_resched)
vlc-8039 0Dnh. 2us : profile_hit (__schedule)
vlc-8039 0Dnh1 2us : sched_clock (__schedule)
vlc-8039 0Dnh2 3us : trace_array (__schedule)
vlc-8039 0Dnh2 3us!: trace_array <<...>-1010> (3a 3a)
vlc-8039 0Dnh2 219us : trace_array <vlc-8039> (73 78)
vlc-8039 0Dnh2 219us : trace_array <<...>-7919> (74 78)
vlc-8039 0Dnh2 220us : trace_array <<...>-11600> (7c 78)
vlc-8039 0Dnh2 220us : trace_array <<...>-3592> (7d 82)
vlc-8039 0Dnh2 220us : trace_array <<...>-3588> (7d 82)
vlc-8039 0Dnh2 220us : trace_array <<...>-3586> (7d 82)
vlc-8039 0Dnh2 220us : trace_array <<...>-3587> (7d 82)
vlc-8039 0Dnh2 220us : trace_array <<...>-3589> (7d 82)
vlc-8039 0Dnh2 221us : trace_array (__schedule)
<...>-1010 0Dnh2 222us : __switch_to (__schedule)
<...>-1010 0Dnh2 223us : __schedule <vlc-8039> (73 3a)
<...>-1010 0Dnh1 224us : trace_stop_sched_switched (__schedule)
<...>-1010 0Dnh2 224us : trace_stop_sched_switched <<...>-1010> (3a 0)
<...>-1010 0Dnh1 224us : trace_stop_sched_switched (__schedule)
vim:ft=help