[pulseaudio-discuss] How to debug pulseaudio?

[Clive Messer]

Hi,

I'd like some help debugging pulseaudio, please. Since upgrading my
Fedora 9 install to the latest 2.6.26 kernels, pulseaudio is forever
shutting down for what appears to be no reason. This does not happen on
2.6.25 kernels. What's interesting is this does not appear to be ALSA,
issue per se, or at least sending audio directly to ALSA works fine and
does not cause problems, it's only pulseuadio that is not happy. 

I have attached a log of pulseaudio -vvvv. Audio was playing from
Amarok, using Xine pulseaudio plugin. After period of time, CPU goes
100% on one of the four cores and pulseaudio shuts down. I would
appreciate it if someone could take a look at the log and provide
instructions if further logging or debugging is required.

Versions of software ....

alsa-plugins-pulseaudio-1.0.16-4.fc9.x86_64
pulseaudio-0.9.10-2.fc9.x86_64
pulseaudio-core-libs-0.9.10-2.fc9.x86_64
pulseaudio-esound-compat-0.9.10-2.fc9.x86_64
pulseaudio-libs-0.9.10-2.fc9.x86_64
pulseaudio-libs-glib2-0.9.10-2.fc9.x86_64
pulseaudio-libs-zeroconf-0.9.10-2.fc9.x86_64
pulseaudio-module-bluetooth-0.9.10-2.fc9.x86_64
pulseaudio-module-gconf-0.9.10-2.fc9.x86_64
pulseaudio-module-jack-0.9.10-2.fc9.x86_64
pulseaudio-module-lirc-0.9.10-2.fc9.x86_64
pulseaudio-module-x11-0.9.10-2.fc9.x86_64
pulseaudio-module-zeroconf-0.9.10-2.fc9.x86_64
pulseaudio-utils-0.9.10-2.fc9.x86_64

kernel-2.6.26.3-29.fc9.x86_64
kernel-2.6.26.5-45.fc9.x86_64

[clivem at pc343:~]$ aplay -l
**** List of PLAYBACK Hardware Devices ****
card 0: Intel [HDA Intel], device 0: ALC883 Analog [ALC883 Analog]
  Subdevices: 1/1
  Subdevice #0: subdevice #0
card 0: Intel [HDA Intel], device 1: ALC883 Digital [ALC883 Digital]
  Subdevices: 1/1
  Subdevice #0: subdevice #0

[clivem at pc343:~]$ aplay -L
front:CARD=Intel,DEV=0
    HDA Intel, ALC883 Analog
    Front speakers
surround40:CARD=Intel,DEV=0
    HDA Intel, ALC883 Analog
    4.0 Surround output to Front and Rear speakers
surround41:CARD=Intel,DEV=0
    HDA Intel, ALC883 Analog
    4.1 Surround output to Front, Rear and Subwoofer speakers
surround50:CARD=Intel,DEV=0
    HDA Intel, ALC883 Analog
    5.0 Surround output to Front, Center and Rear speakers
surround51:CARD=Intel,DEV=0
    HDA Intel, ALC883 Analog
    5.1 Surround output to Front, Center, Rear and Subwoofer speakers
surround71:CARD=Intel,DEV=0
    HDA Intel, ALC883 Analog
    7.1 Surround output to Front, Center, Side, Rear and Woofer speakers
iec958:CARD=Intel,DEV=0
    HDA Intel, ALC883 Digital
    IEC958 (S/PDIF) Digital Audio Output
hdmi:CARD=Intel,DEV=0
    HDA Intel
    HDMI Audio Output
null
    Discard all samples (playback) or generate zero samples (capture)
pulse
    PulseAudio Sound Server
default
    Default


Regards

Clive
-- 
Clive Messer <clive at vacuumtube.org.uk>


-------------- next part --------------
I: main.c: PolicyKit grants us acquire-high-priority privilige.
I: main.c: PolicyKit grants us acquire-real-time privilige.
I: main.c: We're in the group 'pulse-rt', allowing real-time and high-priority scheduling.
I: core-util.c: Successfully gained nice level -11.
I: main.c: Successfully increased RLIMIT_RTPRIO, giving up CAP_NICE.
I: main.c: This is PulseAudio 0.9.10
I: main.c: Page size is 4096 bytes
I: main.c: Fresh high-resolution timers available! Bon appetit!
D: cli-command.c: Checking for existance of '/usr/lib64/pulse-0.9/modules/module-hal-detect.so': success
I: module-hal-detect.c: Trying capability alsa
D: module-hal-detect.c: Not loaded device /org/freedesktop/Hal/devices/computer_alsa_timer
D: module-hal-detect.c: Not loaded device /org/freedesktop/Hal/devices/computer_alsa_sequencer
D: module-hal-detect.c: Not loaded device /org/freedesktop/Hal/devices/pci_8086_3a3e_sound_card_0_alsa_capture_2
D: module-hal-detect.c: Not loaded device /org/freedesktop/Hal/devices/pci_8086_3a3e_sound_card_0_alsa_playback_1
D: module-hal-detect.c: Not loaded device /org/freedesktop/Hal/devices/pci_8086_3a3e_sound_card_0_alsa_capture_1
D: module-hal-detect.c: Loading module-alsa-sink with arguments 'device_id=0 sink_name=alsa_output.pci_8086_3a3e_sound_card_0_alsa_playback_0'
D: alsa-util.c: Trying front:0...
I: module-alsa-sink.c: Successfully opened device front:0.
I: module-alsa-sink.c: Successfully enabled mmap() mode.
ALSA lib control.c:909:(snd_ctl_open_noupdate) Invalid CTL front:0
I: alsa-util.c: Unable to attach to mixer front:0: No such file or directory
I: alsa-util.c: Successfully attached to mixer 'hw:0'
I: alsa-util.c: Using mixer control "Master".
I: sink.c: Created sink 0 "alsa_output.pci_8086_3a3e_sound_card_0_alsa_playback_0" with sample spec "s16le 2ch 44100Hz"
I: source.c: Created source 0 "alsa_output.pci_8086_3a3e_sound_card_0_alsa_playback_0.monitor" with sample spec "s16le 2ch 44100Hz"
I: module-alsa-sink.c: Using 4 fragments of size 4352 bytes.
I: alsa-util.c: ALSA device lacks independant volume controls for each channel, falling back to software volume control.
D: module-alsa-sink.c: Thread starting up
I: core-util.c: Successfully enabled SCHED_FIFO scheduling for thread, with priority 5.
D: rtpoll.c: Acquired POSIX realtime signal SIGRTMIN+29
I: module-alsa-sink.c: Starting playback.
I: module.c: Loaded "module-alsa-sink" (index: #0; argument: "device_id=0 sink_name=alsa_output.pci_8086_3a3e_sound_card_0_alsa_playback_0").
D: module-hal-detect.c: Loading module-alsa-source with arguments 'device_id=0 source_name=alsa_input.pci_8086_3a3e_sound_card_0_alsa_capture_0'
D: alsa-util.c: Trying front:0...
I: module-alsa-source.c: Successfully opened device front:0.
I: module-alsa-source.c: Successfully enabled mmap() mode.
ALSA lib control.c:909:(snd_ctl_open_noupdate) Invalid CTL front:0
I: alsa-util.c: Unable to attach to mixer front:0: No such file or directory
I: alsa-util.c: Successfully attached to mixer 'hw:0'
I: alsa-util.c: Using mixer control "Capture".
I: source.c: Created source 1 "alsa_input.pci_8086_3a3e_sound_card_0_alsa_capture_0" with sample spec "s16le 2ch 44100Hz"
I: module-alsa-source.c: Using 4 fragments of size 4352 bytes.
I: alsa-util.c: All 2 channels can be mapped to mixer channels. Using hardware volume control.
D: module-alsa-source.c: Thread starting up
I: core-util.c: Successfully enabled SCHED_FIFO scheduling for thread, with priority 5.
D: rtpoll.c: Acquired POSIX realtime signal SIGRTMIN+28
I: module.c: Loaded "module-alsa-source" (index: #1; argument: "device_id=0 source_name=alsa_input.pci_8086_3a3e_sound_card_0_alsa_capture_0").
D: module-hal-detect.c: Not loaded device /org/freedesktop/Hal/devices/pci_8086_3a3e_sound_card_0_alsa_hw_specific_2
D: module-hal-detect.c: Not loaded device /org/freedesktop/Hal/devices/pci_8086_3a3e_sound_card_0_alsa_control__1
I: module-hal-detect.c: Loaded 2 modules.
I: module.c: Loaded "module-hal-detect" (index: #2; argument: "").
D: cli-command.c: Checking for existance of '/usr/lib64/pulse-0.9/modules/module-esound-protocol-unix.so': success
I: module.c: Loaded "module-esound-protocol-unix" (index: #3; argument: "").
I: protocol-native.c: loading cookie from disk.
I: module.c: Loaded "module-native-protocol-unix" (index: #4; argument: "").
I: module.c: Loaded "module-volume-restore" (index: #5; argument: "").
D: module-default-device-restore.c: Restored default sink 'alsa_output.pci_8086_3a3e_sound_card_0_alsa_playback_0'.
D: core-subscribe.c: dropped redundant event.
D: module-default-device-restore.c: Restored default source 'alsa_input.pci_8086_3a3e_sound_card_0_alsa_capture_0'.
I: module.c: Loaded "module-default-device-restore" (index: #6; argument: "").
I: module.c: Loaded "module-rescue-streams" (index: #7; argument: "").
D: module-suspend-on-idle.c: Sink alsa_output.pci_8086_3a3e_sound_card_0_alsa_playback_0 becomes idle.
D: module-suspend-on-idle.c: Source alsa_output.pci_8086_3a3e_sound_card_0_alsa_playback_0.monitor becomes idle.
D: module-suspend-on-idle.c: Source alsa_input.pci_8086_3a3e_sound_card_0_alsa_capture_0 becomes idle.
I: module.c: Loaded "module-suspend-on-idle" (index: #8; argument: "").
D: cli-command.c: Checking for existance of '/usr/lib64/pulse-0.9/modules/module-gconf.so': success
I: module.c: Loaded "module-gconf" (index: #9; argument: "").
D: cli-command.c: Checking for existance of '/usr/lib64/pulse-0.9/modules/module-x11-publish.so': success
D: module-x11-publish.c: using already loaded auth cookie.
I: module.c: Loaded "module-x11-publish" (index: #10; argument: "").
I: main.c: Daemon startup complete.
D: module-hal-detect.c: dbus: interface=org.freedesktop.DBus, path=/org/freedesktop/DBus, member=NameAcquired
I: module-suspend-on-idle.c: Source alsa_input.pci_8086_3a3e_sound_card_0_alsa_capture_0 idle for too long, suspending ...
I: module-alsa-source.c: Device suspended...
I: module-suspend-on-idle.c: Source alsa_output.pci_8086_3a3e_sound_card_0_alsa_playback_0.monitor idle for too long, suspending ...
I: module-suspend-on-idle.c: Sink alsa_output.pci_8086_3a3e_sound_card_0_alsa_playback_0 idle for too long, suspending ...
I: module-alsa-sink.c: Device suspended...
I: client.c: Created 0 "Native client (UNIX socket client)"
I: protocol-native.c: Got credentials: uid=500 gid=500 success=1
I: protocol-native.c: Enabled SHM for new connection
I: client.c: Client 0 changed name from "Native client (UNIX socket client)" to "amarokapp"
I: module-volume-restore.c: Restoring sink for <pulsecore/protocol-native.c$amarokapp>
I: module-volume-restore.c: Restoring volume for <pulsecore/protocol-native.c$amarokapp>
I: module-alsa-sink.c: Trying resume...
I: module-alsa-sink.c: Resumed successfully...
I: module-alsa-sink.c: Starting playback.
D: module-suspend-on-idle.c: Sink alsa_output.pci_8086_3a3e_sound_card_0_alsa_playback_0 becomes idle.
D: module-suspend-on-idle.c: Sink alsa_output.pci_8086_3a3e_sound_card_0_alsa_playback_0 becomes busy.
I: sink-input.c: Created input 0 "Audio Stream" on alsa_output.pci_8086_3a3e_sound_card_0_alsa_playback_0 with sample spec s16le 2ch 44100Hz and channel map front-left,front-right
D: memblockq.c: memblockq requested: maxlength=132300, tlength=88200, base=4, prebuf=86436, minreq=1764
D: memblockq.c: memblockq sanitized: maxlength=132300, tlength=88200, base=4, prebuf=86436, minreq=1764
I: client.c: Created 1 "EsounD client (UNIX socket client)"
I: client.c: Created 2 "EsounD client (UNIX socket client)"
D: protocol-esound.c: read(): EOF
I: client.c: Freed 2 "EsounD client (UNIX socket client)"
Soft CPU time limit exhausted, terminating.
Hard CPU time limit exhausted, terminating forcibly.