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

Sun Dec 2 11:20:41 PST 2012

On 12/02/12 05:49, Tanu Kaskinen wrote:
> On Wed, 2012-11-28 at 02:35 +0100, Henrik /KaarPoSoft wrote:
>>
>> It seems that more apps / libraries depend on libpulsecommon-2.1.so
>> which has now been removed (as 2.99.2 has been installed instead).
>> So, I tried to identify every lib/app dependent on pulseaudio, and have
>> now recompiled+reinstalled:
>> gnome-shell
>> alsa-plugins
>> libcanberra
>> gst-plugins-good
>> gnome-control-center
>> gnome-settings-daemon
>> gtk-vnc
>> empathy
>>
>> Now I am *not* able to recreate this hang:
>> open gnome-terminal (as only app on desktop), press backspace, close
>> terminal.
>>
>> However, this seems to hang every time:
>> open gnome-terminal, press backspace twice to get two beeps.
>> open firefox, play html5 video on youtube, close firefox.
>> close gnome-terminal (which is now last app on desktop).
>> Now the desktop is frozen.
>>
>> The last 40 lines of .xsession-errors:
>> ----------------------------------------
>> [0x9e6df4f0] Received opcode <REQUEST>, tag 4294967295
>> [0x9e6df4f0] Received opcode <REQUEST>, tag 4294967295
>> [0x9e6df4f0] Received opcode <REQUEST>, tag 4294967295
>> [0x9e6df4f0] Received opcode <REQUEST>, tag 4294967295
>> [0x9e6df4f0] Received opcode <REQUEST>, tag 4294967295
>> [0x9e6df4f0] Received opcode <REQUEST>, tag 4294967295
>> [0x9e6df4f0] Received opcode <REQUEST>, tag 4294967295
>> [0xb2406210] Received opcode <SUBSCRIBE_EVENT>, tag 4294967295
>> [0x877c6e0] Received opcode <SUBSCRIBE_EVENT>, tag 4294967295
>> [0x9e6df4f0] Received opcode <REPLY>, tag 25
>> [0x9e6df4f0] Received opcode <REPLY>, tag 26
>> [0xa643cd8] Received opcode <SUBSCRIBE_EVENT>, tag 4294967295
>> [0x9e6df4f0] Received opcode <REPLY>, tag 27
>> [0x877c6e0] Received opcode <SUBSCRIBE_EVENT>, tag 4294967295
>> [0x9e6df4f0] Received opcode <REPLY>, tag 28
>> [0x877c6e0] Received opcode <REPLY>, tag 35
>> [0x877c6e0] Received opcode <REPLY>, tag 36
>> [0xa643cd8] Received opcode <SUBSCRIBE_EVENT>, tag 4294967295
>> [0x9e6df4f0] Received opcode <REPLY>, tag 29
>> [0xa643cd8] Received opcode <REPLY>, tag 26
>> [0xa643cd8] Received opcode <REPLY>, tag 27
>> [0x9e6df4f0] Received opcode <REPLY>, tag 30
>> [0x9e6df4f0] Received opcode <REPLY>, tag 31
>> [0x9e6df4f0] Received opcode <REPLY>, tag 32
>> [0x9e6df4f0] Received opcode <REPLY>, tag 33
>> [0x9e6df4f0] Received opcode <REPLY>, tag 34
>> [0x9e6df4f0] Received opcode <REPLY>, tag 35
>> [0x9e6df4f0] Received opcode <REPLY>, tag 36
>> [0x9e6df4f0] Received opcode <REPLY>, tag 37
>> [0x9e6df4f0] Received opcode <REPLY>, tag 38
>> [0xb2406210] Received opcode <SUBSCRIBE_EVENT>, tag 4294967295
>> [0x877c6e0] Received opcode <SUBSCRIBE_EVENT>, tag 4294967295
>> [0x877c6e0] Received opcode <SUBSCRIBE_EVENT>, tag 4294967295
>> [0xa643cd8] Received opcode <SUBSCRIBE_EVENT>, tag 4294967295
>> [0xa643cd8] Received opcode <SUBSCRIBE_EVENT>, tag 4294967295
>> [0xb2406210] Received opcode <ERROR>, tag 9
>> [0x877c6e0] Received opcode <SUBSCRIBE_EVENT>, tag 4294967295
>> [0x877c6e0] Received opcode <SUBSCRIBE_EVENT>, tag 4294967295
>> [0x877c6e0] Received opcode <REPLY>, tag 37
>> [0x877c6e0] Received opcode <REPLY>, tag 38
>> ----------------------------------------
>>
>> The last 20 lines of syslog matching grep 'Received opcode'
>> ----------------------------------------
>> Nov 28 02:05:54 kx8400-5 pulseaudio[2064]: (  52.665|   0.001)
>> [pulseaudio][pulsecore/pdispatch.c:318 pa_pdispatch_run()] [0x868dcc8]
>> Received opcode <GET_PLAYBACK_LATENCY>, tag 27
>> Nov 28 02:05:54 kx8400-5 pulseaudio[2064]: (  52.675|   0.009)
>> [pulseaudio][pulsecore/pdispatch.c:318 pa_pdispatch_run()] [0x8666228]
>> Received opcode <GET_SINK_INPUT_INFO>, tag 35
>> Nov 28 02:05:54 kx8400-5 pulseaudio[2064]: (  52.676|   0.001)
>> [pulseaudio][pulsecore/pdispatch.c:318 pa_pdispatch_run()] [0x86812c0]
>> Received opcode <GET_SINK_INPUT_INFO>, tag 26
>> Nov 28 02:05:54 kx8400-5 pulseaudio[2064]: (  52.677|   0.001)
>> [pulseaudio][pulsecore/pdispatch.c:318 pa_pdispatch_run()] [0x868dcc8]
>> Received opcode <GET_PLAYBACK_LATENCY>, tag 28
>> Nov 28 02:05:54 kx8400-5 pulseaudio[2064]: (  52.678|   0.001)
>> [pulseaudio][pulsecore/pdispatch.c:318 pa_pdispatch_run()] [0x8666228]
>> Received opcode <GET_SINK_INFO>, tag 36
>> Nov 28 02:05:54 kx8400-5 pulseaudio[2064]: (  52.694|   0.015)
>> [pulseaudio][pulsecore/pdispatch.c:318 pa_pdispatch_run()] [0x868dcc8]
>> Received opcode <GET_PLAYBACK_LATENCY>, tag 29
>> Nov 28 02:05:54 kx8400-5 pulseaudio[2064]: (  52.705|   0.011)
>> [pulseaudio][pulsecore/pdispatch.c:318 pa_pdispatch_run()] [0x86812c0]
>> Received opcode <GET_SINK_INFO>, tag 27
>> Nov 28 02:05:54 kx8400-5 pulseaudio[2064]: (  52.734|   0.029)
>> [pulseaudio][pulsecore/pdispatch.c:318 pa_pdispatch_run()] [0x868dcc8]
>> Received opcode <GET_PLAYBACK_LATENCY>, tag 30
>> Nov 28 02:05:54 kx8400-5 pulseaudio[2064]: (  52.815|   0.081)
>> [pulseaudio][pulsecore/pdispatch.c:318 pa_pdispatch_run()] [0x868dcc8]
>> Received opcode <GET_PLAYBACK_LATENCY>, tag 31
>> Nov 28 02:05:54 kx8400-5 pulseaudio[2064]: (  52.976|   0.160)
>> [pulseaudio][pulsecore/pdispatch.c:318 pa_pdispatch_run()] [0x868dcc8]
>> Received opcode <GET_PLAYBACK_LATENCY>, tag 32
>> Nov 28 02:05:55 kx8400-5 pulseaudio[2064]: (  53.297|   0.320)
>> [pulseaudio][pulsecore/pdispatch.c:318 pa_pdispatch_run()] [0x868dcc8]
>> Received opcode <GET_PLAYBACK_LATENCY>, tag 33
>> Nov 28 02:05:55 kx8400-5 pulseaudio[2064]: (  53.325|   0.028)
>> [pulseaudio][pulsecore/pdispatch.c:318 pa_pdispatch_run()] [0x868dcc8]
>> Received opcode <GET_PLAYBACK_LATENCY>, tag 34
>> Nov 28 02:05:55 kx8400-5 pulseaudio[2064]: (  53.327|   0.001)
>> [pulseaudio][pulsecore/pdispatch.c:318 pa_pdispatch_run()] [0x868dcc8]
>> Received opcode <CORK_PLAYBACK_STREAM>, tag 35
>> Nov 28 02:05:55 kx8400-5 pulseaudio[2064]: (  53.327|   0.000)
>> [pulseaudio][pulsecore/pdispatch.c:318 pa_pdispatch_run()] [0x868dcc8]
>> Received opcode <GET_PLAYBACK_LATENCY>, tag 36
>> Nov 28 02:05:55 kx8400-5 pulseaudio[2064]: (  53.328|   0.000)
>> [pulseaudio][pulsecore/pdispatch.c:318 pa_pdispatch_run()] [0x868dcc8]
>> Received opcode <GET_PLAYBACK_LATENCY>, tag 37
>> Nov 28 02:05:55 kx8400-5 pulseaudio[2064]: (  53.328|   0.000)
>> [pulseaudio][pulsecore/pdispatch.c:318 pa_pdispatch_run()] [0x868dcc8]
>> Received opcode <FLUSH_PLAYBACK_STREAM>, tag 38
>> Nov 28 02:05:55 kx8400-5 pulseaudio[2064]: (  53.328|   0.000)
>> [pulseaudio][pulsecore/pdispatch.c:318 pa_pdispatch_run()] [0x868dcc8]
>> Received opcode <GET_PLAYBACK_LATENCY>, tag 39
>> Nov 28 02:05:56 kx8400-5 pulseaudio[2064]: (  54.319|   0.052)
>> [pulseaudio][pulsecore/pdispatch.c:318 pa_pdispatch_run()] [0x86828d8]
>> Received opcode <PLAY_SAMPLE>, tag 9
>> Nov 28 02:06:00 kx8400-5 pulseaudio[2064]: (  58.343|   0.000)
>> [pulseaudio][pulsecore/pdispatch.c:318 pa_pdispatch_run()] [0x8666228]
>> Received opcode <GET_SINK_INFO>, tag 37
>> Nov 28 02:06:00 kx8400-5 pulseaudio[2064]: (  58.343|   0.000)
>> [pulseaudio][pulsecore/pdispatch.c:318 pa_pdispatch_run()] [0x8666228]
>> Received opcode <GET_SOURCE_INFO>, tag 38
>>
>> ----------------------------------------
>>
>> So it would seem that tag 39 is received by pulseaudio daemon, but the
>> response not received by the client (presumably gnome-shell)
> Do you mean the reply to the GET_PLAYBACK_LATENCY message? If this is
> the exact same code that is hanging in the original backtrace, then the
> latency message isn't the problem. Also, the latency message comes from
> a different client than the PLAY_SAMPLE message, so the latency message
> is probably not from gnome-shell.
I concur.
I think that #39 GET_PLAYBACK_LATENCY is from firefox, which was closed, 
hence not receiving the result.
> Assuming that it is always the PLAY_SAMPLE message that hangs, then it
> looks like the reply is received by the client. The last PLAY_SAMPLE
> message has tag 9, and xsession-errors shows that some client receives
> an error reply for tag 9 (an error is expected, because we found out
> already earlier that there are always two PLAY_SAMPLE messages, of which
> the latter one fails).
I concur.
> The original backtrace only has the trace for one thread, the thread
> where the libpulse mainloop runs isn't shown. Could you take a backtrace
> again, this time with "thread apply all bt"? The libpulse thread might
> be hanging too (which would explain why the main thread is hanging,
> since the libpulse thread is responsible for waking up the main thread).
I have changed Xsession to log client messages to syslog.
Unfortunatly they all show up with tag Xsession, not the individual client.

Anyway, I have attached the relevant part of syslog (pulseaudio and 
Xsession), as well as pulseaudio and gnome-shell backtraces for all 
threads.
> Btw, when it hangs, does it hang permanently, needing gnome-shell
> restart?
Permanently, as in at least 10 minutes.
(I don't wait that long every time, but I did a couple of times, and 
nothing changed within 10-15 minutes).
So yes: Needing restart.
(I usually do a reboot to get a clean slate, but somtimes I just restart 
gdm. Have not tried just gnome.shell restart).
> Lastly, when pasting syslog contents, please ensure that the lines
> aren't wrapped. It's really hard to read otherwise.
My apologies. Will use attachments.
/Henrik

Now attaching syslog+backtraces tar+gzipped; previous message was 
rejected; apologies if you receive this twice.

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.freedesktop.org/archives/pulseaudio-discuss/attachments/20121202/af22e2c4/attachment-0001.html>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: pa_bug_2012_12_02_18_45_44.tar.gz
Type: application/x-gzip
Size: 41487 bytes
Desc: not available
URL: <http://lists.freedesktop.org/archives/pulseaudio-discuss/attachments/20121202/af22e2c4/attachment-0001.bin>