Progressive downloading not working with large files when using appsrc
I am currently trying to enable progressive downloading for https://github.com/servo/media and I am observing an unexpected behavior when dealing with large files (and also when disk I/O traffic is high?). In order to enable progressive downloading with the pipeline that we have for a/v playback (appsrc -> gst-player) I had to write a bin subclass (servosrc) to wrap the appsrc to respond to the SCHEDULING query with the BANDWIDTH_LIMITED flag. So the pipeline is: servosrc[appsrc] -> gst-player
What I see in the logs is this:
0:00:00.663961000 [336m20345[00m 0x7f9cd910e850 [37mDEBUG [00m [00m downloadbuffer gstdownloadbuffer.c:532:gboolean get_buffering_percent(GstDownloadBuffer *, gboolean *, gint *):<downloadbuffer0>[00m buffering 1, percent 100
0:00:00.663970000 [336m20345[00m 0x7f9cd910e850 [33;01mLOG [00m [00;01;37;41m GST_MESSAGE gstmessage.c:301:GstMessage *gst_message_new_custom(GstMessageType, GstObject *, GstStructure *):[00m source downloadbuffer0: creating new message 0x7f9cdb02a680 buffering
0:00:00.663978000 [336m20345[00m 0x7f9cd910e850 [33;01mLOG [00m [00m downloadbuffer gstdownloadbuffer.c:1077:gboolean gst_download_buffer_handle_sink_event(GstPad *, GstObject *, GstEvent *):<downloadbuffer0>[00m (downloadbuffer0:sink) signal ADD: 2097152 of 2097152 bytes, 276145548 of 2000000000 ns
0:00:00.663997000 [336m20345[00m 0x7f9cd910e850 [37mDEBUG [00m [00;43m GST_BUS gstbus.c:318:gboolean gst_bus_post(GstBus *, GstMessage *):<bus3>[00m [msg 0x7f9cdb02a680] posting on bus buffering message: 0x7f9cdb02a680, time 99:99:99.999999999, seq-num 245, element 'downloadbuffer0', GstMessageBuffering, buffer-percent=(int)100, buffering-mode=(GstBufferingMode)GST_BUFFERING_DOWNLOAD, avg-in-rate=(int)4317977, avg-out-rate=(int)326579, buffering-left=(gint64)0;
0:00:00.664007000 [336m20345[00m 0x7f9cd910e850 [37mDEBUG [00m [00;01m bin gstbin.c:3717:void gst_bin_handle_message_func(GstBin *, GstMessage *):<uridecodebin0>[00m [msg 0x7f9cdb02a680] handling child downloadbuffer0 message of type buffering
0:00:00.664012000 [336m20345[00m 0x7f9cd910e850 [37mDEBUG [00m [00;01m bin gstbin.c:4054:void gst_bin_handle_message_func(GstBin *, GstMessage *):<uridecodebin0>[00m posting message upward
0:00:00.664024000 [336m20345[00m 0x7f9cd910e850 [37mDEBUG [00m [00;43m GST_BUS gstbus.c:318:gboolean gst_bus_post(GstBus *, GstMessage *):<bus0>[00m [msg 0x7f9cdb02a680] posting on bus buffering message: 0x7f9cdb02a680, time 99:99:99.999999999, seq-num 245, element 'downloadbuffer0', GstMessageBuffering, buffer-percent=(int)100, buffering-mode=(GstBufferingMode)GST_BUFFERING_DOWNLOAD, avg-in-rate=(int)4317977, avg-out-rate=(int)326579, buffering-left=(gint64)0;
0:00:00.664032000 [336m20345[00m 0x7f9cd910e850 [37mDEBUG [00m [00;01m bin gstbin.c:3717:void gst_bin_handle_message_func(GstBin *, GstMessage *):<playbin0>[00m [msg 0x7f9cdb02a680] handling child downloadbuffer0 message of type buffering
0:00:00.664036000 [336m20345[00m 0x7f9cd9167050 [33;01mLOG [00m [00m downloadbuffer gstdownloadbuffer.c:718:GstFlowReturn gst_download_buffer_wait_for_data(GstDownloadBuffer *, guint64, guint):<downloadbuffer0>[00m (downloadbuffer0:src) received ADD: 2097152 of 2097152 bytes, 276145548 of 2000000000 ns
0:00:00.664079000 [336m20345[00m 0x7f9cd9167050 [37mDEBUG [00m [00m downloadbuffer gstdownloadbuffer.c:719:GstFlowReturn gst_download_buffer_wait_for_data(GstDownloadBuffer *, guint64, guint):<downloadbuffer0>[00m got more data
0:00:00.664114000 [336m20345[00m 0x7f9cd9167050 [37mDEBUG [00m [00m downloadbuffer gstdownloadbuffer.c:674:GstFlowReturn gst_download_buffer_wait_for_data(GstDownloadBuffer *, guint64, guint):<downloadbuffer0>[00m wait for 10049590, length 1577
0:00:00.664037000 [336m20345[00m 0x7f9cd910e850 [37mDEBUG [00m [00;01m bin gstbin.c:4054:void gst_bin_handle_message_func(GstBin *, GstMessage *):<playbin0>[00m posting message upward
0:00:00.664151000 [336m20345[00m 0x7f9cd910e850 [37mDEBUG [00m [00;43m GST_BUS gstbus.c:318:gboolean gst_bus_post(GstBus *, GstMessage *):<bus1>[00m [msg 0x7f9cdb02a680] posting on bus buffering message: 0x7f9cdb02a680, time 99:99:99.999999999, seq-num 245, element 'downloadbuffer0', GstMessageBuffering, buffer-percent=(int)100, buffering-mode=(GstBufferingMode)GST_BUFFERING_DOWNLOAD, avg-in-rate=(int)4317977, avg-out-rate=(int)326579, buffering-left=(gint64)0;
0:00:00.664160000 [336m20345[00m 0x7f9cd910e850 [37mDEBUG [00m [00;43m GST_BUS gstbus.c:357:gboolean gst_bus_post(GstBus *, GstMessage *):<bus1>[00m [msg 0x7f9cdb02a680] pushing on async queue
0:00:00.664167000 [336m20345[00m 0x7f9cd910e850 [33;01mLOG [00m [00m GST_POLL gstpoll.c:290:gboolean raise_wakeup(GstPoll *):[00m 0x7f9cd9112990: raise
0:00:00.664179000 [336m20345[00m 0x7f9cd910e850 [37mDEBUG [00m [00;43m GST_BUS gstbus.c:360:gboolean gst_bus_post(GstBus *, GstMessage *):<bus1>[00m [msg 0x7f9cdb02a680] pushed on async queue
0:00:00.664213000 [336m20345[00m 0x7f9cd910e850 [37mDEBUG [00m [00;43m GST_BUS gstbus.c:353:gboolean gst_bus_post(GstBus *, GstMessage *):<bus0>[00m [msg 0x7f9cdb02a680] dropped
0:00:00.664239000 [336m20345[00m 0x7f9cd910e850 [37mDEBUG [00m [00;43m GST_BUS gstbus.c:353:gboolean gst_bus_post(GstBus *, GstMessage *):<bus3>[00m [msg 0x7f9cdb02a680] dropped
0:00:00.664239000 [336m20345[00m 0x7f9cd8c1a000 [33;01mLOG [00m [00;43m GST_BUS gstbus.c:522:GstMessage *gst_bus_timed_pop_filtered(GstBus *, GstClockTime, GstMessageType):<bus1>[00m have 1 messages
0:00:00.664323000 [336m20345[00m 0x7f9cd8c1a000 [33;01mLOG [00m [00m GST_POLL gstpoll.c:314:gboolean release_wakeup(GstPoll *):[00m 0x7f9cd9112990: release
0:00:00.664267000 [336m20345[00m 0x7f9cd910e850 [37mDEBUG [00m [00;01;31;41m GST_PADS gstpad.c:5776:GstFlowReturn gst_pad_send_event_unchecked(GstPad *, GstEvent *, GstPadProbeType):<downloadbuffer0:sink>[00m sent event, ret ok
0:00:00.664358000 [336m20345[00m 0x7f9cd8c1a000 [37mDEBUG [00m [00;43m GST_BUS gstbus.c:546:GstMessage *gst_bus_timed_pop_filtered(GstBus *, GstClockTime, GstMessageType):<bus1>[00m got message 0x7f9cdb02a680, buffering from downloadbuffer0, type mask is 4294967295
0:00:00.664399000 [336m20345[00m 0x7f9cd910e850 [33;01mLOG [00m [00;01;31;41m GST_PADS gstpad.c:5219:GstFlowReturn store_sticky_event(GstPad *, GstEvent *):<downloadbuffer0:sink>[00m stored sticky event eos
0:00:00.664517000 [336m20345[00m 0x7f9cd910e850 [33;01mLOG [00m [00;01;31;41m GST_PADS gstpad.c:5412:GstFlowReturn gst_pad_push_event_unchecked(GstPad *, GstEvent *, GstPadProbeType):<typefindelement0:src>[00m sent event 0x7f9cd91559c0 (eos) to peerpad <downloadbuffer0:sink>, ret ok
0:00:00.664530000 [336m20345[00m 0x7f9cd910e850 [37mDEBUG [00m [00;01;31;41m GST_PADS gstpad.c:3932:gboolean push_sticky(GstPad *, PadEvent *, gpointer):<typefindelement0:src>[00m event eos marked received
0:00:00.664122000 [336m20345[00m 0x7f9cd9167050 [37mDEBUG [00m [00;04m default gstsparsefile.c:419:gboolean gst_sparse_file_get_range_before(GstSparseFile *, gsize, gsize *, gsize *):[00m start 1818624 > 10049590
0:00:00.664457000 [336m20345[00m 0x7f9cd8c1a000 [37mDEBUG [00m [00;43m GST_BUS gstbus.c:839:gboolean gst_bus_source_dispatch(GSource *, GSourceFunc, gpointer):<bus1>[00m source 0x7f9cd8cfaa00 calling dispatch with buffering message: 0x7f9cdb02a680, time 99:99:99.999999999, seq-num 245, element 'downloadbuffer0', GstMessageBuffering, buffer-percent=(int)100, buffering-mode=(GstBufferingMode)GST_BUFFERING_DOWNLOAD, avg-in-rate=(int)4317977, avg-out-rate=(int)326579, buffering-left=(gint64)0;
0:00:00.664538000 [336m20345[00m 0x7f9cd910e850 [37mDEBUG [00m [00;01;31;41m GST_PADS gstpad.c:5776:GstFlowReturn gst_pad_send_event_unchecked(GstPad *, GstEvent *, GstPadProbeType):<typefindelement0:sink>[00m sent event, ret ok
0:00:00.664636000 [336m20345[00m 0x7f9cd9167050 [37mDEBUG [00m [00m downloadbuffer gstdownloadbuffer.c:686:GstFlowReturn gst_download_buffer_wait_for_data(GstDownloadBuffer *, guint64, guint):<downloadbuffer0>[00m range before 0 - 1818624
0:00:00.664695000 [336m20345[00m 0x7f9cd910e850 [33;01mLOG [00m [00;01;31;41m GST_PADS gstpad.c:5219:GstFlowReturn store_sticky_event(GstPad *, GstEvent *):<typefindelement0:sink>[00m stored sticky event eos
0:00:00.664721000 [336m20345[00m 0x7f9cd910e850 [33;01mLOG [00m [00;01;31;41m GST_PADS gstpad.c:5412:GstFlowReturn gst_pad_push_event_unchecked(GstPad *, GstEvent *, GstPadProbeType):<source:src>[00m sent event 0x7f9cd91559c0 (eos) to peerpad <typefindelement0:sink>, ret ok
0:00:00.664731000 [336m20345[00m 0x7f9cd910e850 [33;01mLOG [00m [00;01;35m GST_SCHEDULING gstpad.c:3720:GstFlowReturn do_probe_callbacks(GstPad *, GstPadProbeInfo *, GstFlowReturn):<source:src>[00m do probes
0:00:00.664765000 [336m20345[00m 0x7f9cd8c1a000 [37mDEBUG [00m [00;01;31m GST_STATES gstelement.c:2827:GstStateChangeReturn gst_element_set_state_func(GstElement *, GstState):<playbin0>[00m set_state to PLAYING
0:00:00.664724000 [336m20345[00m 0x7f9cd9167050 [37mDEBUG [00m [00m downloadbuffer gstdownloadbuffer.c:405:void update_levels(GstDownloadBuffer *, guint):[00m levels: bytes 0/2097152, time 0:00:00.000000000/0:00:02.000000000
0:00:00.664833000 [336m20345[00m 0x7f9cd9167050 [37mDEBUG [00m [00m downloadbuffer gstdownloadbuffer.c:716:GstFlowReturn gst_download_buffer_wait_for_data(GstDownloadBuffer *, guint64, guint):<downloadbuffer0>[00m waiting for more data
0:00:00.664844000 [336m20345[00m 0x7f9cd9167050 [33;01mLOG [00m [00m downloadbuffer gstdownloadbuffer.c:718:GstFlowReturn gst_download_buffer_wait_for_data(GstDownloadBuffer *, guint64, guint):<downloadbuffer0>[00m (downloadbuffer0:src) wait for ADD: 0 of 2097152 bytes, 0 of 2000000000 ns
0:00:00.664769000 [336m20345[00m 0x7f9cd910e850 [33;01mLOG [00m [00;01;35m GST_SCHEDULING gstpad.c:3609:void probe_hook_marshal(GHook *, ProbeMarshall *):<source:src>[00m hook 1 with flags 0x00003400 does not match 00001001
0:00:00.664798000 [336m20345[00m 0x7f9cd8c1a000 [37mDEBUG [00m [00;01;31m GST_STATES gstelement.c:2852:GstStateChangeReturn gst_element_set_state_func(GstElement *, GstState):<playbin0>[00m setting target state to PLAYING
0:00:00.664904000 [336m20345[00m 0x7f9cd910e850 [37mDEBUG [00m [00;01;31;41m GST_PADS gstpad.c:3932:gboolean push_sticky(GstPad *, PadEvent *, gpointer):<source:src>[00m event eos marked received
0:00:00.664916000 [336m20345[00m 0x7f9cd910e850 [37mDEBUG [00m [00;01;31;41m GST_PADS gstpad.c:5776:GstFlowReturn gst_pad_send_event_unchecked(GstPad *, GstEvent *, GstPadProbeType):<src:proxypad0>[00m sent event, ret ok
0:00:00.664927000 [336m20345[00m 0x7f9cd910e850 [33;01mLOG [00m [00;01;31;41m GST_PADS gstpad.c:5219:GstFlowReturn store_sticky_event(GstPad *, GstEvent *):<src:proxypad0>[00m stored sticky event eos
0:00:00.664938000 [336m20345[00m 0x7f9cd910e850 [33;01mLOG [00m [00;01;31;41m GST_PADS gstpad.c:5412:GstFlowReturn gst_pad_push_event_unchecked(GstPad *, GstEvent *, GstPadProbeType):<appsrc0:src>[00m sent event 0x7f9cd91559c0 (eos) to peerpad <src:proxypad0>, ret ok
0:00:00.664959000 [336m20345[00m 0x7f9cd910e850 [37mDEBUG [00m [00;01;31;41m GST_PADS gstpad.c:3932:gboolean push_sticky(GstPad *, PadEvent *, gpointer):<appsrc0:src>[00m event eos marked received
0:00:00.664985000 [336m20345[00m 0x7f9cd910e850 [36mINFO [00m [00m task gsttask.c:316:void gst_task_func(GstTask *):<appsrc0:src>[00m Task going to paused
0:00:00.665012000 [336m20345[00m 0x7f9cd8c1a000 [37mDEBUG [00m [00;01;31m GST_STATES gstelement.c:2865:GstStateChangeReturn gst_element_set_state_func(GstElement *, GstState):<playbin0>[00m current READY, old_pending PAUSED, next PAUSED, old return ASYNC
0:00:00.665019000 [336m20345[00m 0x7f9cd8c1a000 [37mDEBUG [00m [00;01;31m GST_STATES gstelement.c:2919:GstStateChangeReturn gst_element_set_state_func(GstElement *, GstState):<playbin0>[00m element was busy with async state change
0:00:00.665028000 [336m20345[00m 0x7f9cd8c1a000 [33;01mLOG [00m [00;01;37;41m GST_MESSAGE gstmessage.c:208:void _gst_message_free(GstMessage *):[00m finalize message 0x7f9cdb02a680, buffering from downloadbuffer0
0:00:00.665036000 [336m20345[00m 0x7f9cd8c1a000 [37mDEBUG [00m [00;43m GST_BUS gstbus.c:844:gboolean gst_bus_source_dispatch(GSource *, GSourceFunc, gpointer):<bus1>[00m source 0x7f9cd8cfaa00 handler returns 1
0:00:01.853420000 [336m20345[00m 0x7f9cd8c1a000 [37mDEBUG [00m [00m query gstquery.c:675:GstQuery *gst_query_new_custom(GstQueryType, GstStructure *):[00m creating new query 0x7f9cd910e8a0 buffering
0:00:01.853494000 [336m20345[00m 0x7f9cd8c1a000 [37mDEBUG [00m [00;01;37;41m GST_ELEMENT_PADS gstelement.c:1962:gboolean gst_element_query(GstElement *, GstQuery *):[00m send query on element playbin0
0:00:01.853540000 [336m20345[00m 0x7f9cd8c1a000 [37mDEBUG [00m [00;01m bin gstbin.c:4375:gboolean gst_bin_query(GstElement *, GstQuery *):<playbin0>[00m Sending query 0x7f9cd910e8a0 (type buffering) to sink children
0:00:01.853570000 [336m20345[00m 0x7f9cd8c1a000 [37mDEBUG [00m [00;01;31m GST_STATES gstbin.c:1971:gint bin_element_is_sink(GstElement *, GstBin *):<playbin0>[00m child uridecodebin0 is not sink
0:00:01.853598000 [336m20345[00m 0x7f9cd8c1a000 [37mDEBUG [00m [00;01;31m GST_STATES gstbin.c:1971:gint bin_element_is_sink(GstElement *, GstBin *):<playbin0>[00m child playsink is sink
0:00:01.853622000 [336m20345[00m 0x7f9cd8c1a000 [37mDEBUG [00m [00;01;37;41m GST_ELEMENT_PADS gstelement.c:1962:gboolean gst_element_query(GstElement *, GstQuery *):[00m send query on element playsink
0:00:01.853649000 [336m20345[00m 0x7f9cd8c1a000 [37mDEBUG [00m [00;01m bin gstbin.c:4375:gboolean gst_bin_query(GstElement *, GstQuery *):<playsink>[00m Sending query 0x7f9cd910e8a0 (type buffering) to sink children
0:00:01.853676000 [336m20345[00m 0x7f9cd8c1a000 [37mDEBUG [00m [00;01;31m GST_STATES gstbin.c:1971:gint bin_element_is_sink(GstElement *, GstBin *):<playsink>[00m child streamsynchronizer0 is not sink
0:00:01.853704000 [336m20345[00m 0x7f9cd8c1a000 [37mDEBUG [00m [00;01m bin gstbin.c:4397:gboolean gst_bin_query(GstElement *, GstQuery *):<playsink>[00m query 0x7f9cd910e8a0 result 0
0:00:01.853730000 [336m20345[00m 0x7f9cd8c1a000 [37mDEBUG [00m [00;01m bin gstbin.c:4397:gboolean gst_bin_query(GstElement *, GstQuery *):<playbin0>[00m query 0x7f9cd910e8a0 result 0
0:00:01.853759000 [336m20345[00m 0x7f9cd8c1a000 [37mDEBUG [00m [00m query gstquery.c:675:GstQuery *gst_query_new_custom(GstQueryType, GstStructure *):[00m creating new query 0x7f9cd910fad0 position
0:00:01.853779000 [336m20345[00m 0x7f9cd8c1a000 [37mDEBUG [00m [00;01;37;41m GST_ELEMENT_PADS gstelement.c:1962:gboolean gst_element_query(GstElement *, GstQuery *):[00m send query on element playbin0
0:00:01.853805000 [336m20345[00m 0x7f9cd8c1a000 [37mDEBUG [00m [00;01m bin gstbin.c:4375:gboolean gst_bin_query(GstElement *, GstQuery *):<playbin0>[00m Sending query 0x7f9cd910fad0 (type position) to sink children
0:00:01.853869000 [336m20345[00m 0x7f9cd8c1a000 [37mDEBUG [00m [00;01;31m GST_STATES gstbin.c:1971:gint bin_element_is_sink(GstElement *, GstBin *):<playbin0>[00m child uridecodebin0 is not sink
0:00:01.853896000 [336m20345[00m 0x7f9cd8c1a000 [37mDEBUG [00m [00;01;31m GST_STATES gstbin.c:1971:gint bin_element_is_sink(GstElement *, GstBin *):<playbin0>[00m child playsink is sink
0:00:01.853918000 [336m20345[00m 0x7f9cd8c1a000 [37mDEBUG [00m [00;01;37;41m GST_ELEMENT_PADS gstelement.c:1962:gboolean gst_element_query(GstElement *, GstQuery *):[00m send query on element playsink
0:00:01.853944000 [336m20345[00m 0x7f9cd8c1a000 [37mDEBUG [00m [00;01m bin gstbin.c:4375:gboolean gst_bin_query(GstElement *, GstQuery *):<playsink>[00m Sending query 0x7f9cd910fad0 (type position) to sink children
0:00:01.853968000 [336m20345[00m 0x7f9cd8c1a000 [37mDEBUG [00m [00;01;31m GST_STATES gstbin.c:1971:gint bin_element_is_sink(GstElement *, GstBin *):<playsink>[00m child streamsynchronizer0 is not sink
0:00:01.853994000 [336m20345[00m 0x7f9cd8c1a000 [37mDEBUG [00m [00;01m bin gstbin.c:4397:gboolean gst_bin_query(GstElement *, GstQuery *):<playsink>[00m query 0x7f9cd910fad0 result 0
0:00:01.854020000 [336m20345[00m 0x7f9cd8c1a000 [37mDEBUG [00m [00;01m bin gstbin.c:4397:gboolean gst_bin_query(GstElement *, GstQuery *):<playbin0>[00m query 0x7f9cd910fad0 result 0
0:00:02.858184000 [336m20345[00m 0x7f9cd8c1a000 [37mDEBUG [00m [00m query gstquery.c:675:GstQuery *gst_query_new_custom(GstQueryType, GstStructure *):[00m creating new query 0x7f9cd910fb20 buffering
0:00:02.858257000 [336m20345[00m 0x7f9cd8c1a000 [37mDEBUG [00m [00;01;37;41m GST_ELEMENT_PADS gstelement.c:1962:gboolean gst_element_query(GstElement *, GstQuery *):[00m send query on element playbin0
0:00:02.858301000 [336m20345[00m 0x7f9cd8c1a000 [37mDEBUG [00m [00;01m bin gstbin.c:4375:gboolean gst_bin_query(GstElement *, GstQuery *):<playbin0>[00m Sending query 0x7f9cd910fb20 (type buffering) to sink children
0:00:02.858332000 [336m20345[00m 0x7f9cd8c1a000 [37mDEBUG [00m [00;01;31m GST_STATES gstbin.c:1971:gint bin_element_is_sink(GstElement *, GstBin *):<playbin0>[00m child uridecodebin0 is not sink
0:00:02.858360000 [336m20345[00m 0x7f9cd8c1a000 [37mDEBUG [00m [00;01;31m GST_STATES gstbin.c:1971:gint bin_element_is_sink(GstElement *, GstBin *):<playbin0>[00m child playsink is sink
0:00:02.858385000 [336m20345[00m 0x7f9cd8c1a000 [37mDEBUG [00m [00;01;37;41m GST_ELEMENT_PADS gstelement.c:1962:gboolean gst_element_query(GstElement *, GstQuery *):[00m send query on element playsinkIt seems that when the buffering level gets to 100, the appsrc wants to pause everything, but it can't and that causes the buffering messages to start jumping from one element to the other, which breaks playback.
I tried to get a standalone test case by extending the progressive streaming playback tutorial here. To test that do:
cd tutorials && cargo run --bin playback-tutorial-4 <file>Where <file> is the absolute path of the media you want to play. I observed that it works with files of ~10Mb. For example:
- It works with https://www.freedesktop.org/software/gstreamer-sdk/data/media/sintel_trailer-480p.webm (unless you set GST_DEBUG=6 :\ )
- It does not work with https://download.blender.org/peach/bigbuckbunny_movies/big_buck_bunny_480p_stereo.ogg
Edited by Tim-Philipp Müller