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

[Henrik /KaarPoSoft]

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@entry=0x9b3c740, id=id@entry=1,
pl=pl@entry=0x954dd30, cb=cb@entry=0, userdata=userdata@entry=0x0) at
dso.c:342
#6  0xb6f0dff0 in ca_context_play_full (c=c@entry=0x9b3c740,
id=id@entry=1, p=0x954dd30, cb=cb@entry=0, userdata=userdata@entry=0x0)
at common.c:522
#7  0xb6f0e339 in ca_context_play (c=0x9b3c740, id=id@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@entry=0x9efbaf0, focus_this=focus_this@entry=0x0,
timestamp=timestamp@entry=0) at core/workspace.c:551
#10 0xb74fb73b in meta_workspace_activate
(workspace=workspace@entry=0x9efbaf0, timestamp=timestamp@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@entry=0xad020864, fn=0xb74df2a0
<meta_screen_remove_workspace>, rvalue=rvalue@entry=0xbfd7e154,
avalue=avalue@entry=0xbfd7e070) at ../src/x86/ffi.c:413
#14 0xb7455e57 in gjs_invoke_c_function
(context=context@entry=0x93ad578, function=0xad020858,
obj=obj@entry=0xabea1500, js_argc=js_argc@entry=2,
js_argv=js_argv@entry=0xac3ff0a8, js_rval=js_rval@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@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@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@entry=0x9121898) at
gmain.c:3075
#31 0xb508a180 in g_main_context_iterate (context=0x9121898,
block=block@entry=1, dispatch=dispatch@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@entry=0x0) at
../sysdeps/unix/sysv/linux/ppoll.c:58
#2  0xb76e902b in pa_mainloop_poll (m=m@entry=0x8f03640) at
pulse/mainloop.c:881
#3  0xb76e97d9 in pa_mainloop_iterate (m=m@entry=0x8f03640,
block=block@entry=1, retval=retval@entry=0xbf9933d0) at
pulse/mainloop.c:955
#4  0xb76e98b4 in pa_mainloop_run (m=m@entry=0x8f03640,
retval=retval@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@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
_______________________________________________
pulseaudio-discuss mailing list
pulseaudio-discuss@lists.freedesktop.org
http://lists.freedesktop.org/mailman/listinfo/pulseaudio-discuss