On 11/03/12 23:36, Colin Guthrie wrote: > 'Twas brillig, and Henrik /KaarPoSoft at 03/11/12 23:07 did gyre and gimble: >> On 11/03/12 19:20, Colin Guthrie wrote: >>> 'Twas brillig, and Henrik /KaarPoSoft at 10/09/12 21:13 did gyre and >>> gimble: >>>> Dear all, >>>> >>>> I am running gnome 3.4 and pulse-audio 2.1. >>>> >>>> When closing a window, gnome-shell sometimes hangs, >>>> waiting for pulse-audio. >>>> >>>> To reproduce: >>>> Open a gnome-terminal, press backspace which produces a nice beep, >>>> press the [X] in the window's title-bar. >>>> Now the whole desktop is unresponsive (the cursor moves with the mouse, >>>> but button presses are ignored). >>>> >>>> This also happens with other applications (eg. firefox), and happens >>>> both with pulse-audio debugging output turned on and off. >>>> >>>> The GNU debugger (gdb) gives the following back-trace for gnome-shell: >>>> >>>> ------------------------------------------------------------ >>>> #0 0xb7735424 in __kernel_vsyscall () >>>> #1 0xb4ff26cd in pthread_cond_wait@@GLIBC_2.3.2 () at >>>> ../nptl/sysdeps/unix/sysv/linux/i386/i686/../i486/pthread_cond_wait.S:143 >>>> >>>> #2 0xb56aa26b in pa_cond_wait (c=0x9bc3ea0, m=0x9a53bd0) at >>>> pulsecore/mutex-posix.c:139 >>>> #3 0xb570743e in pa_threaded_mainloop_wait (m=0x9bae118) at >>>> pulse/thread-mainloop.c:206 >>>> #4 0xb35a54cb in pulse_driver_play (c=0x9b3c740, id=1, >>>> proplist=0x954dd30, cb=0, userdata=0x0) at pulse.c:955 >>>> #5 0xb6f15733 in driver_play (c=c at entry=0x9b3c740, id=id at entry=1, >>>> pl=pl at entry=0x954dd30, cb=cb at entry=0, userdata=userdata at entry=0x0) at >>>> dso.c:342 >>>> #6 0xb6f0dff0 in ca_context_play_full (c=c at entry=0x9b3c740, >>>> id=id at entry=1, p=0x954dd30, cb=cb at entry=0, userdata=userdata at entry=0x0) >>>> at common.c:522 >>>> #7 0xb6f0e339 in ca_context_play (c=0x9b3c740, id=id at entry=1) at >>>> common.c:462 >>>> #8 0xb74fb5eb in workspace_switch_sound (to=0x9efbaf0, from=0x9ef6338) >>>> at core/workspace.c:496 >>>> #9 meta_workspace_activate_with_focus >>>> (workspace=workspace at entry=0x9efbaf0, focus_this=focus_this at entry=0x0, >>>> timestamp=timestamp at entry=0) at core/workspace.c:551 >>>> #10 0xb74fb73b in meta_workspace_activate >>>> (workspace=workspace at entry=0x9efbaf0, timestamp=timestamp at entry=0) at >>>> core/workspace.c:686 >>>> #11 0xb74df414 in meta_screen_remove_workspace (screen=0x911f8b8, >>>> workspace=0x9ef6338, timestamp=0) at core/screen.c:1476 >>>> #12 0xb513f44e in ffi_call_SYSV () at ../src/x86/sysv.S:64 >>>> #13 0xb513f239 in ffi_call (cif=cif at entry=0xad020864, fn=0xb74df2a0 >>>> <meta_screen_remove_workspace>, rvalue=rvalue at entry=0xbfd7e154, >>>> avalue=avalue at entry=0xbfd7e070) at ../src/x86/ffi.c:413 >>>> #14 0xb7455e57 in gjs_invoke_c_function >>>> (context=context at entry=0x93ad578, function=0xad020858, >>>> obj=obj at entry=0xabea1500, js_argc=js_argc at entry=2, >>>> js_argv=js_argv at entry=0xac3ff0a8, js_rval=js_rval at entry=0xbfd7e278) at >>>> gi/function.c:930 >>>> #15 0xb74575bd in function_call (context=0x93ad578, js_argc=2, >>>> vp=0xac3ff098) at gi/function.c:1245 >>>> #16 0xb71dcb7c in js::Invoke(JSContext*, js::CallArgs const&, unsigned >>>> int) () from //lib/libmozjs185.so.1.0 >>>> #17 0xb71c6082 in js::Interpret(JSContext*, JSStackFrame*, unsigned int, >>>> JSInterpMode) () from //lib/libmozjs185.so.1.0 >>>> #18 0xb71dad04 in js::RunScript(JSContext*, JSScript*, JSStackFrame*) () >>>> from //lib/libmozjs185.so.1.0 >>>> #19 0xb71dca59 in js::Invoke(JSContext*, js::CallArgs const&, unsigned >>>> int) () from //lib/libmozjs185.so.1.0 >>>> #20 0xb71dcf0c in js::ExternalInvoke(JSContext*, js::Value const&, >>>> js::Value const&, unsigned int, js::Value*, js::Value*) () from >>>> //lib/libmozjs185.so.1.0 >>>> #21 0xb7150056 in JS_CallFunctionValue () from //lib/libmozjs185.so.1.0 >>>> #22 0xb7455037 in gjs_callback_closure (cif=0x9f09160, >>>> result=0xbfd7ea30, args=0xbfd7e9e0, data=0x9f09148) at gi/function.c:291 >>>> #23 0xb513f2f4 in ffi_closure_SYSV_inner (closure=0xabf5f1c0, >>>> respp=0xbfd7ea3c, args=0xbfd7ea50) at ../src/x86/ffi.c:498 >>>> #24 0xb513f50a in ffi_closure_SYSV () at ../src/x86/sysv.S:188 >>>> #25 0xb74e6463 in run_repaint_laters (data=0x0) at core/util.c:794 >>>> #26 0xb65e52ed in _clutter_run_repaint_functions >>>> (flags=flags at entry=CLUTTER_REPAINT_FLAGS_PRE_PAINT) at >>>> ./clutter-main.c:3572 >>>> #27 0xb65e77d4 in master_clock_update_stages (stages=0x9f020a8, >>>> master_clock=0x9362d28) at ./clutter-master-clock.c:369 >>>> #28 clutter_clock_dispatch (source=source at entry=0x91475f0, callback=0, >>>> user_data=0x0) at ./clutter-master-clock.c:519 >>>> #29 0xb5089de3 in g_main_dispatch (context=0x9121898) at gmain.c:2539 >>>> #30 g_main_context_dispatch (context=context at entry=0x9121898) at >>>> gmain.c:3075 >>>> #31 0xb508a180 in g_main_context_iterate (context=0x9121898, >>>> block=block at entry=1, dispatch=dispatch at entry=1, self=<error reading >>>> variable: Unhandled dwarf expression opcode 0xfa>) at gmain.c:3146 >>>> #32 0xb508a5db in g_main_loop_run (loop=0x913d4c8) at gmain.c:3340 >>>> #33 0xb74d5c68 in meta_run () at core/main.c:555 >>>> #34 0x08049c87 in main (argc=1, argv=0xbfd7ed94) at main.c:334 >>>> ------------------------------------------------------------ >>>> >>>> As far as I can see, >>>> gnome-shell calls the mutter main loop, >>>> which has clutter "repaint", >>>> which in turns calls some JavaScript, >>>> which ask canberra to play a sound, >>>> and pulse-audio is trying to play the sound, >>>> but hangs in a condition wait. >>>> >>>> back-trace for pulseaudio: >>>> ------------------------------------------------------------ >>>> #0 0xb77be424 in __kernel_vsyscall () >>>> #1 0xb6fffa79 in ppoll (fds=0x8f049e0, nfds=23, timeout=<optimized >>>> out>, sigmask=sigmask at entry=0x0) at >>>> ../sysdeps/unix/sysv/linux/ppoll.c:58 >>>> #2 0xb76e902b in pa_mainloop_poll (m=m at entry=0x8f03640) at >>>> pulse/mainloop.c:881 >>>> #3 0xb76e97d9 in pa_mainloop_iterate (m=m at entry=0x8f03640, >>>> block=block at entry=1, retval=retval at entry=0xbf9933d0) at >>>> pulse/mainloop.c:955 >>>> #4 0xb76e98b4 in pa_mainloop_run (m=m at entry=0x8f03640, >>>> retval=retval at entry=0xbf9933d0) at pulse/mainloop.c:973 >>>> #5 0x0804e1cc in main (argc=3, argv=0xbf9935a4) at daemon/main.c:1135 >>>> ------------------------------------------------------------ >>>> >>>> The last 20 entries in the system log: >>>> ------------------------------------------------------------ >>>> [pulseaudio] module-suspend-on-idle.c: Sink >>>> alsa_output.pci-0000_00_1e.2.analog-stereo becomes idle, timeout in 5 >>>> seconds. >>>> [pulseaudio] module-suspend-on-idle.c: Sink >>>> alsa_output.pci-0000_00_1e.2.analog-stereo becomes idle, timeout in 5 >>>> seconds. >>>> [pulseaudio] core.c: Hmm, no streams around, trying to vacuum. >>>> [pulseaudio] protocol-dbus.c: Interface org.PulseAudio.Core1.Stream >>>> removed from object /org/pulseaudio/core1/playback_stream16 >>>> [pulseaudio] sink-input.c: Freeing input 16 "bell-window-system" >>>> [alsa-sink] alsa-sink.c: Increasing wakeup watermark to 40.00 ms >>>> [alsa-sink] ratelimit.c: 284 events suppressed >>>> [alsa-sink] alsa-sink.c: Wakeup from ALSA! >>>> [alsa-sink] alsa-sink.c: Underrun! >>>> [alsa-sink] alsa-sink.c: Increasing wakeup watermark to 50.00 ms >>>> [alsa-sink] alsa-sink.c: Wakeup from ALSA! >>>> [alsa-sink] alsa-sink.c: Underrun! >>>> [alsa-sink] alsa-sink.c: Increasing wakeup watermark to 60.00 ms >>>> [pulseaudio] module-suspend-on-idle.c: Sink >>>> alsa_output.pci-0000_00_1e.2.analog-stereo idle for too long, suspending >>>> ... >>>> [pulseaudio] sink.c: Suspend cause of sink >>>> alsa_output.pci-0000_00_1e.2.analog-stereo is 0x0004, suspending >>>> [pulseaudio] flist.c: pulsecore/hashmap.c: entries flist is full (don't >>>> worry) >>>> [alsa-sink] alsa-sink.c: Device suspended... >>>> [pulseaudio] core.c: Hmm, no streams around, trying to vacuum. >>>> [pulseaudio] reserve-wrap.c: Device lock status of >>>> reserve-monitor-wrapper at Audio0 changed: not busy >>>> [pulseaudio] module-udev-detect.c: /dev/snd/controlC0 is accessible: yes >>>> ------------------------------------------------------------ >>>> >>>> Any suggestions as to what the problem might be would be most >>>> appreciated! >>>> >>>> The above happens with KaarPux version 3.0.1. >>>> KaarPux is a "linux from source" distro I am developing. >>>> See http://kaarpux.kaarposoft.dk/ >>>> >>>> The bug report >>>> http://sourceforge.net/p/kaarpux/tickets/2/ >>>> has full backtraces, straces and log information attached. >>>> >>>> Thanks in advance for any help! >>> So this is technically from libcanberra which in turn uses PulseAudio to >>> output sound. >>> >>> It seems it's waiting for the drain before exiting. The drain can take >>> longer than the sound for various boring reasons we won't go into just >>> now. >>> >>> Longer term the intention is to fix the drain behaviour such that >>> applications like canberra can exit much quicker, but I wonder if there >>> is something that can be done to cancel the wait for drain at the >>> canberra side when exiting. >>> >>> Firstly thing to check I guess is that you're using the latest >>> libcanberra (0.29). >>> >>> Cheers. >>> >>> Col >>> >> Hello Colin! >> Thanks for the response - I was almost giving up on receiving any input >> on this... >> Yes, I am using libcanberra 0.29. >> (I now see an upstream libcanberra 0.30, but I have not tried it yet ...) > Oh, so there is. Tut tut Mr Poettering I don't see any announcement of > this on the libcanberra list! :p > > That said, I wouldn't expect any of the commits since 0.29 to really > make a difference to you as it's mostly about the gstreamer backend > which is not being used in your case... > >> As mentioned above, I am building my own distro, so I guess I am just >> doing something stupid, but looking into archlinux and fedora for >> pulseaudio patches etc. did not ring any bells here. I just can't grok >> what I am doing differently/wrong. > I suspect it's in some way related to the way the canberra gtk module is > hooking into things. Thus it could be more related to glib/gtk than > PulseAudio or Canberra... tho' I am mostly speculating myself. > >> If it was just the application hanging I guess I would have been able to >> debug somehow, but since it is the whole desktop environment hanging, I >> am somewhat at a loss at figuring out where to look... >> Any more hints / requests for more debugging output / suggestions / etc >> would be most appreciated. > Well I presume that in some capacity, the overall mainloop in the DE is > somehow being blocked to wait for the drain of the audio data. Quite why > this would happen I'm struggling to say off the top of my head. > > > As a quick question, how is the x11-bell handled? Are you enabling the > module inside PA that does this itself, or is canberra actually > generating the bell? If the former, this is likely not the right > approach. It's commented out by default in PA and I guess if it does > turn out to be the culprit, we should likely look to remove it. However > if it is canberra triggered then I guess it becomes a bit more complex. I have no clue about x11-bell handling. I am trying to install packages as close to upstream as possible. How can I peek my system to find out how x11-bell is handled??? > > I'm not 100% sure how this should operate, but I guess the bell handling > inside gnome-terminal would be very separate from the workspace switch > sound from gnome-shell/mutter/clutter - i.e. different processes > completely and thus different canberra contexts. Please note that this is (as far as I can tell) not just limited to bell in a terminal. If I open just firefox, play a html5/flash video, and close firefox, I am hung. > > So I'm not really that much help sadly :( On the contrary - now we are in a dialogue, and I hope your help will in the end resolve my problem
