GNOME Bugzilla – Bug 600787
playbin2 has a problem with Ogg stream with "info"
Last modified: 2009-11-18 18:41:25 UTC
I am using gst-plugins-base version 0.10.25-2ubuntu1 (from Ubuntu Karmic), and I see that playbin2 gets stuck on an Ogg stream with "info" (I don't know what that means precisely). To be specific, gst-launch-0.10 playbin2 uri="http://66.162.107.142/cpr1_K128OV.ogg" plays for 10 or 20 seconds or so and then stops playing and just sits there "buffering... 0%", while gst-launch-0.10 playbin2 uri="http://66.162.107.142/cpr1_K128OV_noinfo.ogg" plays for as long as I care to listen. (These streams are from the KCFR site at http://www.cpr.org/listen/live_newsinfo_ogg.pls and http://66.162.107.140/listen/live_newsinfo_ogg_noinfo.pls respectively) This seems to be a regression from the 0.10.22-5 version packaged in Ubuntu Jaunty, which works fine for me.
Fails for me also using git.
Seems to be some racy condition involving new pads being created in oggdemux and old ones discarded.
It seems to boil down to the fact that oggdemux doesn't set timestamps on its output buffers. Details follow: when oggdemux receives this 'info' thingy (I don't know ogg enough to know what it is) it creates and adds new pads, and pushes EOS and removes the old pads. When it adds the new pads, multiqueue is requested a new pad and creates a new internal single-queue empty of buffers, oggdemux will quickly push buffers through this new pad and make queue2 drain quickly. Queue2 thinks it is time to buffer and posts a message, causing the pipeline to pause and the sink to block along with the thread pushing the remaining old pads data (including the EOS). If this pause happens before the EOS leaves decodebin2, the new pads are not exposed and are blocked (just before leaving decodebin2), buffers pushed through the new oggdemux pad will end up in multiqueue. multiqueue will only be filled and block receiving buffers when it reaches about 10MB of data, or 2 secs. As oggdemux doesn't timestamp its output buffers, it might be a long time before the pipeline gets playing again. Hope I've made myself clear. I'll attempt to put timestamps on oggdemux buffers.
decodebin2's multiqueue doesn't care about time. It counts only buffers or bytes.
Ok, I've finally totally understood the problem. Other than the large explanation above, here's some more: for each GstDecodeGroup of decodebin2 there is a multiqueue. A multiqueue can be on two states (in regard to its queues): - prerolling: limit is 2MB (no limits on time or buffers) - playing: limit is 2MB or 5 buffers (no limits on time) The problem is that the new pads of oggdemux have a multiqueue that is on prerolling state, so it will only block on the 2MB limit, unfortunately the stream causes oggdemux to switch pads again before it is reached. I think adding more strict limits to multiqueue might cause regressions on badly interleaved files. Maybe we could add a limit to multiqueues that are not exposed. But it would have to go back to prerolling when exposed (if it has not prerolled yet).
Created attachment 147715 [details] [review] Sets the next group multiqueue to less buffering
Review of attachment 147715 [details] [review]: Good work :) Some comments below ::: gst/playback/gstdecodebin2.c @@ +2265,3 @@ + gst_element_release_request_pad (group->multiqueue, rpad->pad); + gst_object_unref (rpad->pad); + g_free (rpad); Please use GSlice for allocating these structs @@ +2440,3 @@ + GstRequestPadInfo *rpad_iter = (GstRequestPadInfo *) iter->data; + if (!rpad_iter->has_eos) + break; That break will only exit the loop but you probably wanted to exit the switch statement, right? @@ +2454,3 @@ + case GST_EVENT_FLUSH_STOP: + rpad->has_eos = FALSE; + /* TODO maybe we should set the next group back to preroll buffering */ No idea either but NEWSEGMENT events could also be filler segments for sparse streams, in that case resetting to preroll-buffering is not a good idea I guess
(In reply to comment #5) > The problem is that the new pads of oggdemux have a multiqueue that is on > prerolling state, so it will only block on the 2MB limit, unfortunately the > stream causes oggdemux to switch pads again before it is reached. I guess a better approach would be to block oggdemux somehow to prevent it switching to new groups before the previous are finished. Not sure how... By setting those limits different the switching could still happen right? Although it's less likely
Or maybe set the limits different not after EOS but after the group is ready to be exposed (if the active group would be finished). This would still break if less than 5 buffers are in the new group though, right?
(In reply to comment #7) I'll do that changes. Thanks for the review. (In reply to comment #8) > (In reply to comment #5) > > > The problem is that the new pads of oggdemux have a multiqueue that is on > > prerolling state, so it will only block on the 2MB limit, unfortunately the > > stream causes oggdemux to switch pads again before it is reached. > > I guess a better approach would be to block oggdemux somehow to prevent it > switching to new groups before the previous are finished. Not sure how... Can't think of a 'nice' way to do this > > By setting those limits different the switching could still happen right? > Although it's less likely Yes, it would happen and we'd have the same problem if the switching happened in less than 5 buffers or even some more, because queue2 would not set it back to playing as more space would be created and it would never fill enough. (In reply to comment #9) > Or maybe set the limits different not after EOS but after the group is ready to > be exposed (if the active group would be finished). This would still break if > less than 5 buffers are in the new group though, right? We could block the pads of multiqueue if the group already is completed (received no-more-pads) and is not exposed yet. Because it does not need to preroll anymore as it already knows all its pads.
I have patches for fixing oggdemux to put timestamps on buffers. It's non-trivial to do correctly. See #344013 and http://code.entropywave.com/git?p=gstreamer/gst-plugins-base.git;a=shortlog;h=refs/heads/oggdemux
(In reply to comment #11) > I have patches for fixing oggdemux to put timestamps on buffers. It's > non-trivial to do correctly. See #344013 and > http://code.entropywave.com/git?p=gstreamer/gst-plugins-base.git;a=shortlog;h=refs/heads/oggdemux That's good but won't help with this bug unfortunately, multiqueue doesn't look at the time (and shouldn't, see Wim's commit to remove the time limit in decodebin2 some time ago). Thiago, maybe another solution would be to block the multiqueue pads in the event probe by a GCond when EOS arrives and block until the corresponding group is exposed? Of course this condition variable has to be cleared on FLUSH_START and other events then...
I forgot to add that the commit that breaks it is: cf9c6a2271ad35e422c8fba6af842e3ea309d82d I'm now trying to understand why it worked before.
Created attachment 147911 [details] [review] Updated patch to a one-liner Probably not the ideal solution, but fixes this case and any other that has chains of more than 5 buffers ;)
The previous implementation changed to the next group earlier, without waiting for the EOS to leave decodebin2 in some cases. The current only changes after the EOS is pushed and the group is drained.
(In reply to comment #15) > The previous implementation changed to the next group earlier, without waiting > for the EOS to leave decodebin2 in some cases. The current only changes after > the EOS is pushed and the group is drained. Hmm, the current one changes before the last EOS is pushed. See gst_decode_pad_handle_eos() Do you see a change in that commit that would change this behaviour? I can't remember any ;)
I think that code prevents it from changing the active group when it is not drained: drained = chain->active_group ? gst_decode_group_is_drained (chain->active_group) : TRUE; if it is not drained, it will simply print GST_DEBUG_OBJECT (dbin, "Current active group in chain %p is not drained yet", chain); Or did I miss something?
Yes, the group will be switched only if the current group is drained. That means, all EOS except the last one of the current group go through, when the last one is received the groups are switched. This should be the same as in the old decodebin2, right?
If you look through the old code, you'll see that there are calls to gst_decode_group_expose in a lot of places, it is not only called from the _activate_next_group function. i.e. one of these calls happens when the group is blocked (all its endpads are blocked), nothing related to the EOS of the previous group.
I see what you mean now. I got the logs of both versions and couldn't see any significative difference on the group switching. Maybe the new implementation timing exposed the bug. I'll attach those dumps of GST_DEBUG=*decodebin2*:5 if someone wants to take a look and push the simple fix as it is harmless.
Created attachment 148060 [details] current implementation GST_DEBUG=*decodebin*:5 log
Created attachment 148061 [details] old implementation debug output
Fixed. Module: gst-plugins-base Branch: master Commit: e3e7ba0d1a51d084e5d9cf27d0391ce5a989b834 URL: http://cgit.freedesktop.org/gstreamer/gst-plugins-base/commit/?id=e3e7ba0d1a51d084e5d9cf27d0391ce5a989b834 Author: Thiago Santos <thiago.sousa.santos@collabora.co.uk> Date: Wed Nov 18 14:50:28 2009 -0300 decodebin2: set to buffer less on no-more-pads
Review of attachment 147911 [details] [review]: Committed with small docs modification.