This service will be undergoing maintenance at 00:00 UTC, 2016-09-28. It is expected to last about 1 hours

Bug 466316

Summary: Daemon hangs, starts eating up CPU cycles, rhythmbox freezes
Product: [Fedora] Fedora Reporter: Tom London <selinux>
Component: pulseaudioAssignee: Lennart Poettering <lpoetter>
Status: CLOSED DUPLICATE QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: medium Docs Contact:
Priority: medium    
Version: rawhideCC: bnocera, chemobejk, jeff, lkundrak, lpoetter, pierre-bugzilla, sangu.fedora
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: 2008-10-19 16:50:54 EDT Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Bug Depends On:    
Bug Blocks: 438943, 457945    
Attachments:
Description Flags
Output from "strace -p XXXX -o ..." when pulseaudio daemon is "spinning"
none
5 second strace of "pulseaudio daemon" while it appears to be "spinning"
none
5 second strace of "rhythmbox" when pulseaudio appears to be spinning
none
5 seconds strace log from spinning pulsaudio process none

Description Tom London 2008-10-09 14:11:23 EDT
Description of problem:
On every boot/login, I start rhythmbox playing a library of mp3s.

All starts out well, but after a while, rhythmbox no longer shows the "time line" progressing even though the song continues to play.  

If I catch it when this happens, rhythmbox show the "cursor" at 0 seconds (or some point in the middle) throughout the clip.

At the end of the clip/song, rhythmbox does not advance to the "next song", but just hangs.

I can sometimes manually force it to play the "next" clip, but sometimes it is just frozen.

When this occurs, I've noticed that the pulseaudio daemon jumps from 1.3-1.7% of the CPU to 20-60%.  This CPU consumption continues even if I kill off rhythmbox.

Sometimes, if I just leave the system in this state, rhythmbox will "come to life" and play one song (after, say, 30 minutes), and then immediately hang up again.

I only recall this happening after I upgraded to 0.9.13-1 (and -2).

Would an "strace" of the daemon be helpful?  "gdb" backtrace?

Not exactly sure what to do.....

Here is a clip from "top" when all is working well:

Tasks: 146 total,   1 running, 145 sleeping,   0 stopped,   0 zombie
Cpu(s):  4.1%us,  1.6%sy,  0.0%ni, 93.5%id,  0.7%wa,  0.2%hi,  0.0%si,  0.0%st
Mem:   2064728k total,   858772k used,  1205956k free,    32236k buffers
Swap:  4096532k total,        0k used,  4096532k free,   433812k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND            
 3246 tbl       20   0  224m  58m  20m S  4.6  2.9   0:09.08 firefox            
 3225 tbl       20   0  246m  40m  18m S  4.0  2.0   0:05.66 rhythmbox          
 2960 tbl        9 -11  160m 4828 3768 S  1.3  0.2   0:00.55 pulseaudio  

Here is a clip from "top" when audio is wedged.....:

top - 11:10:30 up 59 min,  3 users,  load average: 0.96, 0.56, 0.37
Tasks: 147 total,   1 running, 146 sleeping,   0 stopped,   0 zombie
Cpu(s):  6.8%us, 14.8%sy,  0.0%ni, 78.3%id,  0.0%wa,  0.2%hi,  0.0%si,  0.0%st
Mem:   2064728k total,  1151876k used,   912852k free,    87244k buffers
Swap:  4096532k total,        0k used,  4096532k free,   589124k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND            
 2960 tbl        9 -11  160m 4808 3748 S 32.9  0.2   1:52.20 pulseaudio         
 3246 tbl       20   0  285m 113m  22m S  2.0  5.6   2:46.62 firefox            
 2573 root      20   0  426m  55m  14m S  1.7  2.8   1:56.57 Xorg               
 3225 tbl       20   0  246m  40m  19m S  1.7  2.0   1:35.61 rhythmbox          
 3361 tbl       20   0 78712  11m 8092 S  1.3  0.6   0:23.13 npviewer.bin  

Version-Release number of selected component (if applicable):
pulseaudio-core-libs-0.9.13-2.fc10.i386
pulseaudio-0.9.13-2.fc10.i386
pulseaudio-module-x11-0.9.13-2.fc10.i386
pulseaudio-utils-0.9.13-2.fc10.i386
pulseaudio-libs-glib2-0.9.13-2.fc10.i386
pulseaudio-debuginfo-0.9.13-1.fc10.i386
pulseaudio-libs-0.9.13-2.fc10.i386
pulseaudio-module-gconf-0.9.13-2.fc10.i386
pulseaudio-esound-compat-0.9.13-2.fc10.i386
rhythmbox-0.11.6-13.5966.fc10.i386

How reproducible:
Every session, but at "random" times.

Steps to Reproduce:
1. Boot to gdm, start rhythmbox
2. play and wait for audio hang
3. 
  
Actual results:


Expected results:


Additional info:
Comment 1 Tom London 2008-10-09 14:55:51 EDT
Here is output from "top" for another occurrence:

Tasks: 146 total,   3 running, 143 sleeping,   0 stopped,   0 zombie
Cpu(s):  6.3%us, 13.6%sy,  0.0%ni, 79.9%id,  0.0%wa,  0.2%hi,  0.0%si,  0.0%st
Mem:   2064728k total,  1899144k used,   165584k free,   217788k buffers
Swap:  4096532k total,        0k used,  4096532k free,  1161320k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND            
 3696 tbl        9 -11  159m 4192 3292 S 32.5  0.2   2:16.18 pulseaudio         
 3246 tbl       20   0  297m 115m  23m S  2.0  5.7   5:28.16 firefox            
 3701 tbl       20   0  238m  41m  19m S  2.0  2.1   1:38.32 rhythmbox      

I grabbed this when there was no sound being produced.
Comment 2 Tom London 2008-10-09 15:02:05 EDT
Created attachment 319916 [details]
Output from "strace -p XXXX -o ..." when pulseaudio daemon is "spinning"

I grabbed 5 seconds worth of "strace" from the pulseaudio daemon while it was spinning.

Scenario:  rhythmbox just completed playing a song, top showed pulseaudio daemon eating CPU, no sound, rhythmbox is hung at the end of the song.
Comment 3 John Poelstra 2008-10-09 18:10:03 EDT
This bug has been triaged
Comment 4 Tom London 2008-10-10 16:31:16 EDT
I got a daemon crash (halt actually).  Noticed a "CPU Overload" message in /var/log/messages:

Oct 10 13:26:31 tlondon pulseaudio[10288]: cpulimit.c: Recevied request to terminate due to CPU overload.
Oct 10 13:26:31 tlondon pulseaudio[10288]: main.c: Daemon shutdown initiated.

While this seems to shutdown the daemon, rhythmbox is left "hanging".  I had to kill it manually.

Here is a snippet from /var/log/messages:

Oct 10 13:25:48 tlondon pulseaudio[10288]: protocol-native.c: Requested tlength=200.00 ms, minreq=10.00 ms
Oct 10 13:25:48 tlondon pulseaudio[10288]: protocol-native.c: Final latency 380.00 ms = 180.00 ms + 2*10.00 ms + 180.00 ms
Oct 10 13:26:31 tlondon pulseaudio[10288]: cpulimit.c: Recevied request to terminate due to CPU overload.
Oct 10 13:26:31 tlondon pulseaudio[10288]: main.c: Daemon shutdown initiated.
Oct 10 13:26:31 tlondon pulseaudio[10288]: module.c: Unloading "module-alsa-sink" (index: #0).
Oct 10 13:26:31 tlondon pulseaudio[10288]: module-device-restore.c: Restoring volume for sink auto_null.
Oct 10 13:26:31 tlondon pulseaudio[10288]: module-device-restore.c: Restoring mute state for sink auto_null.
Oct 10 13:26:31 tlondon pulseaudio[10288]: sink.c: Created sink 1 "auto_null" with sample spec s16le 2ch 44100Hz and channel map front-left,front-right
Oct 10 13:26:31 tlondon pulseaudio[10288]: module-device-restore.c: Restoring volume for source auto_null.monitor.
Oct 10 13:26:31 tlondon pulseaudio[10288]: module-device-restore.c: Restoring mute state for source auto_null.monitor.
Oct 10 13:26:31 tlondon pulseaudio[10288]: source.c: Created source 2 "auto_null.monitor" with sample spec s16le 2ch 44100Hz and channel map front-left,front-right
Oct 10 13:26:31 tlondon pulseaudio[10288]: module.c: Loaded "module-null-sink" (index: #14; argument: "sink_name=auto_null").
Oct 10 13:26:31 tlondon pulseaudio[10288]: protocol-native.c: Requested tlength=400.00 ms, minreq=10.00 ms
Oct 10 13:26:31 tlondon pulseaudio[10288]: module-rescue-streams.c: Sucessfully moved sink input 18 "Rhythmbox" to auto_null.
Oct 10 13:26:31 tlondon pulseaudio[10288]: sink.c: Freeing sink 0 "alsa_output.pci_8086_27d8_sound_card_0_alsa_playback_0"
Oct 10 13:26:31 tlondon pulseaudio[10288]: source.c: Freeing source 0 "alsa_output.pci_8086_27d8_sound_card_0_alsa_playback_0.monitor"
Oct 10 13:26:31 tlondon pulseaudio[10288]: module.c: Unloaded "module-alsa-sink" (index: #0).
Oct 10 13:26:31 tlondon pulseaudio[10288]: module.c: Unloading "module-alsa-source" (index: #1).
Oct 10 13:26:31 tlondon pulseaudio[10288]: source.c: Freeing source 1 "alsa_input.pci_8086_27d8_sound_card_0_alsa_capture_0"
Oct 10 13:26:31 tlondon pulseaudio[10288]: module.c: Unloaded "module-alsa-source" (index: #1).
Oct 10 13:26:31 tlondon pulseaudio[10288]: module.c: Unloading "module-hal-detect" (index: #2).
Oct 10 13:26:31 tlondon pulseaudio[10288]: module.c: Unloaded "module-hal-detect" (index: #2).
Oct 10 13:26:31 tlondon pulseaudio[10288]: module.c: Unloading "module-esound-protocol-unix" (index: #3).
Oct 10 13:26:31 tlondon pulseaudio[10288]: module.c: Unloaded "module-esound-protocol-unix" (index: #3).
Oct 10 13:26:31 tlondon pulseaudio[10288]: module.c: Unloading "module-native-protocol-unix" (index: #4).
Oct 10 13:26:31 tlondon pulseaudio[10288]: sink-input.c: Freeing input 18 "'Fat And Greasy' by 'Fats Waller'"
Oct 10 13:26:31 tlondon pulseaudio[10288]: client.c: Freed 19 "Rhythmbox"
Oct 10 13:26:31 tlondon pulseaudio[10288]: module.c: Unloaded "module-native-protocol-unix" (index: #4).
Oct 10 13:26:31 tlondon pulseaudio[10288]: module.c: Unloading "module-stream-restore" (index: #5).
Oct 10 13:26:31 tlondon pulseaudio[10288]: module.c: Unloaded "module-stream-restore" (index: #5).
Oct 10 13:26:31 tlondon pulseaudio[10288]: module.c: Unloading "module-device-restore" (index: #6).
Oct 10 13:26:31 tlondon pulseaudio[10288]: module.c: Unloaded "module-device-restore" (index: #6).
Oct 10 13:26:31 tlondon pulseaudio[10288]: module.c: Unloading "module-default-device-restore" (index: #7).
Oct 10 13:26:31 tlondon pulseaudio[10288]: module.c: Unloaded "module-default-device-restore" (index: #7).
Oct 10 13:26:31 tlondon pulseaudio[10288]: module.c: Unloading "module-rescue-streams" (index: #8).
Oct 10 13:26:31 tlondon pulseaudio[10288]: module.c: Unloaded "module-rescue-streams" (index: #8).
Oct 10 13:26:31 tlondon pulseaudio[10288]: module.c: Unloading "module-always-sink" (index: #9).
Oct 10 13:26:31 tlondon pulseaudio[10288]: module.c: Unloaded "module-always-sink" (index: #9).
Oct 10 13:26:31 tlondon pulseaudio[10288]: module.c: Unloading "module-suspend-on-idle" (index: #10).
Oct 10 13:26:31 tlondon pulseaudio[10288]: module.c: Unloaded "module-suspend-on-idle" (index: #10).
Oct 10 13:26:31 tlondon pulseaudio[10288]: module.c: Unloading "module-console-kit" (index: #11).
Oct 10 13:26:31 tlondon pulseaudio[10288]: client.c: Freed 0 "ConsoleKit Session /org/freedesktop/ConsoleKit/Session2"
Oct 10 13:26:31 tlondon pulseaudio[10288]: module.c: Unloaded "module-console-kit" (index: #11).
Oct 10 13:26:31 tlondon pulseaudio[10288]: module.c: Unloading "module-position-event-sounds" (index: #12).
Oct 10 13:26:31 tlondon pulseaudio[10288]: module.c: Unloaded "module-position-event-sounds" (index: #12).
Oct 10 13:26:31 tlondon pulseaudio[10288]: module.c: Unloading "module-gconf" (index: #13).
Oct 10 13:26:31 tlondon pulseaudio[10288]: module.c: Unloaded "module-gconf" (index: #13).
Oct 10 13:26:31 tlondon pulseaudio[10288]: module.c: Unloading "module-null-sink" (index: #14).
Oct 10 13:26:31 tlondon pulseaudio[10288]: sink.c: Freeing sink 1 "auto_null"
Oct 10 13:26:31 tlondon pulseaudio[10288]: source.c: Freeing source 2 "auto_null.monitor"
Oct 10 13:26:31 tlondon pulseaudio[10288]: module.c: Unloaded "module-null-sink" (index: #14).
Oct 10 13:26:31 tlondon pulseaudio[10288]: main.c: Daemon terminated.
Comment 5 Tom London 2008-10-10 16:43:39 EDT
Searching through old /var/log/message files, I see that this started on 6 October:

[root@tlondon ~]# grep 'CPU overload' /var/log/messages*
/var/log/messages:Oct  6 15:24:16 tlondon pulseaudio[3068]: cpulimit.c: Recevied request to terminate due to CPU overload.
/var/log/messages:Oct  6 16:48:59 tlondon pulseaudio[8641]: cpulimit.c: Recevied request to terminate due to CPU overload.
/var/log/messages:Oct  7 11:10:11 tlondon pulseaudio[3025]: cpulimit.c: Recevied request to terminate due to CPU overload.
/var/log/messages:Oct  7 15:40:24 tlondon pulseaudio[3030]: cpulimit.c: Recevied request to terminate due to CPU overload.
<<<SNIP - deleted messages from 7 Oct through 10 October>>>>
/var/log/messages:Oct 10 13:26:31 tlondon pulseaudio[10288]: cpulimit.c: Recevied request to terminate due to CPU overload.
[root@tlondon ~]# 

I updated to pulseaudio-0.9.13-1.fc10.i386 at 6:30AM of that morning.

In case its relevant, here is the complete list of packages updated then:

Oct 06 06:30:05 Updated: hal-libs-0.5.12-1.20081001git.fc10.i386
Oct 06 06:30:07 Updated: pulseaudio-libs-0.9.13-1.fc10.i386
Oct 06 06:30:08 Updated: libusb-0.1.12-18.fc10.i386
Oct 06 06:30:13 Updated: coreutils-6.12-11.fc10.i386
Oct 06 06:30:16 Updated: util-linux-ng-2.14.1-3.fc10.i386
Oct 06 06:30:17 Updated: libcanberra-0.10-1.fc10.i386
Oct 06 06:30:17 Updated: pulseaudio-core-libs-0.9.13-1.fc10.i386
Oct 06 06:30:19 Updated: pulseaudio-0.9.13-1.fc10.i386
Oct 06 06:30:19 Updated: lockdev-1.0.1-13.fc10.i386
Oct 06 06:30:19 Updated: lirc-libs-0.8.4-0.3.pre1.fc10.i386
Oct 06 06:30:19 Updated: pulseaudio-module-x11-0.9.13-1.fc10.i386
Oct 06 06:30:21 Updated: libcanberra-gtk2-0.10-1.fc10.i386
Oct 06 06:30:21 Updated: fakeroot-1.9.7-18.fc10.i386
Oct 06 06:30:25 Updated: hal-0.5.12-1.20081001git.fc10.i386
Oct 06 06:30:26 Updated: pulseaudio-libs-glib2-0.9.13-1.fc10.i386
Oct 06 06:30:26 Installed: pptp-1.7.2-3.fc10.i386
Oct 06 06:30:26 Installed: libv4l-0.5.0-1.fc10.i386
Oct 06 06:30:27 Updated: glibmm24-2.18.0-3.fc10.i386
Oct 06 06:30:37 Updated: gstreamer-plugins-good-0.10.10-5.fc10.i386
Oct 06 06:30:42 Updated: 1:NetworkManager-pptp-0.7.0-0.11.svn4027.fc10.i386
Oct 06 06:30:42 Updated: pulseaudio-module-gconf-0.9.13-1.fc10.i386
Oct 06 06:30:42 Updated: 1:obex-data-server-0.3.99-2.fc10.i386
Oct 06 06:30:43 Updated: pulseaudio-utils-0.9.13-1.fc10.i386
Oct 06 06:30:47 Updated: 1:doxygen-1.5.7.1-1.fc10.i386
Oct 06 06:30:47 Updated: xorg-x11-server-common-1.5.1-5.fc10.i386
Oct 06 06:30:47 Updated: kernel-firmware-2.6.27-0.393.rc8.git7.fc10.noarch
Oct 06 06:30:48 Updated: hal-devel-0.5.12-1.20081001git.fc10.i386
Oct 06 06:30:48 Updated: lirc-devel-0.8.4-0.3.pre1.fc10.i386
Oct 06 06:30:48 Updated: lockdev-devel-1.0.1-13.fc10.i386
Oct 06 06:30:48 Updated: pulseaudio-esound-compat-0.9.13-1.fc10.i386
Oct 06 06:30:49 Updated: libusb-devel-0.1.12-18.fc10.i386
Oct 06 06:30:52 Updated: kernel-headers-2.6.27-0.393.rc8.git7.fc10.i386
Oct 06 06:31:13 Installed: kernel-2.6.27-0.393.rc8.git7.fc10.i686
Oct 06 06:31:14 Updated: xorg-x11-server-Xorg-1.5.1-5.fc10.i386
Oct 06 06:31:15 Updated: PackageKit-yum-0.3.6-2.fc10.i386
Oct 06 06:31:15 Updated: PackageKit-libs-0.3.6-2.fc10.i386
Oct 06 06:31:15 Installed: PackageKit-gstreamer-plugin-0.3.6-2.fc10.i386
Oct 06 06:31:16 Updated: PackageKit-udev-helper-0.3.6-2.fc10.i386
Oct 06 06:31:18 Updated: PackageKit-0.3.6-2.fc10.i386
Oct 06 06:31:19 Updated: PackageKit-yum-plugin-0.3.6-2.fc10.i386
Oct 06 06:31:32 Updated: gnome-packagekit-0.3.6-2.fc10.i386
Oct 06 06:31:47 Erased: codeina
Oct 06 06:31:59 Installed: kernel-2.6.27-0.393.rc8.git7.fc10.i686
Comment 6 Tom London 2008-10-10 19:10:52 EDT
Got another daemon "CPU overload death" just after I ran this "top":

top - 16:06:04 up  7:16,  3 users,  load average: 1.24, 1.12, 1.00
Tasks: 148 total,   1 running, 147 sleeping,   0 stopped,   0 zombie
Cpu(s): 15.6%us, 25.9%sy,  0.0%ni, 57.1%id,  0.0%wa,  0.2%hi,  1.2%si,  0.0%st
Mem:   2064728k total,  2009264k used,    55464k free,   200696k buffers
Swap:  4096532k total,      508k used,  4096024k free,   634196k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND            
10790 tbl        9 -11  159m 4480 3568 S 46.8  0.2  45:12.78 pulseaudio         
 3505 tbl       20   0  801m 536m  22m S 11.3 26.6  49:14.83 qemu-kvm           
 3472 tbl       20   0  328m 136m  22m S 10.3  6.8  21:56.22 firefox            
10772 tbl       20   0  236m  40m  19m S  4.0  2.0   4:12.32 rhythmbox          

Notice that pulseaudio is at over 45 minutes of CPU time while rhythmbox is at just over 4 minutes.  [Both were started at the same time; rhythmbox was active about 50% of the time.]

Similar entries in /var/log/messages:

Oct 10 16:04:57 tlondon pulseaudio[10790]: sink-input.c: Created input 27 "Playback Stream" on alsa_output.pci_8086_27d8_sound_card_0_alsa_playback_0 with sample spec s16le 2ch 44100Hz and channel map front-left,front-right
Oct 10 16:04:57 tlondon pulseaudio[10790]: protocol-native.c: Requested tlength=200.00 ms, minreq=10.00 ms
Oct 10 16:04:57 tlondon pulseaudio[10790]: protocol-native.c: Final latency 380.00 ms = 180.00 ms + 2*10.00 ms + 180.00 ms
Oct 10 16:07:18 tlondon pulseaudio[10790]: cpulimit.c: Recevied request to terminate due to CPU overload.
Oct 10 16:07:18 tlondon pulseaudio[10790]: main.c: Daemon shutdown initiated.
Oct 10 16:07:18 tlondon pulseaudio[10790]: module.c: Unloading "module-alsa-sink" (index: #0).
Oct 10 16:07:18 tlondon pulseaudio[10790]: module-device-restore.c: Restoring volume for sink auto_null.
Comment 7 Stefan Becker 2008-10-11 09:53:01 EDT
Looks like I'm not the only one with pulseaudio going into a loop after some random time interval, causing it to be killed by the built-in CPU limiter function.

I think at least bugs #466530, #466231, #465610, #464816 and #462200 all describe the same issue.

pulseaudio-0.9.13-2.fc10.i386
kernel-2.6.27-1.fc10.i686
alsa-utils-1.0.18-3.rc3.fc10.i386
alsa-plugins-pulseaudio-1.0.18-1.rc3.fc10.i386
alsa-lib-1.0.18-6.rc3.fc10.i386

CPU:
vendor_id       : AuthenticAMD
cpu family      : 6
model           : 8
model name      : mobile AMD Athlon(tm) XP 2200+
stepping        : 1
cpu MHz         : 1326.790
cache size      : 256 KB

PCI:
00:00.0 Host bridge: VIA Technologies, Inc. P/KN266 Host Bridge
00:01.0 PCI bridge: VIA Technologies, Inc. VT8633 [Apollo Pro266 AGP]
...
00:11.0 ISA bridge: VIA Technologies, Inc. VT8235 ISA Bridge
00:11.1 IDE interface: VIA Technologies, Inc. VT82C586A/B/VT82C686/A/B/VT823x/A/C PIPC Bus Master IDE (rev 06)
00:11.5 Multimedia audio controller: VIA Technologies, Inc. VT8233/A/8235/8237 AC97 Audio Controller (rev 50)
00:11.6 Communication controller: VIA Technologies, Inc. AC'97 Modem Controller(rev 80)

$HOME/.default.pa:
# Set VIA8235 digital out as default sink
load-module module-alsa-sink device="hw:V8235,0,3" sink_name=via82xx_digital
set-default-sink via82xx_digital
# Load system configuration
.include /etc/pulse/default.pa
# Replace X11 bell
load-sample-lazy x11-bell /usr/share/sounds/KDE_Beep_Beep.wav
load-module module-x11-bell

$HOME/.daemon.conf:
; VIA8235 digital out has fixed sample rate
default-sample-rate = 48000

The computer has an optical SPDIF output which is connected to my home theatre amplifier. That's the reason for the 48000Hz fixed sample rate.


I already tried the following things without success:

- Granting high priority rights in PolicyKit
- Switching to "trivial" resampler
- Setting up ALSA plug device with fixed rate 48000 and slave "pcm", i.e. ALSA library does the resampling before the data reaches pulseaudio


I ran pulseaudio with --log-level=debug but it doesn't show anything when the daemon goes into the CPU eating mode.


I'm using the following programs:

- "mplayer -ao alsa" to play an 64kbps MP3 live radio stream from the Internet
- amarok-1.4.10-1.fc9.i386 (I had to remove Amarok 2 Beta 2 again as it is completely useless for end users currently) to play my music collection of OggVorbis encoded files.


For now I've stopped the pulseaudio daemon and switched back to a 48000Hz fixed-rate ALSA plug device for playback and everything works OK, but of course the audio device is not shared anymore.
Comment 8 Tom London 2008-10-11 12:43:55 EDT
Thanks for the pointer to #462200.

I've applied the patch there to alsa-lib*-1.0.18-6.rc3.fc10.i386 and installed.

I'll test this for a while to see if it makes any difference.
Comment 9 Tom London 2008-10-11 14:30:45 EDT
Created attachment 320101 [details]
5 second strace of "pulseaudio daemon" while it appears to be "spinning"

Applying the patch to alsa-lib described in BZ#462200 does not work for me.

After building/installing and rebooting, I continue to get "pulseaudio daemon over consumption":

Tasks: 152 total,   4 running, 148 sleeping,   0 stopped,   0 zombie
Cpu(s):  4.6%us,  9.8%sy,  0.2%ni, 84.5%id,  0.9%wa,  0.1%hi,  0.0%si,  0.0%st
Mem:   2064728k total,  1010012k used,  1054716k free,    75676k buffers
Swap:  4096532k total,        0k used,  4096532k free,   487768k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND            
 3013 tbl        9 -11  160m 5072 4028 S 38.9  0.2  16:49.76 pulseaudio         
 4645 tbl       20   0  279m  92m  21m R 13.0  4.6   0:38.70 firefox            
 2567 root      20   0  419m  54m  13m R  9.3  2.7   1:19.30 Xorg               
    6 root      RT  -5     0    0    0 S  1.9  0.0   0:01.51 migration/1        
 3356 tbl       20   0 11336 6264 4124 S  1.9  0.3   0:04.41 compiz             
 4748 root      20   0  2588  940  708 R  1.9  0.0   0:00.02 top                
    1 root      20   0  2020  884  664 S  0.0  0.0   0:01.17 init               
    2 root      15  -5     0    0    0 S  0.0  0.0   0:00.01 kthreadd  

Although rhythmbox is running, is appears frozen and no sound is being produced. It does not appear to be consuming significant cycles.

Attached here is a 5 second strace of pulseaudio (process 3013 above).

I attach below a 5 second strace of rhythmbox taken "just before" the strace here.
Comment 10 Tom London 2008-10-11 14:32:58 EDT
Created attachment 320102 [details]
5 second strace of "rhythmbox" when pulseaudio appears to be spinning

Rhythmbox appears frozen.  The "time indicator" shown by placing the cursor over the rhythmbox icon in the notification area shows a frozen indication of "5:15 of 2:02"
Comment 11 Tom London 2008-10-11 14:39:02 EDT
For completeness, I'm running latest rawhide, including kernel-2.6.27-3.fc10.i686.

My system is Thinkpad X60 with Intel audio:
00:1b.0 Audio device: Intel Corporation 82801G (ICH7 Family) High Definition Audio Controller (rev 02)


After applying patch described in https://bugzilla.redhat.com/show_bug.cgi?id=462200 I see pulseaudio still behaving as before with no additional error messages (that I can find).
Comment 12 Stefan Becker 2008-10-12 04:35:28 EDT
Created attachment 320136 [details]
5 seconds strace log from spinning pulsaudio process

Updated to latest mplayer from rpmfusion which now comes with the pulse audio output plugin. With my standard MP3 livestream from the Internet the mplayer clock stopped at 6:20 when the pulseaudio process started to spin. The music stream was still played correctly though:

Playing http://213.200.97.110:80/swr3live/livestream.mp3.
...
Bitrate: 64kbit/s                                         
Cache size set to 320 KBytes                              
...
Audio only file format detected.                          
==========================================================================
Opening audio decoder: [mp3lib] MPEG layer-2, layer-3                     
mpg123: Can't rewind stream by 304 bits!                                  
AUDIO: 44100 Hz, 2 ch, s16le, 64.0 kbit/4.54% (ratio: 8000->176400)       
Selected audio codec: [mp3] afm: mp3lib (mp3lib MPEG layer-2, layer-3)    
==========================================================================
AO: [pulse] 44100Hz 2ch s16le (2 bytes per sample)                        
Video: no video                                                           
Starting playback...                                                      
mpg123: Can't rewind stream by 447 bits!                                  
A: 380.7 (06:20.7) of -0.0 (unknown)  0.6% 38%
Comment 13 Stefan Becker 2008-10-18 09:24:39 EDT
Any progress on this matter? Anything we can do to help debug this problem?

I tried to take an oprofile today but for some unknown reason (and missing documentation) opreport/opannotate think the debugging info and source codes are missing although the pulseaudio-debuginfo RPM was installed. Without that information the profile taken was not very informative. If an oprofile would help you please provide detailed instructions how to to take it correctly.
Comment 14 Tom London 2008-10-18 13:30:04 EDT
I have been "replacing" my Thinkpad X60 with a Thinkpad X61 (x86_64).

I have copied over all the music files (mp3's) and installed the x86_64 fluendo codec.

I have been unable to reproduce this issue on this new setup running either Spin1 or Spin2......
Comment 15 Lennart Poettering 2008-10-19 16:50:54 EDT
Looks like yet another duplicate of 462200.

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