[pulseaudio-discuss] gnome-shell hangs, waiting for pulse-audio
Tanu Kaskinen
tanuk at iki.fi
Sat Dec 1 20:49:00 PST 2012
On Wed, 2012-11-28 at 02:35 +0100, Henrik /KaarPoSoft wrote:
> On 11/26/12 16:42, Henrik /KaarPoSoft wrote:
> > Tanu, again: Thanks for your help.
> >
> > I tried the patch and various other changes to log.c, but getting no
> > useful logging, and sometimes segfaults instead (as you also noted).
> >
> > My mind kept coming back to this:
> >
> > ldd /bin/gnome-shell | grep pulse
> > libpulse-mainloop-glib.so.0 => //lib/libpulse-mainloop-glib.so.0
> > (0xb5771000)
> > libpulse.so.0 => //lib/libpulse.so.0 (0xb5723000)
> > libpulsecommon-2.1.so => //lib/pulseaudio/libpulsecommon-2.1.so
> > (0xb56b7000)
> > libpulsecommon-2.99.so => //lib/pulseaudio/libpulsecommon-2.99.so
> > (0xb4da6000)
> >
> > So, I deleted every file installed by the original pulseaudio 2.1,
> > recompiled+installed pulseaudio 2.99.2, and recompiled+installed
> > gnome-shell.
> >
> > Now I have:
> >
> > ldd /bin/gnome-shell | grep pulse
> > libpulse-mainloop-glib.so.0 => //lib/libpulse-mainloop-glib.so.0
> > (0xb56e3000)
> > libpulse.so.0 => //lib/libpulse.so.0 (0xb5695000)
> > libpulsecommon-2.99.so => //lib/pulseaudio/libpulsecommon-2.99.so
> > (0xb5620000)
> >
> > (A quick look at gnome-shell source did not reveal why it would link
> > to an old version; I must have a closer look at this later).
> >
> > And the good news:
> > Now the clients (incl gnome-shell) are showing the "Received opcode"
> > in ~/.xsession-errors (presumably because they log to stderr which is
> > redirected to ~/.xsession-errors).
> >
> > And the even better news:
> > I have tried to recreate the freeze without success.
> > So, maybe 2.99.2 solved the original problem after all.
> >
> > However, I am still having some trouble...
> >
> > Syslog show as lot (about 5/sec to 10/sec) entries like:
> > Nov 26 16:31:04 kx8400-5 pulseaudio[2078]: (1745.440| 0.057)
> > [pulseaudio] pdispatch.c: [0x9ee32f0] Received opcode
> > <GET_PLAYBACK_LATENCY>, tag 1088
> > And ~/.xsession-errors shows the corresponding
> > Received opcode <REPLY>
> >
> > I am not sure if this is a problem or not, but previously I did not
> > notice such pulseaudio bursts in syslog.
> >
> > Further thunderbird crashes every now and then (maybe not related, but
> > it never did that before),
> > and sometimes the terminal does not beep as expected.
> >
> > For the latter case (terminal does not beep as expected) I have this
> > in syslog:
> > [...]
> 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.
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).
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).
Btw, when it hangs, does it hang permanently, needing gnome-shell
restart?
Lastly, when pasting syslog contents, please ensure that the lines
aren't wrapped. It's really hard to read otherwise. If your mail client
doesn't allow you to disable wrapping only for some parts of the message
(at least Evolution allows selecting text and setting the paragraph
style to "Normal" or "Preformatted"), attachments are also an option.
--
Tanu
More information about the pulseaudio-discuss
mailing list