Bug 466530

Summary: Hard CPU time limit exhausted, terminating forcibly.
Product: [Fedora] Fedora Reporter: Mads Kiilerich <mads>
Component: pulseaudioAssignee: Lennart Poettering <lpoetter>
Status: CLOSED DUPLICATE QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: high Docs Contact:
Priority: medium    
Version: rawhideCC: lkundrak, lpoetter, matthew.hirsch, mclasen, pierre-bugzilla
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:47:37 EDT Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Bug Depends On:    
Bug Blocks: 457945    

Description Mads Kiilerich 2008-10-10 15:00:08 EDT
Description of problem:

pulseaudio dies because of exhaustion. Seen when flash playing from myspace. I think I have noticed on my load monitor that something starts eating cpu just before pulse dies.

I think my setup is quite normal and should work.

$ pulseaudio -v
I: caps.c: Limited capabilities successfully to CAP_SYS_NICE.
I: caps.c: Dropping root priviliges.
I: caps.c: Limited capabilities successfully to CAP_SYS_NICE.
I: main.c: We're in the group 'pulse-rt', allowing high-priority scheduling.
I: core-util.c: Successfully gained nice level -11.
I: main.c: Giving up CAP_NICE
I: main.c: This is PulseAudio 0.9.13
I: main.c: Page size is 4096 bytes
I: main.c: Machine ID is 7364f81f52869091316dde0046824401.
I: main.c: Using runtime directory /home/mk/.pulse/7364f81f52869091316dde0046824401:runtime.
I: main.c: Using state directory /home/mk/.pulse.
I: main.c: Running in system mode: no
I: main.c: Fresh high-resolution timers available! Bon appetit!
I: module-hal-detect.c: Trying capability alsa
I: module-alsa-sink.c: Successfully opened device front:0.
I: module-alsa-sink.c: Successfully enabled mmap() mode.
I: module-alsa-sink.c: Successfully enabled timer-based scheduling mode.
I: (alsa-lib)control.c: 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_284b_sound_card_0_alsa_playback_0" with sample spec s16le 2ch 44100Hz and channel map front-left,front-right
I: source.c: Created source 0 "alsa_output.pci_8086_284b_sound_card_0_alsa_playback_0.monitor" with sample spec s16le 2ch 44100Hz and channel map front-left,front-right
I: module-alsa-sink.c: Using 2 fragments of size 32768 bytes, buffer time is 371.52ms
I: module-alsa-sink.c: Time scheduling watermark is 20.00ms
I: module-alsa-sink.c: Volume ranges from 0 to 63.
I: module-alsa-sink.c: Volume ranges from -94.50 dB to 0.00 dB.
I: alsa-util.c: ALSA device lacks independant volume controls for each channel.
I: module-alsa-sink.c: Using hardware volume control. Hardware dB scale supported.
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_284b_sound_card_0_alsa_playback_0 tsched=1").

...

I: module-alsa-sink.c: Underrun!
N: module-alsa-sink.c: Increasing wakeup watermark to 80.00 ms
Soft CPU time limit exhausted, terminating.
E: cpulimit.c: Recevied request to terminate due to CPU overload.
I: main.c: Daemon shutdown initiated.
I: module.c: Unloading "module-alsa-sink" (index: #0).
I: module-device-restore.c: Restoring volume for sink auto_null.
I: module-device-restore.c: Restoring mute state for sink auto_null.
I: sink.c: Created sink 1 "auto_null" with sample spec s16le 2ch 44100Hz and channel map front-left,front-right
I: module-device-restore.c: Restoring volume for source auto_null.monitor.
I: module-device-restore.c: Restoring mute state for source auto_null.monitor.
I: source.c: Created source 2 "auto_null.monitor" with sample spec s16le 2ch 44100Hz and channel map front-left,front-right
I: module.c: Loaded "module-null-sink" (index: #14; argument: "sink_name=auto_null").
I: protocol-native.c: Requested tlength=2040.00 ms, minreq=20.00 ms
I: module-rescue-streams.c: Sucessfully moved sink input 13 "Adobe Flash" to auto_null.
I: sink.c: Freeing sink 0 "alsa_output.pci_8086_284b_sound_card_0_alsa_playback_0"
I: source.c: Freeing source 0 "alsa_output.pci_8086_284b_sound_card_0_alsa_playback_0.monitor"
I: module.c: Unloaded "module-alsa-sink" (index: #0).
I: module.c: Unloading "module-alsa-source" (index: #1).
Hard CPU time limit exhausted, terminating forcibly.
Aborted


I assume this is OK:
$ tail /etc/security/limits.conf

# End of file

## Automatically appended by jack-audio-connection-kit
@jackuser - rtprio 20
@jackuser - memlock 4194304

## Automatically appended by jack-audio-connection-kit
@pulse-rt - rtprio 20
@pulse-rt - nice -20


https://bugs.launchpad.net/ubuntu/+source/pulseaudio/+bug/202089 might be similar ...


Version-Release number of selected component (if applicable):

pulseaudio-libs-0.9.13-2.fc10.i386
pulseaudio-module-x11-0.9.13-2.fc10.i386
pulseaudio-esound-compat-0.9.13-2.fc10.i386
pulseaudio-module-gconf-0.9.13-2.fc10.i386
pulseaudio-0.9.13-2.fc10.i386
pulseaudio-utils-0.9.13-2.fc10.i386
pulseaudio-core-libs-0.9.13-2.fc10.i386
pulseaudio-libs-glib2-0.9.13-2.fc10.i386
gstreamer-plugins-pulse-0.9.7-1.fc10.i386
xine-lib-pulseaudio-1.1.15-1.fc10.1.i386
alsa-plugins-pulseaudio-1.0.18-1.rc3.fc10.i386
flash-plugin-9.0.124.0-release.i386
libflashsupport-000-0.5.svn20070904.i386
nspluginwrapper-1.1.0-11.fc10.i386
kernel-2.6.27-1.fc10.i686

How reproducible:

happened a couple of times after half en hour
Comment 1 Matt Hirsch 2008-10-14 16:32:59 EDT
I also experience this bug. I'm running Fedora 9 x86_64, fully updated:

kernel-2.6.26.5-45.fc9.x86_64
pulseaudio-0.9.10-2.fc9.x86_64
alsa-plugins-pulseaudio-1.0.16-4.fc9.x86_64
alsa-utils-1.0.17-2.fc9.x86_64
alsa-lib-1.0.17-2.fc9.x86_64

After running for awhile, the pulseaudio daemon dies. If I restart it on the terminal, after awhile I get this:

Soft CPU time limit exhausted, terminating.
Hard CPU time limit exhausted, terminating forcibly.
Aborted

This may be related to the adobe flash player crashing (which seems to happen a lot on my system). However, it does not happen every time the flash player crashes, nor does the flash player crash every time it happens.

I haven't changed the default pulseaudio configuration, though I upgraded the system from F7 -> F8 -> F9 through yum update.
Comment 2 Matt Hirsch 2008-10-14 16:36:52 EDT
http://www.pulseaudio.org/ticket/207

This pulseaudio bug may be related. 

Why isn't the pulseaudio bugtracker an option in external bugs in bugzilla?
Comment 3 Mads Kiilerich 2008-10-14 19:39:22 EDT
Matthew:

I am quite sure that I have seen the problem on an un-resumed machine.

I also thought this (or a similar) problem was related to flash. But the problem has also appeared without flash or nspluginwrapper running, just pidgin and rhythmbox playing ogg.

I don't know how much the audio infrastructure has changed between f9 and f10, but I don't think we should assume that they have similar problems.
Comment 4 Matt Hirsch 2008-10-14 20:51:49 EDT
I never suspend or hibernate my machine, and I still get this problem. Since the symptom is so similar it seems reasonable that they are related problems.
Comment 5 Matthias Clasen 2008-10-15 20:43:22 EDT
I am seeing this problem too. pulseaudio commits suicide after playing ~ 1 cd worth of music in rhythmbox. The only other client open was pavucontrol. 

Full log of pa -vvv available upon request.
Comment 6 Mads Kiilerich 2008-10-15 21:15:32 EDT
This is perhaps the same as or related to

Bug 466316 - Daemon hangs, starts eating up CPU cycles, rhythmbox freezes 
Bug 466338 -  I: memblock.c: Pool full
Comment 7 Mads Kiilerich 2008-10-16 11:45:52 EDT
I just got
Oct 16 17:33:21 dev-mk pulseaudio[3265]: cpulimit.c: Recevied request to terminate due to CPU overload.

That was when playing an ogg from rhythmbox. flash-plugin not installed. (livna plugins is installed but not used.) Rhythmbox was hanging and didn't redraw after that. I assume that that is a rhythmbox bug ...

5 seconds before the suicide something (the pulseaudio process, I assume) started using 100% of one cpu (on my dual-core system). So the problem isn't that pulseaudio terminates, but that it starts using all cpu.

With log-level = debug nothing was logged when it started eating cpu.

I am setting the severity to high.
Comment 8 Lennart Poettering 2008-10-17 06:38:30 EDT
Which driver is this?
Comment 9 Mads Kiilerich 2008-10-17 08:48:12 EDT
I don't know how to answer that - does the following answer it?

==> /proc/asound/modules <==
 0 snd_hda_intel

==> /proc/asound/card0/codec#0 <==
Codec: Analog Devices AD1983
Address: 0
Vendor Id: 0x11d41983
Subsystem Id: 0x102801da
Revision Id: 0x100400
No Modem Function Group found
Default PCM:
    rates [0x7f]: 8000 11025 16000 22050 32000 44100 48000
    bits [0xe]: 16 20 24
    formats [0x1]: PCM
Comment 10 Lennart Poettering 2008-10-19 16:34:58 EDT
Yes it does.

Could you please generate a bit of profiling for me? 

http://pulseaudio.org/wiki/HowToUseOProfile

This will help me understand where exactly PA starts to spin in a 100%-CPU-Loop.

Please make sure to run the newest kernel from rawhide when doing this.
Comment 11 Lennart Poettering 2008-10-19 16:47:37 EDT
Oh and this actually looks like yet another dupe of 462200...

*** This bug has been marked as a duplicate of bug 462200 ***
Comment 12 Mads Kiilerich 2008-10-20 06:53:21 EDT
I can confirm that with the latest updates it seems to work a lot better.

Stressing the machine still gives

Oct 20 12:03:37 dev-mk pulseaudio[3360]: protocol-native.c: Requested tlength=200.00 ms, minreq=10.00 ms
Oct 20 12:03:37 dev-mk pulseaudio[3360]: protocol-native.c: Final latency 380.00 ms = 180.00 ms + 2*10.00 ms + 180.00 ms
Oct 20 12:30:51 dev-mk kernel: [drm] Num pipes: 1
Oct 20 12:31:14 dev-mk pulseaudio[3360]: module-alsa-sink.c: Underrun!
Oct 20 12:31:14 dev-mk pulseaudio[3360]: module-alsa-sink.c: Increasing wakeup watermark to 40.00 ms
Oct 20 12:31:14 dev-mk pulseaudio[3360]: module-alsa-sink.c: Underrun!
Oct 20 12:31:14 dev-mk pulseaudio[3360]: module-alsa-sink.c: Increasing wakeup watermark to 80.00 ms
Oct 20 12:31:24 dev-mk pulseaudio[3360]: module-alsa-sink.c: Device suspended...
Oct 20 12:32:03 dev-mk pulseaudio[3360]: sink-input.c: Freeing input 12 "'Last Night When We Were Young' by 'Caroline Henderson'"
Oct 20 12:32:11 dev-mk pulseaudio[3360]: client.c: Freed 20 "Rhythmbox"
Oct 20 12:32:11 dev-mk pulseaudio[3360]: protocol-native.c: Connection died.
Oct 20 12:32:30 dev-mk pulseaudio[3360]: client.c: Created 21 "Native client (UNIX socket client)"
Oct 20 12:32:30 dev-mk pulseaudio[3360]: protocol-native.c: Got credentials: uid=500 gid=500 success=1
Oct 20 12:32:39 dev-mk pulseaudio[3360]: module-stream-restore.c: Restoring device for stream sink-input-by-application-name:Rhythmbox.
Oct 20 12:32:39 dev-mk pulseaudio[3360]: module-stream-restore.c: Restoring volume for sink input sink-input-by-application-name:Rhythmbox.
Oct 20 12:32:39 dev-mk pulseaudio[3360]: module-alsa-sink.c: Trying resume...
Oct 20 12:32:40 dev-mk pulseaudio[3360]: (alsa-lib)conf.c: Unknown parameters 0
Oct 20 12:32:40 dev-mk pulseaudio[3360]: (alsa-lib)pcm.c: Unknown PCM front:0
Oct 20 12:32:40 dev-mk pulseaudio[3360]: module-alsa-sink.c: Error opening PCM device front:0: Invalid argument
Oct 20 12:32:40 dev-mk pulseaudio[3360]: resampler.c: Forcing resampler 'copy', because of fixed, identical sample rates.
Oct 20 12:32:40 dev-mk pulseaudio[3360]: resampler.c: Using resampler 'copy'
Oct 20 12:32:40 dev-mk pulseaudio[3360]: resampler.c: Using float32le as working format.
Oct 20 12:32:40 dev-mk pulseaudio[3360]: sink-input.c: Created input 13 "Playback Stream" on alsa_output.pci_8086_284b_sound_card_0_alsa_playback_0 with sample spec float32le 2ch 44100Hz and channel map front-left,front-right
Oct 20 12:32:40 dev-mk pulseaudio[3360]: protocol-native.c: Requested tlength=200.00 ms, minreq=10.00 ms
Oct 20 12:32:40 dev-mk pulseaudio[3360]: protocol-native.c: Final latency 380.00 ms = 180.00 ms + 2*10.00 ms + 180.00 ms
Oct 20 12:32:50 dev-mk pulseaudio[3360]: sink-input.c: Assertion 'i->thread_info.rewrite_nbytes == 0' failed at pulsecore/sink-input.c:1147, function pa_sink_input_request_rewind(). Aborting.

Which causes Rhythmbox to hang.

Is an oprofile interesting in that situation too?