Re: jack, PREEMPT_DESKTOP, delayed interrupts?

Fernando Lopez-Lezcano
2005-09-26T18:00:27Z

On Wed, 2005-08-31 at 09:35 +0200, Ingo Molnar wrote:
> * Fernando Lopez-Lezcano <nando@ccrma.Stanford.EDU> wrote:
> > Do a "tar cvf usr.tar /usr" just to read/write a lot to disk (this
> > within the same SATA disk). Watch memory being used in a system
> > monitor applet up to 100%. After a while, hard to say how long (maybe
> > 10/15 minutes?) the system eventually can get into a state where Jack
> > starts printing messages of the type "delay of 3856.000 usecs exceeds
> > estimated spare time of 2653.000; restart ..." (if I understand
> > correctly this means interrupts are being delayed on their way to
> > Jack, or at least Jack thinks they are arriving too late), along with
> > some less frequent xun notices.
> >
> > Now the strange thing is that this condition seems to be persistent.
> > Nothing I do after it starts to happen seems to halt those messages.
> > Including stopping Jack and starting it again, and even (tried it
> > once) stopping the alsa sound driver and loading it again. Nothing out
> > of the ordinary in dmesg or /var/log/messages. I would guess that
> > something "breaks" inside the kernel with regards to interrupt
> > handling and/or whatever Jack uses to measure time inside the kernel?
> > Interrupts are prioritized correctly (rtc, then audio and jack runs at
> > lower realtime priority than the audio interrupts), everything else
> > looks fine.
>
[MUNCH]
> - please enable all latency tracing options like Lee suggested, and do
> "echo 0 > /proc/sys/kernel/preempt_max_latency" to get some traces.

I have done that, finally, but I'm not sure I'm clear on the sequence of
things I have to do, sorry.

echo 0 > /proc/sys/kernel/preempt_max_latency
(zeroes the max latency, I guess).

When should I look at /proc/latency_trace? What exactly does it show? (I
know it is nicely commented :-) Is it just one trace?

I'm including one sample output...
-- Fernando

# cat /proc/latency_trace
preemption latency trace v1.1.5 on 2.6.13-0.3.rdtd.rhfc4.ccrmasmp
--------------------------------------------------------------------
latency: 10852 us, #70/70, CPU#0 | (M:preempt VP:0, KP:1, SP:1 HP:1
#P:2)
-----------------
| task: qjackctl-4797 (uid:743 nice:0 policy:1 rt_prio:61)
-----------------

_------=> CPU#
/ _-----=> irqs-off
| / _----=> need-resched
|| / _---=> hardirq/softirq
||| / _--=> preempt-depth
|||| /
||||| delay
cmd pid ||||| time | caller
\ / ||||| \ | /
<...>-4593 1Dnh3 0us : MacPrivateStat (SkPnmiGetStruct)
<...>-4593 1Dnh3 0us : MacPrivateStat (SkPnmiGetStruct)
<...>-4593 1Dnh3 0us : MacUpdate (MacPrivateStat)
<...>-4593 1Dnh3 0us : GetStatVal (MacPrivateStat)
<...>-4593 1Dnh3 0us : GetPhysStatVal (GetStatVal)
<...>-4593 1Dnh3 1us+: SkGmMacStatistic (GetPhysStatVal)
<...>-4593 1Dnh3 3us : MacPrivateStat (SkPnmiGetStruct)
<...>-4593 1Dnh3 3us : MacUpdate (MacPrivateStat)
<...>-4593 1Dnh3 3us : GetStatVal (MacPrivateStat)
<...>-4593 1Dnh3 3us : GetPhysStatVal (GetStatVal)
<...>-4593 1Dnh3 3us+: SkGmMacStatistic (GetPhysStatVal)
<...>-4593 1Dnh3 5us : MacPrivateStat (SkPnmiGetStruct)
<...>-4593 1Dnh3 6us : MacPrivateStat (SkPnmiGetStruct)
<...>-4593 1Dnh3 6us : MacUpdate (MacPrivateStat)
<...>-4593 1Dnh3 6us : GetStatVal (MacPrivateStat)
<...>-4593 1Dnh3 6us : GetPhysStatVal (GetStatVal)
<...>-4593 1Dnh3 6us+: SkGmMacStatistic (GetPhysStatVal)
<...>-4593 1Dnh3 8us : MacPrivateStat (SkPnmiGetStruct)
<...>-4593 1Dnh3 9us : MacUpdate (MacPrivateStat)
<...>-4593 1Dnh3 9us : GetStatVal (MacPrivateStat)
<...>-4593 1Dnh3 9us : GetPhysStatVal (GetStatVal)
<...>-4593 1Dnh3 9us+: SkGmMacStatistic (GetPhysStatVal)
<...>-4593 1Dnh3 11us : MacPrivateStat (SkPnmiGetStruct)
<...>-4593 1Dnh3 11us : MacPrivateStat (SkPnmiGetStruct)
<...>-4593 1Dnh3 12us : MacUpdate (MacPrivateStat)
<...>-4593 1Dnh3 12us : GetStatVal (MacPrivateStat)
<...>-4593 1Dnh3 12us : GetPhysStatVal (GetStatVal)
<...>-4593 1Dnh3 12us : MacPrivateStat (SkPnmiGetStruct)
<...>-4593 1Dnh3 12us : MacUpdate (MacPrivateStat)
<...>-4593 1Dnh3 12us : GetStatVal (MacPrivateStat)
<...>-4593 1Dnh3 13us : GetPhysStatVal (GetStatVal)
<...>-4593 1Dnh3 13us : MacPrivateStat (SkPnmiGetStruct)
<...>-4593 1Dnh3 13us : MacPrivateStat (SkPnmiGetStruct)
<...>-4593 1Dnh3 13us : MacUpdate (MacPrivateStat)
<...>-4593 1Dnh3 13us : GetStatVal (MacPrivateStat)
<...>-4593 1Dnh3 13us : GetPhysStatVal (GetStatVal)
<...>-4593 1Dnh3 13us : MacPrivateStat (SkPnmiGetStruct)
<...>-4593 1Dnh3 13us : MacUpdate (MacPrivateStat)
<...>-4593 1Dnh3 13us : GetStatVal (MacPrivateStat)
<...>-4593 1Dnh3 14us : GetPhysStatVal (GetStatVal)
<...>-4593 1Dnh3 14us : MacPrivateStat (SkPnmiGetStruct)
<...>-4593 1Dnh3 14us : MacPrivateStat (SkPnmiGetStruct)
<...>-4593 1Dnh3 14us : MacUpdate (MacPrivateStat)
<...>-4593 1Dnh3 14us : GetStatVal (MacPrivateStat)
<...>-4593 1Dnh3 14us : GetPhysStatVal (GetStatVal)
<...>-4593 1Dnh3 14us+: SkGmMacStatistic (GetPhysStatVal)
<...>-4593 1Dnh3 17us : GetStatVal (MacPrivateStat)
<...>-4593 1Dnh3 18us : GetPhysStatVal (GetStatVal)
<...>-4593 1Dnh3 18us : SkGmMacStatistic (GetPhysStatVal)
<...>-4593 1Dnh3 20us : GetStatVal (MacPrivateStat)
<...>-4593 1Dnh3 20us : GetPhysStatVal (GetStatVal)
<...>-4593 1Dnh3 20us+: SkGmMacStatistic (GetPhysStatVal)
<...>-4593 1Dnh3 22us : GetStatVal (MacPrivateStat)
<...>-4593 1Dnh3 22us : GetPhysStatVal (GetStatVal)
<...>-4593 1Dnh3 22us+: SkGmMacStatistic (GetPhysStatVal)
<...>-4593 1Dnh3 24us!: MacPrivateStat (SkPnmiGetStruct)
softirq--8 0Dnh4 9901us : trace_change_sched_cpu (1 0 0)
softirq--8 0Dnh4 9901us : _raw_spin_unlock (trace_change_sched_cpu)
softirq--8 0Dnh3 9902us : enqueue_task (move_tasks)
softirq--8 0Dnh3 9902us : resched_task (move_tasks)
softirq--8 0Dnh3 9902us : _raw_spin_unlock (load_balance_newidle)
softirq--8 0Dnh2 9902us : preempt_schedule (_raw_spin_unlock)
<...>-4797 0Dnh2 9903us : __switch_to (__schedule)
<...>-4797 0Dnh2 9904us : __schedule <softirq--8> (62 26)
<...>-4797 0Dnh2 9904us : _raw_spin_unlock_irq (__schedule)
<...>-4797 0...1 9904us : trace_stop_sched_switched (__schedule)
<...>-4797 0Dnh1 9905us : _raw_spin_lock (trace_stop_sched_switched)
<...>-4797 0Dnh2 9905us : trace_stop_sched_switched <<...>-4797> (26
0)
<...>-4797 0Dnh2 9905us : trace_stop_sched_switched (__schedule)