Bug 472339

Summary: snd-intel8x0: timing unstable (snd_pcm_avail() overflows, signals POLLOUT when it shouldn't)
Product: [Fedora] Fedora Reporter: Kieran Clancy <clancy.kieran+redhat>
Component: kernelAssignee: Kernel Maintainer List <kernel-maint>
Status: CLOSED RAWHIDE QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: medium Docs Contact:
Priority: medium    
Version: rawhideCC: amlau, antonio.montagnani, awilliam, behdad, bruno, bugzilla, cdahlin, dimmu299792458, dmalcolm, dragomir.dan, edoutreleau, gene-redhat, jkysela, john.ellson, jsmith.fedora, kernel-maint, kwait, libbe, linux, lkundrak, lpoetter, mads, mc69921, mcepl, mcepl, mishu, nsoracco, pavlik.horak, pterjan, quintela, redhat, ricardo.arguello, roland, ruben, tgrondin, wwoods
Target Milestone: ---   
Target Release: ---   
Hardware: All   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2009-04-22 12:25:19 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 446452    
Attachments:
Description Flags
/var/log/messages ouput when I noticed sound start stuttering none

Description Kieran Clancy 2008-11-20 08:32:48 UTC 
Description of problem:
Every now and then, pulseaudio will stop playing sound, but it appears to be running properly. Any program trying to play sound connects to the pulseaudio socket, establishes some information (pulseaudio -vvv logs some messages to the console about what has connected to it, and logs normally about volume changes and memory blocks etc) and then further polls to that socket just time out. I'm not really sure how to debug this. I am getting this problem with audacious, mplayer, totem, etc.

Version-Release number of selected component (if applicable):
pulseaudio-0.9.10-2.fc9.i386

How reproducible:
Hard to reproduce reliably.

Steps to Reproduce:
1. Play some sound. I have no idea what actually triggers it.
2. After a while, sound stops playing. Any application from this point that tries to play something hangs or busy waits.
3. Pulseaudio needs to be restarted to make sound work again.

Additional information:
An strace of pulseaudio shows this, while I am trying to play something but no sound is being output:
gettimeofday({1227169915, 609375}, NULL) = 0
recvmsg(10, {msg_name(0)=NULL, msg_iov(1)=[{"\0\0\0\30\377\377\377\377\0\0\0\0\0\0\0\0\0\0\0\0", 20}], msg_controllen=24, {cmsg_len=24, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS{pid=1740, uid=500, gid=500}}, msg_flags=0}, 0) = 20
send(10, "L\0\0\0\2L\0\0\f\335", 10, MSG_NOSIGNAL) = 10
gettimeofday({1227169915, 609950}, NULL) = 0
poll([{fd=4, events=POLLIN}, {fd=10, events=POLLIN|POLLOUT, revents=POLLIN|POLLOUT}, {fd=17, events=POLLIN}, {fd=16, events=POLLIN}, {fd=22, events=POLLIN}, {fd=27, events=POLLIN}, {fd=26, events=POLLIN}, {fd=25, events=POLLIN}, {fd=24, events=POLLIN}, {fd=21, events=POLLIN}, {fd=15, events=POLLIN}, {fd=11, events=POLLIN|POLLERR|POLLHUP}, {fd=11, events=0}, {fd=8, events=POLLIN}, {fd=6, events=POLLIN}], 15, 539) = 1
gettimeofday({1227169915, 610302}, NULL) = 0
recvmsg(10, {msg_name(0)=NULL, msg_iov(1)=[{"L\0\0\0\16L\0\0\f\336L\0\0\0\0TI% {\0\t:Q", 24}], msg_controllen=24, {cmsg_len=24, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS{pid=1740, uid=500, gid=500}}, msg_flags=0}, 0) = 24
write(13, "\1\0\0\0\0\0\0\0", 8)        = 8
futex(0x9467ab0, FUTEX_WAIT_PRIVATE, 0, NULL) = 0
write(13, "\1\0\0\0\0\0\0\0", 8)        = 8
futex(0x9467ab0, FUTEX_WAIT_PRIVATE, 0, NULL) = 0
gettimeofday({1227169915, 611283}, NULL) = 0
send(10, "\0\0\0A\377\377\377\377\0\0\0\0\0\0\0\0\0\0\0\0", 20, MSG_NOSIGNAL) = 20
gettimeofday({1227169915, 611637}, NULL) = 0
poll([{fd=4, events=POLLIN}, {fd=10, events=POLLIN|POLLOUT, revents=POLLOUT}, {fd=17, events=POLLIN}, {fd=16, events=POLLIN}, {fd=22, events=POLLIN}, {fd=27, events=POLLIN}, {fd=26, events=POLLIN}, {fd=25, events=POLLIN}, {fd=24, events=POLLIN}, {fd=21, events=POLLIN}, {fd=15, events=POLLIN}, {fd=11, events=POLLIN|POLLERR|POLLHUP}, {fd=11, events=0}, {fd=8, events=POLLIN}, {fd=6, events=POLLIN}], 15, 538) = 1
gettimeofday({1227169915, 612003}, NULL) = 0
send(10, "L\0\0\0\2L\0\0\f\336U\0\0\0\0\0\1f\271U\0\0\0\0\0\0\0\0000TI%"..., 65, MSG_NOSIGNAL) = 65
gettimeofday({1227169915, 612399}, NULL) = 0
poll([{fd=4, events=POLLIN}, {fd=10, events=POLLIN|POLLOUT, revents=POLLOUT}, {fd=17, events=POLLIN}, {fd=16, events=POLLIN}, {fd=22, events=POLLIN}, {fd=27, events=POLLIN}, {fd=26, events=POLLIN}, {fd=25, events=POLLIN}, {fd=24, events=POLLIN}, {fd=21, events=POLLIN}, {fd=15, events=POLLIN}, {fd=11, events=POLLIN|POLLERR|POLLHUP}, {fd=11, events=0}, {fd=8, events=POLLIN}, {fd=6, events=POLLIN}], 15, 537) = 1
Comment 1 Kieran Clancy 2008-11-27 22:46:33 UTC 
Just upgraded to F10, but am still getting this with:
pulseaudio-0.9.13-6.fc10.i386
Comment 2 Lennart Poettering 2008-12-08 23:05:20 UTC 
Which sound driver is this?

Please run PA like this in a terminal:

pulseaudio -vvvv

This will show you debug output of PA while it is running. Then try to reproduce the bug.

(You might need to call pulseaudio -k first to stop the running instance, since only one instance may be running per user)
Comment 3 Kieran Clancy 2008-12-11 13:55:00 UTC 
According to lspci -v:
00:1f.5 Multimedia audio controller: Intel Corporation 82801EB/ER (ICH5/ICH5R) AC'97 Audio Controller (rev 02)
	Subsystem: EPoX Computer Co., Ltd. Device 4004
	Flags: bus master, medium devsel, latency 0, IRQ 17
	I/O ports at d400 [size=256]
	I/O ports at d800 [size=64]
	Memory at fc001000 (32-bit, non-prefetchable) [size=512]
	Memory at fc002000 (32-bit, non-prefetchable) [size=256]
	Capabilities: <access denied>
	Kernel driver in use: Intel ICH
	Kernel modules: snd-intel8x0

Here is the output of pulseaudio -vvvv before the bug occurs. It is worth noting that I usually suspend my computer a couple of times a day, which is probably what the Wakeup/Underrun messages are about. The bug occurred when trying to play a sound after resuming from suspend, but this doesn't always happen.

D: protocol-native.c: Early requests mode enabled, configuring sink latency to minreq.
D: memblockq.c: memblockq requested: maxlength=4194304, tlength=44100, base=4, prebuf=35280, minreq=8820 maxrewind=0
D: memblockq.c: memblockq sanitized: maxlength=4194304, tlength=44100, base=4, prebuf=35280, minreq=8820 maxrewind=0
I: protocol-native.c: Final latency 600.00 ms = 300.00 ms + 2*100.00 ms + 100.00 ms
D: module-alsa-sink.c: Requested to rewind 65536 bytes.
D: module-alsa-sink.c: Limited to 13176 bytes.
D: module-alsa-sink.c: before: 3294
D: module-alsa-sink.c: after: 3294
D: module-alsa-sink.c: Rewound 13176 bytes.
D: sink.c: Processing rewind...
D: module-alsa-sink.c: latency set to 100.00ms
D: module-alsa-sink.c: hwbuf_unused_frames=11584
D: module-alsa-sink.c: setting avail_min=27257
D: module-alsa-sink.c: Requesting rewind due to latency change.
D: module-alsa-sink.c: Requested to rewind 65536 bytes.
D: module-alsa-sink.c: Limited to 61680 bytes.
D: module-alsa-sink.c: before: 15420
D: module-alsa-sink.c: after: 15420
D: module-alsa-sink.c: Rewound 61680 bytes.
D: sink.c: Processing rewind...
D: sink-input.c: Have to rewind 61680 bytes on render memblockq.
E: alsa-util.c: snd_pcm_avail_update() returned a value that is exceptionally large: 252532 bytes (1315 ms) Most likely this is an ALSA driver bug. Please report this issue to the PulseAudio developers.
I: module-alsa-sink.c: Underrun!
N: module-alsa-sink.c: Increasing wakeup watermark to 36.75 ms
W: alsa-util.c: Got POLLERR from ALSA
W: alsa-util.c: Got POLLOUT from ALSA
W: alsa-util.c: PCM state is SUSPENDED
D: module-alsa-sink.c: Wakeup from ALSA! OUTPUT
I: module-alsa-sink.c: Starting playback.
I: (alsa-lib)pcm_hw.c: SNDRV_PCM_IOCTL_START failed
I: module-alsa-sink.c: Underrun!
N: module-alsa-sink.c: Increasing wakeup watermark to 73.50 ms
D: module-alsa-sink.c: Wakeup from ALSA! OUTPUT
I: module-alsa-sink.c: Underrun!
N: module-alsa-sink.c: Increasing wakeup watermark to 97.00 ms
D: module-alsa-sink.c: Wakeup from ALSA! OUTPUT
I: module-alsa-sink.c: Underrun!

Here is the output after the bug is triggered (having tried to play a sound):

D: sink-input.c: Requesting rewind due to corking
D: module-suspend-on-idle.c: Sink alsa_output.pci_8086_24d5_sound_card_0_alsa_playback_0 becomes idle.
D: module-alsa-sink.c: hwbuf_unused_frames=0
D: module-alsa-sink.c: setting avail_min=46909
D: module-suspend-on-idle.c: Sink alsa_output.pci_8086_24d5_sound_card_0_alsa_playback_0 becomes idle.
I: sink-input.c: Freeing input 7 "ALSA Playback"
I: module-stream-restore.c: Restoring device for stream sink-input-by-application-name:ALSA plug-in [audacious].
I: module-stream-restore.c: Restoring volume for sink input sink-input-by-application-name:ALSA plug-in [audacious].
D: module-stream-restore.c: Not restoring mute state for sink input sink-input-by-application-name:ALSA plug-in [audacious], because already set.
D: module-suspend-on-idle.c: Sink alsa_output.pci_8086_24d5_sound_card_0_alsa_playback_0 becomes busy.
I: resampler.c: Using resampler 'speex-float-3'
I: resampler.c: Using float32le as working format.
I: resampler.c: Choosing speex quality setting 3.
D: memblockq.c: memblockq requested: maxlength=33554432, tlength=0, base=4, prebuf=0, minreq=1 maxrewind=0
D: memblockq.c: memblockq sanitized: maxlength=33554432, tlength=33554432, base=4, prebuf=0, minreq=4 maxrewind=0
I: sink-input.c: Created input 8 "ALSA Playback" on alsa_output.pci_8086_24d5_sound_card_0_alsa_playback_0 with sample spec s16le 2ch 22050Hz and channel map front-left,front-right
I: protocol-native.c: Requested tlength=500.00 ms, minreq=100.00 ms
D: protocol-native.c: Early requests mode enabled, configuring sink latency to minreq.
D: memblockq.c: memblockq requested: maxlength=4194304, tlength=44100, base=4, prebuf=35280, minreq=8820 maxrewind=0
D: memblockq.c: memblockq sanitized: maxlength=4194304, tlength=44100, base=4, prebuf=35280, minreq=8820 maxrewind=0
I: protocol-native.c: Final latency 600.00 ms = 300.00 ms + 2*100.00 ms + 100.00 ms
D: module-alsa-sink.c: Requested to rewind 65536 bytes.
D: module-alsa-sink.c: Limited to 528 bytes.
D: module-alsa-sink.c: before: 132
D: module-alsa-sink.c: after: 132
D: module-alsa-sink.c: Rewound 528 bytes.
D: sink.c: Processing rewind...
D: module-alsa-sink.c: latency set to 100.00ms
D: module-alsa-sink.c: hwbuf_unused_frames=11584
D: module-alsa-sink.c: setting avail_min=12161
D: module-alsa-sink.c: Requesting rewind due to latency change.
D: module-alsa-sink.c: Requested to rewind 65536 bytes.
D: module-alsa-sink.c: Limited to 46912 bytes.
D: module-alsa-sink.c: before: 11728
D: module-alsa-sink.c: after: 11728
D: module-alsa-sink.c: Rewound 46912 bytes.
D: sink.c: Processing rewind...
D: sink-input.c: Have to rewind 46912 bytes on render memblockq.
Comment 4 Lennart Poettering 2008-12-17 22:02:24 UTC 
Timing is broken in the intel8x0 driver.
Comment 5 Kieran Clancy 2008-12-30 04:52:38 UTC 
I am wondering if this has anything to do with suspend/resume... A wild hunch I had was that perhaps pulseaudio is waking up after a resume and going "Oh my, I just missed my timeout by 10000 seconds, I better change my timing parameters" and the new timing parameters are causing random problems and overruns etc. I have no idea if this makes any sense.
Comment 6 Lennart Poettering 2009-03-03 01:44:30 UTC 
I am taking the liberty to mark this as F11Blocker since it makes PA virtually useless on intel8x0 which still is quite  common chipset.
Comment 7 Lennart Poettering 2009-04-02 13:59:06 UTC 
*** Bug 486068 has been marked as a duplicate of this bug. ***
Comment 8 Lennart Poettering 2009-04-02 13:59:45 UTC 
*** Bug 471804 has been marked as a duplicate of this bug. ***
Comment 9 Timothy Grondin 2009-04-03 06:00:11 UTC 
Still having the same problem with todays update. 
Kernel version 2.6.29.1-37.rc1.fc11.i586. 

Same output when running pulseaudio from terminal. 

N: alsa-sink.c: Increasing wakeup watermark to 40.00 ms
E: alsa-util.c: snd_pcm_avail() returned a value that is exceptionally large:
4294956152 bytes (24347823 ms).
E: alsa-util.c: Most likely this is a bug in the ALSA driver 'snd_intel8x0'.
Please report this issue to the ALSA developers.
E: rtpoll.c: Assertion 'usec <= ((pa_usec_t) 1000000ULL)*60ULL*60ULL' failed at
pulsecore/rtpoll.c:548, function pa_rtpoll_set_timer_relative(). Aborting.
Aborted


grep -r 'snd_pcm_avai'  /var/log/ brings:

var/log/messages:Mar 31 17:33:43 localhost pulseaudio[2915]: alsa-util.c:
snd_pcm_avail() returned a value that is exceptionally large: 4294955008 bytes
(24347817 ms).
/var/log/messages:Mar 31 17:56:48 localhost pulseaudio[4259]: alsa-util.c:
snd_pcm_avail() returned a value that is exceptionally large: 4294953908 bytes
(24347811 ms).
/var/log/messages:Mar 31 18:24:37 localhost pulseaudio[19139]: alsa-util.c:
snd_pcm_avail() returned a value that is exceptionally large: 4294953808 bytes
(24347810 ms).
/var/log/messages:Mar 31 20:52:17 localhost pulseaudio[2924]: alsa-util.c:
snd_pcm_avail() returned a value that is exceptionally large: 4294955360 bytes
(24347819 ms).
/var/log/messages:Apr  1 02:08:48 localhost pulseaudio[2850]: alsa-util.c:
snd_pcm_avail() returned a value that is exceptionally large: 937292 bytes
(5313 ms).
/var/log/messages:Apr  1 14:15:24 localhost pulseaudio[2975]: alsa-util.c:
snd_pcm_avail() returned a value that is exceptionally large: 4294966420 bytes
(24347882 ms).
/var/log/messages:Apr  2 00:03:06 localhost pulseaudio[2931]: alsa-util.c:
snd_pcm_avail() returned a value that is exceptionally large: 4294953780 bytes
(24347810 ms).

I still don't have the problem with kernel 2.6.29-0.258.2.3.rc8.git2.fc11.1586. 

Just with the newer kernels.
Comment 10 Timothy Grondin 2009-04-03 06:01:14 UTC 
The tail end of running pulseaudio -vvvv

D: module-hal-detect.c: dbus: interface=org.freedesktop.Hal.Device, path=/org/freedesktop/Hal/devices/computer, member=InterfaceLockReleased
D: module-console-kit.c: dbus: interface=org.freedesktop.Hal.Device, path=/org/freedesktop/Hal/devices/computer, member=InterfaceLockReleased
I: alsa-sink.c: Underrun!
N: alsa-sink.c: Increasing wakeup watermark to 30.00 ms
D: protocol-native.c: Underrun on ''Bring Me to Life' by 'Evanescence'', 0 bytes in queue.
D: protocol-native.c: Requesting rewind due to end of underrun.
D: alsa-sink.c: Requested to rewind 47192 bytes.
D: alsa-sink.c: Limited to 9696 bytes.
D: alsa-sink.c: before: 2424
D: alsa-sink.c: after: 2424
D: alsa-sink.c: Rewound 9696 bytes.
D: sink.c: Processing rewind...
D: sink-input.c: Have to rewind 9696 bytes on render memblockq.
D: source.c: Processing rewind...
D: alsa-sink.c: Wakeup from ALSA!
E: alsa-util.c: snd_pcm_avail() returned a value that is exceptionally large: 4294956560 bytes (24347826 ms).
E: alsa-util.c: Most likely this is a bug in the ALSA driver 'snd_intel8x0'. Please report this issue to the ALSA developers.
D: protocol-native.c: Underrun on ''Bring Me to Life' by 'Evanescence'', 0 bytes in queue.
D: protocol-native.c: Underrun on ''Bring Me to Life' by 'Evanescence'', 0 bytes in queue.
D: protocol-native.c: Underrun on ''Bring Me to Life' by 'Evanescence'', 0 bytes in queue.
D: protocol-native.c: Underrun on ''Bring Me to Life' by 'Evanescence'', 0 bytes in queue.
D: protocol-native.c: Underrun on ''Bring Me to Life' by 'Evanescence'', 0 bytes in queue.
D: protocol-native.c: Underrun on ''Bring Me to Life' by 'Evanescence'', 0 bytes in queue.
D: protocol-native.c: Underrun on ''Bring Me to Life' by 'Evanescence'', 0 bytes in queue.
D: protocol-native.c: Underrun on ''Bring Me to Life' by 'Evanescence'', 0 bytes in queue.
D: protocol-native.c: Underrun on ''Bring Me to Life' by 'Evanescence'', 0 bytes in queue.
D: protocol-native.c: Underrun on ''Bring Me to Life' by 'Evanescence'', 0 bytes in queue.
D: protocol-native.c: Underrun on ''Bring Me to Life' by 'Evanescence'', 0 bytes in queue.
E: rtpoll.c: Assertion 'usec <= ((pa_usec_t) 1000000ULL)*60ULL*60ULL' failed at pulsecore/rtpoll.c:548, function pa_rtpoll_set_timer_relative(). Aborting.
Aborted
Comment 11 Behdad Esfahbod 2009-04-04 17:11:11 UTC 
I also started experiencing this a few days ago.  Definitely F11 blocker.  PA dies every few minutes here.  I wish there was an autostart mechanism at least.
Comment 12 Lennart Poettering 2009-04-05 14:47:05 UTC 
Behdad, actually there is an autospawn logic and it is enabled by default. Doesn't work that for you?
Comment 13 Behdad Esfahbod 2009-04-05 15:52:08 UTC 
(In reply to comment #12)
> Behdad, actually there is an autospawn logic and it is enabled by default.
> Doesn't work that for you?  

No it doesn't.  When it dies there's no pulseaudio running anymore and I have been restarting manually.

Maybe g-s-d do that instead?
Comment 14 Matěj Cepl 2009-04-06 14:13:12 UTC 
(In reply to comment #5)
> I am wondering if this has anything to do with suspend/resume... A wild hunch I
> had was that perhaps pulseaudio is waking up after a resume and going "Oh my, I
> just missed my timeout by 10000 seconds, I better change my timing parameters"
> and the new timing parameters are causing random problems and overruns etc. I
> have no idea if this makes any sense.  

"me too" from me. And now, this is my office workstation, so it has never been suspended.
Comment 15 Lennart Poettering 2009-04-06 14:13:50 UTC 
Behdad, PA is not so much a session daemon but a user daemon. Restarting it from g-s-d is hence not really possible.
Comment 16 Kieran Clancy 2009-04-06 14:41:24 UTC 
I don't know if this changes anything, but I have started to have occasional (though far fewer) problems like this even after uninstalling pulseaudio... Would this problem be unrelated?
Comment 17 Lennart Poettering 2009-04-06 15:01:58 UTC 
The interesting line here is this one:

E: alsa-util.c: snd_pcm_avail() returned a value that is exceptionally large:
4294956152 bytes (24347823 ms).

And this one in the second blurb.

E: alsa-util.c: snd_pcm_avail() returned a value that is exceptionally large:
4294956560 bytes (24347826 ms).

Both logs seem to be done on 32bit. 

Similar to what is described in bug 485734 snd_pcm_avail() appears to overflow here as well. Adjusting the values by INT_MAX seems to fix the results:

2^32-4294956152 is 11144

2^32-4294956560 is 10736

Both values would then make a lot of sense.
Comment 18 Behdad Esfahbod 2009-04-07 20:10:02 UTC 
(In reply to comment #17)
> The interesting line here is this one:
> 
> E: alsa-util.c: snd_pcm_avail() returned a value that is exceptionally large:
> 4294956152 bytes (24347823 ms).
> 
> And this one in the second blurb.
> 
> E: alsa-util.c: snd_pcm_avail() returned a value that is exceptionally large:
> 4294956560 bytes (24347826 ms).
> 
> Both logs seem to be done on 32bit. 
> 
> Similar to what is described in bug 485734 snd_pcm_avail() appears to overflow
> here as well. Adjusting the values by INT_MAX seems to fix the results:
> 
> 2^32-4294956152 is 11144
> 
> 2^32-4294956560 is 10736
> 
> Both values would then make a lot of sense.  

Can we get a fix instead?  Or some word from kernel guys?  This was working perfectly until two weeks ago.  Damn it, sounds is plain unusable.
Comment 19 Timothy Grondin 2009-04-07 21:20:15 UTC 
I'd love to have this fixed but while were waiting is there some kind of temporary workaround we can use to get our sound working again?

Thanks
Comment 20 John Ellson 2009-04-08 21:04:52 UTC 
Re: Comment #19    Removing pulseaudio works for me:

    rpm -e pulseaudio pulseaudio-module-x11 pulseaudio-module-zeroconf pulseaudio-esound-compat pulseaudio-module-lirc pulseaudio-module-jack pulseaudio-module-gconf paprefs pavucontrol pavumeter paman pulseaudio-module-bluetooth  kde-settings-pulseaudio fluxbox-pulseaudio alsa-plugins-pulseaudio


You may need to use alsamixer to adjust the volume.


Just wondering, if this is supposed to be a kernel bug, then why does removing pulseaudio make alsa work?
Comment 21 Timothy Grondin 2009-04-08 21:35:49 UTC 
(In reply to comment #20)
> Re: Comment #19    Removing pulseaudio works for me:
> 
>     rpm -e pulseaudio pulseaudio-module-x11 pulseaudio-module-zeroconf
> pulseaudio-esound-compat pulseaudio-module-lirc pulseaudio-module-jack
> pulseaudio-module-gconf paprefs pavucontrol pavumeter paman
> pulseaudio-module-bluetooth  kde-settings-pulseaudio fluxbox-pulseaudio
> alsa-plugins-pulseaudio
> 
> 
> You may need to use alsamixer to adjust the volume.
> 
> 
> Just wondering, if this is supposed to be a kernel bug, then why does removing
> pulseaudio make alsa work?  


Indeed.

I took out pulseaudio and my sound works fine. Very odd

I guess I'll add pulseaudio to my list of software to remove by default for now. I'm personally amazed this kind of bug can exist in a beta and for so long.
Comment 22 Jaroslav Kysela 2009-04-09 08:20:13 UTC 
Guys, could you reproduce the error with the latest aplay utility (alsa-utils package) from http://www.alsa-project.org/snapshot/ ? alsa-lib-1.0.19 is required (or you may grab latest alsa-lib from snapshot, too).

There is a ring buffer position test now, try this command:

aplay -v -f dat -D plughw:0 -N --test-position --test-coef=2 --test-nowait /dev/zero

Last three values printed on BUFPOS lines should be zero.

Rewind feature is not used in this test.

To Lennart (comment#17): ALSA works internally with frames, so working with value converted to bytes and INT_MAX limit does not make much sense (although I admit the diffs in this context looks suspiciously).
Comment 23 Will Woods 2009-04-09 15:45:02 UTC 
I did a little digging - I think the ridiculous snd_pcm_avail() values come from snd_pcm_mmap_playback_avail():

    snd_pcm_sframes_t avail;
    avail = *pcm->hw.ptr + pcm->buffer_size - *pcm->appl.ptr;
    if (avail < 0)
        avail += pcm->boundary;

On my systems, when the problem occurs, it's because hw.ptr has apparently jumped backward without appl.ptr changing. (is that possible?) 

Here's some data I collected during a failure:

/proc/asound/card0/pcm0p/sub0/sw_params:
tstamp_mode: ENABLE
period_step: 1
avail_min: 16384
start_threshold: 4294967295
stop_threshold: 1073741824
silence_threshold: 0
silence_size: 0
boundary: 1073741824

/proc/asound/card0/pcm0p/sub0/status (snapshot 1): 
state: RUNNING
trigger_time: 17683.691109354
tstamp      : 17727.106580988
delay       : 3034
avail       : 13350
avail_max   : 13350
-----
hw_ptr      : 1982053
appl_ptr    : 1985087

/proc/asound/card0/pcm0p/sub0/status (snapshot 2):
state: RUNNING
trigger_time: 17683.691109354
tstamp      : 17727.117222681
delay       : -1073722892
avail       : 1073739276
avail_max   : 1073739276
-----
hw_ptr      : 1966155
appl_ptr    : 1985087

As you can see, appl_ptr is unchanged but hw_ptr went from 1982053 to 1966155 (backwards??). This causes (hw.ptr+buffer_size - appl.ptr) to be negative (-2548), which triggers the "avail += pcm->boundary;" line, which yields 1073739276 - the avail value shown in the second snapshot.

The associated pulseaudio log is similar to this one:
I: alsa-sink.c: Underrun!
N: alsa-sink.c: Increasing wakeup watermark to 50.00 ms
D: protocol-native.c: Underrun on ''Peacebone' by 'Animal Collective'', 0 bytes in queue.
D: protocol-native.c: Requesting rewind due to end of underrun.
D: alsa-sink.c: Wakeup from ALSA!
E: alsa-util.c: snd_pcm_avail() returned a value that is exceptionally large: 1073737928 (24347798 ms).
E: alsa-util.c: Most likely this is a bug in the ALSA driver 'snd_intel8x0'. Please report this issue to the ALSA developers.

I'm just guessing here, but maybe the rewind moved hw_ptr but failed to move appl_ptr? Or maybe hw_ptr jumped backward due to a hardware error? I don't know what could cause this situation, but there it is.
Comment 24 Will Woods 2009-04-09 15:50:20 UTC 
Re: comment 22: I compiled the new aplay from git, and the ring buffer test command you mentioned has been running for 45 minutes with no errors:

BUFPOS: avg9/16378 min2/0 max16384/16382 (16384) (0:0/0)

But you said this doesn't use rewind, so if rewinding is the cause of the problem, this test wouldn't encounter it.
Comment 25 Jaroslav Kysela 2009-04-09 17:35:02 UTC 
Will, thanks for your input and testing. If hw_ptr goes to backward, it's from the driver. Could you enable xrun_debug and look to dmesg when snd_pcm_avail() problem occurs if there are some messages?

echo 1 > /proc/asound/card0/pcm0p/sub0/xrun_debug
Comment 26 Will Woods 2009-04-09 18:38:43 UTC 
Sadly, no messages appeared. I did:
  echo 1 > /proc/asound/card0/pcm0*/xrun_debug
and triggered the problem, but nothing appears in dmesg.

But in the observed data, the delta between the two hw_ptr values is -2548, which is less than buffer_size. The hw_ptr_error check in snd_pcm_update_hw_ptr{,_interrupt} does:

    if (delta < 0) {
        delta += runtime->buffer_size;
        if (delta < 0) {
            hw_ptr_error(substream,

So it looks like the case I'm seeing might not trigger those debugging messages anyway?
Comment 27 Jaroslav Kysela 2009-04-09 18:46:20 UTC 
Will, could you increase number of used periods from 2 to 8 in PA? It should be parameter "fragment" for alsa_sink. The xrun_debug code should do better checks in this setup.
Comment 28 Will Woods 2009-04-09 20:37:03 UTC 
Successfully produced some error messages.

I had to rebuild pulseaudio to adjust the number of periods used in tsched mode. snd_pcm_dump() data follows:

D: alsa-util.c: snd_pcm_dump():
D: alsa-util.c: Hardware PCM card 0 'Intel 82801DB-ICH4' device 0 subdevice 0
D: alsa-util.c: Its setup is:
D: alsa-util.c:   stream       : PLAYBACK
D: alsa-util.c:   access       : MMAP_INTERLEAVED
D: alsa-util.c:   format       : S16_LE
D: alsa-util.c:   subformat    : STD
D: alsa-util.c:   channels     : 2
D: alsa-util.c:   rate         : 44100
D: alsa-util.c:   exact rate   : 44100 (44100/1)
D: alsa-util.c:   msbits       : 16
D: alsa-util.c:   buffer_size  : 16384
D: alsa-util.c:   period_size  : 2048
D: alsa-util.c:   period_time  : 46439
D: alsa-util.c:   tstamp_mode  : ENABLE
D: alsa-util.c:   period_step  : 1
D: alsa-util.c:   avail_min    : 15502
D: alsa-util.c:   period_event : 0
D: alsa-util.c:   start_threshold  : -1
D: alsa-util.c:   stop_threshold   : 1073741824
D: alsa-util.c:   silence_threshold: 0
D: alsa-util.c:   silence_size : 0
D: alsa-util.c:   boundary     : 1073741824

With this config, pulseaudio no longer dies, but I get a lot of "alsa-sink.c: Wakeup from ALSA!" messages.

dmesg has messages like these:
ALSA sound/core/pcm_lib.c:308: hda_codec: hw_ptr skipping! (pos=8192, delta=14337, period=2048)
ALSA sound/core/pcm_lib.c:308: hda_codec: hw_ptr skipping! (pos=6144, delta=14699, period=2048)
ALSA sound/core/pcm_lib.c:308: hda_codec: hw_ptr skipping! (pos=2048, delta=14337, period=2048)
[~140 similar lines cut]
ALSA sound/core/pcm_lib.c:308: hda_codec: hw_ptr skipping! (pos=14336, delta=14337, period=2048)
ALSA sound/core/pcm_lib.c:308: hda_codec: hw_ptr skipping! (pos=0, delta=14337, period=2048)
ALSA sound/core/pcm_lib.c:308: hda_codec: hw_ptr skipping! (pos=8192, delta=14367, period=2048)
ALSA sound/core/pcm_lib.c:308: hda_codec: hw_ptr skipping! (pos=8193, delta=14368, period=2048)

Does that help at all?
Comment 29 Lennart Poettering 2009-04-09 23:43:58 UTC 
*** Bug 495007 has been marked as a duplicate of this bug. ***
Comment 30 Matthew C 2009-04-10 06:52:13 UTC 
Hello.  I am using rawhide as of 4/9/2009 with a custom compiled kernel, version 2.6.29.1.  The customization was to enable the staging driver et131x.  It is kind of hard to keep up with rawhide without a network driver :-)  I also turned some debugging options off that came with the source kernel.

It appears that I use the same driver, although my hardware is a "82801G (ICH7 Family)" instead of a "82801EB/ER (ICH5/ICH5R)"

# lspci -v
00:1e.2 Multimedia audio controller: Intel Corporation 82801G (ICH7 Family) AC'97 Audio Controller (rev 02)
        Subsystem: Device 414c:4760
        Flags: bus master, medium devsel, latency 0, IRQ 17
        I/O ports at f000 [size=256]
        I/O ports at fa00 [size=64]
        Memory at fdffe000 (32-bit, non-prefetchable) [size=512]
        Memory at fdffd000 (32-bit, non-prefetchable) [size=256]
        Capabilities: [50] Power Management version 2
        Kernel driver in use: Intel ICH
        Kernel modules: snd-intel8x0

I also added the following lines to /etc/pulse/default.pa because I use the
S/PDIF output instead of the analogue output:
load-module module-alsa-sink device=hw:0,4 sink_name=iec958_output
set-default-sink iec958_output

$ pulseaudio --log-target=stderr 2> pulse.log
I: caps.c: Limited capabilities successfully to CAP_SYS_NICE.
I: caps.c: Dropping root privileges.
I: caps.c: Limited capabilities successfully to CAP_SYS_NICE.
W: pid.c: Stale PID file, overwriting.
N: alsa-sink.c: Increasing wakeup watermark to 30.00 ms
E: alsa-util.c: snd_pcm_avail() returned a value that is exceptionally large: 4294937348 bytes (22369465 ms).
E: alsa-util.c: Most likely this is a bug in the ALSA driver 'snd_intel8x0'. Please report this issue to the ALSA developers.
E: alsa-util.c: snd_pcm_delay() returned a value that is exceptionally large: 496944 bytes (2588 ms).
E: alsa-util.c: Most likely this is a bug in the ALSA driver 'snd_intel8x0'. Please report this issue to the ALSA developers.
E: rtpoll.c: Assertion 'usec <= ((pa_usec_t) 1000000ULL)*60ULL*60ULL' failed at pulsecore/rtpoll.c:548, function pa_rtpoll_set_timer_relative(). Aborting.


This is the hardware that I am using:
https://logisysus.com/catalog/product_info.php?products_id=530
Comment 31 Matthew C 2009-04-10 08:52:12 UTC 
I applied this patch (a selected change that looked promising from ftp://ftp.alsa-project.org/pub/driver/alsa-driver-1.0.19.tar.bz2) to ~/rpmbuild/BUILD/kernel-2.6.29/linux-2.6.29.i586/sound/pci/intel8x0.c and I still get the same behaviour.
@@ -617,7 +617,7 @@ static int snd_intel8x0_ali_codec_semaphore(struct intel8x0 *chip)
int time = 100;
if (chip->buggy_semaphore)
return 0; /* just ignore ... */
- while (time-- && (igetdword(chip, ICHREG(ALI_CAS)) & ALI_CAS_SEM_BUSY))
+ while (--time && (igetdword(chip, ICHREG(ALI_CAS)) & ALI_CAS_SEM_BUSY))
udelay(1);
if (! time && ! chip->in_ac97_init)
snd_printk(KERN_WARNING "ali_codec_semaphore timeout\n");
diff --git a/sound/soc/atmel/atmel_ssc_dai.c b/sound/soc/atmel/atmel_ssc_dai.c
index c5d6790..ff0054b 100644
Comment 32 Jaroslav Kysela 2009-04-10 10:54:09 UTC 
Please, could you test this kernel patch with your hw?

http://git.alsa-project.org/?p=alsa-kernel.git;a=commitdiff;h=bbf6ad1399e9516b0a95de3ad58ffbaed670e4cc

Also, enable xrun_debug code to see what happens with the ring buffer position returned from the intel8x0 driver:

echo 1 > /proc/asound/card0/pcm0p/xrun_debug
echo 1 > /proc/asound/card0/pcm0c/xrun_debug

or for all PCM devices:

for i in `find /proc/asound/card0 -name xrun_debug` ; do echo 1 > $i; done

Look to /var/log/messages or use dmesg to see kernel messages.
Comment 34 Will Woods 2009-04-10 22:19:14 UTC 
Applied the patch and rebuilt my kernel; pulseaudio now dies at startup. The following messages appear in dmesg:

ALSA sound/core/pcm_lib.c:337: hda_codec: hw_ptr skipping! (pos=16034, delta=9398, period=16384, jdelta=201/213)
ALSA sound/core/pcm_lib.c:263: hda_codec: hw_ptr skipping! [Q] (pos=0, delta=9748, period=16384, jdelta=209/221/0)
ALSA sound/core/pcm_lib.c:337: hda_codec: hw_ptr skipping! (pos=16360, delta=10746, period=16384, jdelta=230/243)
ALSA sound/core/pcm_lib.c:337: hda_codec: hw_ptr skipping! (pos=16361, delta=10747, period=16384, jdelta=230/243)
ALSA sound/core/pcm_lib.c:337: hda_codec: hw_ptr skipping! (pos=16361, delta=10747, period=16384, jdelta=230/243)
ALSA sound/core/pcm_lib.c:263: hda_codec: hw_ptr skipping! [Q] (pos=0, delta=10770, period=16384, jdelta=230/244/0)
ALSA sound/core/pcm_lib.c:337: hda_codec: hw_ptr skipping! (pos=16042, delta=9520, period=16384, jdelta=204/215)
ALSA sound/core/pcm_lib.c:337: hda_codec: hw_ptr skipping! (pos=16261, delta=10746, period=16384, jdelta=230/243)
ALSA sound/core/pcm_lib.c:337: hda_codec: hw_ptr skipping! (pos=16261, delta=10746, period=16384, jdelta=230/243)
ALSA sound/core/pcm_lib.c:337: hda_codec: hw_ptr skipping! (pos=16262, delta=10747, period=16384, jdelta=230/243)
ALSA sound/core/pcm_lib.c:263: hda_codec: hw_ptr skipping! [Q] (pos=0, delta=9862, period=16384, jdelta=211/223/0)
ALSA sound/core/pcm_lib.c:263: hda_codec: hw_ptr skipping! [Q] (pos=0, delta=10869, period=16384, jdelta=232/246/0)

kernel-2.6.29.1-66.ww1.i586 (-66 + the requested patch)
pulseaudio-0.9.15-9.test8.fc11.i586
Comment 35 Jaroslav Kysela 2009-04-10 23:21:57 UTC 
Will, the timing from your card is very inaccurate (differs from the jiffies clock by about 5% - it's expected to be in 1%).

Please, try:

a) set ac97_clock parameter for snd-intel8x0 module to 45200 (calculated from max 
   jdelta values - 48000/(246/232) - assuming that you are running with 48000
   ac97_clock now - look to "intel8x0: clocking to" messages and correct value
   in expression if measured value differs
b) if a) does not work - try replace HZ/100 expression in patch with HZ/20
c) if b) does not work - try set .periods_min in sound/pci/intel8x0.c to 2
Comment 36 Andrew Jamison 2009-04-11 01:30:28 UTC 
I am not sure of the technical details involved here so please when replying to this if you need to be as simplistic as possible i am new to this stuff anyway Pulseaudio crashed on me after the most recent update i was told this was due to the error found by this bug here is the error output from running pulseaudio verbosely

E: alsa-util.c: snd_pcm_avail() returned a value that is exceptionally large: 4293875052 bytes (8113898 ms).
E: alsa-util.c: Most likely this is a bug in the ALSA driver 'snd_intel8x0'. Please report this issue to the ALSA developers.
E: alsa-util.c: snd_pcm_dump():
E: alsa-util.c: Hooks PCM
E: alsa-util.c: Its setup is:
E: alsa-util.c:   stream       : PLAYBACK
E: alsa-util.c:   access       : MMAP_INTERLEAVED
E: alsa-util.c:   format       : S16_LE
E: alsa-util.c:   subformat    : STD
E: alsa-util.c:   channels     : 6
E: alsa-util.c:   rate         : 44100
E: alsa-util.c:   exact rate   : 44100 (44100/1)
E: alsa-util.c:   msbits       : 16
E: alsa-util.c:   buffer_size  : 5461
E: alsa-util.c:   period_size  : 5461
E: alsa-util.c:   period_time  : 123832
E: alsa-util.c:   tstamp_mode  : ENABLE
E: alsa-util.c:   period_step  : 1
E: alsa-util.c:   avail_min    : 5461
E: alsa-util.c:   period_event : 0
E: alsa-util.c:   start_threshold  : -1
E: alsa-util.c:   stop_threshold   : 1431568384
E: alsa-util.c:   silence_threshold: 0
E: alsa-util.c:   silence_size : 0
E: alsa-util.c:   boundary     : 1431568384
E: alsa-util.c: Slave: Hardware PCM card 3 'Intel ICH5' device 0 subdevice 0
E: alsa-util.c: Its setup is:
E: alsa-util.c:   stream       : PLAYBACK
E: alsa-util.c:   access       : MMAP_INTERLEAVED
E: alsa-util.c:   format       : S16_LE
E: alsa-util.c:   subformat    : STD
E: alsa-util.c:   channels     : 6
E: alsa-util.c:   rate         : 44100
E: alsa-util.c:   exact rate   : 44100 (44100/1)
E: alsa-util.c:   msbits       : 16
E: alsa-util.c:   buffer_size  : 5461
E: alsa-util.c:   period_size  : 5461
E: alsa-util.c:   period_time  : 123832
E: alsa-util.c:   tstamp_mode  : ENABLE
E: alsa-util.c:   period_step  : 1
E: alsa-util.c:   avail_min    : 5461
E: alsa-util.c:   period_event : 0
E: alsa-util.c:   start_threshold  : -1
E: alsa-util.c:   stop_threshold   : 1431568384
E: alsa-util.c:   silence_threshold: 0
E: alsa-util.c:   silence_size : 0
E: alsa-util.c:   boundary     : 1431568384
D: protocol-native.c: Underrun on 'Playback Stream', 0 bytes in queue.
E: alsa-util.c: snd_pcm_delay() returned a value that is exceptionally large: 1629448 bytes (3079 ms).
E: alsa-util.c: Most likely this is a bug in the ALSA driver 'snd_intel8x0'. Please report this issue to the ALSA developers.
E: alsa-util.c: snd_pcm_dump():
E: alsa-util.c: Hooks PCM
E: alsa-util.c: Its setup is:
E: alsa-util.c:   stream       : PLAYBACK
E: alsa-util.c:   access       : MMAP_INTERLEAVED
E: alsa-util.c:   format       : S16_LE
E: alsa-util.c:   subformat    : STD
E: alsa-util.c:   channels     : 6
E: alsa-util.c:   rate         : 44100
E: alsa-util.c:   exact rate   : 44100 (44100/1)
E: alsa-util.c:   msbits       : 16
E: alsa-util.c:   buffer_size  : 5461
E: alsa-util.c:   period_size  : 5461
E: alsa-util.c:   period_time  : 123832
E: alsa-util.c:   tstamp_mode  : ENABLE
E: alsa-util.c:   period_step  : 1
E: alsa-util.c:   avail_min    : 5461
E: alsa-util.c:   period_event : 0
E: alsa-util.c:   start_threshold  : -1
E: alsa-util.c:   stop_threshold   : 1431568384
E: alsa-util.c:   silence_threshold: 0
E: alsa-util.c:   silence_size : 0
E: alsa-util.c:   boundary     : 1431568384
E: alsa-util.c: Slave: Hardware PCM card 3 'Intel ICH5' device 0 subdevice 0
E: alsa-util.c: Its setup is:
E: alsa-util.c:   stream       : PLAYBACK
E: alsa-util.c:   access       : MMAP_INTERLEAVED
E: alsa-util.c:   format       : S16_LE
E: alsa-util.c:   subformat    : STD
E: alsa-util.c:   channels     : 6
E: alsa-util.c:   rate         : 44100
E: alsa-util.c:   exact rate   : 44100 (44100/1)
E: alsa-util.c:   msbits       : 16
E: alsa-util.c:   buffer_size  : 5461
E: alsa-util.c:   period_size  : 5461
E: alsa-util.c:   period_time  : 123832
E: alsa-util.c:   tstamp_mode  : ENABLE
E: alsa-util.c:   period_step  : 1
E: alsa-util.c:   avail_min    : 5461
E: alsa-util.c:   period_event : 0
E: alsa-util.c:   start_threshold  : -1
E: alsa-util.c:   stop_threshold   : 1431568384
E: alsa-util.c:   silence_threshold: 0
E: alsa-util.c:   silence_size : 0
E: alsa-util.c:   boundary     : 1431568384
E: rtpoll.c: Assertion 'usec <= ((pa_usec_t) 1000000ULL)*60ULL*60ULL' failed at pulsecore/rtpoll.c:548, function pa_rtpoll_set_timer_relative(). Aborting.
Aborted
Comment 37 Will Woods 2009-04-11 04:53:34 UTC 
Jaroslav - You're absolutely right about the timing of my card. For some reason the clock is way off. Normally it's 48000, but for some reason recently it's been clocking to ~50000, as it did with bug 441087:

intel8x0_measure_ac97_clock: measured 50916 usecs
intel8x0: clocking to 50872

50872/(246/232) = 47977, which is less than 0.1% difference from 48000.

So now the question is: why is the clock measurement wrong (again)? Does this just require an updated hardware quirk or something?
Comment 38 Luckis P 2009-04-11 19:51:11 UTC 
Bad news for me, now pulseaudio and alsa are not just displaying the usual errors:

"  E: alsa-util.c: snd_pcm_avail() returned a value that is exceptionally large:
4293875052 bytes (8113898 ms).
E: alsa-util.c: Most likely this is a bug in the ALSA driver 'snd_intel8x0'.
Please report this issue to the ALSA developers. "
(...)

i now have a new-(i think) entry, now when i start pulseaudio i get this :

"  W: alsa-source.c: Your kernel driver is broken: it reports a volume range from 18.00 dB to 18.00 dB which makes no sense."

Is there anything i can do about that or is it a minor thing? How can i have a broken kernel driver and sound working at the same time??
Comment 39 Lennart Poettering 2009-04-12 02:16:50 UTC 
*** Bug 492698 has been marked as a duplicate of this bug. ***
Comment 40 Lennart Poettering 2009-04-12 02:18:13 UTC 
*** Bug 495301 has been marked as a duplicate of this bug. ***
Comment 41 Luckis P 2009-04-12 12:14:02 UTC 
Ok it seems that the "kernel driver broken" message is related to the bug 469416. Don't mind the irrelevant comment earlier. 
Is there any patch or workaround for this PA/ALSA issue described here? 
 pulseaudio 0.9.15-test8
Card : Intel 82801DB-ICH4        Chip : Analog Devices AD1981B
00:1f.5 Multimedia audio controller: Intel Corporation 82801DB/DBL/DBM (ICH4/ICH4-L/ICH4-M) AC'97 Audio Controller (rev 02)
Comment 42 Jaroslav Kysela 2009-04-13 07:09:01 UTC 
Luckis: Please, attach output from 'alsa-info.sh --no-upload' to bug#469416.

Will: Could you test my patch in comment#32 with 'ac97_clock=48000' parameter for snd-intel8x0 module? I'll try to give a look to clock measuring problem later.
Comment 43 Lennart Poettering 2009-04-13 14:55:42 UTC 
*** Bug 495462 has been marked as a duplicate of this bug. ***
Comment 44 Will Woods 2009-04-13 17:06:29 UTC 
Jaroslav: I've finally managed to confirm that - ignoring volume-setting issues covered elsewhere - audio *works as expected* with your patch from comment #32 and a correct ac97_clock setting.

I set ac97_clock by putting:
  options snd_intel8x0 ac97_clock=48000
in /etc/modprobe.conf.

As with bug 485734, there are occasional messages in dmesg with xrun_debug on:
ALSA sound/core/pcm_lib.c:337: hda_codec: hw_ptr skipping! (pos=8192, delta=8976, period=16384, jdelta=18/203)
ALSA sound/core/pcm_lib.c:337: hda_codec: hw_ptr skipping! (pos=0, delta=8630, period=16384, jdelta=10/195)
ALSA sound/core/pcm_lib.c:337: hda_codec: hw_ptr skipping! (pos=8192, delta=8193, period=16384, jdelta=0/185)
ALSA sound/core/pcm_lib.c:337: hda_codec: hw_ptr skipping! (pos=0, delta=8193, period=16384, jdelta=0/185)
ALSA sound/core/pcm_lib.c:337: hda_codec: hw_ptr skipping! (pos=8192, delta=8193, period=16384, jdelta=0/185)
ALSA sound/core/pcm_lib.c:337: hda_codec: hw_ptr skipping! (pos=8192, delta=8193, period=16384, jdelta=0/185)
ALSA sound/core/pcm_lib.c:337: hda_codec: hw_ptr skipping! (pos=0, delta=8193, period=16384, jdelta=0/185)
ALSA sound/core/pcm_lib.c:337: hda_codec: hw_ptr skipping! (pos=0, delta=8193, period=16384, jdelta=0/185)
But there's no skipping and pulseaudio no longer dies - in fact it works better than it has since F9 or so.

Assuming your approval, I'm going to recommend the kernel team apply that patch immediately. 

Should we backport the hda fix from alsa-kernel (commit fa00e046) as well? I haven't tested that one at all.
Comment 45 Will Woods 2009-04-13 18:48:46 UTC 
The patch from comment #32 (and others from alsa-kernel) will be in kernel-2.6.29.1-70, which should appear in tomorrow's rawhide. Can the reporter(s) in this bug please update to at least these package versions:
  pulseaudio-0.9.15-9.test8.fc11
  kernel-2.6.29.1-70.fc11
and retest? 

If you have problems, check to see if your system is having problems measuring the ac97 clock. Check the output of 'dmesg | grep intel8x0' for a line like:
  intel8x0: clocking to 51810
the value should be something like 48000 or 44100 - if it's not, try setting ac97_clock to a more appropriate value as mentioned in comment #44, and see if that helps. 

We'll open another bug for the clock measuring problem(s) shortly.
Comment 46 Jaroslav Kysela 2009-04-13 19:52:21 UTC 
Will, thanks for your testing. I see only one possible problem - the checks to verify the DMA position values might be too strict, The code in patch assumes that the difference of soundcards's clock from the system jiffies clock is max. about 1%. I am not sure if difference of clock is not bigger for some sound hardware - although it's certainly possible bug in the lowlevel driver to not pass correct sample rate value to higher level.

Also, your messages shows that the snd-intel8x0 has problems to read correct ring buffer positions. I prepared two patches:

An attempt to fix measure routine in snd-intel8x0:

http://git.alsa-project.org/?p=alsa-kernel.git;a=commitdiff;h=920e4ae31cb113328e617f4a0663fb17d7b09124

An attempt to fix bad ring buffer position values in snd-intel8x0:

http://git.alsa-project.org/?p=alsa-kernel.git;a=commit;h=da2436a23c038055b1da6fe30b6ea2886b1e07b0

Please, try both patches and report if:

a) automatic clock measuring (without setting of ac97_clock module parameter) is OK (or attach messages, please)
b) if hw_ptr skipping messages go completely away

Regarding commmit fa00e046 for snd-hda-intel: I tested it on my machine and it works well for me (it eliminates hw_ptr skipping messages for snd-hda-intel as da2436a23 for snd-intel8x0).
Comment 47 Will Woods 2009-04-13 23:05:13 UTC 
Jaroslav - I applied those two patches and tested on intel8x0 and intel-hda. Results are as follows:

a) automatic clock measuring
I now get a *different* wrong value for ac97_clock:
  intel8x0_measure_ac97_clock: measured 51179 usecs (2364 samples)
  intel8x0: clocking to 41000
I'm almost certain it should be 48000; at 41000 (or 44000/44100) everything sounds sloooow. As a note, there's also this in dmesg:
  * The chipset may have PM-Timer Bug. Due to workarounds for a bug,
  * this clock source is slow. If you are sure your timer does not have
  * this bug, please use "acpi_pm_good" to disable the workaround
Could this cause problems with the clock measuring code?

b) hw_ptr skipping messages 
These appear to be gone completely. Hooray!
Comment 51 Jaroslav Kysela 2009-04-14 20:48:58 UTC 
It seems that patch 920e4a from comment #46 introduced another problem. The fix is in this patch:

http://git.alsa-project.org/?p=alsa-kernel.git;a=commitdiff;h=29dab4fd3176e25dfab6cd763beb02d87973c288
Comment 53 Jaroslav Kysela 2009-04-15 08:24:29 UTC 
Please, ignore comment #52.

And the patch bellow might fix the issue with "measured clock # rejected"
problem. Please, confirm.

http://git.alsa-project.org/?p=alsa-kernel.git;a=commitdiff;h=2ec775e7053c82bc90858ede011b35aeb416995b
Comment 54 Matthew C 2009-04-15 11:23:07 UTC 
I am using rawhide, kernel-2.6.29.1-70.fc11.src.rpm, and configs/kernel-2.6.29.1-i686-PAE.config.  I enabled Staging drivers / Agere ET-1310 Gigabit Ethernet support for network access.  I kind of cheated and skipped applying patches and went to the current source for sound/pci/intel8x0.c at git.alsa-project:
http://git.alsa-project.org/?p=alsa-kernel.git;a=blob_plain;f=sound/pci/intel8x0.c;hb=2ec775e7053c82bc90858ede011b35aeb416995b

Although I had to replace:
	err = snd_card_create(index, id, THIS_MODULE, 0, &card);
	if (err < 0)
		return err;

with:
	card = snd_card_new(index, id, THIS_MODULE, 0);
	if (card == NULL)
		return -ENOMEM;

Before, Flash videos would last 30-120 seconds before crashing.  I have been watching a single Flash video for over 20 minutes.  Amarok also works at the same time.

From /var/log/dmesg:
Intel ICH 0000:00:1e.2: PCI INT A -> GSI 17 (level, low) -> IRQ 17
Intel ICH 0000:00:1e.2: setting latency timer to 64
intel8x0_measure_ac97_clock: measured 50518 usecs (2435 samples)
intel8x0: clocking to 48000
Comment 55 Jared Smith 2009-04-15 15:35:23 UTC 
I'm using the 2.6.29.1-70 kernel directly from rawhide (no patches, etc.) and sounds is once again working well.
Comment 56 Lennart Poettering 2009-04-15 17:05:11 UTC 
*** Bug 495846 has been marked as a duplicate of this bug. ***
Comment 57 Will Woods 2009-04-15 17:26:55 UTC 
Marking as MODIFIED, since there are patches for the greater part of this issue. If you continue to have this problem with rawhide kernels newer than -70, please check the ac97 clock detection (from /var/log/dmesg).

The patches from comment #51 and comment #53 address that issue; I'm building a kernel locally to test those now.
Comment 58 Kieran Clancy 2009-04-15 21:11:14 UTC 
As the original reporter, I have been a bit puzzled by all the activity surrounding this bug recently. I assume that something got broken in rawhide?

Is this problem with rawhide likely to be related to my original problem? If so, is it possible that any of these fixes can be back-ported to F10?

Thanks.
Comment 59 Will Woods 2009-04-15 21:30:39 UTC 
Kieran: Yes, the problem from F10 worsened in rawhide - and pulseaudio started handling it differently, and crashing as a result. As far as I can tell it's the same problem, though. Backporting the fixes to F10 may be possible, but first we have to be sure it's actually fixed.

As for comment #57: the build finished, I installed the kernel and power-cycled the machine.. and its motherboard died. Dang! 

I've continued testing with another intel8x0 machine.

No pulseaudio crashes so far, although I do have these messages:
[wwoods@zebes ~]$ dmesg | egrep -i 'alsa|intel8x0|clock'
hpet clockevent registered
ALSA sound/pci/ac97/ac97_codec.c:2159: MC'97 1 converters and GPIO not ready (0xff00)
ALSA sound/pci/ac97/ac97_codec.c:2127: AC'97 0 analog subsections not ready
intel8x0_measure_ac97_clock: measured 50914 usecs (11 samples)
intel8x0: measured clock 216 rejected
intel8x0_measure_ac97_clock: measured 50935 usecs (11 samples)
intel8x0: measured clock 215 rejected
Clocksource tsc unstable (delta = -269258325 ns)
ALSA sound/core/pcm_lib.c:337: hda_codec: hw_ptr skipping! (pos=8192, delta=8194, period=16384, jdelta=0/185)
ALSA sound/core/pcm_lib.c:337: hda_codec: hw_ptr skipping! (pos=8192, delta=8194, period=16384, jdelta=0/185)
ALSA sound/core/pcm_lib.c:337: hda_codec: hw_ptr skipping! (pos=0, delta=8193, period=16384, jdelta=0/185)
ALSA sound/core/pcm_lib.c:337: hda_codec: hw_ptr skipping! (pos=0, delta=8193, period=16384, jdelta=0/185)
ALSA sound/core/pcm_lib.c:337: hda_codec: hw_ptr skipping! (pos=8192, delta=8193, period=16384, jdelta=0/185)
ALSA sound/core/pcm_lib.c:337: hda_codec: hw_ptr skipping! (pos=8192, delta=8193, period=16384, jdelta=0/185)
ALSA sound/core/pcm_lib.c:337: hda_codec: hw_ptr skipping! (pos=0, delta=8194, period=16384, jdelta=0/185)
ALSA sound/core/pcm_lib.c:337: hda_codec: hw_ptr skipping! (pos=8192, delta=8193, period=16384, jdelta=0/185)
ALSA sound/core/pcm_lib.c:337: hda_codec: hw_ptr skipping! (pos=8192, delta=8193, period=16384, jdelta=0/185)

I've definitely got the right kernel bits - note the retry of intel8x0_measure_ac97_clock, from the patch in comment #53.

One strange thing I noticed - I've seen negative values for delay in /proc/asound/card0/pcm0p/sub0/status, and avail_max always seems to equal avail - even if avail drops, avail_max drops with it. Is that correct?
Comment 60 Matthew C 2009-04-15 21:48:08 UTC 
Comment #59,

My pcm0p reports closed, but pcm4p reports something.  This is probably because I use the S/PDIF / IEC958 digital output on hw:0,4.  I took the following samples about 60 seconds apart while listing to a an online mp3 stream from VLC.  VLC is sending the sound to Pulseaudio and Pulseaudio is sending the sound to ALSA at hw:0,4.

date;cat /proc/asound/card0/pcm4p/sub0/status
Wed Apr 15 17:44:36 EDT 2009
state: RUNNING
trigger_time: 36809.396907883
tstamp      : 39258.655934275
delay       : 5008
avail       : 11376
avail_max   : 11376
-----
hw_ptr      : 117577400
appl_ptr    : 117582408

$ date;cat /proc/asound/card0/pcm4p/sub0/status
Wed Apr 15 17:45:36 EDT 2009
state: RUNNING
trigger_time: 36809.396907883
tstamp      : 39318.363625875
delay       : 4689
avail       : 11695
avail_max   : 11695
-----
hw_ptr      : 120443685
appl_ptr    : 120448374
Comment 61 Will Woods 2009-04-15 21:51:16 UTC 
(In reply to comment #58)
> Is this problem with rawhide likely to be related to my original problem? If
> so, is it possible that any of these fixes can be back-ported to F10?

I've been informed that the first set of patches here (see comment #32) have gone into the new F10 kernel in updates-testing:
  * Mon Apr 13 2009 Chuck Ebbert <cebbert> 2.6.29.1-22
  - Copy ALSA pulseaudio fixes from F-11. 
See https://admin.fedoraproject.org/updates/F10/FEDORA-2009-3685

F10 users, please update to kernel-2.6.29.1-30.fc10 and retest.
Comment 62 Will Woods 2009-04-16 18:29:50 UTC 
I've created bug 496119 to track problems measuring ac97_clock on intel8x0.

Anyone who has experienced the snd_pcm_avail() overflow (and associated PulseAudio crashes) on intel8x0 sound hardware, please update your kernel:
  F11: kernel-2.6.29.1-70.fc11 or newer
  F10: kernel-2.6.29.1-30.fc10 or newer
and retest. I haven't been able to reproduce the snd_pcm_avail() problem while using these kernels. 

Unless someone else can reproduce the problem I think this bug may be fixed. Kieran, as the original reporter, I'd especially like your input here.
Comment 63 Kieran Clancy 2009-04-19 00:54:41 UTC 
Unfortunately, I was able to reproduce the bug with 2.6.29.1-30.

There were no messages in the log from pulseaudio -vvvv about snd_pcm_avail() - so maybe that part is fixed, but about 10 seconds after the audio froze, pulseaudio decided to print about 5000 lines of:
"D: protocol-native.c: Requesting rewind due to end of underrun."

Unfortunately these lines filled up my terminal buffer so I couldn't save the messages before that (though they were nothing out of the ordinary from what I could see). I will try to reproduce it again while logging to a file this time.
Comment 64 Lennart Poettering 2009-04-19 21:28:58 UTC 
Kieran, this is unrelated. This bug is purely about ALSA's snd_pcm_avail() not working.

The 'Requesting rewind messages' happen when the app does not fulfil the latency requirements and sends PA the requested PCM data too late. If the data form the apps reach PA too late it will try to fix up the audio data it already wrote to the audio device unless it has already been played.

Again, this is completely unrelated to the bug report here.
Comment 65 Kieran Clancy 2009-04-20 10:44:08 UTC 
Okay, well anyway the snd_pcm_avail() messages seem to be gone - so I guess that bit must be fixed.

I have opened bug 496608 to track my other problem.
Comment 66 Juan Quintela 2009-04-22 01:35:55 UTC 
I have this problem here:
alsa-plugins-pulseaudio-1.0.18-3.fc11.i586
kernel-2.6.29.1-100.fc11.i586
pulseaudio-0.9.15-10.fc11.i586

I have never had sound from internal audio on rawhide.  Notice that if I plug an usb headset, I can move the audio streams to the USB headset, and sound works as expected.

I can see when using internal audio that pavumeter and pavucontrol sees the audio stream, but I never had sound output.

removing pulseaudio and friends (as in previous command) don't fix the problem for me, still no sound.
Comment 67 Lennart Poettering 2009-04-22 11:13:58 UTC 
Juan, this is completely unrelated. Please don't hijack bugs like this. Try 'alsamixer -c0' or suchlike and play around with your mixer. Your problem is probably just a mixer initialization issue.

Jaroslav, I think it would be best to close this bug, as everything seems to be fixed!
Comment 68 Jaroslav Kysela 2009-04-22 12:25:19 UTC 
Closing the bug. Create new bug for other problems.
Comment 69 Nick 2009-07-29 01:36:10 UTC 
I hate to revive this bug..

This afternoon, I was listening to an mp3 radio stream in Amarok.  I started noticing what occasionally sounded like vinyl crackle over my headphones.

Initially, I figured someone moved the needle on the record (it was a live d'n'b station after all).  But it happened repeatedly, and on different streams.

OK, amarok 2 is buggy, tried mplayer.  Same malfunction!  I should note that pulseaudio's process spiked to 100% at the time I noticed the sound degradation. 

killed pulseaudio, then told mplayer to use the card's alsa driver directly:

$ mplayer -ao alsa:device=hw=0 <stream> 

and it played fine.  

I restarted pulseaudio, and I've been fine since, but again, I don't know what triggered the issue.

I've only seen this on my Thinkpad T40 which in fact uses snd_intel8x0, and I do suspend it to RAM regularly (2x a day usually).

I'm up to date via yum as of this posting, and I'll attach a log with the Alsa output errors, which include the snd_pcm_avail() errors mentioned in this bug.

I'm running Kernel 2.6.29.6-213.fc11.i586.
Comment 70 Nick 2009-07-29 01:38:17 UTC 
Created attachment 355479 [details]
/var/log/messages ouput when I noticed sound start stuttering
Comment 71 Nick 2009-07-29 01:40:05 UTC 
lspci -v output:

00:1f.5 Multimedia audio controller: Intel Corporation 82801DB/DBL/DBM (ICH4/ICH4-L/ICH4-M) AC'97 Audio Controller (rev 01)
        Subsystem: IBM ThinkPad T41
        Flags: bus master, medium devsel, latency 0, IRQ 5
        I/O ports at 1c00 [size=256]
        I/O ports at 18c0 [size=64]
        Memory at c0000c00 (32-bit, non-prefetchable) [size=512]
        Memory at c0000800 (32-bit, non-prefetchable) [size=256]
        Capabilities: <access denied>
        Kernel driver in use: Intel ICH
        Kernel modules: snd-intel8x0
Comment 72 Lubomir Rintel 2009-07-29 06:14:47 UTC 
Nick: I believe your problem is bug #506075
Comment 73 Nick 2009-07-29 18:34:53 UTC 
Lubomir: I believe you're right.  For some reason, my search didn't show that one.  

What's the ettiquette on cross-posting from one bug to another?
Comment 74 Keith 2009-08-16 04:14:17 UTC 
I'm running kernel version:

$ uname -r
2.6.29.6-217.2.7.fc11.i586

and am still seeing this bug.  Relevant portion of /var/log/messages:

Aug 15 22:50:42 localhost pulseaudio[2119]: alsa-sink.c: Increasing wakeup watermark to 40.00 ms
Aug 15 22:50:42 localhost pulseaudio[2119]: alsa-util.c: snd_pcm_avail() returned a value that is exceptionally large: 4294956108 bytes (24347823 ms).
Aug 15 22:50:42 localhost pulseaudio[2119]: alsa-util.c: Most likely this is a bug in the ALSA driver 'snd_intel8x0'. Please report this issue to the ALSA developers.
Aug 15 22:50:42 localhost pulseaudio[2119]: alsa-util.c: snd_pcm_dump():
Aug 15 22:50:42 localhost pulseaudio[2119]: alsa-util.c: Hardware PCM card 0 'Intel ICH6' device 0 subdevice 0
Aug 15 22:50:42 localhost pulseaudio[2119]: alsa-util.c: Its setup is:
Aug 15 22:50:42 localhost pulseaudio[2119]: alsa-util.c:   stream       : PLAYBACK
Aug 15 22:50:42 localhost pulseaudio[2119]: alsa-util.c:   access       : MMAP_INTERLEAVED
Aug 15 22:50:42 localhost pulseaudio[2119]: alsa-util.c:   format       : S16_LE
Aug 15 22:50:42 localhost pulseaudio[2119]: alsa-util.c:   subformat    : STD
Aug 15 22:50:42 localhost pulseaudio[2119]: alsa-util.c:   channels     : 2
Aug 15 22:50:42 localhost pulseaudio[2119]: alsa-util.c:   rate         : 44100
Aug 15 22:50:42 localhost pulseaudio[2119]: alsa-util.c:   exact rate   : 44100 (44100/1)
Aug 15 22:50:42 localhost pulseaudio[2119]: alsa-util.c:   msbits       : 16
Aug 15 22:50:42 localhost pulseaudio[2119]: alsa-util.c:   buffer_size  : 16384
Aug 15 22:50:42 localhost pulseaudio[2119]: alsa-util.c:   period_size  : 16384
Aug 15 22:50:42 localhost pulseaudio[2119]: alsa-util.c:   period_time  : 371519
Aug 15 22:50:42 localhost pulseaudio[2119]: alsa-util.c:   tstamp_mode  : ENABLE
Aug 15 22:50:42 localhost pulseaudio[2119]: alsa-util.c:   period_step  : 1
Aug 15 22:50:42 localhost pulseaudio[2119]: alsa-util.c:   avail_min    : 16384
Aug 15 22:50:42 localhost pulseaudio[2119]: alsa-util.c:   period_event : 0
Aug 15 22:50:42 localhost pulseaudio[2119]: alsa-util.c:   start_threshold  : -1
Aug 15 22:50:42 localhost pulseaudio[2119]: alsa-util.c:   stop_threshold   : 1073741824
Aug 15 22:50:42 localhost pulseaudio[2119]: alsa-util.c:   silence_threshold: 0
Aug 15 22:50:42 localhost pulseaudio[2119]: alsa-util.c:   silence_size : 0
Aug 15 22:50:42 localhost pulseaudio[2119]: alsa-util.c:   boundary     : 1073741824
Aug 15 22:50:42 localhost pulseaudio[2119]: alsa-util.c:   appl_ptr     : 4770543
Aug 15 22:50:42 localhost pulseaudio[2119]: alsa-util.c:   hw_ptr       : 4751362
Aug 15 22:50:42 localhost pulseaudio[2119]: alsa-util.c: snd_pcm_delay() returned a value that is exceptionally large: 389360 bytes (2207 ms).
Aug 15 22:50:42 localhost pulseaudio[2119]: alsa-util.c: Most likely this is a bug in the ALSA driver 'snd_intel8x0'. Please report this issue to the ALSA developers.

Running pulseaudio -vvvv also gives me the rewind error messages as from comment 63 above, but unlike him, I am still getting the snd_pcm_delay() error message as well.  I apologize if this I'm posting this in the wrong place, but the broken sound was getting kind of old.
Comment 75 Lennart Poettering 2009-08-17 19:29:01 UTC 
*** Bug 514431 has been marked as a duplicate of this bug. ***
Comment 76 Dave Malcolm 2009-08-21 13:05:07 UTC 
Similarly to comment #74, I'm still seeing the "snd_pcm_avail() returned a value that is exceptionally large" error in the log (which coincides with Rhythmbox stopping playback of an audio file and pulse restarting) on a recent F11 kernel (i.e. more recent than the one mentioned by Will in comment #62)

$ uname -a
Linux brick 2.6.29.6-217.2.8.fc11.i686.PAE #1 SMP Sat Aug 15 01:07:59 EDT 2009 i686 i686 i386 GNU/Linux

Aug 21 08:50:33 brick pulseaudio[5345]: alsa-sink.c: Underrun!
Aug 21 08:50:33 brick pulseaudio[5345]: alsa-sink.c: Increasing wakeup watermark to 30.00 ms
Aug 21 08:50:33 brick pulseaudio[5345]: alsa-sink.c: Underrun!
Aug 21 08:50:33 brick pulseaudio[5345]: alsa-sink.c: Increasing wakeup watermark to 40.00 ms
Aug 21 08:50:33 brick pulseaudio[5345]: alsa-util.c: snd_pcm_avail() returned a value that is exceptionally large: 4294959696 bytes (22369581 ms).
Aug 21 08:50:33 brick pulseaudio[5345]: alsa-util.c: Most likely this is a bug in the ALSA driver 'snd_intel8x0'. Please report this issue to the ALSA developers.
Aug 21 08:50:33 brick pulseaudio[5345]: alsa-util.c: snd_pcm_dump():
Aug 21 08:50:33 brick pulseaudio[5345]: alsa-util.c: Hardware PCM card 0 'Intel ICH6' device 0 subdevice 0
Aug 21 08:50:33 brick pulseaudio[5345]: alsa-util.c: Its setup is:
Aug 21 08:50:33 brick pulseaudio[5345]: alsa-util.c:   stream       : PLAYBACK
Aug 21 08:50:33 brick pulseaudio[5345]: alsa-util.c:   access       : MMAP_INTERLEAVED
Aug 21 08:50:33 brick pulseaudio[5345]: alsa-util.c:   format       : S16_LE
Aug 21 08:50:33 brick pulseaudio[5345]: alsa-util.c:   subformat    : STD
Aug 21 08:50:33 brick pulseaudio[5345]: alsa-util.c:   channels     : 2
Aug 21 08:50:33 brick pulseaudio[5345]: alsa-util.c:   rate         : 48000
Aug 21 08:50:33 brick pulseaudio[5345]: alsa-util.c:   exact rate   : 48000 (48000/1)
Aug 21 08:50:33 brick pulseaudio[5345]: alsa-util.c:   msbits       : 16
Aug 21 08:50:33 brick pulseaudio[5345]: alsa-util.c:   buffer_size  : 16384
Aug 21 08:50:33 brick pulseaudio[5345]: alsa-util.c:   period_size  : 16384
Aug 21 08:50:33 brick pulseaudio[5345]: alsa-util.c:   period_time  : 341333
Aug 21 08:50:33 brick pulseaudio[5345]: alsa-util.c:   tstamp_mode  : ENABLE
Aug 21 08:50:33 brick pulseaudio[5345]: alsa-util.c:   period_step  : 1
Aug 21 08:50:33 brick pulseaudio[5345]: alsa-util.c:   avail_min    : 16384
Aug 21 08:50:33 brick pulseaudio[5345]: alsa-util.c:   period_event : 0
Aug 21 08:50:33 brick pulseaudio[5345]: alsa-util.c:   start_threshold  : -1
Aug 21 08:50:33 brick pulseaudio[5345]: alsa-util.c:   stop_threshold   : 1073741824
Aug 21 08:50:33 brick pulseaudio[5345]: alsa-util.c:   silence_threshold: 0
Aug 21 08:50:33 brick pulseaudio[5345]: alsa-util.c:   silence_size : 0
Aug 21 08:50:33 brick pulseaudio[5345]: alsa-util.c:   boundary     : 1073741824
Aug 21 08:50:33 brick pulseaudio[5345]: alsa-util.c:   appl_ptr     : 3147636
Aug 21 08:50:33 brick pulseaudio[5345]: alsa-util.c:   hw_ptr       : 3129352
Aug 21 08:50:33 brick pulseaudio[5345]: alsa-util.c: snd_pcm_delay() returned a value that is exceptionally large: 402968 bytes (2098 ms).
Aug 21 08:50:33 brick pulseaudio[5345]: alsa-util.c: Most likely this is a bug in the ALSA driver 'snd_intel8x0'. Please report this issue to the ALSA developers.

Should this bug be reopened, or should I file a new bug?  Any other info I need to supply?  Thanks.  (Rhythmbox is almost unusable for me at the moment, alas)
Comment 77 Roland Roberts 2009-09-23 16:18:03 UTC 
Like comment #76, the problem is still present in F11

# uname -4
2.6.30.5-43.fc11.i586

and from syslog:

Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c: snd_pcm_avail() returned a value that is exceptionally large: 3087007376 bytes (17500041 ms).
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c: Most likely this is a bug in the ALSA driver 'snd_hda_intel'. Please report this issue to the ALSA developers.
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c: snd_pcm_dump():
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c: Soft volume PCM
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c: Control: PCM Playback Volume
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c: min_dB: -51
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c: max_dB: 0
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c: resolution: 256
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c: Its setup is:
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   stream       : PLAYBACK
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   access       : MMAP_INTERLEAVED
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   format       : S16_LE
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   subformat    : STD
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   channels     : 2
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   rate         : 44100
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   exact rate   : 44100 (44100/1)
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   msbits       : 16
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   buffer_size  : 1760
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   period_size  : 352
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   period_time  : 7981
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   tstamp_mode  : ENABLE
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   period_step  : 1
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   avail_min    : 352
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   period_event : 0
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   start_threshold  : -1
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   stop_threshold   : 1845493760
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   silence_threshold: 0
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   silence_size : 0
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   boundary     : 1845493760
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c: Slave: Hardware PCM card 0 'HDA Intel' device 0 subdevice 0
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c: Its setup is:
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   stream       : PLAYBACK
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   access       : MMAP_INTERLEAVED
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   format       : S16_LE
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   subformat    : STD
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   channels     : 2
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   rate         : 44100
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   exact rate   : 44100 (44100/1)
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   msbits       : 16
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   buffer_size  : 1760
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   period_size  : 352
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   period_time  : 7981
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   tstamp_mode  : ENABLE
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   period_step  : 1
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   avail_min    : 352
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   period_event : 0
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   start_threshold  : -1
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   stop_threshold   : 1845493760
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   silence_threshold: 0
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   silence_size : 0
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   boundary     : 1845493760
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   appl_ptr     : 37424733
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   hw_ptr       : 37422881
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c: snd_pcm_delay() returned a value that is exceptionally large: 1208032344 bytes (6848255 ms).
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c: Most likely this is a bug in the ALSA driver 'snd_hda_intel'. Please report this issue to the ALSA developers.
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c: snd_pcm_dump():
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c: Soft volume PCM
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c: Control: PCM Playback Volume
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c: min_dB: -51
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c: max_dB: 0
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c: resolution: 256
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c: Its setup is:
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   stream       : PLAYBACK
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   access       : MMAP_INTERLEAVED
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   format       : S16_LE
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   subformat    : STD
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   channels     : 2
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   rate         : 44100
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   exact rate   : 44100 (44100/1)
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   msbits       : 16
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   buffer_size  : 1760
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   period_size  : 352
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   period_time  : 7981
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   tstamp_mode  : ENABLE
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   period_step  : 1
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   avail_min    : 352
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   period_event : 0
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   start_threshold  : -1
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   stop_threshold   : 1845493760
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   silence_threshold: 0
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   silence_size : 0
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   boundary     : 1845493760
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c: Slave: Hardware PCM card 0 'HDA Intel' device 0 subdevice 0
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c: Its setup is:
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   stream       : PLAYBACK
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   access       : MMAP_INTERLEAVED
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   format       : S16_LE
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   subformat    : STD
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   channels     : 2
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   rate         : 44100
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   exact rate   : 44100 (44100/1)
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   msbits       : 16
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   buffer_size  : 1760
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   period_size  : 352
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   period_time  : 7981
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   tstamp_mode  : ENABLE
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   period_step  : 1
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   avail_min    : 352
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   period_event : 0
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   start_threshold  : -1
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   stop_threshold   : 1845493760
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   silence_threshold: 0
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   silence_size : 0
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   boundary     : 1845493760
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   appl_ptr     : 37442333
Sep 23 12:07:55 aristarchus pulseaudio[22078]: alsa-util.c:   hw_ptr       : 37424135
Sep 23 12:08:08 aristarchus pulseaudio[22078]: cpulimit.c: Received request to terminate due to CPU overload.
Sep 23 12:08:08 aristarchus kernel: pulseaudio[22078]: segfault at 5a66eb ip 005a66eb sp bfbbb75c error 4 in libexpat.so.1.5.2[5be000+25000]
Sep 23 12:08:08 aristarchus pulseaudio[22746]: pid.c: Stale PID file, overwriting.
Sep 23 12:08:08 aristarchus pulseaudio[22754]: pid.c: Daemon already running.
Sep 23 12:09:20 aristarchus pulseaudio[22746]: alsa-util.c: snd_pcm_avail() returned a value that is exceptionally large: 3087007636 bytes (17500043 ms).
Sep 23 12:09:20 aristarchus pulseaudio[22746]: alsa-util.c: Most likely this is a bug in the ALSA driver 'snd_hda_intel'. Please report this issue to the ALSA developers.
Sep 23 12:09:20 aristarchus pulseaudio[22746]: alsa-util.c: snd_pcm_dump():
Sep 23 12:09:20 aristarchus pulseaudio[22746]: alsa-util.c: Soft volume PCM
Sep 23 12:09:20 aristarchus pulseaudio[22746]: alsa-util.c: Control: PCM Playback Volume
Sep 23 12:09:20 aristarchus pulseaudio[22746]: alsa-util.c: min_dB: -51
Sep 23 12:09:20 aristarchus pulseaudio[22746]: alsa-util.c: max_dB: 0
Sep 23 12:09:20 aristarchus pulseaudio[22746]: alsa-util.c: resolution: 256
Sep 23 12:09:20 aristarchus pulseaudio[22746]: alsa-util.c: Its setup is:
Sep 23 12:09:20 aristarchus pulseaudio[22746]: alsa-util.c:   stream       : PLAYBACK
Sep 23 12:09:20 aristarchus pulseaudio[22746]: alsa-util.c:   access       : MMAP_INTERLEAVED
Sep 23 12:09:20 aristarchus pulseaudio[22746]: alsa-util.c:   format       : S16_LE
Sep 23 12:09:20 aristarchus pulseaudio[22746]: alsa-util.c:   subformat    : STD
Sep 23 12:09:20 aristarchus pulseaudio[22746]: alsa-util.c:   channels     : 2
Sep 23 12:09:20 aristarchus pulseaudio[22746]: alsa-util.c:   rate         : 44100
Sep 23 12:09:20 aristarchus pulseaudio[22746]: alsa-util.c:   exact rate   : 44100 (44100/1)
Sep 23 12:09:20 aristarchus pulseaudio[22746]: alsa-util.c:   msbits       : 16
Sep 23 12:09:20 aristarchus pulseaudio[22746]: alsa-util.c:   buffer_size  : 1760
Sep 23 12:09:20 aristarchus pulseaudio[22746]: alsa-util.c:   period_size  : 352
Sep 23 12:09:20 aristarchus pulseaudio[22746]: alsa-util.c:   period_time  : 7981
Sep 23 12:09:20 aristarchus pulseaudio[22746]: alsa-util.c:   tstamp_mode  : ENABLE
Sep 23 12:09:20 aristarchus pulseaudio[22746]: alsa-util.c:   period_step  : 1
Sep 23 12:09:20 aristarchus pulseaudio[22746]: alsa-util.c:   avail_min    : 352
Sep 23 12:09:20 aristarchus pulseaudio[22746]: alsa-util.c:   period_event : 0
Sep 23 12:09:20 aristarchus pulseaudio[22746]: alsa-util.c:   start_threshold  : -1
Sep 23 12:09:20 aristarchus pulseaudio[22746]: alsa-util.c:   stop_threshold   : 1845493760
Sep 23 12:09:20 aristarchus pulseaudio[22746]: alsa-util.c:   silence_threshold: 0
Sep 23 12:09:20 aristarchus pulseaudio[22746]: alsa-util.c:   silence_size : 0
Sep 23 12:09:20 aristarchus pulseaudio[22746]: alsa-util.c:   boundary     : 1845493760
Sep 23 12:09:20 aristarchus pulseaudio[22746]: alsa-util.c: Slave: Hardware PCM card 0 'HDA Intel' device 0 subdevice 0
Sep 23 12:09:20 aristarchus pulseaudio[22746]: alsa-util.c: Its setup is:
Sep 23 12:09:20 aristarchus pulseaudio[22746]: alsa-util.c:   stream       : PLAYBACK
Sep 23 12:09:20 aristarchus pulseaudio[22746]: alsa-util.c:   access       : MMAP_INTERLEAVED
Sep 23 12:09:20 aristarchus pulseaudio[22746]: alsa-util.c:   format       : S16_LE
Sep 23 12:09:20 aristarchus pulseaudio[22746]: alsa-util.c:   subformat    : STD
Sep 23 12:09:20 aristarchus pulseaudio[22746]: alsa-util.c:   channels     : 2
Sep 23 12:09:20 aristarchus pulseaudio[22746]: alsa-util.c:   rate         : 44100
Sep 23 12:09:20 aristarchus pulseaudio[22746]: alsa-util.c:   exact rate   : 44100 (44100/1)
Sep 23 12:09:20 aristarchus pulseaudio[22746]: alsa-util.c:   msbits       : 16
Sep 23 12:09:20 aristarchus pulseaudio[22746]: alsa-util.c:   buffer_size  : 1760
Sep 23 12:09:20 aristarchus pulseaudio[22746]: alsa-util.c:   period_size  : 352
Sep 23 12:09:20 aristarchus pulseaudio[22746]: alsa-util.c:   period_time  : 7981
Sep 23 12:09:20 aristarchus pulseaudio[22746]: alsa-util.c:   tstamp_mode  : ENABLE
Sep 23 12:09:20 aristarchus pulseaudio[22746]: alsa-util.c:   period_step  : 1
Sep 23 12:09:20 aristarchus pulseaudio[22746]: alsa-util.c:   avail_min    : 352
Sep 23 12:09:20 aristarchus pulseaudio[22746]: alsa-util.c:   period_event : 0
Sep 23 12:09:20 aristarchus pulseaudio[22746]: alsa-util.c:   start_threshold  : -1
Sep 23 12:09:20 aristarchus pulseaudio[22746]: alsa-util.c:   stop_threshold   : 1845493760
Sep 23 12:09:20 aristarchus pulseaudio[22746]: alsa-util.c:   silence_threshold: 0
Sep 23 12:09:20 aristarchus pulseaudio[22746]: alsa-util.c:   silence_size : 0
Sep 23 12:09:20 aristarchus pulseaudio[22746]: alsa-util.c:   boundary     : 1845493760
Sep 23 12:09:20 aristarchus pulseaudio[22746]: alsa-util.c:   appl_ptr     : 3152542
Sep 23 12:09:20 aristarchus pulseaudio[22746]: alsa-util.c:   hw_ptr       : 3150755
[root@aristarchus ~]#
Comment 78 Adam Williamson 2009-10-20 01:21:36 UTC 
if you're still seeing instances of this bug, please file new reports, I believe that's a better way to have them addressed than commenting on a report that's been closed. It would also be helpful to know in those reports if the problem persists in an F12 live image (to see what it's like with the newer ALSA in kernel 2.6.32). Thanks.

-- 
Fedora Bugzappers volunteer triage team
https://fedoraproject.org/wiki/BugZappers
Comment 79 Roland Roberts 2009-10-20 18:33:49 UTC 
Let me suggest that if you are seeing a bug where the message reads "snd_pcm_avail() returned a value that is exceptionally large" that Bug 497636 *may* be appropriate.