[pulseaudio-discuss] gnome-shell hangs, waiting for pulse-audio

Sat Nov 3 15:36:02 PDT 2012

'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'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.

So I'm not really that much help sadly :(

Col

-- 

Colin Guthrie
gmane(at)colin.guthr.ie
http://colin.guthr.ie/

Day Job:
  Tribalogic Limited http://www.tribalogic.net/
Open Source:
  Mageia Contributor http://www.mageia.org/
  PulseAudio Hacker http://www.pulseaudio.org/
  Trac Hacker http://trac.edgewall.org/