> The only reliable way to debug this stuff is with the latency tracer
> (see the list archives for details).
Here is a latency trace. I started sooperlooper with it's gui and loaded
a loop. After a fem minutes some xruns occur that throw sooperlooper out
of jack. The trace is from immediately after this. Does this reveal
anything?
gerrit
preemption latency trace v1.1.5 on 2.6.14-rt22-debugy
--------------------------------------------------------------------
latency: 89 us, #64/64, CPU#0 | (M:rt VP:0, KP:0, SP:1 HP:1)
-----------------
| task: softirq-timer/0-3 (uid:0 nice:0 policy:1 rt_prio:1)
-----------------
_------=> CPU#
/ _-----=> irqs-off
| / _----=> need-resched
|| / _---=> hardirq/softirq
||| / _--=> preempt-depth
|||| /
||||| delay
cmd pid ||||| time | caller
\ / ||||| \ | /
sooperlo-5783 0D... 1us : common_interrupt ((0))
sooperlo-5783 0D.h. 3us+: do_IRQ (80713f8 0 0)
sooperlo-5783 0D.h1 6us+: mask_and_ack_8259A (__do_IRQ)
sooperlo-5783 0D.h1 12us+: redirect_hardirq (__do_IRQ)
sooperlo-5783 0D.h. 14us : handle_IRQ_event (__do_IRQ)
sooperlo-5783 0D.h. 16us : timer_interrupt (handle_IRQ_event)
sooperlo-5783 0D.h. 17us : io_apic_timer_ack (timer_interrupt)
sooperlo-5783 0D.h. 18us : handle_tick_update (timer_interrupt)
sooperlo-5783 0D.h1 20us : do_timer (handle_tick_update)
sooperlo-5783 0D.h. 21us : update_process_times (handle_tick_update)
sooperlo-5783 0D.h. 22us : account_user_time (update_process_times)
sooperlo-5783 0D.h. 23us : run_local_timers (update_process_times)
sooperlo-5783 0D.h. 25us : raise_softirq (run_local_timers)
sooperlo-5783 0D.h. 26us+: wakeup_softirqd (raise_softirq)
sooperlo-5783 0D.h. 28us : wake_up_process (wakeup_softirqd)
sooperlo-5783 0D.h. 29us+: try_to_wake_up (wake_up_process)
sooperlo-5783 0D.h1 31us : activate_task (try_to_wake_up)
sooperlo-5783 0D.h1 31us : sched_clock (activate_task)
sooperlo-5783 0D.h1 33us+: recalc_task_prio (activate_task)
sooperlo-5783 0D.h1 36us : __recalc_task_prio (recalc_task_prio)
sooperlo-5783 0D.h1 37us : __recalc_task_prio <<...>-3> (62 62)
sooperlo-5783 0D.h1 38us : activate_task <<...>-3> (62 7)
sooperlo-5783 0D.h1 39us+: enqueue_task (activate_task)
sooperlo-5783 0Dnh1 41us : try_to_wake_up <<...>-3> (62 74)
sooperlo-5783 0Dnh. 42us : preempt_schedule (try_to_wake_up)
sooperlo-5783 0Dnh. 43us : wake_up_process (wakeup_softirqd)
sooperlo-5783 0Dnh. 44us : rcu_pending (update_process_times)
sooperlo-5783 0Dnh. 46us : scheduler_tick (update_process_times)
sooperlo-5783 0Dnh. 47us+: sched_clock (scheduler_tick)
sooperlo-5783 0Dnh1 49us+: task_timeslice (scheduler_tick)
sooperlo-5783 0Dnh. 51us+: preempt_schedule (scheduler_tick)
sooperlo-5783 0Dnh1 53us : note_interrupt (__do_IRQ)
sooperlo-5783 0Dnh1 55us+: enable_8259A_irq (__do_IRQ)
sooperlo-5783 0Dnh1 57us : preempt_schedule (enable_8259A_irq)
sooperlo-5783 0Dnh. 57us : preempt_schedule (__do_IRQ)
sooperlo-5783 0Dnh. 58us : irq_exit (do_IRQ)
sooperlo-5783 0Dn.. 59us : __schedule (work_resched)
sooperlo-5783 0Dn.. 60us : profile_hit (__schedule)
sooperlo-5783 0Dn.1 60us+: sched_clock (__schedule)
<...>-3 0D..2 65us+: __switch_to (__schedule)
<...>-3 0D..2 68us : __schedule <sooperlo-5783> (74 62)
<...>-3 0D.h2 70us : do_IRQ (c039a4f4 9 0)
<...>-3 0D.h3 71us+: mask_and_ack_8259A (__do_IRQ)
<...>-3 0D.h3 78us : redirect_hardirq (__do_IRQ)
<...>-3 0D.h3 79us : wake_up_process (redirect_hardirq)
<...>-3 0D.h3 79us : try_to_wake_up (wake_up_process)
<...>-3 0D.h4 80us : activate_task (try_to_wake_up)
<...>-3 0D.h4 80us : sched_clock (activate_task)
<...>-3 0D.h4 80us : recalc_task_prio (activate_task)
<...>-3 0D.h4 81us : __recalc_task_prio (recalc_task_prio)
<...>-3 0D.h4 82us : __recalc_task_prio <<...>-14> (1d 1d)
<...>-3 0D.h4 82us : activate_task <<...>-14> (1d 8)
<...>-3 0D.h4 83us : enqueue_task (activate_task)
<...>-3 0Dnh4 83us : try_to_wake_up <<...>-14> (1d 62)
<...>-3 0Dnh3 84us : preempt_schedule (try_to_wake_up)
<...>-3 0Dnh3 84us : wake_up_process (redirect_hardirq)
<...>-3 0Dnh2 84us : preempt_schedule (__do_IRQ)
<...>-3 0Dnh2 85us : irq_exit (do_IRQ)
<...>-3 0Dn.2 85us < (608)
<...>-3 0.n.1 87us : preempt_schedule (__schedule)
<...>-3 0.n.1 87us : sub_preempt_count (__schedule)
<...>-3 0.n.1 89us : sub_preempt_count_ti (sub_preempt_count)
vim:ft=help
