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>
