Bug 456802

Summary: pulseaudio logging out of control.
Product: [openSUSE] openSUSE 11.1 Reporter: Bart Whiteley <bwhiteley>
Component: SoundAssignee: Scott Reeves <sreeves>
Status: RESOLVED FIXED QA Contact: E-mail List <qa-bugs>
Severity: Critical    
Priority: P3 - Medium CC: aj, forgotten_ny8t7SHjD_, jgreen, ke, mge, sreeves, tiwai
Version: RC 1Flags: coolo: SHIP_STOPPER-
Target Milestone: ---   
Hardware: Other   
OS: Other   
Whiteboard: pulseaudio maint:released:sle11:24435 maint:released:sle11:24612
Found By: Development Services Priority:
Business Priority: Blocker: ---
Marketing QA Status: --- IT Deployment: ---
Attachments: strace output
more strace output
another strace log

Description Bart Whiteley 2008-12-05 16:11:47 UTC
I observed my disk grinding nonstop, and eventually tracked it down to this:

The following lines are logged to /var/log/messages and /var/log/warn at a rate of about 40 lines per second:

Dec  5 09:01:06 lap pulseaudio[3626]: alsa-util.c: Got POLLERR from ALSA
Dec  5 09:01:06 lap pulseaudio[3626]: alsa-util.c: PCM state is RUNNING
Dec  5 09:01:06 lap pulseaudio[3626]: alsa-util.c: Got POLLERR from ALSA
Dec  5 09:01:06 lap pulseaudio[3626]: alsa-util.c: PCM state is RUNNING
Dec  5 09:01:06 lap pulseaudio[3626]: alsa-util.c: Got POLLERR from ALSA
Dec  5 09:01:06 lap pulseaudio[3626]: alsa-util.c: PCM state is RUNNING
Dec  5 09:01:06 lap pulseaudio[3626]: alsa-util.c: Got POLLERR from ALSA
Dec  5 09:01:06 lap pulseaudio[3626]: alsa-util.c: PCM state is RUNNING
Dec  5 09:01:06 lap pulseaudio[3626]: alsa-util.c: Got POLLERR from ALSA
Dec  5 09:01:06 lap pulseaudio[3626]: alsa-util.c: PCM state is RUNNING
Dec  5 09:01:06 lap pulseaudio[3626]: alsa-util.c: Got POLLERR from ALSA
...

I killed and restarted pulseaudio, and the problem stopped.
Comment 1 Rodrigo Moya 2008-12-08 14:53:04 UTC
Can you replicate this? If so, please get a strace of pulseaudio:

$ strace -f -ttt -o /tmp/strace-log -s 4096 -p <pid_of_pulseaudio_daemon>

and attach /tmp/strace-log to this bug please
Comment 2 Bart Whiteley 2008-12-20 01:58:22 UTC
Created attachment 261532 [details]
strace output

I can't reproduce it at will, but it did happen again with 11.1 GM.  I attached the strace log.  This time it stopped on its own after a while.
Comment 3 Bart Whiteley 2008-12-20 02:03:30 UTC
Both times that I've experienced this it was right after resuming from s2ram.  Syslog indicates that the problem started immediately after resuming, and occurred for just under 5 minutes before stopping on its own. 
Comment 4 Bart Whiteley 2008-12-23 06:13:09 UTC
Created attachment 262172 [details]
more strace output

It's happening again.  I had to kill it this time to get it to stop.
Comment 5 Bart Whiteley 2008-12-24 23:39:05 UTC
Created attachment 262416 [details]
another strace log

Still happening.  Please fix it.
Comment 6 Bart Whiteley 2009-01-15 19:45:15 UTC
This happens nearly every time I resume from s2ram.  Any workarounds?
Comment 7 Rodrigo Moya 2009-01-16 12:04:46 UTC
I'm building a package with some upstream fixes in http://download.opensuse.org/repositories/home:/rodrigomoya:/branches:/GNOME:/Factory/

As soon as it's built, I'll poke you to test it
Comment 9 Oliver Neukum 2009-01-17 20:58:01 UTC
Which of these packages are necessary for testing?
Comment 10 Rodrigo Moya 2009-01-19 09:49:53 UTC
the *pulse* ones, that is pulseaudio-* and libpulse*
Comment 11 Takashi Iwai 2009-01-19 13:34:22 UTC
*** Bug 466923 has been marked as a duplicate of this bug. ***
Comment 12 Oliver Neukum 2009-01-19 13:59:23 UTC
They do not solve the problem:

Jan 19 13:56:21 vanamonde pulseaudio[4414]: alsa-util.c: Got POLLERR from ALSA
Jan 19 13:56:21 vanamonde pulseaudio[4414]: alsa-util.c: Got POLLOUT from ALSA
Jan 19 13:56:21 vanamonde pulseaudio[4414]: alsa-util.c: PCM state is RUNNING
Jan 19 13:56:21 vanamonde pulseaudio[4414]: alsa-util.c: Got POLLERR from ALSA
Jan 19 13:56:21 vanamonde pulseaudio[4414]: alsa-util.c: Got POLLOUT from ALSA
Jan 19 13:56:21 vanamonde pulseaudio[4414]: alsa-util.c: PCM state is RUNNING
Jan 19 13:56:21 vanamonde pulseaudio[4414]: alsa-util.c: Got POLLERR from ALSA
Jan 19 13:56:22 vanamonde pulseaudio[4414]: alsa-util.c: Got POLLOUT from ALSA
Jan 19 13:56:22 vanamonde pulseaudio[4414]: alsa-util.c: PCM state is RUNNING
Jan 19 13:56:22 vanamonde pulseaudio[4414]: alsa-util.c: Got POLLERR from ALSA
Jan 19 13:56:22 vanamonde pulseaudio[4414]: alsa-util.c: Got POLLOUT from ALSA
Jan 19 13:56:22 vanamonde pulseaudio[4414]: alsa-util.c: PCM state is RUNNING
Jan 19 13:56:22 vanamonde pulseaudio[4414]: alsa-util.c: Got POLLERR from ALSA
Jan 19 13:56:23 vanamonde pulseaudio[4414]: alsa-util.c: Got POLLOUT from ALSA
Jan 19 13:56:23 vanamonde pulseaudio[4414]: alsa-util.c: PCM state is RUNNING
Jan 19 13:56:23 vanamonde pulseaudio[4414]: alsa-util.c: Got POLLERR from ALSA
Jan 19 13:56:23 vanamonde pulseaudio[4414]: alsa-util.c: Got POLLOUT from ALSA
Jan 19 13:56:23 vanamonde pulseaudio[4414]: alsa-util.c: PCM state is RUNNING
Jan 19 13:56:23 vanamonde pulseaudio[4414]: alsa-util.c: Got POLLERR from ALSA
Jan 19 13:56:24 vanamonde pulseaudio[4414]: alsa-util.c: Got POLLOUT from ALSA
Jan 19 13:56:24 vanamonde pulseaudio[4414]: alsa-util.c: PCM state is RUNNING
Comment 13 Bart Whiteley 2009-01-21 16:15:48 UTC
I also can confirm that the packages from comment #8 do not fix the problem.
Comment 14 Oliver Neukum 2009-01-22 08:49:57 UTC
A closer look reveals that the problem starts during suspension. It merely continues after resumption.

Jan 22 09:40:14 vanamonde kernel: PM: Syncing filesystems ... done.
Jan 22 09:40:24 vanamonde pulseaudio[4406]: alsa-util.c: Got POLLERR from ALSA
Jan 22 09:40:24 vanamonde pulseaudio[4406]: alsa-util.c: Got POLLOUT from ALSA
Jan 22 09:40:24 vanamonde pulseaudio[4406]: alsa-util.c: PCM state is SUSPENDED
Jan 22 09:40:24 vanamonde kernel: Freezing user space processes ... (elapsed 0.03 seconds) done.
Jan 22 09:40:24 vanamonde kernel: Freezing remaining freezable tasks ... (elapsed 0.00 seconds) done.
Comment 15 JP Rosevear 2009-02-12 18:21:57 UTC
It looks like this may happen if you are playing something via alsa when you suspend.

This is:
http://pulseaudio.org/ticket/265

Takeshi, maybe you can decipher Lennart for us?
Comment 16 Takashi Iwai 2009-02-20 08:05:33 UTC
The messages in comment #14 is pretty normal and it's no error.  The poll returns with an error because it's suspended.  PA spews simply too many chats.

The problem is rather the endless messages even in the "RUNNING" state like in comment #12.  Any reliable way to reproduce this?  Of course, it might be tied with the hardware...
Comment 17 Scott Reeves 2009-03-05 01:22:53 UTC
Looking at the git commit history for that file there have been multiple improvements in handling errors or better logging if not handled.

I have an upgraded pulseaudio 0.9.14 (plus some selective patches). Could you try updating to this version and then testing to see if the problem still occurs.  There are 2 different 0.9.14 options available, the stock mode and a glitch_free_disabled mode (glitch_free is a pulseaudio feature we are currently shipping but that causes problems with some sound drivers).  Could you try the stock mode first and if you still see the problem then try the glitch_free_disabled mode.

The rpms are at
stock mode - http://www.gnome.org/~sreeves/openSUSE_11.1/pulse/
GF_disabled - http://www.gnome.org/~sreeves/openSUSE_11.1/pulse_GF_disabled/
You can easily upgrade from 0.9.12 to 0.9.14 with the following steps
1. sudo zypper addrepo http://www.gnome.org/~sreeves/openSUSE_11.1/pulse/ pulse_repo
2. sudo zypper refresh -f pulse_repo
3. sudo zypper up --force-resolution -r pulse_repo pulseaudio libpulse0

You can switch between the stock and GF_disabled mode by installing the respective rpms or the only difference between the stock and GF_disabled rpms is the change of the line
load-module module-hal-detect
to
load-module module-hal-detect tsched=0
in the /etc/pulse/default.pa  and  /etc/pulse/system.pa files

Make sure after any changes you stop any playing sound to free the devices, and kill the pulseaudio daemon (pulseaudio –kill) so it will reload with the new settings.

When you report any results make sure and specify what version and mode you were running.
Thanks.
Comment 18 Bart Whiteley 2009-03-05 17:19:39 UTC
I can't get sound to work with the new packages.  Everything seems like it should work.  For example, in the volume control, I see the various apps that should be emitting sound.  However, no sound comes from the speakers.
Comment 19 Ke Cheng Bi 2009-03-20 09:06:12 UTC
I try the new packages in both the stock and GF_disabled mode, nothing can be heard when play a mp3 file with banshee.
Comment 20 Bart Whiteley 2009-03-20 16:06:10 UTC
I was able to get the test packages to work with Scott's help.  Try killing pulseaudio, and then moving or removing ~/.pulse.  Then restart pulseaudio. 

Alternatively, run 'pavucontrol' (or double-click the volume applet in the panel).  Go to Output Devices.  If two are listed, try switching which one is set to default. 

I haven't seen the logging problem since switching to the new packages.
Comment 26 Swamp Workflow Management 2009-05-04 14:57:29 UTC
The SWAMPID for this issue is 24401.
Please submit the patch and patchinfo file using this ID.
(https://swamp.suse.de/webswamp/wf/24401)
Comment 27 Dirk Mueller 2009-05-11 15:05:18 UTC
package has been submitted. Matthias, please update release notes for SLE(S/D).
Comment 33 Dirk Mueller 2009-05-20 10:42:10 UTC
yes.
Comment 35 Andreas Jaeger 2009-05-26 12:18:12 UTC
The patch seems to be incomplete:

On my openSUSE 11.1/x86-64 system I just noticed:

> zypper patch
> Loading repository data...
> Reading installed packages...
> Resolving package dependencies...
>
> Problem: nothing provides pulseaudio-lang = 0.9.14 needed by
> pulseaudio-0.9.14-2.1.1.x86_64
> Solution 1: Following actions will be done:
>  deinstallation of pulseaudio-esound-compat-0.9.12-9.5.x86_64
>  deinstallation of pulseaudio-module-zeroconf-0.9.12-9.5.x86_64
>  deinstallation of pulseaudio-module-x11-0.9.12-9.5.x86_64
>  deinstallation of pulseaudio-module-lirc-0.9.12-9.5.x86_64
>  deinstallation of pulseaudio-module-jack-0.9.12-9.5.x86_64
>  deinstallation of pulseaudio-module-bluetooth-0.9.12-9.5.x86_64
>  deinstallation of pulseaudio-0.9.12-9.5.x86_64
> Solution 2: do not install patch:libpulse-browse0-915.noarch
>
> Choose from above solutions by number or cancel [1/2/C]:
Comment 36 Swamp Workflow Management 2009-06-09 07:34:29 UTC
Update released for: gdbm, gdbm-debuginfo, gdbm-debugsource, gdbm-devel, libpulse-browse0, libpulse-devel, libpulse-mainloop-glib0, libpulse0, libpulsecore4, pulseaudio, pulseaudio-debuginfo, pulseaudio-debugsource, pulseaudio-esound-compat, pulseaudio-lang, pulseaudio-module-bluetooth, pulseaudio-module-gconf, pulseaudio-module-jack, pulseaudio-module-lirc, pulseaudio-module-x11, pulseaudio-module-zeroconf, pulseaudio-utils
Products:
openSUSE 11.1 (debug, i586, ppc, ppc64, x86_64)
Comment 37 Swamp Workflow Management 2009-06-09 20:46:12 UTC
The SWAMPID for this issue is 24401.
Please submit the patch and patchinfo file using this ID.
(https://swamp.suse.de/webswamp/wf/24401)
Comment 38 Scott Reeves 2009-06-09 22:56:30 UTC
Update was released.
Comment 39 Swamp Workflow Management 2009-06-15 22:09:54 UTC
Update released for: libpulse-browse0, libpulse-devel, libpulse-mainloop-glib0, libpulse0, libpulse0-32bit, libpulse0-x86, libpulsecore7, pulseaudio, pulseaudio-debuginfo, pulseaudio-debugsource, pulseaudio-esound-compat, pulseaudio-lang, pulseaudio-module-bluetooth, pulseaudio-module-gconf, pulseaudio-module-jack, pulseaudio-module-lirc, pulseaudio-module-x11, pulseaudio-module-zeroconf, pulseaudio-utils
Products:
SLE-DEBUGINFO 11 (i386, ia64, ppc64, s390x, x86_64)
SLE-DESKTOP 11 (i386, x86_64)
SLE-SDK 11 (i386, ia64, ppc64, s390x, x86_64)
SLE-SERVER 11 (i386, ia64, ppc64, s390x, x86_64)
Comment 40 Swamp Workflow Management 2009-06-16 09:33:05 UTC
Update released for: release-notes-sled
Products:
SLE-DESKTOP 11 (i386, x86_64)
Comment 41 Swamp Workflow Management 2009-06-16 09:33:09 UTC
Update released for: release-notes-sled
Products:
SLE-DESKTOP 11 (i386, x86_64)