Bug 497636

Summary: [snd_usb_audio] snd_pcm_avail() returned a value that is exceptionally large
Product: [Fedora] Fedora Reporter: David Nielsen <gnomeuser>
Component: alsa-libAssignee: Jaroslav Kysela <jkysela>
Status: CLOSED WONTFIX QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: medium Docs Contact:
Priority: low    
Version: 11CC: alauschke, amlau, bugs.michael, cedric.olivier, c.shoemaker, dolik, itamar, jkysela, jussi.eloranta, kernel-maint, lkundrak, lpoetter, mishu, mrunge, natxo, roland, tore, wtogami
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: 2010-06-28 08:12:16 EDT Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Bug Depends On:    
Bug Blocks: 446451    
Attachments:
Description Flags
pulseaudio log E: only output
none
pa.log as produced with alsa-lib 1.0.20 none

Description David Nielsen 2009-04-25 08:26:01 EDT
Created attachment 341314 [details]
pulseaudio log E: only output

Description of problem:

I am experiencing a large amount of stuttering audio, the attached debug information could be captured when running pulseaudio -vvvv

The laptop has Intel HDA built in as well as an external soundblaster card connected via USB and a mic in the USB webcam. The snd_usb_audio driver here appears to be causing the problem. The external card is set as the default playback device and configured for 5.1 analog output.

Pulseaudio is being run with tsched=0 to avoid a loud painful crackling sound upon waking to the card.

Version-Release number of selected component (if applicable):
kernel-2.6.29.1-102.fc11.x86_64
pulseaudio-0.9.15-11.fc11.x86_64

How reproducible:
100%

Steps to Reproduce:
1. playback audio, youtube videos via gnash especially seem good at triggering this

Actual results:
stuttering audio to the point of making it unlistenable

Expected results:
smooth audio experience

Additional info:
x86_64, da_DK.UTF-8
Comment 1 Lennart Poettering 2009-04-25 10:50:33 EDT
That snd_pcm_avail() issue is a kernel driver problem. Reassigning.
Comment 2 David Nielsen 2009-05-19 03:16:33 EDT
Adding Jaroslav Kysela, as I recall the gentleman is who ALSA bugs go to, if not I apologize.
Comment 3 Jaroslav Kysela 2009-05-19 03:27:55 EDT
Do you have alsa-lib 1.0.20 installed in your system? Please, provide PA error log with alsa-lib-1.0.20.
Comment 4 David Nielsen 2009-05-19 03:56:09 EDT
Created attachment 344583 [details]
pa.log as produced with alsa-lib 1.0.20

Here you go, full pa.log with the requested alsa-lib version
Comment 5 Jaroslav Kysela 2009-05-19 08:56:55 EDT
Reassigning to alsa-lib. It's probably alsa-lib problem.

I require more assistance to trace problem. Let me, please, know, if you could compile alsa-lib from sources (www.alsa-project.org). I will send you patches to show more communication parameters between alsa-lib <-> PA to identify this issue. Thanks.
Comment 6 Jaroslav Kysela 2009-05-19 09:01:01 EDT
Forgot to note: appl_ptr is behind buffer_size . In this case alsa-lib means that hw_ptr overlaped boundary (and the result is too big values from avail and delay functions). The reason might be that there's a bug in alsa-lib or an application wrote too much samples or the bug might be really in kernel (hw_ptr goes backward).
Comment 7 David Nielsen 2009-05-19 10:01:22 EDT
If you provide a patch I will happily apply it to my alsa-lib rpm but I would rather avoid having to compile a cvs snaphot. Removing alsa-lib from the rpm db sounds like it would bring regular sized havoc. Would that be acceptable?
Comment 8 Jaroslav Kysela 2009-05-19 14:07:43 EDT
Fine, I'll prepare a patch tomorrow. You may use LD_PRELOAD to use test alsa-lib binary from another location without installing library to base /usr/lib* tree. I'll give you instructions.
Comment 9 David Nielsen 2009-05-21 04:44:43 EDT
Sound good, I'm setting this to block F11Target and needinfo from you pending the arrival of the test patch.
Comment 10 Jaroslav Kysela 2009-05-21 05:02:35 EDT
Please, untar alsa-lib-1.0.20 tar ball from www.alsa-project.org and uncomment DEBUG_MMAP in alsa-lib/src/pcm/pcm_hw.c. Compile with './configure && make' and run PA with 'LD_PRELOAD=$ALSALIB/src/.libs/libasound.so pulseaudio $ARGS' - substitute ALSALIB with alsa-lib base directory and $ARGS with your PA arguments.
Attach the log (it should contain lines like appl_forward: hw_ptr= ....
Comment 11 David Nielsen 2009-05-21 15:28:49 EDT
Doing that I have thus far been unable to reproduce the PA crash, I also don't see the additional output in the log. This makes no sense, by all rights it should crash yet despite hours of playing flash video and listening to music the sound will become choppy, it will freeze for several seconds and generally suck 7 ways from sunday but it will not crash. In regular testing before I was able to see this crash sometimes in a matter of minutes.

what gives?
Comment 12 Bug Zapper 2009-06-09 10:32:57 EDT
This bug appears to have been reported against 'rawhide' during the Fedora 11 development cycle.
Changing version to '11'.

More information and reason for this action is here:
http://fedoraproject.org/wiki/BugZappers/HouseKeeping
Comment 13 Michael Schwendt 2009-07-19 08:34:19 EDT
Has anything been found out here?

I see snd_pcm_avail_update() return ridiculously high values > 980000000 with a different kernel driver (snd_ens1371) and when creating some cpu load. alsa-lib doesn't recover from that automatically.
Comment 14 Jaroslav Kysela 2009-07-20 05:18:45 EDT
Michael, could you do tests described in comment#10?
Comment 15 Michael Schwendt 2009-07-20 06:23:57 EDT
Well, my problems are _without_ PulseAudio (yum -y remove pulseaudio) as it has not pleased me so far. And with DEBUG_MMAP enabled in alsa-lib, I still don't get any debug output when running Audacious.

But I've installed the new  kernel-2.6.29.6-213.fc11.i586  from updates-testing, and it makes a change! So far I've been unable to reproduce deadlocks with that kernel. [There is a new symptom, too: When running "lvcool" (bad habit with Athlon/Duron), Audacious starts skipping frames and advances its play position at approximately 5x-speed whereas with kernel-2.6.29.5-191.fc11.i586 and older it wouldn't do that.]
Comment 16 Lubomir Rintel 2009-08-03 04:09:00 EDT
*** Bug 481043 has been marked as a duplicate of this bug. ***
Comment 17 Jussi Eloranta 2009-08-09 14:34:11 EDT
As of kernel 2.6.29.6-217.2.3.fc11.i586 and alsa-lib version 1.0.20-1, I am still seeing this (with pulseaudio). Output from /var/log/messages:

Aug  9 11:22:29 localhost pulseaudio[2295]: alsa-sink.c: Increasing minimal late
ncy to 1.00 ms
Aug  9 11:22:29 localhost pulseaudio[2295]: alsa-sink.c: Increasing minimal late
ncy to 2.00 ms
Aug  9 11:22:29 localhost pulseaudio[2295]: alsa-util.c: snd_pcm_avail() returne
d a value that is exceptionally large: 4294964340 bytes (24347870 ms).
Aug  9 11:22:29 localhost pulseaudio[2295]: alsa-util.c: Most likely this is a b
ug in the ALSA driver 'snd_intel8x0'. Please report this issue to the ALSA devel
opers.
Aug  9 11:22:29 localhost pulseaudio[2295]: alsa-util.c: snd_pcm_dump():
Aug  9 11:22:29 localhost pulseaudio[2295]: alsa-util.c: Hardware PCM card 0 'In
tel 82801DB-ICH4' device 0 subdevice 0
Aug  9 11:22:29 localhost pulseaudio[2295]: alsa-util.c: Its setup is:
Aug  9 11:22:29 localhost pulseaudio[2295]: alsa-util.c:   stream       : PLAYBA
CK
Aug  9 11:22:29 localhost pulseaudio[2295]: alsa-util.c:   access       : MMAP_I
NTERLEAVED
Aug  9 11:22:29 localhost pulseaudio[2295]: alsa-util.c:   format       : S16_LE
Aug  9 11:22:29 localhost pulseaudio[2295]: alsa-util.c:   subformat    : STD
Aug  9 11:22:29 localhost pulseaudio[2295]: alsa-util.c:   channels     : 2
Aug  9 11:22:29 localhost pulseaudio[2295]: alsa-util.c:   rate         : 44100
Aug  9 11:22:29 localhost pulseaudio[2295]: alsa-util.c:   exact rate   : 44100 
(44100/1)
Aug  9 11:22:29 localhost pulseaudio[2295]: alsa-util.c:   msbits       : 16
Aug  9 11:22:29 localhost pulseaudio[2295]: alsa-util.c:   buffer_size  : 16384
Aug  9 11:22:29 localhost pulseaudio[2295]: alsa-util.c:   period_size  : 16384
Aug  9 11:22:29 localhost pulseaudio[2295]: alsa-util.c:   period_time  : 371519
Aug  9 11:22:29 localhost pulseaudio[2295]: alsa-util.c:   tstamp_mode  : ENABLE
Aug  9 11:22:29 localhost pulseaudio[2295]: alsa-util.c:   period_step  : 1
Aug  9 11:22:29 localhost pulseaudio[2295]: alsa-util.c:   avail_min    : 16384
Aug  9 11:22:29 localhost pulseaudio[2295]: alsa-util.c:   period_event : 0
Aug  9 11:22:29 localhost pulseaudio[2295]: alsa-util.c:   start_threshold  : -1
Aug  9 11:22:29 localhost pulseaudio[2295]: alsa-util.c:   stop_threshold   : 10
73741824
Aug  9 11:22:29 localhost pulseaudio[2295]: alsa-util.c:   silence_threshold: 0
Aug  9 11:22:29 localhost pulseaudio[2295]: alsa-util.c:   silence_size : 0
Aug  9 11:22:29 localhost pulseaudio[2295]: alsa-util.c:   boundary     : 107374
1824
Aug  9 11:22:29 localhost pulseaudio[2295]: alsa-util.c:   appl_ptr     : 770791
Aug  9 11:22:29 localhost pulseaudio[2295]: alsa-util.c:   hw_ptr       : 753668
Aug  9 11:22:29 localhost pulseaudio[2295]: alsa-util.c: snd_pcm_delay() returne
d a value that is exceptionally large: 349768 bytes (1982 ms).
Aug  9 11:22:29 localhost pulseaudio[2295]: alsa-util.c: Most likely this is a b
ug in the ALSA driver 'snd_intel8x0'. Please report this issue to the ALSA devel
opers.
Aug  9 11:22:29 localhost pulseaudio[2295]: alsa-util.c: snd_pcm_dump():
Aug  9 11:22:29 localhost pulseaudio[2295]: alsa-util.c: Hardware PCM card 0 'In
tel 82801DB-ICH4' device 0 subdevice 0
Aug  9 11:22:29 localhost pulseaudio[2295]: alsa-util.c: Its setup is:
Aug  9 11:22:29 localhost pulseaudio[2295]: alsa-util.c:   stream       : PLAYBA
CK
Aug  9 11:22:29 localhost pulseaudio[2295]: alsa-util.c:   access       : MMAP_I
NTERLEAVED
Aug  9 11:22:29 localhost pulseaudio[2295]: alsa-util.c:   format       : S16_LE
Aug  9 11:22:29 localhost pulseaudio[2295]: alsa-util.c:   subformat    : STD
Aug  9 11:22:29 localhost pulseaudio[2295]: alsa-util.c:   channels     : 2
Aug  9 11:22:29 localhost pulseaudio[2295]: alsa-util.c:   rate         : 44100
Aug  9 11:22:29 localhost pulseaudio[2295]: alsa-util.c:   exact rate   : 44100 
(44100/1)
Aug  9 11:22:29 localhost pulseaudio[2295]: alsa-util.c:   msbits       : 16
Aug  9 11:22:29 localhost pulseaudio[2295]: alsa-util.c:   buffer_size  : 16384
Aug  9 11:22:29 localhost pulseaudio[2295]: alsa-util.c:   period_size  : 16384
Aug  9 11:22:30 localhost pulseaudio[2295]: alsa-util.c:   period_time  : 371519
Aug  9 11:22:30 localhost pulseaudio[2295]: alsa-util.c:   tstamp_mode  : ENABLE
Aug  9 11:22:30 localhost pulseaudio[2295]: alsa-util.c:   period_step  : 1
Aug  9 11:22:30 localhost pulseaudio[2295]: alsa-util.c:   avail_min    : 16384
Aug  9 11:22:30 localhost pulseaudio[2295]: alsa-util.c:   period_event : 0
Aug  9 11:22:30 localhost pulseaudio[2295]: alsa-util.c:   start_threshold  : -1
Aug  9 11:22:30 localhost pulseaudio[2295]: alsa-util.c:   stop_threshold   : 10
73741824
Aug  9 11:22:30 localhost pulseaudio[2295]: alsa-util.c:   silence_threshold: 0
Aug  9 11:22:30 localhost pulseaudio[2295]: alsa-util.c:   silence_size : 0
Aug  9 11:22:30 localhost pulseaudio[2295]: alsa-util.c:   boundary     : 107374
1824
Aug  9 11:22:30 localhost pulseaudio[2295]: alsa-util.c:   appl_ptr     : 841351
Aug  9 11:22:30 localhost pulseaudio[2295]: alsa-util.c:   hw_ptr       : 753909

This happens always when I try to play something from youtube (sound disappear after a while). If I restart firerox and replay, the audio works again for a moment and then goes away (with the above messages in the syslog). I suppose that this is my audio card (from lspci):

00:1f.5 Multimedia audio controller: Intel Corporation 82801DB/DBL/DBM (ICH4/ICH4-L/ICH4-M) AC'97 Audio Controller (rev 01)
Comment 18 Natxo Asenjo 2009-08-11 13:47:26 EDT
I have this same problem with 00:1e.2 Multimedia audio controller: Intel Corporation 82801FB/FBM/FR/FW/FRW (ICH6 Family) AC'97 Audio Controller (rev 03)

I have solved it booting fedora 11 with 2.6.29.5-191.fc11.i586, the first kernel of its lifecycle. Using that kernel (same userland) the sound works.
Comment 19 Jussi Eloranta 2009-08-19 01:01:37 EDT
Just to clarify, this happens with many other programs too - not just youtube...
Comment 20 Roland Roberts 2009-09-23 12:02:15 EDT
This does not appear to be snd_usb_audio related as I am seeing the same problem when that module is not loaded.  Sound controller on my laptop is 

00:1b.0 Audio device: Intel Corporation 82801G (ICH7 Family) High Definition Audio Controller (rev 01)

# lsmod | grep snd
snd_hda_codec_idt      51592  1 
snd_hda_intel          24164  4 
snd_hda_codec          59380  2 snd_hda_codec_idt,snd_hda_intel
snd_hwdep               6716  1 snd_hda_codec
snd_pcm                62596  3 snd_hda_intel,snd_hda_codec
snd_timer              17876  1 snd_pcm
snd                    50336  13 snd_hda_codec_idt,snd_hda_intel,snd_hda_codec,snd_hwdep,snd_pcm,snd_timer
soundcore               5476  1 snd
snd_page_alloc          7712  2 snd_hda_intel,snd_pcm

Kernel is 
# uname -a
Linux aristarchus.rlent.pnet 2.6.30.5-43.fc11.i586 #1 SMP Thu Aug 27 21:18:54 EDT 2009 i686 i686 i386 GNU/Linux

so the supposed fix with 2.6.29.5-191.fc11.i586 doesn't fix it here.
Comment 21 Chris Shoemaker 2009-09-30 19:53:50 EDT
Can someone provide some guidance as to whether this bug is truly specific to snd_usb_audio, or whether it's more general?

And, could this bug cause this:

Sep 30 13:34:05 ipem pulseaudio[2741]: alsa-sink.c: ALSA woke us up to write new data to the device, but there was actually nothing to write!
Sep 30 13:34:05 ipem pulseaudio[2741]: alsa-sink.c: Most likely this is a bug in the ALSA driver ‘snd_usb_audio’. Please report this issue to the ALSA developers.
Sep 30 13:34:05 ipem pulseaudio[2741]: alsa-sink.c: We were woken up with POLLOUT set — however a subsequent snd_pcm_avail() returned 0 or another value < min_avail.

This is: 2.6.29.5-191.fc11.x86_64
alsa-plugins-pulseaudio-1.0.18-3.fc11.x86_64
alsa-utils-1.0.20-3.fc11.x86_64
alsa-lib-1.0.20-1.fc11.x86_64
pulseaudio-0.9.15-14.fc11.x86_64
Comment 22 Roland Roberts 2009-09-30 23:20:41 EDT
What guidance are you looking for?  I'm having the same symptoms (based on the log message) and snd_usb_audio is not loaded (doesn't show up in lsmod) per my comment #20.
Comment 23 Roland Roberts 2009-10-20 14:44:41 EDT
I think having "snd_usb_audio" in the title on this bug is misleading.  I see
this problem DAILY on my Dell D820 laptop with an HDA Intel built-in card.  No
USB involved that I can tell.

It's also a bit disturbing that the bug is still in the NEW category after 6
months since its initial report.  I browsed around the ALSA bug list and can't
find anything there about this, so it doesn't look like it got bumped over to
them.

For all practical purposes, audio is dead on my laptop.  I can listen to audio
for anywhere from a few minutes (perhaps 20) down to a minute (or two) before
it crashes requiring me to restart the audio application(s).

Chris, you asked for more guidance.  I hope my response didn't sound like I was
being snippy, it was serious.  I don't know what guidance you are looking for,
but my own earlier reports show it doesn't seem to be related to snd_usb_audio.
 I have no USB audio connected most of the time and it has certainly been
failing without any USB audio devices connected.  I have also seen the message
from alsa-sink.  about snd_pcm_avail() returning 0, but I unlike the one that
returns an excessively large number, I see it only sometime when the device
hangs.
Comment 24 Chris Shoemaker 2009-10-20 15:07:52 EDT
I didn't take your response as snippy.  I'm just trying to get some clarity as to what exactly this bug is.  I realize some people are seeing errors without snd_usb_audio and some are seeing it with snd_usb_audio.  I'd like someone knowledgeable to say either:

a) yes, this bug can cause these kinds of problems either with or without snd_usb_audio, so it is more general than just snd_usb_audio, or

b) no, even though the error logs show some similarities, the same bug can not be responsible for both cases, so each case deserves it's own bug file.

And ultimately, I'm hoping someone can describe what information would help in resolving this bug, because I, too, have frustratingly unreliable audio, and lots of noise in the logs about snd_usb_audio.
Comment 25 Bug Zapper 2010-04-27 09:55:49 EDT
This message is a reminder that Fedora 11 is nearing its end of life.
Approximately 30 (thirty) days from now Fedora will stop maintaining
and issuing updates for Fedora 11.  It is Fedora's policy to close all
bug reports from releases that are no longer maintained.  At that time
this bug will be closed as WONTFIX if it remains open with a Fedora 
'version' of '11'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version prior to Fedora 11's end of life.

Bug Reporter: Thank you for reporting this issue and we are sorry that 
we may not be able to fix it before Fedora 11 is end of life.  If you 
would still like to see this bug fixed and are able to reproduce it 
against a later version of Fedora please change the 'version' of this 
bug to the applicable version.  If you are unable to change the version, 
please add a comment here and someone will do it for you.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events.  Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.

The process we are following is described here: 
http://fedoraproject.org/wiki/BugZappers/HouseKeeping
Comment 26 Bug Zapper 2010-06-28 08:12:16 EDT
Fedora 11 changed to end-of-life (EOL) status on 2010-06-25. Fedora 11 is 
no longer maintained, which means that it will not receive any further 
security or bug fix updates. As a result we are closing this bug.

If you can reproduce this bug against a currently maintained version of 
Fedora please feel free to reopen this bug against that version.

Thank you for reporting this bug and we are sorry it could not be fixed.