* Re: jack, PREEMPT_DESKTOP, delayed interrupts?
@ 2005-09-26 19:08 Karsten Wiese
2005-09-28 9:38 ` Ingo Molnar
0 siblings, 1 reply; 9+ messages in thread
From: Karsten Wiese @ 2005-09-26 19:08 UTC (permalink / raw)
To: Fernando Lopez-Lezcano; +Cc: Ingo Molnar, linux-kernel
[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #1: Type: text/plain; charset="us-ascii", Size: 1713 bytes --]
> # 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)
<snip>
> <...>-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)
Maybe your ethernet device is getting in the way.
Do you also get jack dropouts with ethernet chip disabled,
it's Module unloaded?
Karsten
___________________________________________________________
Was denken Sie über E-Mail? Wir hören auf Ihre Meinung: http://surveylink.yahoo.com/wix/p0379378.aspx
^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: jack, PREEMPT_DESKTOP, delayed interrupts?
2005-09-26 19:08 jack, PREEMPT_DESKTOP, delayed interrupts? Karsten Wiese
@ 2005-09-28 9:38 ` Ingo Molnar
2005-09-28 16:29 ` Fernando Lopez-Lezcano
0 siblings, 1 reply; 9+ messages in thread
From: Ingo Molnar @ 2005-09-28 9:38 UTC (permalink / raw)
To: Karsten Wiese; +Cc: Fernando Lopez-Lezcano, linux-kernel
* Karsten Wiese <annabellesgarden@yahoo.de> wrote:
> > latency: 10852 us, #70/70, CPU#0 | (M:preempt VP:0, KP:1, SP:1 HP:1
> > softirq--8 0Dnh4 9901us : trace_change_sched_cpu (1 0 0)
>
> Maybe your ethernet device is getting in the way.
> Do you also get jack dropouts with ethernet chip disabled,
> it's Module unloaded?
also, the M:preempt suggests that it's not a PREEMPT_RT kernel but a
PREEMPT_DESKTOP kernel. Do the dropouts happen even with a PREEMPT_RT
kernel?
Ingo
^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: jack, PREEMPT_DESKTOP, delayed interrupts?
2005-09-28 9:38 ` Ingo Molnar
@ 2005-09-28 16:29 ` Fernando Lopez-Lezcano
0 siblings, 0 replies; 9+ messages in thread
From: Fernando Lopez-Lezcano @ 2005-09-28 16:29 UTC (permalink / raw)
To: Ingo Molnar; +Cc: nando, Karsten Wiese, linux-kernel
On Wed, 2005-09-28 at 11:38 +0200, Ingo Molnar wrote:
> * Karsten Wiese <annabellesgarden@yahoo.de> wrote:
>
> > > latency: 10852 us, #70/70, CPU#0 | (M:preempt VP:0, KP:1, SP:1 HP:1
>
> > > softirq--8 0Dnh4 9901us : trace_change_sched_cpu (1 0 0)
> >
> > Maybe your ethernet device is getting in the way.
> > Do you also get jack dropouts with ethernet chip disabled,
> > it's Module unloaded?
>
> also, the M:preempt suggests that it's not a PREEMPT_RT kernel but a
> PREEMPT_DESKTOP kernel. Do the dropouts happen even with a PREEMPT_RT
> kernel?
Last time I tried a PREEMPT_RT (not that long ago) I was not able to
boot into it, it was failing very very early in the boot sequence. I
could try again if it would be valuable.
-- Fernando
^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: jack, PREEMPT_DESKTOP, delayed interrupts?
2005-08-31 7:35 ` Ingo Molnar
2005-08-31 15:08 ` Fernando Lopez-Lezcano
@ 2005-09-26 17:59 ` Fernando Lopez-Lezcano
1 sibling, 0 replies; 9+ messages in thread
From: Fernando Lopez-Lezcano @ 2005-09-26 17:59 UTC (permalink / raw)
To: Ingo Molnar; +Cc: jackit-devel, Lee Revell, linux-kernel, cc, Steven Rostedt
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)
^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: jack, PREEMPT_DESKTOP, delayed interrupts?
2005-08-31 7:35 ` Ingo Molnar
@ 2005-08-31 15:08 ` Fernando Lopez-Lezcano
2005-09-26 17:59 ` Fernando Lopez-Lezcano
1 sibling, 0 replies; 9+ messages in thread
From: Fernando Lopez-Lezcano @ 2005-08-31 15:08 UTC (permalink / raw)
To: Ingo Molnar; +Cc: jackit-devel, Lee Revell, linux-kernel, cc, Steven Rostedt
On Wed, 2005-08-31 at 00:35, 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.
>
> are the messages unstoppable, even if the system is completely idle? And
> you get this only with the SMP kernel, correct?
That's correct. I have to try harder with a UP kernel but I'm short on
time. I should see how idle I can get the system (ie: logout, start
stopping processes), but quitting jack and all related apps and/or
restarting alsa does not fix the problem. Top does not show anything
strange in terms of cpu usage.
> i dont know what's going on, but here are a couple of ideas to debug
> this further:
>
> - could you check whether there are any SCHED_FIFO tasks that shouldnt
> be there:
>
> ps -meo pid,tid,class,rtprio,ni,pri,psr,pcpu,stat,wchan:14,comm | grep FF
Seems to be fine (I'm doing this remotely so I can't look at the screen
to see if jack is still spewing messages):
- 2 FF 99 - 139 0 0.0 S migration_thre -
- 3 FF 1 - 41 0 0.0 S ksoftirqd -
- 4 FF 1 - 41 0 0.0 S ksoftirqd -
- 5 FF 1 - 41 0 0.0 S ksoftirqd -
- 6 FF 1 - 41 0 0.0 S ksoftirqd -
- 7 FF 1 - 41 0 0.0 S ksoftirqd -
- 8 FF 1 - 41 0 0.0 S ksoftirqd -
- 10 FF 99 - 139 0 0.0 S watchdog -
- 11 FF 99 - 139 1 0.0 S migration_thre -
- 12 FF 1 - 41 1 0.0 S ksoftirqd -
- 13 FF 1 - 41 1 0.0 S ksoftirqd -
- 14 FF 1 - 41 1 0.0 S ksoftirqd -
- 15 FF 1 - 41 1 0.0 S ksoftirqd -
- 16 FF 1 - 41 1 0.0 S ksoftirqd -
- 17 FF 1 - 41 1 0.0 S ksoftirqd -
- 19 FF 99 - 139 1 0.0 S watchdog -
- 20 FF 1 - 41 0 0.0 S< worker_thread -
- 21 FF 1 - 41 1 0.0 S< worker_thread -
- 27 FF 49 - 89 0 0.0 S< irqd -
- 295 FF 80 - 120 0 0.0 S< irqd -
- 313 FF 49 - 89 0 0.0 S< irqd -
- 346 FF 46 - 86 0 0.0 S< irqd -
- 378 FF 50 - 90 0 0.0 S< irqd -
- 408 FF 44 - 84 0 0.0 S< irqd -
- 421 FF 60 - 100 0 0.0 S< irqd -
- 923 FF 42 - 82 0 0.0 S< irqd -
- 947 FF 41 - 81 0 0.0 S< irqd -
the next line is the soundcard interrupt:
- 1033 FF 70 - 110 0 0.0 S< irqd -
- 1046 FF 69 - 109 0 0.0 S< irqd -
- 1205 FF 59 - 99 0 0.0 S< irqd -
- 3946 FF 37 - 77 0 0.0 S< irqd -
- 3947 FF 36 - 76 0 0.0 S< irqd -
- 3972 FF 35 - 75 0 0.0 S< irqd -
- 4434 FF 34 - 74 0 0.0 S< irqd -
These guys should be jackd (no clients are running):
- 4674 FF 61 - 101 1 0.2 SLl - -
- 4671 FF 72 - 112 1 0.0 SLsl - -
- 4672 FF 62 - 102 1 0.6 SLsl - -
Interrupt lines:
# cat /proc/interrupts
CPU0 CPU1
0: 112487 51273672 IO-APIC-edge [.........N/ 0] timer
1: 1 638 IO-APIC-edge [........../ 0] i8042
7: 2 1 IO-APIC-edge [..P......./ 0] parport0
8: 0 1 IO-APIC-edge [.........N/ 0] rtc
9: 0 0 IO-APIC-level [........../ 0] acpi
12: 128 25211 IO-APIC-edge [........../ 0] i8042
14: 1271 459434 IO-APIC-edge [........../ 0] ide0
177: 0 0 IO-APIC-level [........../ 0] libata
185: 2613 701940 IO-APIC-level [........../ 0] libata,
ehci_hcd:usb1
193: 609 174347 IO-APIC-level [........../ 0] SysKonnect
SK-98xx
201: 25124 38426783 IO-APIC-level [.........N/ 0] ICE1712,
ohci1394
209: 0 0 IO-APIC-level [.........N/ 0] NVidia
CK8S, ohci_hcd:usb2
217: 0 0 IO-APIC-level [........../ 0]
ohci_hcd:usb3
225: 11191 3327675 IO-APIC-level [........../ 0]
radeon@pci:0000:01:00.0
NMI: 0 0
LOC: 51386600 51386544
ERR: 1
MIS: 0
Thanks for all the debugging tips!!
I'll see what I can do today.
-- Fernando
^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: jack, PREEMPT_DESKTOP, delayed interrupts?
2005-08-31 2:03 Fernando Lopez-Lezcano
2005-08-31 2:39 ` Lee Revell
@ 2005-08-31 7:35 ` Ingo Molnar
2005-08-31 15:08 ` Fernando Lopez-Lezcano
2005-09-26 17:59 ` Fernando Lopez-Lezcano
1 sibling, 2 replies; 9+ messages in thread
From: Ingo Molnar @ 2005-08-31 7:35 UTC (permalink / raw)
To: Fernando Lopez-Lezcano
Cc: jackit-devel, Lee Revell, linux-kernel, cc, Steven Rostedt
* 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.
are the messages unstoppable, even if the system is completely idle? And
you get this only with the SMP kernel, correct?
i dont know what's going on, but here are a couple of ideas to debug
this further:
- could you check whether there are any SCHED_FIFO tasks that shouldnt
be there:
ps -meo pid,tid,class,rtprio,ni,pri,psr,pcpu,stat,wchan:14,comm | grep FF
we had bugs in the past that caused RT priorities to 'leak' on SMP
systems.
- please enable all latency tracing options like Lee suggested, and do
"echo 0 > /proc/sys/kernel/preempt_max_latency" to get some traces.
- if everything fails and automatic latency tracing does not show
anything out of ordinary, then you could try to do "user-triggered
tracing" of jackd's critical path. This is more laborous to do, but
should pinpoint the latency reason in a pretty sure way.
user-triggered tracing is done via adding those special gettimeofday
calls to jackd and recompiling jackd. I've attached an older hack
against jackd below, you might need to merge it to recent jackd. NOTE:
this patch will only work if you are getting xrun messages from ALSA.
It has to be reworked if your latencies are not actual xruns.
then, once the patched jackd is running, you can enable user-triggered
tracing via:
echo 1 > /proc/sys/kernel/trace_user_triggered
then you should start seeing jackd's latency path measured, not the
kernel's internal critical sections. [ Tracing overhead tip: for
user-triggered tracing it is enough to have CONFIG_WAKEUP_TIMING and
CONFIG_LATENCY_TRACE enabled, the other debugging options can be
turned off, to minimize overhead. ]
Ingo
diff -dupPNr jackit.0/drivers/alsa/alsa_driver.c jackit.1/drivers/alsa/alsa_driver.c
--- jackit.0/drivers/alsa/alsa_driver.c 2004-11-26 17:24:24.000000000 +0000
+++ jackit.1/drivers/alsa/alsa_driver.c 2004-11-30 13:41:24.521791456 +0000
@@ -1077,13 +1077,16 @@ alsa_driver_xrun_recovery (alsa_driver_t
&& driver->process_count > XRUN_REPORT_DELAY) {
struct timeval now, diff, tstamp;
driver->xrun_count++;
+ gettimeofday(0,0);
gettimeofday(&now, 0);
snd_pcm_status_get_trigger_tstamp(status, &tstamp);
timersub(&now, &tstamp, &diff);
*delayed_usecs = diff.tv_sec * 1000000.0 + diff.tv_usec;
+#if 0
fprintf(stderr, "\n\n**** alsa_pcm: xrun of at least %.3f "
"msecs\n\n",
*delayed_usecs / 1000.0);
+#endif
}
if (alsa_driver_stop (driver) ||
@@ -1185,6 +1188,12 @@ alsa_driver_wait (alsa_driver_t *driver,
nfds++;
}
+ { // Trigger off trace every other poll...
+ static unsigned int xruntrace_count = 0;
+ if ((xruntrace_count++ % 1) == 0)
+ gettimeofday(0,1);
+ }
+
poll_enter = jack_get_microseconds ();
if (poll_enter > driver->poll_next) {
^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: jack, PREEMPT_DESKTOP, delayed interrupts?
2005-08-31 2:39 ` Lee Revell
@ 2005-08-31 5:12 ` Fernando Lopez-Lezcano
0 siblings, 0 replies; 9+ messages in thread
From: Fernando Lopez-Lezcano @ 2005-08-31 5:12 UTC (permalink / raw)
To: Lee Revell; +Cc: jackit-devel, Ingo Molnar, linux-kernel, cc
On Tue, 2005-08-30 at 19:39, Lee Revell wrote:
> On Tue, 2005-08-30 at 19:03 -0700, Fernando Lopez-Lezcano wrote:
> > Hi, I'm starting to look at a strange problem. The configuration is:
> > hardware: AMD X2 4400+ dual core, NForce3 chipset, Midiman 66 soundcard
> > software: 2.6.13 smp + patch-2.6.13-rt1, PREEMPT_DESKTOP
> > jack 0.100.4, current cvs
> > alsa 1.0.10rc1
> >
>
> Enable all latency debug options and post the contents
> of /proc/latency_trace when this happens.
Will try to, I'm about to go on a trip so that may have to wait.
> Also what file system are you using?
Ext3, Jack mounts its pipes and stuff in /dev/shm
> And is the SMT scheduler enabled?
Is this it?: CONFIG_SCHED_SMT=y
-- Fernando
^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: jack, PREEMPT_DESKTOP, delayed interrupts?
2005-08-31 2:03 Fernando Lopez-Lezcano
@ 2005-08-31 2:39 ` Lee Revell
2005-08-31 5:12 ` Fernando Lopez-Lezcano
2005-08-31 7:35 ` Ingo Molnar
1 sibling, 1 reply; 9+ messages in thread
From: Lee Revell @ 2005-08-31 2:39 UTC (permalink / raw)
To: Fernando Lopez-Lezcano; +Cc: jackit-devel, Ingo Molnar, linux-kernel, cc
On Tue, 2005-08-30 at 19:03 -0700, Fernando Lopez-Lezcano wrote:
> Hi, I'm starting to look at a strange problem. The configuration is:
> hardware: AMD X2 4400+ dual core, NForce3 chipset, Midiman 66 soundcard
> software: 2.6.13 smp + patch-2.6.13-rt1, PREEMPT_DESKTOP
> jack 0.100.4, current cvs
> alsa 1.0.10rc1
>
Enable all latency debug options and post the contents
of /proc/latency_trace when this happens. Also what file system are you
using? And is the SMT scheduler enabled?
Lee
^ permalink raw reply [flat|nested] 9+ messages in thread
* jack, PREEMPT_DESKTOP, delayed interrupts?
@ 2005-08-31 2:03 Fernando Lopez-Lezcano
2005-08-31 2:39 ` Lee Revell
2005-08-31 7:35 ` Ingo Molnar
0 siblings, 2 replies; 9+ messages in thread
From: Fernando Lopez-Lezcano @ 2005-08-31 2:03 UTC (permalink / raw)
To: jackit-devel, Ingo Molnar, Lee Revell, linux-kernel
Cc: Fernando Pablo Lopez-Lezcano, cc
Hi, I'm starting to look at a strange problem. The configuration is:
hardware: AMD X2 4400+ dual core, NForce3 chipset, Midiman 66 soundcard
software: 2.6.13 smp + patch-2.6.13-rt1, PREEMPT_DESKTOP
jack 0.100.4, current cvs
alsa 1.0.10rc1
This is the sequence of events. Start Jack inside Qjackctl (a Jack Audio
Connection Kit GUI front end) with 2 x 128 frames, start Ardour (a
digital audio workstation) - load a very simple recording session, start
Hydrogen (a drum machine). Play around with them, everything seems to
work fine. No glitches, very solid performance.
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.
I could not get this to happen while running a uniprocessor kernel on
the same machine but I may not have tried long enough. I do see a "delay
exceeds" or "xun" message every once in a while but not a steady,
unstoppable stream of them.
This seemed to be much worse, or easier to trigger, when running an
older realtime-preempt-2.6.12-final-V0.7.51-27 smp kernel.
I don't know what information may be useful to even start making some
sense out of this.
-- Fernando
^ permalink raw reply [flat|nested] 9+ messages in thread
end of thread, other threads:[~2005-09-28 16:29 UTC | newest]
Thread overview: 9+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2005-09-26 19:08 jack, PREEMPT_DESKTOP, delayed interrupts? Karsten Wiese
2005-09-28 9:38 ` Ingo Molnar
2005-09-28 16:29 ` Fernando Lopez-Lezcano
-- strict thread matches above, loose matches on Subject: below --
2005-08-31 2:03 Fernando Lopez-Lezcano
2005-08-31 2:39 ` Lee Revell
2005-08-31 5:12 ` Fernando Lopez-Lezcano
2005-08-31 7:35 ` Ingo Molnar
2005-08-31 15:08 ` Fernando Lopez-Lezcano
2005-09-26 17:59 ` Fernando Lopez-Lezcano
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).