[ALSA] emu10k1: hw_ptr skipping when unpausing mplayer

[ALSA] emu10k1: hw_ptr skipping when unpausing mplayer

[Piotr Kaczuba]

Since 2.6.30 I'm experiencing sound and video stuttering when unpausing 
mplayer. The soundcard is an Audigy 1, driver is emu10k1. Kernel is 
x86_64, userspace is 32-bit. I doesn't happen always, but regularly 
enough.


Below is the ouput of mplayer:

[AO_ALSA] alsa-lib: pcm.c:6482:(snd_pcm_mmap_commit) commit offset (8886) 
doesn't match with appl_ptr (139955) % buf_size (16384)
[AO_ALSA] Write error: Broken pipe
[AO_ALSA] Trying to reset soundcard.
[AO_ALSA] alsa-lib: pcm_hw.c:578:(snd_pcm_hw_prepare) 
SNDRV_PCM_IOCTL_PREPARE failed: Device or resource busy
[AO_ALSA] alsa-lib: pcm_hw.c:578:(snd_pcm_hw_prepare) 
SNDRV_PCM_IOCTL_PREPARE failed: Device or resource busy
[AO_ALSA] alsa-lib: pcm_hw.c:578:(snd_pcm_hw_prepare) 
SNDRV_PCM_IOCTL_PREPARE failed: Device or resource busy
[AO_ALSA] pcm prepare error: Device or resource busy


After setting xrun_debug to 5 I get the following in the log:

PCM: hw_ptr skipping! [Q] (pos=3071, delta=17225, period=1024, 
jdelta=18/358/0)
Pid: 0, comm: swapper Not tainted 2.6.30.1-orbiter.x86-64.1 #1
Call Trace:
 <IRQ>  [<ffffffffa02d7c7f>] ? snd_pcm_period_elapsed+0x4df/0x520 
[snd_pcm]
 [<ffffffffa031f15f>] ? snd_emu10k1_interrupt+0x25f/0x550 [snd_emu10k1]
 [<ffffffff8023a9ba>] ? run_timer_softirq+0x1a/0x250
 [<ffffffff80268e99>] ? handle_IRQ_event+0x39/0xe0
 [<ffffffff8026ad19>] ? handle_fasteoi_irq+0x79/0x110
 [<ffffffff8020dd17>] ? handle_irq+0x17/0x20
 [<ffffffff8020d7c1>] ? do_IRQ+0x51/0xd0
 [<ffffffff8020bd13>] ? ret_from_intr+0x0/0x9
 <EOI>  [<ffffffff8021bea0>] ? lapic_next_event+0x0/0x20
 [<ffffffff802127aa>] ? default_idle+0x3a/0x40
 [<ffffffff8020a017>] ? cpu_idle+0x47/0xa0
 [<ffffffff805a5aba>] ? start_kernel+0x2c3/0x384
 [<ffffffff805a5373>] ? x86_64_start_kernel+0xe1/0xf2
PCM: hw_ptr skipping! (pos=5482, delta=3434, period=1024, jdelta=50/71)
Pid: 2870, comm: mplayer Not tainted 2.6.30.1-orbiter.x86-64.1 #1
Call Trace:
 [<ffffffffa02d6bd3>] ? snd_pcm_update_hw_ptr+0x1d3/0x220 [snd_pcm]
 [<ffffffffa02d211d>] ? snd_pcm_hwsync+0x9d/0xe0 [snd_pcm]
 [<ffffffffa02d54e3>] ? snd_pcm_ioctl_compat+0x753/0x980 [snd_pcm]
 [<ffffffff80209b36>] ? __switch_to+0x226/0x270
 [<ffffffff80475407>] ? thread_return+0x30/0x1f9
 [<ffffffff8024a032>] ? hrtimer_cancel+0x12/0x20
 [<ffffffff80476710>] ? do_nanosleep+0x30/0xb0
 [<ffffffff8024a0e0>] ? hrtimer_nanosleep+0xa0/0x130
 [<ffffffff802ddd8b>] ? compat_sys_ioctl+0x19b/0x3e0
 [<ffffffff8024d3bb>] ? getnstimeofday+0x5b/0xe0
 [<ffffffff80266b56>] ? audit_syscall_entry+0x166/0x190
 [<ffffffff80227266>] ? cstar_dispatch+0x7/0x26
PCM: hw_ptr skipping! [Q] (pos=7443, delta=5395, period=1024, 
jdelta=91/112/2)
Pid: 2870, comm: mplayer Not tainted 2.6.30.1-orbiter.x86-64.1 #1
Call Trace:
 <IRQ>  [<ffffffffa02d7c7f>] ? snd_pcm_period_elapsed+0x4df/0x520 
[snd_pcm]
 [<ffffffffa031f15f>] ? snd_emu10k1_interrupt+0x25f/0x550 [snd_emu10k1]
 [<ffffffff80268e99>] ? handle_IRQ_event+0x39/0xe0
 [<ffffffff8022cd9d>] ? try_to_wake_up+0x14d/0x160
 [<ffffffff8026ad19>] ? handle_fasteoi_irq+0x79/0x110
 [<ffffffff8020dd17>] ? handle_irq+0x17/0x20
 [<ffffffff8020d7c1>] ? do_IRQ+0x51/0xd0
 [<ffffffff8020bd13>] ? ret_from_intr+0x0/0x9
 [<ffffffff8021bea0>] ? lapic_next_event+0x0/0x20
 [<ffffffff802354bd>] ? __do_softirq+0x3d/0xf0
 [<ffffffff8020c2ea>] ? call_softirq+0x1a/0x30
 [<ffffffff8020dcbd>] ? do_softirq+0x2d/0x70
 [<ffffffff802352a5>] ? irq_exit+0x85/0xa0
 [<ffffffff8021c74e>] ? smp_apic_timer_interrupt+0x4e/0x80
 [<ffffffff8020be63>] ? apic_timer_interrupt+0x13/0x20
 <EOI>  [<ffffffffa02d20d9>] ? snd_pcm_hwsync+0x59/0xe0 [snd_pcm]
 [<ffffffffa02d211d>] ? snd_pcm_hwsync+0x9d/0xe0 [snd_pcm]
 [<ffffffffa02d54e3>] ? snd_pcm_ioctl_compat+0x753/0x980 [snd_pcm]
 [<ffffffff80209b36>] ? __switch_to+0x226/0x270
 [<ffffffff80475407>] ? thread_return+0x30/0x1f9
 [<ffffffff8024a032>] ? hrtimer_cancel+0x12/0x20
 [<ffffffff80476710>] ? do_nanosleep+0x30/0xb0
 [<ffffffff8024a0e0>] ? hrtimer_nanosleep+0xa0/0x130
 [<ffffffff802ddd8b>] ? compat_sys_ioctl+0x19b/0x3e0
 [<ffffffff8024d3bb>] ? getnstimeofday+0x5b/0xe0
 [<ffffffff80266b56>] ? audit_syscall_entry+0x166/0x190
 [<ffffffff80227266>] ? cstar_dispatch+0x7/0x26

The log is virtually flooded with these messages until I interrupt 
mplayer.

I'd be graceful for any help.

Greetings,
Piotr

Re: [ALSA] emu10k1: hw_ptr skipping when unpausing mplayer

[Takashi Iwai]

At Sat, 18 Jul 2009 16:07:07 +0000 (UTC),
Piotr Kaczuba wrote:
> 
> Since 2.6.30 I'm experiencing sound and video stuttering when unpausing 
> mplayer. The soundcard is an Audigy 1, driver is emu10k1. Kernel is 
> x86_64, userspace is 32-bit. I doesn't happen always, but regularly 
> enough.

To be sure -- isn't it arch-independent?  I guess 64bit user-space
can cause the same problem.

> 
> 
> Below is the ouput of mplayer:
> 
> [AO_ALSA] alsa-lib: pcm.c:6482:(snd_pcm_mmap_commit) commit offset (8886) 
> doesn't match with appl_ptr (139955) % buf_size (16384)
> [AO_ALSA] Write error: Broken pipe
> [AO_ALSA] Trying to reset soundcard.
> [AO_ALSA] alsa-lib: pcm_hw.c:578:(snd_pcm_hw_prepare) 
> SNDRV_PCM_IOCTL_PREPARE failed: Device or resource busy
> [AO_ALSA] alsa-lib: pcm_hw.c:578:(snd_pcm_hw_prepare) 
> SNDRV_PCM_IOCTL_PREPARE failed: Device or resource busy
> [AO_ALSA] alsa-lib: pcm_hw.c:578:(snd_pcm_hw_prepare) 
> SNDRV_PCM_IOCTL_PREPARE failed: Device or resource busy
> [AO_ALSA] pcm prepare error: Device or resource busy

Hm, these errors in snd_pcm_hw_prepare look different.
Maybe it's a bug in libao, but needs more investigation.


> After setting xrun_debug to 5 I get the following in the log:
> 
> PCM: hw_ptr skipping! [Q] (pos=3071, delta=17225, period=1024, 
> jdelta=18/358/0)
> Pid: 0, comm: swapper Not tainted 2.6.30.1-orbiter.x86-64.1 #1
> Call Trace:
>  <IRQ>  [<ffffffffa02d7c7f>] ? snd_pcm_period_elapsed+0x4df/0x520 
> [snd_pcm]
>  [<ffffffffa031f15f>] ? snd_emu10k1_interrupt+0x25f/0x550 [snd_emu10k1]
>  [<ffffffff8023a9ba>] ? run_timer_softirq+0x1a/0x250
>  [<ffffffff80268e99>] ? handle_IRQ_event+0x39/0xe0
>  [<ffffffff8026ad19>] ? handle_fasteoi_irq+0x79/0x110
>  [<ffffffff8020dd17>] ? handle_irq+0x17/0x20
>  [<ffffffff8020d7c1>] ? do_IRQ+0x51/0xd0
>  [<ffffffff8020bd13>] ? ret_from_intr+0x0/0x9
>  <EOI>  [<ffffffff8021bea0>] ? lapic_next_event+0x0/0x20
>  [<ffffffff802127aa>] ? default_idle+0x3a/0x40
>  [<ffffffff8020a017>] ? cpu_idle+0x47/0xa0
>  [<ffffffff805a5aba>] ? start_kernel+0x2c3/0x384
>  [<ffffffff805a5373>] ? x86_64_start_kernel+0xe1/0xf2
> PCM: hw_ptr skipping! (pos=5482, delta=3434, period=1024, jdelta=50/71)
> Pid: 2870, comm: mplayer Not tainted 2.6.30.1-orbiter.x86-64.1 #1
> Call Trace:
>  [<ffffffffa02d6bd3>] ? snd_pcm_update_hw_ptr+0x1d3/0x220 [snd_pcm]
>  [<ffffffffa02d211d>] ? snd_pcm_hwsync+0x9d/0xe0 [snd_pcm]
>  [<ffffffffa02d54e3>] ? snd_pcm_ioctl_compat+0x753/0x980 [snd_pcm]
>  [<ffffffff80209b36>] ? __switch_to+0x226/0x270
>  [<ffffffff80475407>] ? thread_return+0x30/0x1f9
>  [<ffffffff8024a032>] ? hrtimer_cancel+0x12/0x20
>  [<ffffffff80476710>] ? do_nanosleep+0x30/0xb0
>  [<ffffffff8024a0e0>] ? hrtimer_nanosleep+0xa0/0x130
>  [<ffffffff802ddd8b>] ? compat_sys_ioctl+0x19b/0x3e0
>  [<ffffffff8024d3bb>] ? getnstimeofday+0x5b/0xe0
>  [<ffffffff80266b56>] ? audit_syscall_entry+0x166/0x190
>  [<ffffffff80227266>] ? cstar_dispatch+0x7/0x26
> PCM: hw_ptr skipping! [Q] (pos=7443, delta=5395, period=1024, 
> jdelta=91/112/2)
> Pid: 2870, comm: mplayer Not tainted 2.6.30.1-orbiter.x86-64.1 #1
> Call Trace:
>  <IRQ>  [<ffffffffa02d7c7f>] ? snd_pcm_period_elapsed+0x4df/0x520 
> [snd_pcm]
>  [<ffffffffa031f15f>] ? snd_emu10k1_interrupt+0x25f/0x550 [snd_emu10k1]
>  [<ffffffff80268e99>] ? handle_IRQ_event+0x39/0xe0
>  [<ffffffff8022cd9d>] ? try_to_wake_up+0x14d/0x160
>  [<ffffffff8026ad19>] ? handle_fasteoi_irq+0x79/0x110
>  [<ffffffff8020dd17>] ? handle_irq+0x17/0x20
>  [<ffffffff8020d7c1>] ? do_IRQ+0x51/0xd0
>  [<ffffffff8020bd13>] ? ret_from_intr+0x0/0x9
>  [<ffffffff8021bea0>] ? lapic_next_event+0x0/0x20
>  [<ffffffff802354bd>] ? __do_softirq+0x3d/0xf0
>  [<ffffffff8020c2ea>] ? call_softirq+0x1a/0x30
>  [<ffffffff8020dcbd>] ? do_softirq+0x2d/0x70
>  [<ffffffff802352a5>] ? irq_exit+0x85/0xa0
>  [<ffffffff8021c74e>] ? smp_apic_timer_interrupt+0x4e/0x80
>  [<ffffffff8020be63>] ? apic_timer_interrupt+0x13/0x20
>  <EOI>  [<ffffffffa02d20d9>] ? snd_pcm_hwsync+0x59/0xe0 [snd_pcm]
>  [<ffffffffa02d211d>] ? snd_pcm_hwsync+0x9d/0xe0 [snd_pcm]
>  [<ffffffffa02d54e3>] ? snd_pcm_ioctl_compat+0x753/0x980 [snd_pcm]
>  [<ffffffff80209b36>] ? __switch_to+0x226/0x270
>  [<ffffffff80475407>] ? thread_return+0x30/0x1f9
>  [<ffffffff8024a032>] ? hrtimer_cancel+0x12/0x20
>  [<ffffffff80476710>] ? do_nanosleep+0x30/0xb0
>  [<ffffffff8024a0e0>] ? hrtimer_nanosleep+0xa0/0x130
>  [<ffffffff802ddd8b>] ? compat_sys_ioctl+0x19b/0x3e0
>  [<ffffffff8024d3bb>] ? getnstimeofday+0x5b/0xe0
>  [<ffffffff80266b56>] ? audit_syscall_entry+0x166/0x190
>  [<ffffffff80227266>] ? cstar_dispatch+0x7/0x26
> 
> The log is virtually flooded with these messages until I interrupt 
> mplayer.

It's endless because the reset failed in the above.

The problem is likely due to some wrong operation in the pause/restart.
Does the patch below work around a problem?

If this works (somehow, not causing the same error), we can focus more
on the pause implementation of emu10k1.


thanks,

Takashi

---
diff --git a/sound/pci/emu10k1/emupcm.c b/sound/pci/emu10k1/emupcm.c
index 55b83ef..ae405a4 100644
--- a/sound/pci/emu10k1/emupcm.c
+++ b/sound/pci/emu10k1/emupcm.c
@@ -953,7 +953,7 @@ static struct snd_pcm_hardware snd_emu10k1_playback =
 	.info =			(SNDRV_PCM_INFO_MMAP | SNDRV_PCM_INFO_INTERLEAVED |
 				 SNDRV_PCM_INFO_BLOCK_TRANSFER |
 				 SNDRV_PCM_INFO_RESUME |
-				 SNDRV_PCM_INFO_MMAP_VALID | SNDRV_PCM_INFO_PAUSE),
+				 SNDRV_PCM_INFO_MMAP_VALID /*| SNDRV_PCM_INFO_PAUSE*/),
 	.formats =		SNDRV_PCM_FMTBIT_U8 | SNDRV_PCM_FMTBIT_S16_LE,
 	.rates =		SNDRV_PCM_RATE_CONTINUOUS | SNDRV_PCM_RATE_8000_96000,
 	.rate_min =		4000,

Re: [ALSA] emu10k1: hw_ptr skipping when unpausing mplayer

[Piotr Kaczuba]

On Mon, Jul 20, 2009 at 08:33:37AM +0200, Takashi Iwai wrote:
> At Sat, 18 Jul 2009 16:07:07 +0000 (UTC),
> Piotr Kaczuba wrote:
> > 
> > Since 2.6.30 I'm experiencing sound and video stuttering when unpausing 
> > mplayer. The soundcard is an Audigy 1, driver is emu10k1. Kernel is 
> > x86_64, userspace is 32-bit. I doesn't happen always, but regularly 
> > enough.
> 
> To be sure -- isn't it arch-independent?  I guess 64bit user-space
> can cause the same problem.
I've tested it and it's the same with 64bit mplayer.

[...]
> The problem is likely due to some wrong operation in the pause/restart.
> Does the patch below work around a problem?
> 
> If this works (somehow, not causing the same error), we can focus more
> on the pause implementation of emu10k1.
[...]

Yes, the patch helps. I've tried half a dozen times and the problem
hasn't reappeared. No messages at all with xrun_debug either. So it
is probably the pause implementation of emu10k1.

Thanks,
Piotr

Re: [ALSA] emu10k1: hw_ptr skipping when unpausing mplayer

[Takashi Iwai]

At Mon, 20 Jul 2009 20:57:21 +0200,
Piotr Kaczuba wrote:
> 
> On Mon, Jul 20, 2009 at 08:33:37AM +0200, Takashi Iwai wrote:
> > At Sat, 18 Jul 2009 16:07:07 +0000 (UTC),
> > Piotr Kaczuba wrote:
> > > 
> > > Since 2.6.30 I'm experiencing sound and video stuttering when unpausing 
> > > mplayer. The soundcard is an Audigy 1, driver is emu10k1. Kernel is 
> > > x86_64, userspace is 32-bit. I doesn't happen always, but regularly 
> > > enough.
> > 
> > To be sure -- isn't it arch-independent?  I guess 64bit user-space
> > can cause the same problem.
> I've tested it and it's the same with 64bit mplayer.

OK.

> [...]
> > The problem is likely due to some wrong operation in the pause/restart.
> > Does the patch below work around a problem?
> > 
> > If this works (somehow, not causing the same error), we can focus more
> > on the pause implementation of emu10k1.
> [...]
> 
> Yes, the patch helps. I've tried half a dozen times and the problem
> hasn't reappeared. No messages at all with xrun_debug either. So it
> is probably the pause implementation of emu10k1.

Thanks.  And did you test with the recent 2.6.31-rc* kernel, right?


Takashi

Re: [ALSA] emu10k1: hw_ptr skipping when unpausing mplayer

[Piotr Kaczuba]

W dniu 2009-07-21 07:48, Takashi Iwai pisze:
[...]
> Thanks.  And did you test with the recent 2.6.31-rc* kernel, right?
[...]

No, it was with 2.6.30.1. I will try with the latest rc today evening.

Thanks,
Piotr

Re: [ALSA] emu10k1: hw_ptr skipping when unpausing mplayer

[Takashi Iwai]

At Tue, 21 Jul 2009 11:41:38 +0200,
Piotr Kaczuba wrote:
> 
> W dniu 2009-07-21 07:48, Takashi Iwai pisze:
> [...]
> > Thanks.  And did you test with the recent 2.6.31-rc* kernel, right?
> [...]
> 
> No, it was with 2.6.30.1. I will try with the latest rc today evening.

Oh, then this might be a bug that has been already fixed.
I vaguely remember a similar bug...


Takashi

Re: [ALSA] emu10k1: hw_ptr skipping when unpausing mplayer

[Piotr Kaczuba]

On Tue, Jul 21, 2009 at 11:41:38AM +0200, Piotr Kaczuba wrote:
[...]
> No, it was with 2.6.30.1. I will try with the latest rc today evening.
[...]

With 2.6.31-rc3 there's definitely an improvement. Xrun_debug set to 5,
I see for example the following on unpause:

[  430.788525] __ratelimit: 97 callbacks suppressed
[  430.789516] PCM: hw_ptr skipping! [Q] (pos=3071, delta=16446,
period=1024, jdelta=1/342/0)
[  430.809853] PCM: hw_ptr skipping! [Q] (pos=4095, delta=2047,
period=1024, jdelta=21/42/0)
[  430.824984] PCM: hw_ptr skipping! (pos=4821, delta=2773, period=1024,
jdelta=36/57)
[  430.827087] PCM: hw_ptr skipping! (pos=4922, delta=2874, period=1024,
jdelta=39/59)
[  430.829350] PCM: hw_ptr skipping! (pos=5031, delta=2983, period=1024,
jdelta=41/62)
[  430.831256] PCM: hw_ptr skipping! [Q] (pos=5122, delta=3074,
period=1024, jdelta=43/64/1)
[  430.835786] PCM: hw_ptr skipping! (pos=5340, delta=2268, period=1024,
jdelta=4/47)
[  430.837913] PCM: hw_ptr skipping! (pos=5442, delta=2370, period=1024,
jdelta=6/49)
[  430.839881] PCM: hw_ptr skipping! (pos=5536, delta=2464, period=1024,
jdelta=8/51)
[  430.842959] PCM: hw_ptr skipping! (pos=5684, delta=2612, period=1024,
jdelta=11/54)


But there's no flood of messages anymore and no tracebacks either. In
fact, mplayer continues to play without any stutter.

Thanks,
Piotr