Bug 488025

Please provide a longer excerpt from syslog. Has PA complained about snd_pcm_avail() being broken or something like this?

The assert shown above is usually just a followup issue.

Created attachment 333762 [details]
/var/log/messages

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

/var/log/messages:Mar  1 18:55:11 localhost pulseaudio[3276]: alsa-sink.c: We were woken up with POLLOUT set -- however a subsequent snd_pcm_avail() returned 0 or another value < min_avail.
/var/log/messages:Mar  1 20:30:10 localhost pulseaudio[3974]: alsa-sink.c: We were woken up with POLLOUT set -- however a subsequent snd_pcm_avail() returned 0 or another value < min_avail.
/var/log/messages:Mar  2 17:46:40 localhost pulseaudio[3230]: alsa-sink.c: We were woken up with POLLOUT set -- however a subsequent snd_pcm_avail() returned 0 or another value < min_avail.

Prior to the crash, I didn't see anything except recieved wakeout from ALSA messages for the duration of my terminal buffer (I wasn't clever enough to log to a file at the time).

In messages I can also see this:

Mar  2 17:12:00 localhost pulseaudio[3230]: alsa-sink.c: Increasing wakeup watermark to 30,00 ms
Mar  2 17:12:14 localhost pulseaudio[3230]: alsa-sink.c: Increasing wakeup watermark to 40,00 ms
Mar  2 17:46:40 localhost pulseaudio[3230]: alsa-sink.c: ALSA woke us up to write new data to the device, but there was actually nothing to write!
Mar  2 17:46:40 localhost pulseaudio[3230]: alsa-sink.c: Most likely this is a bug in the ALSA driver 'snd_usb_audio'. Please report this issue to the ALSA developers.
Mar  2 17:46:40 localhost pulseaudio[3230]: alsa-sink.c: We were woken up with POLLOUT set -- however a subsequent snd_pcm_avail() returned 0 or another value < min_avail.
Mar  2 17:46:45 localhost pulseaudio[3230]: alsa-sink.c: Increasing wakeup watermark to 50,00 ms

I have attached my /var/log/messages for examination

More information:

I also seem to be having this issue. 

Running pulse audio from the terminal outputs: 

[tgrondin@localhost ~]$ 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.
N: main.c: Called SUID root and real-time and/or high-priority scheduling was requested in the configuration. However, we lack the necessary privileges:
N: main.c: We are not in group 'pulse-rt', PolicyKit refuse to grant us the requested privileges and we have no increase RLIMIT_NICE/RLIMIT_RTPRIO resource limits.
N: main.c: For enabling real-time/high-priority scheduling please acquire the appropriate PolicyKit privileges, or become a member of 'pulse-rt', or increase the RLIMIT_NICE/RLIMIT_RTPRIO resource limits for this user.
W: pid.c: Stale PID file, overwriting.
N: alsa-source.c: Increasing minimal latency to 8.00 ms
N: alsa-source.c: Increasing minimal latency to 16.00 ms
N: alsa-source.c: Increasing minimal latency to 26.00 ms
N: alsa-source.c: Increasing wakeup watermark to 15.99 ms
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: 4294954096 bytes (24347812 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.
[tgrondin@localhost ~]$ 


If there is any other information or test I can perform to help I'll be glad to do it.

The issue is only showing with kernel 2.6.29-21.
I reverted back to kernel 2.6.29-0.258 and am no longer having the issue.

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.

Timothy, you have a different driver. This is unrelated. For intel8x0 related issues please follow bug 472339. You'd do me favour if you could post your log excerpts on that bug.

Dvaid, I am pretty sure that the assert you hit is unrelated to those messages. Could you please retry to trigger this, but first set log-level to 'debug' in /etc/pulse/daemon.conf?

Created attachment 337948 [details]
pulseaudio --log-target=stderr 2> pulse.log

I am hoping this provides the information you requested Lennart

(In reply to comment #6)
> Timothy, you have a different driver. This is unrelated. For intel8x0 related
> issues please follow bug 472339. You'd do me favour if you could post your log
> excerpts on that bug.  

Done, 

I added what is here and the output of pulseaudio -vvvv

I figured I would add output from the alsa-time-test tool on the pulseaudio website as well.

First the assertion and sigabrt message:
alsa-time-test: alsa-time-test.c:189: main: Assertion `(unsigned) avail <= buffer_size' failed.
Afbrudt (SIGABRT)

It takes less than a minute to hit this.

Created attachment 337998 [details]
head output of ./alsa-time-test hw:1 > log

cat /proc/asound/pcm

00-00: USB Audio : USB Audio : capture 1
01-00: USB Audio : USB Audio : playback 1 : capture 1
02-00: ALC861VD Analog : ALC861VD Analog : playback 1 : capture 1

Created attachment 337999 [details]
tail output of ./alsa-time-test hw:1 > log

I found a good way to make this happen every few minutes, attempting to watch a flash movie. I can be sure to trigger it within minutes. It also means I have to kill the plugin, browser, restart pulseaudio and attempt to fast forward to the correct place.

What seems to happen is that right before pulseaudio crashes the CPU fan (and thus I assume the load) spikes and then the desktop turns in unusable molasses.

Not that flash is the only way to provoke it, merely watching a movie from the harddrive or from my external usb harddrive will do the same. 

It is rendering the desktop for all intents and purposes completely unusable.

I would like to report that I am experiencing this bug as well.

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.

However, I have some other things going on with my system.  I have to compile my own kernel because the staging driver et131x is not enabled on the Fedora kernel.
I am using kernel 2.6.29.1 with rawhide up to date as of 4/9/2009.

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

This is my computer:
https://logisysus.com/catalog/product_info.php?products_id=530

(In reply to comment #14)
> I would like to report that I am experiencing this bug as well.

I am replying to myself here, after reading Lennart Poettering's reply to Timothy about the driver.  I found this bug via Google, and it was not clear to me initially that this Pulseaudio error message comes from the snd_usb_audio driver.  I had to look into David Nielsen's /var/log/messages to find that out.  I will take my bug over to 472339.  I apologize for the noise, but maybe we could somehow make it more clear that this error comes from the ALSA snd_usb_audio driver?  The bug's description is on the effect (Pulseaudio crashing, which is shared with bug 472339) and does not mention the cause until you start reading and interpreting the logs in comment #2.

Thanks.

David, you issue is triggered by the intel hda driverin your setup.

*** This bug has been marked as a duplicate of bug 485734 ***