GNOME Bugzilla – Bug 701997
[regression] playbin: loses audio clock and hangs when switching songs after about-to-finish
Last modified: 2013-07-10 15:18:10 UTC
This is a regression in git master I believe: tpm@zingle:~/gst/glib-git/gst-plugins-base/tests/icles/playback$ ./test7 file:///home/tpm/music/Daft\ Punk\ -\ Alive\ 2007/01-Daft\ Punk\ -\ Robot\ Rock\ -\ Oh\ Yeah.mp3 file:///home/tpm/music/Daft\ Punk\ -\ Alive\ 2007/02-Daft\ Punk\ -\ Touch\ It\ -\ Technologic.mp3 NEW CLOCK: GstPulseSinkClock 0:00:00.000000000 / 0:06:27.918367346 0:00:00.263087000 / 0:06:27.918367346 ... 0:06:25.497557000 / 0:06:27.918367346 0:06:25.998394000 / 0:06:27.918367346 CLOCK LOST: GstPulseSinkClock NEW CLOCK: GstSystemClock -:--:--.--------- / 0:05:29.769795918 -:--:--.--------- / 0:05:29.769795918 -:--:--.--------- / 0:05:29.769795918 -:--:--.--------- / 0:05:29.769795918 Note the switch of clock here. (There's another issue which I noticed in totem which doesn't use about-to-finish, and that's that when switching to the second song the song stutters as if someone kept the 'p' key pressed for pause/play/pause/play etc.. Might be related.).
This might have been introduced by this commit: commit 77af24c493cb773943061ecf8d6229d271d077ab Author: Sebastian Dröge <slomo@circular-chaos.org> Date: Sat Jun 8 23:04:43 2013 +0200 playbin: Proxy sink messages if we activate a sink in playbin already This makes sure the application gets any context related messages and can do whatever is required to a) get the sink a context or b) share the context with other elements in the pipeline. The proxying is necessary because the sink is not a child element of playbin, but instead will at a later point be a child of some bin inside playsink. https://bugzilla.gnome.org/show_bug.cgi?id=700967
Considering all the other about-to-finish bugs there seems to be a more general problem behind all this too, but will try to have some time to debug how exactly my commit breaks things even more :)
Actually, I thought it was that commit but was doing the regression check with rhythmbox. Using the test7 playback test and bisecting, it seems the regression was introduced by this commit: a8d1b4549184f4aec88132b3650fa2b8fe1ca970 is the first bad commit commit a8d1b4549184f4aec88132b3650fa2b8fe1ca970 Author: Sreerenj Balachandran <sreerenj.balachandran@intel.com> Date: Mon Apr 29 22:17:53 2013 +0300 playbin: autoplug the audio/video decoders and sinks based on capsfeatures. Autoplug the decoder elements and sink elements based on the number of common capsfeatures if the ranks are the same. This will also helps to autoplug the h/w_decoder and h/w_renderer. https://bugzilla.gnome.org/show_bug.cgi?id=698712 Seems a bit weird though ....
Not weird at all, due to this commit the logic that previously only affected non-raw sinks is also used for raw sinks. Thus also pulsesink and xvimagesink. Previously they were just used by autoaudiosink/autovideosink inside playsink, now playbin selects them actively.
And it's not re-using the (previously used) pulsesink ... when switching tracks. Apart from the fact that re-using previously-used sinks is a bit suboptimal ... I don't get why a new clock isn't being re-selected/re-used.
The observed path goes like this: 0) standard playback, except that the sink selection is now done in playbin and not playsink, therefore group->audio_sink gets set to the sink used in playsink. This doesn't cause any issue ... for the time being. In this case pulsesink is used. ... playback of first URI .... 1) the uridecodebin gets drained, about-to-finish is notified, a new URI gets set and therefore setup_next_source gets called 2) setup_next_source 2.1) calls deactivate_group on the old (drained) group 2.1.1) unlinks selectors, releases playsink pads, NULLs/unrefs selectors. That part is fine 2.1.2) .. but then it compares the group->audio_sink to playbin->audio_sink and considers it as a custom sink so sets it to NULL and unrefs it. This is wrong IMHO. Changing states of elements still being used in playsink should not be playbin's responsibility. Note that the audio_sink is *still* present in playsink, it was not removed from it ! 2.1.3) due to setting pulsesink to NULL, a clock-lost message is posted on the bus, the bins/pipeline know they will need to grab a new clock 3) ... I gave up trying to follow what happens after that, but essentially there is a race betwen playbin (and contents) going to PLAYING and people fighting over whether pulsesink should go to NULL or PLAYING, the end result being that when playbin asks for someone to provide a clock, pulsesink is in NULL, doesn't have a valid ringbuffer, and therefore doesn't return a clock The first part that really makes me uncomfortable is 2.1.2 ....
3) because playsink is set to NULL, the thread stops with flushing and queue stops pushing. 4) playsink is set to PLAYING again, the new uridecodebin is linked but immediately stops because the queue is still flushing.
I am also experiencing an issue that sounds related to this, trying to implement playlists. I don't use the about-to-finish signal. I handle the EOS message, take playbin back to READY, set the next uri, restart playback by setting it back to PLAYING and it will sporadically stop playback after a few seconds. And I only get an EOS once, after the first song. Any subsequent songs will get the about-to-finish (which I don't do anything with), but I never see any more EOS on the pipeline.
Another problem here is that decodebin/playbin chooses a new pulsesink because it apparently forgot about the already existing one (because the existing one is in the other source group) :) I think it should also try to preserve the sink. From the debug logs this would've already been a problem before sree's changes, but there only for sinks that are plugged because they can handle encoded streams.
If I change playbin to remember the previously autoselected sinks for the group everything is working again btw. However what Wim and Edward noticed in comment #6 and comment #7 need some fixing too.
commit 7c28c180ec7e77cbd800e035a6b04c858be32d61 Author: Sebastian Dröge <slomo@circular-chaos.org> Date: Tue Jul 2 14:25:28 2013 +0200 playbin: If we had a previous autoplugged sink, try to reuse it https://bugzilla.gnome.org/show_bug.cgi?id=701997 commit b3a15872b7b781d4cae0e2f9d4cd1da9beda1e31 Author: Sebastian Dröge <slomo@circular-chaos.org> Date: Tue Jul 2 14:18:20 2013 +0200 playsink: If we switch sinks, make sure that the old sink is set to NULL commit 841d738f7ca982010a9c64d75a749ce08e7031bc Author: Sebastian Dröge <slomo@circular-chaos.org> Date: Tue Jul 2 14:02:57 2013 +0200 playbin: Don't change the state of sinks that we passed to playsink already commit c7255910108bbc9cafd6b0bc16c9ec0219c9b4cf Author: Sebastian Dröge <slomo@circular-chaos.org> Date: Tue Jul 2 14:01:52 2013 +0200 playsink: Consider new audio/video sinks when reconfiguring commit a0e61534efb205a5b5d8b628523be4dfb83245d5 Author: Sebastian Dröge <slomo@circular-chaos.org> Date: Tue Jul 2 12:27:03 2013 +0200 playbin: Improve debug output regarding sink selection
I tried the latest changes and there's still no EOS after the about-to-finish signal (that I don't handle) for subsequent songs. I get the EOS after the first one.
Created attachment 248670 [details] [review] increase sink base time on next track. This hack is a workaround that allow one to get the second track content (stable for audio only and if one wait for eos, as I use first track duration as offset). Ie I found that if one play a first song telling "1, 2" ; then the second one is enqueued (telling "a, b, c, d, e, f, g, h" then the setup_next source would play the second one starting from "d". In fact it is more complex than that as the streamsynchronizer removes the discont flag, thus I get "a, e, f, g, h". Removing the code that discard this discont flag I get the "d, e, f,g, h". Thus the clue that it has to do with running time and segments.
commit c8cfaff1ff03c2c1f6670280cc311fdf118a2a20 Author: Sebastian Dröge <slomo@circular-chaos.org> Date: Wed Jul 10 14:30:31 2013 +0200 inputselector: Keep previous active sinkpad around until we're done with it Otherwise we'll send a new segment event downstream for each buffer. test7 works fine for me now with many (audio-only) files in a row. Anything else left broken here?
(In reply to comment #12) > I tried the latest changes and there's still no EOS after the about-to-finish > signal (that I don't handle) for subsequent songs. I get the EOS after the > first one. Disregard this comment, I think my code has flaws. I wrote a really simple application to reproduce the issue and it appears to work just fine.
commit 9ab6ab42572a28e447f761485c457f2a71eabb86 Author: Sebastian Dröge <slomo@circular-chaos.org> Date: Wed Jul 10 17:16:14 2013 +0200 playbin: Only give sinks a new bus if they have no parent yet Otherwise we will remove the bus that would proxy messages to playsink and never set it again. If the sink is already in playsink, all failures are fatal anyway as it's either a sink that worked before or one that was set by the user. https://bugzilla.gnome.org/show_bug.cgi?id=701997 commit ba4ec10aa5068bda478f1d96fa7265327588ae26 Author: Sebastian Dröge <slomo@circular-chaos.org> Date: Wed Jul 10 15:52:10 2013 +0200 bin: Always forward clock-lost message if we're not a top-level bin This makes sure that no bin misses the clock-lost messages, independent of the state, and could return an old, non-working clock from gst_bin_provide_clock_func(). https://bugzilla.gnome.org/show_bug.cgi?id=701997