After an evaluation, GNOME has moved from Bugzilla to GitLab. Learn more about GitLab.
No new issues can be reported in GNOME Bugzilla anymore.
To report an issue in a GNOME project, go to GNOME GitLab.
Do not go to GNOME Gitlab for: Bluefish, Doxygen, GnuCash, GStreamer, java-gnome, LDTP, NetworkManager, Tomboy.
Bug 701997 - [regression] playbin: loses audio clock and hangs when switching songs after about-to-finish
[regression] playbin: loses audio clock and hangs when switching songs after ...
Status: RESOLVED FIXED
Product: GStreamer
Classification: Platform
Component: gst-plugins-base
git master
Other Linux
: Normal blocker
: 1.1.2
Assigned To: GStreamer Maintainers
GStreamer Maintainers
Depends on:
Blocks:
 
 
Reported: 2013-06-11 10:19 UTC by Tim-Philipp Müller
Modified: 2013-07-10 15:18 UTC
See Also:
GNOME target: ---
GNOME version: ---


Attachments
increase sink base time on next track. (1.23 KB, patch)
2013-07-08 21:30 UTC, Alban Browaeys
rejected Details | Review

Description Tim-Philipp Müller 2013-06-11 10:19:45 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.).
Comment 1 Edward Hervey 2013-06-17 14:13:04 UTC
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
Comment 2 Sebastian Dröge (slomo) 2013-06-18 09:49:25 UTC
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 :)
Comment 3 Edward Hervey 2013-06-18 09:59:04 UTC
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 ....
Comment 4 Sebastian Dröge (slomo) 2013-06-18 11:10:08 UTC
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.
Comment 5 Edward Hervey 2013-06-18 11:30:43 UTC
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.
Comment 6 Edward Hervey 2013-06-18 13:26:23 UTC
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 ....
Comment 7 Wim Taymans 2013-06-27 10:07:37 UTC
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.
Comment 8 GstBlub 2013-06-28 14:43:29 UTC
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.
Comment 9 Sebastian Dröge (slomo) 2013-07-02 10:08:34 UTC
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.
Comment 10 Sebastian Dröge (slomo) 2013-07-02 10:39:58 UTC
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.
Comment 11 Sebastian Dröge (slomo) 2013-07-02 12:46:33 UTC
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
Comment 12 GstBlub 2013-07-05 19:27:53 UTC
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.
Comment 13 Alban Browaeys 2013-07-08 21:30:22 UTC
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.
Comment 14 Sebastian Dröge (slomo) 2013-07-10 12:35:50 UTC
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?
Comment 15 GstBlub 2013-07-10 15:06:53 UTC
(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.
Comment 16 Sebastian Dröge (slomo) 2013-07-10 15:18:10 UTC
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