[alsa-devel] Timer instability

[Clive Messer]

On Tuesday 03 Mar 2009 17:41:22 Takashi Iwai wrote:

> > Hrm, but still an unexpected jump is found.
> >
> > If you build the driver with CONFIG_SND_PCM_XRUN_DEBUG=y, you must
> > have /proc/asound/card0/pcm0p/xrun_debug.  Echo 1 to this (as root)
> > 	echo 1 > /proc/asound/card0/pcm0p/xrun_debug
> > and try the program, see whether any debug message appears.
> > If any message appears, it means basically an unstable hardware.
> >
> > Also, the below is a patch I tried to clean up and improve the
> > handling.  Give it a try (and do echo 1 above for testing).
>
> BTW, the original test program is very hard to see what's wrong
> because it spews out way too many lines.  The below is a filtered-out
> version.
>
> It prints only unexpected jumps of avail values (the threshold is
> set 100 blindly).  The output is like below:
>
> 	% ./alsa-time-test hw
> 	21720872	(4987)	delta 216	avail 216	delay 4200
> 	21943118	(65)	delta 208	avail 208	delay 4208
> 	23752310	(3)	delta 232	avail 232	delay 4184
> 	23761847	(5972)	delta 264	avail 264	delay 4152
>
> The first column is the usec from the program start, the next value in
> parentheses is the time-step from the last time of status changes,
> the delta is the increase of avail, and the rest are raw values.
>
> If a too large delta appears in a short time-step, something is wrong.
> If it appears in a large time-step, it's simply a wrong responsiveness
> (aka system latency).

Hello Takashi/Lennart,

Sorry, I have been busy for a few days.
I patched my kernel (kernel-2.6.29-0.53.rc7.fc10.x86_64) with your pcm_lib.c 
patch and 'echo 1 > /proc/asound/card0/pcm0p/xrun_debug'.

I have done several runs with the new alsa-time-test.c code. Typically I get a 
bunch of kernel dmesg when I start the alsa-time-test program but not 
afterwards. Just a reminder - I'm running this on fast hardware - X58 / Core 
i7 920 - the machine is not loaded at all, so latency should be very low. 
snd_hda_intel - ' 00-00: AD198x Analog : AD198x Analog : playback 1 : capture 
3'.

Here is an example run .....

hw_ptr skipping! (pos=2096, delta=2096, period=1472)
hw_ptr skipping! (pos=2096, delta=2096, period=1472)
hw_ptr skipping! (pos=3600, delta=3600, period=1472)
hw_ptr skipping! (pos=3600, delta=3600, period=1472)
hw_ptr skipping! (pos=3600, delta=3600, period=1472)
hw_ptr skipping! (pos=3600, delta=3600, period=1472)
hw_ptr skipping! (pos=3600, delta=3600, period=1472)
hw_ptr skipping! (pos=3600, delta=3600, period=1472)

9901323          (2632)  delta 111       avail 117       delay 4299
19901290        (2599)  delta 112       avail 112       delay 4304
29901285        (3)     delta 112       avail 112       delay 4304
39901315        (2624)  delta 120       avail 120       delay 4296
49901317        (2626)  delta 112       avail 112       delay 4304
59901317        (2625)  delta 112       avail 112       delay 4304
69901323        (2632)  delta 118       avail 118       delay 4298
79901391        (3)     delta 120       avail 120       delay 4296
89901327        (2634)  delta 112       avail 112       delay 4304
99901283        (2591)  delta 120       avail 120       delay 4296
109901334       (2642)  delta 120       avail 120       delay 4296
119901320       (2627)  delta 112       avail 112       delay 4304

Regards

Clive
-- 
Clive Messer <clive at vacuumtube.org.uk>