Page MenuHome

100% CPU - One Thread
Closed, InvalidPublic

Description

Arch Linux 2.6.35
Blender 2.55 rev. 33087
pulseaudio 0.9.21

Requires: Pulseaudio + removable (usb) sound card

Reproduce:
. use pulseaudio as default audio device
. start blender
. remove sound card

Result: 100% CPU on one thread

Affects: laptop users

Details

Type
Bug

Event Timeline

Another case of bad local pulseaudio install?

Assigning to our sound expert :)

Hmm, most likely... Have I ever stated that I hate pulseaudio? :-)

Questions:
- What output device are you using? OpenAL or SDL?
- What happens if you remove the card while having another application running that uses the same library (OpenAL/SDL)?

Most likely there will be nothing I can do about, report the bug to pulseaudio...

BTW: you have arch linux? why the hell are you using pulse? xD

I'm using blender with OpenAL, configured:
. stereo
. 2048
. 44.1 kHz
. 32-bit float

I've tested OpenAL through PulseAudio with:
. supertux2
. warsow
None show CPU bug when removing USB sound device. OpenAL is configured as:
$ cat .openalrc
(define devices '(alsa))
(define alsa-device "pulse")


Similar with SDL. Tested against:
. mplayer
[export SDL_AUDIODRIVER=alsa; mplayer -ao sdl big_buck_bunny_480p_h264.mov]
. hedgewars


Hehe, abut pulse... I started using linux back when dmix was a POS (really not that long ago). Now I can't live without its routing and recording capabilities.

Well, the question is how I should debug that... I have neither a USB sound card nor pulse audio...
Can you check if the usage normalizes again if you switch to the "None" Device in the settings? And does the same happen if you chose SDL as backend?

Hm, difficult. Not sure how to help. I tried running strace
strace -t -o blender_audio_strace ./blender
I pulled the usb card out at 15:28:40 +- 1 sec but nothing shows up in the log, just megabytes of the following:

15:28:39 nanosleep({0, 5000000}, NULL) = 0
15:28:40 gettimeofday({1290198520, 1273}, NULL) = 0
15:28:40 read(3, 0x96ae418, 4096) = -1 EAGAIN (Resource temporarily unavailable)

Answer #1
. start blender with OpenAL audio output -> remove usb device -> high cpu usage -> blah blah
. in blender preferences switch to "None" device. CPU automatically drops to <1.0%
. in blender preferences switch back to "OpenAL" device. CPU remains <1.0%

Answer #2
. Couldn't reproduce with SDL

Can you try the attached patch, if it removes the problem please?

Afraid Not.

More information: whatever causes this bug, causes blender to hang, ie. either kill -s 9 blender or kill the parent process (terminal) in order to close the application. So maybe I can try running in GDB.

I tried to build blender with debugging symbols:
scons -j 2 BF_DEBUG=True

Then, started GDB. Waited for CPU bug. Pressed [ctrl-c] in GDB. Backtracke might be helpful???
(gdb) exec-file blender.run
(gdb) run
Starting program: /home/orbisvicis/Q/luxrender-blender-vcs/blender/PATCH/blender.run
[Thread debugging using libthread_db enabled]
[New Thread 0xaf5f9b70 (LWP 9408)]
[New Thread 0xaedf8b70 (LWP 9409)]
found bundled python: /home/orbisvicis/Q/luxrender-blender-vcs/blender/PATCH/install/linux2/2.55/python

^C
Program received signal SIGINT, Interrupt.
0xb7fe1424 in __kernel_vsyscall ()
(gdb) bt
#0 0xb7fe1424 in __kernel_vsyscall ()
#1 0xb6581ede in pthread_join () from /lib/libpthread.so.0
#2 0xb7c0cce1 in StopThread () from /usr/lib/libopenal.so.1
#3 0xaedf8b70 in ?? ()
#4 0x08e3eaa7 in ?? ()
#5 0x08e346d9 in ?? ()
#6 0x089e7b78 in ?? ()
#7 0x0847bfe2 in ?? ()
#8 0x08482014 in ?? ()
#9 0x0848b4f9 in ?? ()
#10 0x0848b93d in ?? ()
#11 0x0848ba93 in ?? ()
#12 0x086e59e1 in ?? ()
#13 0x086f5620 in ?? ()
#14 0x0848a851 in ?? ()
#15 0x0848ce41 in ?? ()
#16 0x0848d910 in ?? ()
#17 0x084867d8 in ?? ()
#18 0x0847b89f in ?? ()
#19 0xb65d4c76 in __libc_start_main () from /lib/libc.so.6
#20 0x08479241 in ?? ()
(gdb)

If it was a debug build, this would not show all those ?? in the backtrace, please do a debug build! No idea how that works with scons, I'm using cmake, but I'm sure, you'll find out.

Ok, "exec-file" from GDB does not load debugging symbols ... that was the problem.

Now, *!@#$!$ heisenbugs. Plaguing me all my life except when I want to observe them. Bug wouldn't appear, or would only appear after resume from sleep, and even then the blender was able to exit normally. So just a bunch of backtraces while blender's windowmanager was sleeping. But finally, here is the backtrace (btw against the patched version) (generated after quiting blender hung the program):

$ gdb blender.run
GNU gdb (GDB) 7.2
Copyright (C) 2010 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law. Type "show copying"
and "show warranty" for details.
This GDB was configured as "i686-pc-linux-gnu".
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>...
Reading symbols from /home/orbisvicis/Q/luxrender-blender-vcs/blender/PATCH/blender.run...done.
(gdb) r
Starting program: /home/orbisvicis/Q/luxrender-blender-vcs/blender/PATCH/blender.run
[Thread debugging using libthread_db enabled]
[New Thread 0xaf5f9b70 (LWP 4883)]
[New Thread 0xaedf8b70 (LWP 4884)]
found bundled python: /home/orbisvicis/Q/luxrender-blender-vcs/blender/PATCH/install/linux2/2.55/python
^C
Program received signal SIGINT, Interrupt.
0xb7fe1424 in __kernel_vsyscall ()
(gdb) bt full
#0 0xb7fe1424 in __kernel_vsyscall ()
No symbol table info available.
#1 0xb6581ede in pthread_join () from /lib/libpthread.so.0
No symbol table info available.
\#2 0xb7c0cce1 in StopThread () from /usr/lib/libopenal.so.1
No symbol table info available.
#3 0xaedf8b70 in ?? ()
No symbol table info available.
#4 0x08e3eaa7 in AUD_OpenALDevice::~AUD_OpenALDevice (this=0x9896eb8, __in_chrg=<value optimized out>) at intern/audaspace/OpenAL/AUD_OpenALDevice.cpp:425
No locals.
#5 0x08e346d9 in AUD_exit () at intern/audaspace/intern/AUD_C-API.cpp:174
No locals.
#6 0x089e7b78 in sound_exit () at source/blender/blenkernel/intern/sound.c:120
No locals.
#7 0x0847bfe2 in WM_exit (C=0x9599728) at source/blender/windowmanager/intern/wm_init_exit.c:336
win = 0x0
#8 0x08482014 in wm_exit_blender_op (C=0x9599728, op=0xa4ee6f8) at source/blender/windowmanager/intern/wm_operators.c:2025
No locals.
#9 0x0848b4f9 in wm_operator_invoke (C=0x9599728, ot=0x96e4cc0, event=0x0, properties=0x0, reports=0x0, poll_only=0) at source/blender/windowmanager/intern/wm_event_system.c:644
op = 0xa4ee6f8
wm = 0x9812fa0
retval = 8
#10 0x0848b8d0 in wm_operator_call_internal (C=0x9599728, ot=0x96e4cc0, properties=0x0, reports=0x0, context=7, poll_only=0) at source/blender/windowmanager/intern/wm_event_system.c:773
ar = 0x982d7c0
area = 0x982bd00
type = 0
window = 0x9813078
event = 0x0
retval = 152890860
#11 0x0848ba93 in WM_operator_name_call (C=0x9599728, opstring=0x8f7ac66 "WM_OT_quit_blender", context=7, properties=0x0) at source/blender/windowmanager/intern/wm_event_system.c:822
ot = 0x96e4cc0
#12 0x086e59e1 in ui_apply_but_funcs_after (C=0x9599728) at source/blender/editors/interface/interface_handlers.c:372
afterf = 0x980fba8
after = {next = 0x0, prev = 0x0, func = 0, func_arg1 = 0x0, func_arg2 = 0x0, func_arg3 = 0x0, funcN = 0, func_argN = 0x0, rename_func = 0, rename_arg1 = 0x0, rename_orig = 0x0, handle_func = 0, handle_func_arg = 0x0, retval = -1,
butm_func = 0, butm_func_arg = 0x0, a2 = 0, optype = 0x96e4cc0, opcontext = 7, opptr = 0x0, rnapoin = {id = {data = 0x0}, type = 0x0, data = 0x0}, rnaprop = 0x0, context = 0x0, undostr = '\000' <repeats 511 times>, autokey = 0}
opptr = {id = {data = 0xbffff1d8}, type = 0x8a1498d, data = 0x9599728}
funcs = {first = 0x0, last = 0x0}
#13 0x086f578a in ui_handler_popup (C=0x9599728, event=0xa4c9c60, userdata=0xa4dd428) at source/blender/editors/interface/interface_handlers.c:5949
menu = 0xa4dd428
#14 0x0848a851 in wm_handler_ui_call (C=0x9599728, handler=0xa4c97f8, event=0xa4c9c60, always_pass=0) at source/blender/windowmanager/intern/wm_event_system.c:321
area = 0x982bd00
region = 0x982d7c0
menu = 0x0
retval = -1235800076
#15 0x0848ce41 in wm_handlers_do (C=0x9599728, event=0xa4c9c60, handlers=0x98130f4) at source/blender/windowmanager/intern/wm_event_system.c:1420
wm = 0x9812fa0
handler = 0xa4c97f8
nexthandler = 0x988de50
action = 0
always_pass = 0
#16 0x0848d910 in wm_event_do_handlers (C=0x9599728) at source/blender/windowmanager/intern/wm_event_system.c:1683
action = 0
event = 0xa4c9c60
wm = 0x9812fa0
win = 0x9813078
#17 0x084867d8 in WM_main (C=0x9599728) at source/blender/windowmanager/intern/wm.c:342
No locals.
#18 0x0847b89f in main (argc=1, argv=0xbffff734) at source/creator/creator.c:1184
syshandle = 0
C = 0x9599728
ba = 0x96d4d20
(gdb)


Backtrace doesn't seem very helpful, am I right. Gahh, going to rebuild without optimizations, maybe eke out some more information.

hmm, thought I built without optimization, maybe not:
gdb still says "<value optimized out>"
Do these look incorrect?
BF_DEBUG = True
REL_CFLAGS = ['-O0']
REL_CCFLAGS = ['-O0']

Hmm, no the backtrace isn't really helpful, because it's from the main thread that is waiting for another thread to quit. The backtrace from the thread that should quit is the one that's interesting!

No idea about that optimization thing, but it doesn't matter that much as long as I can see where in code it hangs (for now).

the other two threads don't seem to have anything to do with blender? The backtrace from the first thread was identical, so here is the output from the other two:

(gdb) thread 2
[Switching to thread 2 (Thread 0xaf5f9b70 (LWP 26954))]#0 0xb7fe1424 in __kernel_vsyscall ()
(gdb) bt full
#0 0xb7fe1424 in __kernel_vsyscall ()
No symbol table info available.
#1 0xb6682bd6 in poll () from /lib/libc.so.6
No symbol table info available.
#2 0xb36f2ef2 in poll_func () from /usr/lib/libpulse.so.0
No symbol table info available.
#3 0xb36e1dd9 in pa_mainloop_poll () from /usr/lib/libpulse.so.0
No symbol table info available.
#4 0xb36e25c4 in pa_mainloop_iterate () from /usr/lib/libpulse.so.0
No symbol table info available.
#5 0xb36e26a4 in pa_mainloop_run () from /usr/lib/libpulse.so.0
No symbol table info available.
#6 0xb36f2e93 in thread () from /usr/lib/libpulse.so.0
No symbol table info available.
#7 0xb36b55c5 in internal_thread_func () from /usr/lib/libpulsecommon-0.9.21.so
No symbol table info available.
#8 0xb6580e60 in start_thread () from /lib/libpthread.so.0
No symbol table info available.
#9 0xb668cf9e in clone () from /lib/libc.so.6
No symbol table info available.
(gdb) thread 3
[Switching to thread 3 (Thread 0xaedf8b70 (LWP 26955))]#0 0xb7fe1424 in __kernel_vsyscall ()
(gdb) bt full
#0 0xb7fe1424 in __kernel_vsyscall ()
No symbol table info available.
#1 0xb6682bd6 in poll () from /lib/libc.so.6
No symbol table info available.
#2 0xb5e59ea6 in ?? () from /usr/lib/libasound.so.2
No symbol table info available.
#3 0xb5e5a063 in snd_pcm_wait () from /usr/lib/libasound.so.2
No symbol table info available.
#4 0xb5e60100 in ?? () from /usr/lib/libasound.so.2
No symbol table info available.
#5 0xb5ea26df in ?? () from /usr/lib/libasound.so.2
No symbol table info available.
#6 0xb5e58de4 in snd_pcm_writei () from /usr/lib/libasound.so.2
No symbol table info available.
#7 0xb7c0f1bb in ALSANoMMapProc () from /usr/lib/libopenal.so.1
No symbol table info available.
#8 0x00000000 in ?? ()
No symbol table info available.
(gdb) info thread
* 3 Thread 0xaedf8b70 (LWP 26955) 0xb7fe1424 in __kernel_vsyscall ()
2 Thread 0xaf5f9b70 (LWP 26954) 0xb7fe1424 in __kernel_vsyscall ()
1 Thread 0xb463f720 (LWP 26951) 0xb7fe1424 in __kernel_vsyscall ()

I wanted to confirm that it was OpenAL only, not SDL by switching to SDL in the user preferences... can't: blender froze. Exact same backtrace (except the first few functions in the main thread) across all three threads.

I can switch from [OpenAL -> None] without problem though

Switching back from [None -> OpenAL] resumes bug.

Switching from [None->SDL] doesn't manifest bug

meh [OpenAL -> None] sometimes hangs

Just realized when testing SDL from blending I had forgotten to set SDL_AUDIODRIVER=alsa. (currently its set to pulse but SDL on Arch Linux isn't built with pulse support)

Soo.... yep. Same 100% CPU problem with SDL as with OpenAL

And it's *possible*? that the same bug manifests in SDL and OpenAL apps. I noticed now for the first time that mplayer & hedgewars CPU usage > 100%, and from mplayer:
ALSA lib pcm.c:7245:(snd_pcm_recover) underrun occured
ALSA lib pcm.c:7245:(snd_pcm_recover) underrun occured
ALSA lib pcm.c:7245:(snd_pcm_recover) underrun occured

But I'm pretty sure that before only blender had this problem. So weird. Maybe different bugs. !@$#^$!% pulseaudio

As you write, pulseaudio !@$#^$!% :D Report this to them, if the problem is in OpenAL and SDL and also other apps, it's definitely no blender problem.

You might also consider not using it at all, esp. if you're an arch linux user, you should have the knowledge. ;)

Closing.

Joerg Mueller (nexyon) closed this task as Invalid.Nov 22 2010, 5:45 PM