Bug 488025

Summary: Pulseaudio crashes with usec <= ((pa_usec_t) 1000000ULL)*60ULL*60ULL
Product: [Fedora] Fedora Reporter: David Nielsen <gnomeuser>
Component: pulseaudioAssignee: Lennart Poettering <lpoetter>
Status: CLOSED DUPLICATE QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: medium Docs Contact:
Priority: low    
Version: rawhideCC: lkundrak, lpoetter, mc69921, mishu, tgrondin
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-10 10:33:48 EDT Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---
Bug Depends On:    
Bug Blocks: 446452    
Attachments:
Description Flags
/var/log/messages
none
pulseaudio --log-target=stderr 2> pulse.log
none
head output of ./alsa-time-test hw:1 > log
none
tail output of ./alsa-time-test hw:1 > log none

Description David Nielsen 2009-03-02 04:11:19 EST
Description of problem:
I have experienced this on a couple of occasions, leaving Pulseaudio to it's own devices it will crash with the following message at random (this time it took a good 10 hours to hit the condition).

E: rtpoll.c: Assertion 'usec <= ((pa_usec_t) 1000000ULL)*60ULL*60ULL' failed at pulsecore/rtpoll.c:548, function pa_rtpoll_set_timer_relative(). Aborting.
Afbrudt (SIGABRT)

Version-Release number of selected component (if applicable):
pulseaudio-0.9.15-3.test3.fc11.x86_64
Comment 1 Lennart Poettering 2009-03-02 10:47:02 EST
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.
Comment 2 David Nielsen 2009-03-02 11:55:31 EST
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
Comment 3 Timothy Grondin 2009-03-31 20:30:19 EDT
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.
Comment 4 Timothy Grondin 2009-03-31 22:47:52 EDT
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.
Comment 5 Timothy Grondin 2009-04-02 00:12:15 EDT
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 6 Lennart Poettering 2009-04-02 10:02:15 EDT
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.
Comment 7 Lennart Poettering 2009-04-02 10:03:50 EDT
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?
Comment 8 David Nielsen 2009-04-02 18:43:51 EDT
Created attachment 337948 [details]
pulseaudio --log-target=stderr 2> pulse.log

I am hoping this provides the information you requested Lennart
Comment 9 Timothy Grondin 2009-04-03 02:03:05 EDT
(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
Comment 10 David Nielsen 2009-04-03 04:26:16 EDT
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.
Comment 11 David Nielsen 2009-04-03 04:27:44 EDT
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
Comment 12 David Nielsen 2009-04-03 04:28:42 EDT
Created attachment 337999 [details]
tail output of ./alsa-time-test hw:1 > log
Comment 13 David Nielsen 2009-04-07 04:32:22 EDT
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.
Comment 14 Matthew C 2009-04-10 01:53:30 EDT
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
Comment 15 Matthew C 2009-04-10 02:12:36 EDT
(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.
Comment 16 Lennart Poettering 2009-04-10 10:33:48 EDT
David, you issue is triggered by the intel hda driverin your setup.

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