GNOME Bugzilla – Bug 761815
playbin: changing playbin flags stalls playback
Last modified: 2018-05-12 06:38:56 UTC
Changing the playbin flags (audio, subitles, softvolume, etc) while playing, playback just stalls. The only way to resume playback is to seek. This also happens on a recent 1.6 branch.
The culprit commit seems to be 62053852de (3bc67006d on the 1.6 branch)
To reproduce, just check / uncheck the playbin flags checkboxes in the playbacktest example UI while playing. The video should stall immediatly. I've confirmed this happens with at least the audio, subtitles and softvolume flags.
Here is what happens when you quickly disable/enable audio: disable: 1) The pads are set to block for reconfigure 2) they all block and reconfigure happens, disabling audio 3) the audio branch receives a not-linked return and that goes up to multiqueue, making the audio queue thread sleep until other streams advance or a reconfigure is received. enable: 1) pads are set to block 2) multiqueue's video queue thread is about to push and decides to not wake-up the sleeping queue threads because their time is still smaller than required and pushes a buffer. This thread will block on playsink 3) multiqueue's audio queue is still waiting to be waken and nothing can wake it up anymore. In the end: Playsink is holding the video thread that could wake up the audio thread waiting for the audio thread to be blocked. The audio thread is sleeping because of a not-linked return and needs the video thread to be waken but playsink is blocking it. Deadlock!
+ Trace 235961
Thread 11 (Thread 0x7fffca188700 (LWP 20246))
Thread 10 (Thread 0x7fffcb1b0700 (LWP 20245))
Thread 8 (Thread 0x7fffd326d700 (LWP 20243))
Thread 6 (Thread 0x7fffe53c1700 (LWP 20241))
Thread 5 (Thread 0x7fffe5bc2700 (LWP 20240))
Thread 4 (Thread 0x7fffe6c41700 (LWP 20239))
Created attachment 320910 [details] [review] playsink: unlock upstream after not-linked returns with reconfigure Send reconfigure upstream when enabling a branch to unlock threads that are possibly sleeping after a previous not-linked return. === Please test if it solves your issue
The patch doesn't help at all either 1.6 or master. Your patch only sends reconfigure events when the audio, video or text flags are _enabled_ (not disabled). The bug happens when _ANY_ flag in playbin is enabled or disabled.
(In reply to Arnaud Vrac from comment #5) > The patch doesn't help at all either 1.6 or master. > > Your patch only sends reconfigure events when the audio, video or text flags > are _enabled_ (not disabled). > > The bug happens when _ANY_ flag in playbin is enabled or disabled. I couldn't reproduce it with any other flags other than video/audio/text. Can you get a gdb stack trace of the deadlock when it happens with other flags? Also which flag you used and a GST_DEBUG=6 log might also be helpful.
Managed to reproduce it if I disable the audio and then go play with other flags.
Created attachment 320996 [details] [review] playsink: unlock upstream after not-linked returns with reconfigure Updated patch to only block pads that are actually being used or going to be used to prevent deadlock when a disabled pad is blocked
It still doesn't work. Here's the log where I'm disabling the text flag: with master + your patch: unsetting flag 0x00000004 0:00:10.041914653 18431 0x1c5c890 LOG playsink gstplaysink.c:4264:gst_play_sink_reconfigure:<playsink> Triggering reconfiguration 0:00:10.041955510 18431 0x1c5c890 LOG playsink gstplaysink.c:4266:gst_play_sink_reconfigure:<playsink> locking from thread 0x1c5c890 0:00:10.041974088 18431 0x1c5c890 LOG playsink gstplaysink.c:4266:gst_play_sink_reconfigure:<playsink> locked from thread 0x1c5c890 0:00:10.041996018 18431 0x1c5c890 LOG playsink gstplaysink.c:4282:gst_play_sink_reconfigure:<playsink> unlocking from thread 0x1c5c890 0:00:10.049303804 18431 0x7ff8f0014ed0 LOG playsink gstplaysink.c:4309:sinkpad_blocked_cb:<playsink> locking from thread 0x7ff8f0014ed0 0:00:10.049348782 18431 0x7ff8f0014ed0 LOG playsink gstplaysink.c:4309:sinkpad_blocked_cb:<playsink> locked from thread 0x7ff8f0014ed0 0:00:10.049373366 18431 0x7ff8f0014ed0 DEBUG playsink gstplaysink.c:4317:sinkpad_blocked_cb:<playsink:audio_sink> Audio pad blocked 0:00:10.049397182 18431 0x7ff8f0014ed0 LOG playsink gstplaysink.c:4357:sinkpad_blocked_cb:<playsink> unlocking from thread 0x7ff8f0014ed0 0:00:10.059885755 18431 0x1bbfd90 DEBUG playsink gstplaysink.c:2386:gst_play_sink_text_src_event:<tbin:src> Got event qos event: 0x7ff8e923c5f0, time 99:99:99.999999999, seq-num 833, GstEventQOS, type=(GstQOSType)GST_QOS_TYPE_OVERFLOW, proportion=(double)0.049415756281619781, diff=(gint64)-40408000, timestamp=(guint64)2920000000; 0:00:10.060383445 18431 0x7ff8f0014cf0 LOG playsink gstplaysink.c:4309:sinkpad_blocked_cb:<playsink> locking from thread 0x7ff8f0014cf0 0:00:10.060418156 18431 0x7ff8f0014cf0 LOG playsink gstplaysink.c:4309:sinkpad_blocked_cb:<playsink> locked from thread 0x7ff8f0014cf0 0:00:10.060433033 18431 0x7ff8f0014cf0 DEBUG playsink gstplaysink.c:4314:sinkpad_blocked_cb:<playsink:video_sink> Video pad blocked 0:00:10.060444975 18431 0x7ff8f0014cf0 LOG playsink gstplaysink.c:4357:sinkpad_blocked_cb:<playsink> unlocking from thread 0x7ff8f0014cf0 with master + your patch and 62053852de reverted: unsetting flag 0x00000004 0:00:07.588011930 18146 0xc1f8a0 LOG playsink gstplaysink.c:4262:gst_play_sink_reconfigure:<playsink> Triggering reconfiguration 0:00:07.588050483 18146 0xc1f8a0 LOG playsink gstplaysink.c:4264:gst_play_sink_reconfigure:<playsink> locking from thread 0xc1f8a0 0:00:07.588076953 18146 0xc1f8a0 LOG playsink gstplaysink.c:4264:gst_play_sink_reconfigure:<playsink> locked from thread 0xc1f8a0 0:00:07.588113969 18146 0xc1f8a0 LOG playsink gstplaysink.c:4280:gst_play_sink_reconfigure:<playsink> unlocking from thread 0xc1f8a0 0:00:07.623598991 18146 0x7fd9c4062450 LOG playsink gstplaysink.c:4307:sinkpad_blocked_cb:<playsink> locking from thread 0x7fd9c4062450 0:00:07.623946312 18146 0x7fd9c4062450 LOG playsink gstplaysink.c:4307:sinkpad_blocked_cb:<playsink> locked from thread 0x7fd9c4062450 0:00:07.624084668 18146 0x7fd9c4062450 DEBUG playsink gstplaysink.c:4315:sinkpad_blocked_cb:<playsink:audio_sink> Audio pad blocked 0:00:07.623601086 18146 0x7fd9c40ad370 DEBUG playsink gstplaysink.c:2386:gst_play_sink_text_src_event:<tbin:src> Got event qos event: 0x7fd9c12399f0, time 99:99:99.999999999, seq-num 750, GstEventQOS, type=(GstQOSType)GST_QOS_TYPE_OVERFLOW, proportion=(double)0.054286038175832774, diff=(gint64)-40293000, timestamp=(guint64)1919000000; 0:00:07.624121963 18146 0x7fd9c4062450 DEBUG playsink gstplaysink.c:4332:sinkpad_blocked_cb:<playsink> All pads blocked -- reconfiguring 0:00:07.624187894 18146 0x7fd9c4062450 DEBUG playsink gstplaysink.c:4337:sinkpad_blocked_cb:<playsink> Video pad is raw: 1 0:00:07.624221697 18146 0x7fd9c4062450 DEBUG playsink gstplaysink.c:4343:sinkpad_blocked_cb:<playsink> Audio pad is raw: 1 0:00:07.624237691 18146 0x7fd9c4062450 DEBUG playsink gstplaysink.c:3192:gst_play_sink_do_reconfigure:<playsink> reconfiguring 0:00:07.624252776 18146 0x7fd9c4062450 LOG playsink gstplaysink.c:3197:gst_play_sink_do_reconfigure:<playsink> locking from thread 0x7fd9c4062450 0:00:07.624268561 18146 0x7fd9c4062450 LOG playsink gstplaysink.c:3197:gst_play_sink_do_reconfigure:<playsink> locked from thread 0x7fd9c4062450 0:00:07.624284973 18146 0x7fd9c4062450 DEBUG playsink gstplaysink.c:3255:gst_play_sink_do_reconfigure:<playsink> audio:1, video:1, vis:0, text:0 0:00:07.624309208 18146 0x7fd9c4062450 DEBUG playsink gstplaysink.c:3268:gst_play_sink_do_reconfigure:<playsink> adding video, raw 1 0:00:07.624365780 18146 0x7fd9c4062450 DEBUG playsink gstplaysink.c:3361:gst_play_sink_do_reconfigure:<playsink> adding video deinterlace chain 0:00:07.624386942 18146 0x7fd9c4062450 DEBUG playsink gstplaysink.c:3363:gst_play_sink_do_reconfigure:<playsink> setting up deinterlacing chain 0:00:07.624427589 18146 0x7fd9c4062450 DEBUG playsink gstplaysink.c:3380:gst_play_sink_do_reconfigure:<playsink> adding video chain 0:00:07.624446866 18146 0x7fd9c4062450 DEBUG playsink gstplaysink.c:3470:gst_play_sink_do_reconfigure:<playsink> adding audio 0:00:07.624462161 18146 0x7fd9c4062450 DEBUG playsink gstplaysink.c:3591:gst_play_sink_do_reconfigure:<playsink> adding audio chain 0:00:07.624492402 18146 0x7fd9c4062450 DEBUG playsink gstplaysink.c:3712:gst_play_sink_do_reconfigure:<playsink> no vis needed 0:00:07.624511050 18146 0x7fd9c4062450 DEBUG playsink gstplaysink.c:3792:gst_play_sink_do_reconfigure:<playsink> no text needed 0:00:07.624525018 18146 0x7fd9c4062450 DEBUG playsink gstplaysink.c:3835:gst_play_sink_do_reconfigure:<playsink> turning off the text 0:00:07.624570904 18146 0x7fd9c4062450 LOG playsink gstplaysink.c:3844:gst_play_sink_do_reconfigure:<playsink> unlocking from thread 0x7fd9c4062450 0:00:07.624597234 18146 0x7fd9c4062450 LOG playsink gstplaysink.c:4355:sinkpad_blocked_cb:<playsink> unlocking from thread 0x7fd9c4062450
The problem seems to be that the text pad is never unblocked after a block, when it is enabled. I'm not sure what's supposed to unblock it.
Hum actually that's wrong; the text pad is never blocked after the probe is set. I'm not sure what's supposed to trigger the block.
The problem is that the subtitle thread is locked inside playsink in the subtitle renderer and it needs video buffers to be unlocked, but the video thread is going to block before entering playsink. Still not sure how to properly fix this one.
We could block the subtitle and only then block the video to make sure the subtitle thread doesn't stall downstream, but this assumes the subtitles is the sparse one. This might not be true for watching a slide set with subtitles that could have very long duration video frames with multiple subtitles per frame.
What should happen about this? It looks like the most important blocker for 1.8.0 at this point.
(sorry for the delay, was re-re-re-reading the playsink code...) The provided patch is wrong. It goes under the assumption that playsink->flags is what's actually configured. playsink->flags actually corresponds to "I would like you to configure yourself to this combination of flags if possible". Knowing whether a certain "flag" is active or not depends on a (way too big) list of things: * Whether a pad was requested for that input * Whether a chain was created already for a flag * Whether the input caps for a given pad changed or not * ... The design/code hasn't fundamentally changed since 0.10 ... which is the core issue. But we don't have time to rewrite/refactor/redesign this in the current timeframe. What I'm currently looking at is the following: * set_flags only stores the flags (i.e. don't apply the proposed patch) * Only make decisions of what to block/activate/unlink in gst_play_sink_reconfigure(). ** The rationale is that by then the various pads should have been requested, i.e. we have all the information needed to figure out the next steps ** This also means figuring out the various need_{audio|video|vis|deinterlace|text} variables there (which is currently done in _do_reconfigure() which is *after* pads are blocked). ** Use the presence (or not) of a chain to determine whether a "flag" is already active or not (ex: textchain != NULL => text flag was active previously) ** If a flag is to be removed (ex: audiochain != NULL but need_audio is FALSE) then just set an idle probe which will unlink/destroy the associated chain ** Only add a blocking probe if really need (i.e. a chain was added) I'll update once I have more results
Change of plans. I'm going to revert the patch that caused this regression for the 1.8 release. The rationale is that: * the issue (that the patch fixes) was only exhibited for a customer who is using decodebin3/playbin3, which is a lot more sensitive to dataflow in the pipeline. With decodebin2 this problem doesn't seem to happen (we would have noticed by now). * In order to properly fix the issue, it requires some refactoring (as explained in my previous comment). That being said, I am keeping the bug open so that we can fix it properly once decodebin3/playbin3 land into 1.9.x.
I am marking this bug as obsolete. If you want to (de)activate audio/video/... you can do so in playbin3/decodebin3 using the SELECT_STREAMS. Since 1.14 it will also add/remove the sink in playsink if/when needed (i.e. if you unselect the audio stream, the whole audio path including sinks will be removed).