[snd_usb_audio] snd_pcm_avail() returned a value that is exceptionally large

Created attachment 341314
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

That snd_pcm_avail() issue is a kernel driver problem. Reassigning.

Adding Jaroslav Kysela, as I recall the gentleman is who ALSA bugs go to, if not I apologize.

Do you have alsa-lib 1.0.20 installed in your system? Please, provide PA error log with alsa-lib-1.0.20.

Created attachment 344583
pa.log as produced with alsa-lib 1.0.20

Here you go, full pa.log with the requested alsa-lib version

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.

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).

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?

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.

Sound good, I'm setting this to block F11Target and needinfo from you pending the arrival of the test patch.

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= ....

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?

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

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.

Michael, could you do tests described in comment#10?

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.]

*** Bug 481043 has been marked as a duplicate of this bug. ***

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' devic...

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.

Just to clarify, this happens with many other programs too - not just youtube...

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.

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

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.

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.

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.

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

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.