commit c87d9732004b3f8fd82d729f12ccfb96c0df279e
Author: Takashi Iwai <ti...@suse.de>
Date: Wed May 27 10:53:33 2009 +0200
ALSA: Enable PCM hw_ptr_jiffies check only in xrun_debug mode
The PCM hw_ptr jiffies check results sometimes in problems when a
hardware doesn't give smooth hw_ptr updates. So far, au88x0 and some
other drivers appear not working due to this strict check.
However, this check is a nice debug tool, and the capability should be
still kept.
Hence, we disable this check now as default unless the user enables it
by setting the xrun_debug mode to the specific stream via a proc file.
Signed-off-by: Takashi Iwai <ti...@suse.de>
causes sound to skip while listing to MP3s using mplayer on
intel8x0 sound cards.
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majo...@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
Could you set CONFIG_SND_PCM_XRUN_DEBUG=y and do
# echo 1 > /proc/asound/card0/pcm0p/xrun_debug
then check your app? Does it work better, and get any kernel messages?
Basically it's rather a job of the lowlevel driver (intel8x0) to fix /
filter out the bogus values.
I though we have already some code to correct it in 2.6.30, but it
seems not enough...
Also, it'd be helpful if you can check whether the problem exists in
the current sound git tree (for-linus branch), too.
git://git.kernel.org/pub/scm/linux/kernel/git/tiwai/sound-2.6.git for-linus
thanks,
Takashi
I'm also affected by the issue described above.
Can somebody point out, how I can set this xrun_debug thing or can
somebody provide a patch that reverts the change?
Regards,
Sven
Which hardware?
> Can somebody point out, how I can set this xrun_debug thing or can
> somebody provide a patch that reverts the change?
Did you read my reply to David?
Takashi
It's a Samsung X20 notebook that has some "SoundMAX" hardware.
I don't know how to describe it better. Does the ALSA driver report,
which ac97 chip is connected?
I'm using the snd_intel8x0 kernel module.
>> Can somebody point out, how I can set this xrun_debug thing or can
>> somebody provide a patch that reverts the change?
>
> Did you read my reply to David?
I will try, what is described there and I will report back if I get any
debug output.
Regards,
Sven
OK, then really a same issue.
I think the problem is independent of the codec ("SoundMax" is a name
of Analog-Device codec chips) but rather the controller, which you see
in lspci.
> >> Can somebody point out, how I can set this xrun_debug thing or can
> >> somebody provide a patch that reverts the change?
> >
> > Did you read my reply to David?
>
> I will try, what is described there and I will report back if I get any
> debug output.
Thanks, that'll be be helpful.
Takashi
> Could you set CONFIG_SND_PCM_XRUN_DEBUG=y and do
> # echo 1 > /proc/asound/card0/pcm0p/xrun_debug
> then check your app? Does it work better, and get any kernel messages?
Yes, the skipping goes away and I get hw_ptr skipping kernel messages:
[61581.519051] PCM: hw_ptr skipping! (pos=10240, delta=15368, period=1024, jdelta=0/32)
[61584.420358] PCM: hw_ptr skipping! (pos=2048, delta=16328, period=1024, jdelta=2/34)
[61593.956318] PCM: hw_ptr skipping! (pos=1024, delta=15368, period=1024, jdelta=0/32)
[61596.964300] PCM: hw_ptr skipping! (pos=14336, delta=15368, period=1024, jdelta=0/32)
[61600.036292] PCM: hw_ptr skipping! (pos=14336, delta=15368, period=1024, jdelta=0/32)
[61605.454947] PCM: hw_ptr skipping! (pos=12288, delta=15368, period=1024, jdelta=0/32)
> Also, it'd be helpful if you can check whether the problem exists in
> the current sound git tree (for-linus branch), too.
> git://git.kernel.org/pub/scm/linux/kernel/git/tiwai/sound-2.6.git for-linus
I'm building this to test right now, will report when I try it out.
[ Just another data point. ]
I'm experiencing similar problem with the sound in recent -next kernels.
Though the only debug data that I'm getting with xrun_debug == 1 is:
XRUN: pcmC0D0p:0
XRUN: pcmC0D0p:0
XRUN: pcmC0D0p:0
XRUN: pcmC0D0p:0
XRUN: pcmC0D0p:0
with xrun_debug == 3:
XRUN: pcmC0D0p:0
Pid: 4718, comm: audacious Not tainted 2.6.30-next-20090611-07944-gc1b019d-dirty #21
Call Trace:
[<e1074684>] xrun+0x8b/0x92 [snd_pcm]
[<e10746fd>] snd_pcm_update_hw_ptr_post+0x72/0xa9 [snd_pcm]
[<e1074c2d>] snd_pcm_update_hw_ptr+0x18f/0x19b [snd_pcm]
[<e1071b9e>] snd_pcm_common_ioctl1+0xa56/0x14e4 [snd_pcm]
[<c0141628>] ? getnstimeofday+0x52/0xda
[<c016ce03>] ? might_fault+0x4b/0x88
[<c016ce03>] ? might_fault+0x4b/0x88
[<c016ce03>] ? might_fault+0x4b/0x88
[<c018ecd3>] ? core_sys_select+0x27e/0x2c9
[<e1072d51>] snd_pcm_playback_ioctl1+0x37a/0x3d2 [snd_pcm]
[<e1072e17>] snd_pcm_kernel_ioctl+0x38/0x5d [snd_pcm]
[<e1297443>] snd_pcm_oss_ioctl+0x7b1/0xc08 [snd_pcm_oss]
[<c016ce03>] ? might_fault+0x4b/0x88
[<e1296c92>] ? snd_pcm_oss_ioctl+0x0/0xc08 [snd_pcm_oss]
[<c018cfab>] vfs_ioctl+0x22/0x69
[<c018d475>] do_vfs_ioctl+0x483/0x4bd
[<c01833c3>] ? fget_light+0x43/0xe1
[<c0183437>] ? fget_light+0xb7/0xe1
[<c018d4db>] sys_ioctl+0x2c/0x45
[<c0102988>] sysenter_do_call+0x12/0x36
Which driver?
> Though the only debug data that I'm getting with xrun_debug == 1 is:
>
> XRUN: pcmC0D0p:0
> XRUN: pcmC0D0p:0
> XRUN: pcmC0D0p:0
> XRUN: pcmC0D0p:0
> XRUN: pcmC0D0p:0
>
> with xrun_debug == 3:
> XRUN: pcmC0D0p:0
> Pid: 4718, comm: audacious Not tainted 2.6.30-next-20090611-07944-gc1b019d-dirty #21
> Call Trace:
The semantics of xrun_debug proc file was a bit changed. Now it's
bit flags, and 4 corresponds to the additional jiffies check (1 is to
show the debug message, 2 to show stack trace).
Try to set 5 to xrun_debug. Do you get other messages?
thanks,
Takashi
OK, then obviously intel8x0 driver gets screwed and is giving bogus
position data.
At Thu, 11 Jun 2009 05:02:20 -0700 (PDT),
David Miller wrote:
>
> From: Takashi Iwai <ti...@suse.de>
> Date: Wed, 10 Jun 2009 21:37:14 +0200
>
> > Also, it'd be helpful if you can check whether the problem exists in
> > the current sound git tree (for-linus branch), too.
> > git://git.kernel.org/pub/scm/linux/kernel/git/tiwai/sound-2.6.git for-linus
>
> Same behavior as 2.6.30, but debugging messages are formatted differently
> :-)
>
> [ 1109.062182] PCM: Lost interrupts? (stream=0, delta=16384, intr_ptr=73728)
> [ 1125.126123] PCM: Lost interrupts? (stream=0, delta=16384, intr_ptr=861184)
> [ 1131.398094] PCM: Lost interrupts? (stream=0, delta=16384, intr_ptr=1178624)
> [ 1135.579406] PCM: Lost interrupts? (stream=0, delta=16384, intr_ptr=1395712)
> [ 1145.115367] PCM: Lost interrupts? (stream=0, delta=16384, intr_ptr=1869824)
> [ 1152.688670] PCM: Lost interrupts? (stream=0, delta=16384, intr_ptr=2249728)
I guess this is because of the change of xrun_debug semantics.
Try to set 5 to xrun_debug instead of 1. Then you'll get the similar
results like 2.6.30, I guess. (Setting to 4 will run with the sanity
check but without debug prints, BTW.)
I'll investigate the problem, but probably a bit later as now is a
long weekend in Germany...
thanks,
Takashi
snd_intel8x0
> > Though the only debug data that I'm getting with xrun_debug == 1 is:
> >
> > XRUN: pcmC0D0p:0
> > XRUN: pcmC0D0p:0
> > XRUN: pcmC0D0p:0
> > XRUN: pcmC0D0p:0
> > XRUN: pcmC0D0p:0
> >
> > with xrun_debug == 3:
> > XRUN: pcmC0D0p:0
> > Pid: 4718, comm: audacious Not tainted 2.6.30-next-20090611-07944-gc1b019d-dirty #21
> > Call Trace:
>
> The semantics of xrun_debug proc file was a bit changed. Now it's
> bit flags, and 4 corresponds to the additional jiffies check (1 is to
> show the debug message, 2 to show stack trace).
>
> Try to set 5 to xrun_debug. Do you get other messages?
With xrun_debug == 5 I get:
PCM: hw_ptr skipping! (pos=14336, delta=15893, period=1024, jdelta=3/90)
PCM: hw_ptr skipping! (pos=11264, delta=15893, period=1024, jdelta=3/90)
PCM: hw_ptr skipping! (pos=7168, delta=15888, period=1024, jdelta=3/90)
PCM: hw_ptr skipping! (pos=8192, delta=15915, period=1024, jdelta=3/90)
PCM: hw_ptr skipping! (pos=15360, delta=15888, period=1024, jdelta=3/90)
XRUN: pcmC0D0p:0
PCM: hw_ptr skipping! (pos=6144, delta=15890, period=1024, jdelta=3/90)
PCM: hw_ptr skipping! (pos=3072, delta=15890, period=1024, jdelta=3/90)
[ They seem to be the same as reported by davem against 2.6.30. ]
and the skipping is gone.
Yes.
> and the skipping is gone.
Does the patch below fix the problem?
If not, how about to revert the commit below?
commit da2436a23c038055b1da6fe30b6ea2886b1e07b0
Author: Jaroslav Kysela <pe...@perex.cz>
Date: Mon Apr 13 21:31:25 2009 +0200
[ALSA] intel8x0: do not use zero value from PICB register
thanks,
Takashi
---
diff --git a/sound/pci/intel8x0.c b/sound/pci/intel8x0.c
index 173bebf..e894da0 100644
--- a/sound/pci/intel8x0.c
+++ b/sound/pci/intel8x0.c
@@ -1077,8 +1077,8 @@ static snd_pcm_uframes_t snd_intel8x0_pcm_pointer(struct snd_pcm_substream *subs
ptr1 <<= ichdev->pos_shift;
ptr = ichdev->fragsize1 - ptr1;
ptr += position;
- ichdev->last_pos = ptr;
- ichdev->last_pos_jiffies = jiffies;
+ if (ptr >= ichdev->size)
+ ptr = 0;
} else {
ptr1 = jiffies - ichdev->last_pos_jiffies;
if (ptr1)
@@ -1086,9 +1086,9 @@ static snd_pcm_uframes_t snd_intel8x0_pcm_pointer(struct snd_pcm_substream *subs
ptr = ichdev->last_pos + ptr1 * ichdev->jiffy_to_bytes;
ptr %= ichdev->size;
}
+ ichdev->last_pos = ptr;
+ ichdev->last_pos_jiffies = jiffies;
spin_unlock(&chip->reg_lock);
- if (ptr >= ichdev->size)
- return 0;
return bytes_to_frames(substream->runtime, ptr);
Unfortunately, it did not fix the issue.
> If not, how about to revert the commit below?
>
> commit da2436a23c038055b1da6fe30b6ea2886b1e07b0
> Author: Jaroslav Kysela <pe...@perex.cz>
> Date: Mon Apr 13 21:31:25 2009 +0200
> [ALSA] intel8x0: do not use zero value from PICB register
Same here.
Hmm... How about the patch below, then?
This should show other debug prints from intel8x0 if my guess is right.
thanks,
Takashi
---
diff --git a/sound/pci/intel8x0.c b/sound/pci/intel8x0.c
index 173bebf..1b292ae 100644
--- a/sound/pci/intel8x0.c
+++ b/sound/pci/intel8x0.c
@@ -1048,7 +1048,8 @@ static int snd_intel8x0_pcm_prepare(struct snd_pcm_substream *substream)
ichdev->pos_shift = (runtime->sample_bits > 16) ? 2 : 1;
}
snd_intel8x0_setup_periods(chip, ichdev);
- ichdev->jiffy_to_bytes = (runtime->rate * 4 * ichdev->pos_shift) / HZ;
+ ichdev->jiffy_to_bytes =
+ runtime->rate * (2 * runtime->sample_bits / 8) / HZ;
return 0;
}
@@ -1056,9 +1057,11 @@ static snd_pcm_uframes_t snd_intel8x0_pcm_pointer(struct snd_pcm_substream *subs
{
struct intel8x0 *chip = snd_pcm_substream_chip(substream);
struct ichdev *ichdev = get_ichdev(substream);
+ struct snd_pcm_runtime *runtime = substream->runtime;
size_t ptr1, ptr;
int civ, timeout = 10;
- unsigned int position;
+ unsigned int position, threshold;
+ unsigned long jdelta;
spin_lock(&chip->reg_lock);
do {
@@ -1073,22 +1076,29 @@ static snd_pcm_uframes_t snd_intel8x0_pcm_pointer(struct snd_pcm_substream *subs
ptr1 == igetword(chip, ichdev->reg_offset + ichdev->roff_picb))
break;
} while (timeout--);
+ jdelta = jiffies - ichdev->last_pos_jiffies;
if (ptr1 != 0) {
ptr1 <<= ichdev->pos_shift;
ptr = ichdev->fragsize1 - ptr1;
- ptr += position;
- ichdev->last_pos = ptr;
- ichdev->last_pos_jiffies = jiffies;
- } else {
- ptr1 = jiffies - ichdev->last_pos_jiffies;
- if (ptr1)
- ptr1 -= 1;
- ptr = ichdev->last_pos + ptr1 * ichdev->jiffy_to_bytes;
- ptr %= ichdev->size;
- }
+ threshold = (jdelta + (HZ / 100)) *
+ runtime->rate * (2 * runtime->sample_bits / 8) / HZ;
+ if (ptr <= threshold) {
+ ptr += position;
+ if (ptr >= ichdev->size)
+ ptr = 0;
+ goto updated;
+ } else
+ printk(KERN_DEBUG "XXX intel8x0: invalid update "
+ "%d (jdelta=%ld)\n", (int)ptr, jdelta);
+ }
+ if (jdelta)
+ jdelta--;
+ ptr = ichdev->last_pos + jdelta * ichdev->jiffy_to_bytes;
+ ptr %= ichdev->size;
+ updated:
+ ichdev->last_pos = ptr;
+ ichdev->last_pos_jiffies = jiffies;
spin_unlock(&chip->reg_lock);
- if (ptr >= ichdev->size)
- return 0;
return bytes_to_frames(substream->runtime, ptr);
}
Still not fixed.
> This should show other debug prints from intel8x0 if my guess is right.
There is a lot of them.. :)
XXX intel8x0: invalid update 4060 (jdelta=3)
XXX intel8x0: invalid update 4040 (jdelta=3)
XXX intel8x0: invalid update 4024 (jdelta=3)
XXX intel8x0: invalid update 3992 (jdelta=2)
XXX intel8x0: invalid update 3956 (jdelta=3)
XXX intel8x0: invalid update 4044 (jdelta=2)
XXX intel8x0: invalid update 4028 (jdelta=3)
XXX intel8x0: invalid update 4020 (jdelta=3)
XXX intel8x0: invalid update 3984 (jdelta=3)
XXX intel8x0: invalid update 4052 (jdelta=2)
..
Below is the output. Note, that audacious 2.x was not only skipping a
little bit. In fact, the clock that was showing the time of audio played
was running twice as fast or even 4 times as fast. The sound was played
at the right samplerate but in fast it seems, that much of the audio
data was skipped and I only heard a series of short fragments of what
should have been the song I'm listening to.
PCM: hw_ptr skipping! (pos=4096, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=4096, delta=7611, period=1024, jdelta=10/158)
PCM: hw_ptr skipping! (pos=4096, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=6144, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=3072, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=5120, delta=7630, period=1024, jdelta=10/158)
PCM: hw_ptr skipping! (pos=3072, delta=7629, period=1024, jdelta=10/158)
PCM: hw_ptr skipping! (pos=6144, delta=7609, period=1024, jdelta=9/158)
PCM: hw_ptr skipping! (pos=5120, delta=7618, period=1024, jdelta=10/158)
PCM: hw_ptr skipping! (pos=1024, delta=7620, period=1024, jdelta=9/158)
PCM: hw_ptr skipping! (pos=4096, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=3072, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=0, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=7168, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=1024, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=6144, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=6144, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=3072, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=4096, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=5120, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=6144, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=7168, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=0, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=1024, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=2048, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=3072, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=4096, delta=7169, period=1024, jdelta=0/149)
__ratelimit: 202 callbacks suppressed
PCM: hw_ptr skipping! (pos=7168, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=0, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=1024, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=2048, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=3072, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=4096, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=5120, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=6144, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=7168, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=0, delta=7169, period=1024, jdelta=0/149)
__ratelimit: 202 callbacks suppressed
PCM: hw_ptr skipping! (pos=3072, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=4096, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=5120, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=6144, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=7168, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=1024, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=2048, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=3072, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=4096, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=5120, delta=7169, period=1024, jdelta=0/149)
__ratelimit: 196 callbacks suppressed
PCM: hw_ptr skipping! (pos=7168, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=0, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=1024, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=2048, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=3072, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=4096, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=5120, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=6144, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=7168, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=0, delta=7169, period=1024, jdelta=0/149)
__ratelimit: 201 callbacks suppressed
PCM: hw_ptr skipping! (pos=3072, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=4096, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=5120, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=6144, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=7168, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=0, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=1024, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=2048, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=3072, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=4096, delta=7169, period=1024, jdelta=0/149)
__ratelimit: 199 callbacks suppressed
PCM: hw_ptr skipping! (pos=7168, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=0, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=1024, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=2048, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=3072, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=4096, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=5120, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=6144, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=7168, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=0, delta=7169, period=1024, jdelta=0/149)
__ratelimit: 199 callbacks suppressed
PCM: hw_ptr skipping! (pos=3072, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=4096, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=5120, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=6144, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=7168, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=0, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=1024, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=2048, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=3072, delta=7169, period=1024, jdelta=0/149)
PCM: hw_ptr skipping! (pos=4096, delta=7169, period=1024, jdelta=0/149)
__ratelimit: 12 callbacks suppressed
PCM: hw_ptr skipping! (pos=4096, delta=7610, period=1024, jdelta=9/158)
PCM: hw_ptr skipping! (pos=4096, delta=7611, period=1024, jdelta=9/158)
Regards,
Sven
OK, it must be the same problem indeed as David and Bartlomiej see.
Although Bartlomiej wrote that reverting the commit below didn't help,
I still suspect it comes from there.
commit da2436a23c038055b1da6fe30b6ea2886b1e07b0
Author: Jaroslav Kysela <pe...@perex.cz>
Date: Mon Apr 13 21:31:25 2009 +0200
[ALSA] intel8x0: do not use zero value from PICB register
The below is a revised patch to fix the possible regression from this.
Could you guys give it a try, or check reverting the above?
thanks,
Takashi
---
diff --git a/sound/pci/intel8x0.c b/sound/pci/intel8x0.c
index 173bebf..2446ed6 100644
--- a/sound/pci/intel8x0.c
+++ b/sound/pci/intel8x0.c
@@ -1077,15 +1077,18 @@ static snd_pcm_uframes_t snd_intel8x0_pcm_pointer(struct snd_pcm_substream *subs
ptr1 <<= ichdev->pos_shift;
ptr = ichdev->fragsize1 - ptr1;
ptr += position;
- ichdev->last_pos = ptr;
- ichdev->last_pos_jiffies = jiffies;
} else {
ptr1 = jiffies - ichdev->last_pos_jiffies;
if (ptr1)
ptr1 -= 1;
ptr = ichdev->last_pos + ptr1 * ichdev->jiffy_to_bytes;
ptr %= ichdev->size;
+ if (ptr < position ||
+ ptr > position + substream->runtime->period_size)
+ ptr = position;
}
+ ichdev->last_pos = ptr;
+ ichdev->last_pos_jiffies = jiffies;
spin_unlock(&chip->reg_lock);
if (ptr >= ichdev->size)
return 0;
The issue is still present with the revised patch.
I think we should go back to basic. The patch below cuts off the
position compensation but falls back to the last value, which is a
safer option. How about this?
thanks,
Takashi
---
diff --git a/sound/pci/intel8x0.c b/sound/pci/intel8x0.c
index 173bebf..1c02705 100644
--- a/sound/pci/intel8x0.c
+++ b/sound/pci/intel8x0.c
@@ -356,8 +356,6 @@ struct ichdev {
unsigned int position;
unsigned int pos_shift;
unsigned int last_pos;
- unsigned long last_pos_jiffies;
- unsigned int jiffy_to_bytes;
int frags;
int lvi;
int lvi_frag;
@@ -844,7 +842,6 @@ static int snd_intel8x0_pcm_trigger(struct snd_pcm_substream *substream, int cmd
case SNDRV_PCM_TRIGGER_PAUSE_RELEASE:
val = ICH_IOCE | ICH_STARTBM;
ichdev->last_pos = ichdev->position;
- ichdev->last_pos_jiffies = jiffies;
break;
case SNDRV_PCM_TRIGGER_SUSPEND:
ichdev->suspended = 1;
@@ -1048,7 +1045,6 @@ static int snd_intel8x0_pcm_prepare(struct snd_pcm_substream *substream)
ichdev->pos_shift = (runtime->sample_bits > 16) ? 2 : 1;
}
snd_intel8x0_setup_periods(chip, ichdev);
- ichdev->jiffy_to_bytes = (runtime->rate * 4 * ichdev->pos_shift) / HZ;
return 0;
}
@@ -1073,19 +1069,13 @@ static snd_pcm_uframes_t snd_intel8x0_pcm_pointer(struct snd_pcm_substream *subs
ptr1 == igetword(chip, ichdev->reg_offset + ichdev->roff_picb))
break;
} while (timeout--);
+ ptr = ichdev->last_pos;
if (ptr1 != 0) {
ptr1 <<= ichdev->pos_shift;
ptr = ichdev->fragsize1 - ptr1;
ptr += position;
- ichdev->last_pos = ptr;
- ichdev->last_pos_jiffies = jiffies;
- } else {
- ptr1 = jiffies - ichdev->last_pos_jiffies;
- if (ptr1)
- ptr1 -= 1;
- ptr = ichdev->last_pos + ptr1 * ichdev->jiffy_to_bytes;
- ptr %= ichdev->size;
}
+ ichdev->last_pos = ptr;
spin_unlock(&chip->reg_lock);
if (ptr >= ichdev->size)
return 0;
If that patch also doesn't work, we need to track the position update
sequence in more details.
The patch below will dump the each position update (CAUTION: it can be
long logs!). Please apply it instead of the previous one, run with
xrun_debug=5 on 2.6.31 (or xrun_debug=1 on 2.6.30), and give the
outputs around a skip occurs.
thanks,
Takashi
---
diff --git a/sound/pci/intel8x0.c b/sound/pci/intel8x0.c
index 173bebf..0a8a055 100644
--- a/sound/pci/intel8x0.c
+++ b/sound/pci/intel8x0.c
@@ -1059,6 +1059,7 @@ static snd_pcm_uframes_t snd_intel8x0_pcm_pointer(struct snd_pcm_substream *subs
size_t ptr1, ptr;
int civ, timeout = 10;
unsigned int position;
+ unsigned long jdelta;
spin_lock(&chip->reg_lock);
do {
@@ -1073,19 +1074,17 @@ static snd_pcm_uframes_t snd_intel8x0_pcm_pointer(struct snd_pcm_substream *subs
ptr1 == igetword(chip, ichdev->reg_offset + ichdev->roff_picb))
break;
} while (timeout--);
+ jdelta = jiffies - ichdev->last_pos_jiffies;
+ printk(KERN_DEBUG "XXX intel8x0: ptr1=%d/%d, base=%d, jdelta=%ld\n",
+ (int)ptr1, position, ichdev->fragsize1, jdelta);
+ ptr = ichdev->last_pos;
if (ptr1 != 0) {
ptr1 <<= ichdev->pos_shift;
ptr = ichdev->fragsize1 - ptr1;
ptr += position;
- ichdev->last_pos = ptr;
- ichdev->last_pos_jiffies = jiffies;
- } else {
- ptr1 = jiffies - ichdev->last_pos_jiffies;
- if (ptr1)
- ptr1 -= 1;
- ptr = ichdev->last_pos + ptr1 * ichdev->jiffy_to_bytes;
- ptr %= ichdev->size;
}
+ ichdev->last_pos = ptr;
+ ichdev->last_pos_jiffies = jiffies;
> If that patch also doesn't work, we need to track the position update
> sequence in more details.
> The patch below will dump the each position update (CAUTION: it can be
> long logs!). Please apply it instead of the previous one, run with
> xrun_debug=5 on 2.6.31 (or xrun_debug=1 on 2.6.30), and give the
> outputs around a skip occurs.
The patch doesn't work.
I put up a debugging log at:
http://vger.kernel.org/~davem/asound.log
there is a "PCM: hw_ptr skipping! ..." message near the end.
Thanks! I see the problem now. It's a race in the update of the
current buffer position. The counter was reset to the full fragment
size, but its index still points the previous position. So, the
driver was confused and put the position back.
The below is a revised patch. It has an additional sanity check.
Please give it a try.
Takashi
---
diff --git a/sound/pci/intel8x0.c b/sound/pci/intel8x0.c
index 173bebf..474e40a 100644
--- a/sound/pci/intel8x0.c
+++ b/sound/pci/intel8x0.c
@@ -356,8 +356,6 @@ struct ichdev {
unsigned int position;
unsigned int pos_shift;
unsigned int last_pos;
- unsigned long last_pos_jiffies;
- unsigned int jiffy_to_bytes;
int frags;
int lvi;
int lvi_frag;
@@ -844,7 +842,6 @@ static int snd_intel8x0_pcm_trigger(struct snd_pcm_substream *substream, int cmd
case SNDRV_PCM_TRIGGER_PAUSE_RELEASE:
val = ICH_IOCE | ICH_STARTBM;
ichdev->last_pos = ichdev->position;
- ichdev->last_pos_jiffies = jiffies;
break;
case SNDRV_PCM_TRIGGER_SUSPEND:
ichdev->suspended = 1;
@@ -1048,7 +1045,6 @@ static int snd_intel8x0_pcm_prepare(struct snd_pcm_substream *substream)
ichdev->pos_shift = (runtime->sample_bits > 16) ? 2 : 1;
}
snd_intel8x0_setup_periods(chip, ichdev);
- ichdev->jiffy_to_bytes = (runtime->rate * 4 * ichdev->pos_shift) / HZ;
return 0;
}
@@ -1073,19 +1069,19 @@ static snd_pcm_uframes_t snd_intel8x0_pcm_pointer(struct snd_pcm_substream *subs
ptr1 == igetword(chip, ichdev->reg_offset + ichdev->roff_picb))
break;
} while (timeout--);
+ ptr = ichdev->last_pos;
if (ptr1 != 0) {
ptr1 <<= ichdev->pos_shift;
ptr = ichdev->fragsize1 - ptr1;
ptr += position;
- ichdev->last_pos = ptr;
- ichdev->last_pos_jiffies = jiffies;
- } else {
- ptr1 = jiffies - ichdev->last_pos_jiffies;
- if (ptr1)
- ptr1 -= 1;
- ptr = ichdev->last_pos + ptr1 * ichdev->jiffy_to_bytes;
- ptr %= ichdev->size;
+ if (ptr < ichdev->last_pos) {
+ /* invalid position; likely ptr1 went back to
+ * fragsize1 while the base position wasn't updated yet
+ */
+ ptr = ichdev->last_pos;
+ }
}
+ ichdev->last_pos = ptr;
spin_unlock(&chip->reg_lock);
if (ptr >= ichdev->size)
return 0;
Damn, that was buggy again. The fixed version is below.
Takashi
---
diff --git a/sound/pci/intel8x0.c b/sound/pci/intel8x0.c
index 173bebf..8aa5687 100644
--- a/sound/pci/intel8x0.c
+++ b/sound/pci/intel8x0.c
@@ -356,8 +356,6 @@ struct ichdev {
unsigned int position;
unsigned int pos_shift;
unsigned int last_pos;
- unsigned long last_pos_jiffies;
- unsigned int jiffy_to_bytes;
int frags;
int lvi;
int lvi_frag;
@@ -844,7 +842,6 @@ static int snd_intel8x0_pcm_trigger(struct snd_pcm_substream *substream, int cmd
case SNDRV_PCM_TRIGGER_PAUSE_RELEASE:
val = ICH_IOCE | ICH_STARTBM;
ichdev->last_pos = ichdev->position;
- ichdev->last_pos_jiffies = jiffies;
break;
case SNDRV_PCM_TRIGGER_SUSPEND:
ichdev->suspended = 1;
@@ -1048,7 +1045,6 @@ static int snd_intel8x0_pcm_prepare(struct snd_pcm_substream *substream)
ichdev->pos_shift = (runtime->sample_bits > 16) ? 2 : 1;
}
snd_intel8x0_setup_periods(chip, ichdev);
- ichdev->jiffy_to_bytes = (runtime->rate * 4 * ichdev->pos_shift) / HZ;
return 0;
}
@@ -1073,19 +1069,23 @@ static snd_pcm_uframes_t snd_intel8x0_pcm_pointer(struct snd_pcm_substream *subs
ptr1 == igetword(chip, ichdev->reg_offset + ichdev->roff_picb))
break;
} while (timeout--);
+ ptr = ichdev->last_pos;
if (ptr1 != 0) {
ptr1 <<= ichdev->pos_shift;
ptr = ichdev->fragsize1 - ptr1;
ptr += position;
- ichdev->last_pos = ptr;
- ichdev->last_pos_jiffies = jiffies;
- } else {
- ptr1 = jiffies - ichdev->last_pos_jiffies;
- if (ptr1)
- ptr1 -= 1;
- ptr = ichdev->last_pos + ptr1 * ichdev->jiffy_to_bytes;
- ptr %= ichdev->size;
+ if (ptr < ichdev->last_pos) {
+ unsigned int pos_base, last_base;
+ pos_base = position / ichdev->fragsize1;
+ last_base = ichdev->last_pos / ichdev->fragsize1;
+ /* another sanity check; ptr1 can go back to full
+ * before the base position is updated
+ */
+ if (pos_base == last_base)
> The below is a revised patch. It has an additional sanity check.
> Please give it a try.
This is significantly worse.
It skips many times every second. It even skips at least once
per second with xrun_debug set to "5".
[340486.694613] intel8x0_measure_ac97_clock: measured 50109 usecs (2416 samples)
[340486.694620] intel8x0: clocking to 48000
[340542.816403] PCM: hw_ptr skipping! [Q] (pos=16280, delta=16280, period=1024, jdelta=2/33/0)
[340542.837725] PCM: hw_ptr skipping! [Q] (pos=16280, delta=16280, period=1024, jdelta=5/33/1)
[340542.859059] PCM: hw_ptr skipping! [Q] (pos=16280, delta=15256, period=1024, jdelta=2/31/0)
[340542.868179] PCM: hw_ptr skipping! (pos=16280, delta=15256, period=1024, jdelta=3/31)
[340542.869193] PCM: hw_ptr skipping! (pos=16280, delta=15256, period=1024, jdelta=3/31)
[340542.869364] PCM: hw_ptr skipping! (pos=16280, delta=15256, period=1024, jdelta=3/31)
[340542.869384] PCM: hw_ptr skipping! (pos=16280, delta=15256, period=1024, jdelta=3/31)
[340542.880392] PCM: hw_ptr skipping! [Q] (pos=16280, delta=15256, period=1024, jdelta=4/31/1)
[340542.890488] PCM: hw_ptr skipping! (pos=16280, delta=14232, period=1024, jdelta=1/29)
[340542.890508] PCM: hw_ptr skipping! (pos=16280, delta=14232, period=1024, jdelta=1/29)
Thanks for quick testing!
I'll put this to the next 2.6.31 pull request and mark it for 2.6.30
stable kernel.
Bartlomiej, Sven, if you have still a problem with this patch, please
let me know.
Takashi
Seems to work fine.
I have been listening music fir quite a few minutes - skip free.
Thanks!
Sven