Changing properties on a pipeline in playing state

[arunzg]

Attached debug log snippets at the end: of the 7 segments, problem is seen at 7. 

I have the following configuration:

souphttp --> hlsdemux -->  appsink

Pretty much given the manifest URI, this pipeline send the samples to app and application uses the signal (new sample) to put the data in buffer.

hlsdemux has the property connection-speed using which one can control the choice of variant below a bitrate. Initial value of this is default which means it can choose dynamically based on the current bitrate that is calculated at the end of a fragment download.

While this pipeline is running and application is collecting the samples, a configuration thread with the application, upon getting input, changes connection-speed to a certain number. This means if fragments are being downloaded at highest possible rate, now the next fragment should be rate limited to the new value. This is working. BUT after the changes incorporated on the datapath (after a fragment download), there's a freeze which varies from 4-7mins during which nothing happens (there's a WAIT) and after that it continues to finish it.

Any clues? Thanks in advance for your help!

Application:(Config thread)

With or without changing pipeline status setting below, same effect: 

ret = gst_element_set_state( pAppHlsCtx ->pipeline, GST_STATE_PAUSED);

g_object_set(pAppHlsCtx->hlsDemux, "connection-speed", value, NULL);

ret = gst_element_set_state( pAppHlsCtx ->pipeline, GST_STATE_PLAYING);

DEBUG LOG: This is where it waits everytime when config changed:

Connection-speed changed by config in the middle of fragment download (1)

0:00:10.797018357 [336m25649 [00m 0x7f6564086630 [37mDEBUG   [00m [00m       adaptivedemux gstadaptivedemux.c:360:gst_adaptive_demux_set_property:<hlsdemux> [00m Connection speed set to 200000
0:00:10.797027416 [336m25649 [00m 0x7f6564086630 [37mTRACE   [00m [00m       adaptivedemux gstadaptivedemux.c:370:gst_adaptive_demux_set_property: [00m Unlocking from thread 0x7f6564086630
0:00:10.797044828 [336m25649 [00m 0x7f6564086630 [37mTRACE   [00m [00;01;31;44m     GST_REFCOUNTING gstobject.c:237:gst_object_ref:<test-pipeline> [00m 0x10ce1f0 ref 1->2
0:00:10.797058900 [336m25649 [00m 0x7f6564086630 [33;01mLOG     [00m [00;01;37;44m      GST_PROPERTIES gstobject.c:472:gst_object_dispatch_properties_changed:<test-pipeline> [00m deep notification from hlsdemux (connection-speed)

.....

.....  Fragment download by a thread completed (2) 

0:00:11.059384719 [336m25649 [00m 0x7f656c004370 [37mDEBUG   [00m [00;43m             GST_BUS gstbus.c:316:gst_bus_post:<bus3> [00m [msg 0x10d29c0] posting on bus element message: 0x10d29c0, time 99:99:99.999999999, seq-num 639, element 'hlsdemux', adaptive-streaming-statistics, manifest-uri=(string)http://devimages.apple.com.edgekey.net/iphone/samples/bipbop/bipbopall.m3u8, uri=(string)http://devimages.apple.com.edgekey.net/iphone/samples/bipbop/gear4/fileSequence17.ts, fragment-start-time=(guint64)527087377757, fragment-stop-time=(guint64)527087838938936, fragment-size=(guint64)17170792, fragment-download-time=(guint64)428503249;
0:00:11.059396707 [336m25649 [00m 0x7f656c004370 [37mDEBUG   [00m [00;43m             GST_BUS gstbus.c:355:gst_bus_post:<bus3> [00m [msg 0x10d29c0] pushing on async queue

....

.... New next fragment getting chosen as per the new connection-speed (3) 

0:00:11.059704628 [336m25649 [00m 0x7f656c004370 [33;01mLOG     [00m [00m       adaptivedemux gstadaptivedemux.c:2240:gst_adaptive_demux_stream_update_current_bitrate:<hlsdemux> [00m Connection-speed is set to 200 kbps, using it
0:00:11.059719002 [336m25649 [00m 0x7f656c004370 [37mDEBUG   [00m [00m            hlsdemux gsthlsdemux.c:579:gst_hls_demux_set_current_variant:<hlsdemux> [00m Switching Variant. Copying over sequence 18 and sequence_pos 0:03:00.000000000
0:00:11.059731534 [336m25649 [00m 0x7f656c004370 [36mINFO   [00m [00m            hlsdemux gsthlsdemux.c:1597:gst_hls_demux_change_playlist:<hlsdemux> [00m Client was on 737777bps, max allowed is 200000bps, switching to bitrate 200000bps
0:00:11.059746954 [336m25649 [00m 0x7f656c004370 [37mDEBUG   [00m [00m       uridownloader gsturidownloader.c:562:gst_uri_downloader_fetch_uri_with_range:<uridownloader0> [00m Fetching URI http://devimages.apple.com.edgekey.net/iphone/samples/bipbop/gear1/prog_index.m3u8

.....

.....Previous fragment download completed (4)   Not sure what is the difference between (2) and this (4) that happens 

.....        after the media playlist for new connection limit downloaded!!

0:00:11.360280538 [336m25649 [00m 0x7f655c0034a0 [33;01mLOG     [00m [00m       adaptivedemux gstadaptivedemux.c:3583:gst_adaptive_demux_stream_download_loop:<'':src_1> [00m download loop start
0:00:11.360289875 [336m25649 [00m 0x7f655c0034a0 [37mTRACE   [00m [00m       adaptivedemux gstadaptivedemux.c:3585:gst_adaptive_demux_stream_download_loop: [00m Locking from thread 0x7f655c0034a0
0:00:11.360310544 [336m25649 [00m      0x1026d40 [37mDEBUG   [00m [00m       adaptivedemux gstadaptivedemux.c:3220:gst_adaptive_demux_stream_download_uri:<hlsdemux:src_0> [00m Finished Waiting for fragment download: http://devimages.apple.com.edgekey.net/iphone/samples/bipbop/gear4/fileSequence17.ts

....

.... Chose new fragment as per the changed parameter (5) 

0:00:11.360624748 [336m25649 [00m 0x7f655c0034a0 [37mDEBUG   [00m [00m                 hls m3u8.c:862:gst_m3u8_get_next_fragment: [00m Got fragment with sequence 18 (current sequence 18)
0:00:11.360636604 [336m25649 [00m 0x7f655c0034a0 [37mDEBUG   [00m [00m            hlsdemux gsthlsdemux.c:1109:gst_hls_demux_update_fragment_info:<hlsdemux> [00m Stream 0x7f655c661540 URI now http://devimages.apple.com.edgekey.net/iphone/samples/bipbop/gear1/fileSequence18.ts

....

....

....Between (5) and now new Pad created as bitrate changed.. BUT WATCH THE FOLLOWING IN RED.. NOT SURE WHAT THIS TELLS (6)

0:00:11.926670203 [336m25649 [00m 0x7f655c0035e0 [37mDEBUG   [00m [00;01;35m      GST_SCHEDULING gstpad.c:4324:gst_pad_chain_data_unchecked:<appsink1:sink> [00m calling chainfunction &gst_base_sink_chain with buffer buffer: 0x7f655c2c2900, pts 0:03:00.000000000, dts 99:99:99.999999999, dur 99:99:99.999999999, size 7569, offset 0, offset_end 7569, flags 0x4040
0:00:11.926697905 [336m25649 [00m 0x7f655c0035e0 [37mDEBUG   [00m [00m            basesink gstbasesink.c:3524:gst_base_sink_chain_unlocked:<appsink1> [00m got times start: 0:03:00.000000000, end: 99:99:99.999999999
0:00:11.926716591 [336m25649 [00m 0x7f655c0035e0 [37mDEBUG   [00m [00m            basesink gstbasesink.c:2112:gst_base_sink_get_sync_times:<appsink1> [00m got times start: 0:03:00.000000000, stop: 99:99:99.999999999, do_sync 1
0:00:11.926725903 [336m25649 [00m 0x7f655c0035e0 [37mDEBUG   [00m [00;04m             default gstsegment.c:737:gst_segment_to_running_time_full: [00m invalid position (-1)
0:00:11.926740393 [336m25649 [00m 0x7f655c0035e0 [37mDEBUG   [00m [00m            basesink gstbasesink.c:2694:gst_base_sink_do_sync:<appsink1> [00m reset rc_time to time 0:03:00.000000000
0:00:11.926756101 [336m25649 [00m 0x7f655c0035e0 [37mDEBUG   [00m [00m            basesink gstbasesink.c:2706:gst_base_sink_do_sync:<appsink1> [00m possibly waiting for clock to reach 0:03:00.000000000, adjusted 0:03:00.000000000
0:00:11.926771291 [336m25649 [00m 0x7f655c0035e0 [33;01mLOG     [00m [00m            basesink gstbasesink.c:2283:gst_base_sink_wait_clock:<appsink1> [00m time 0:03:00.000000000, base_time 146:24:39.092172263

.....

..... THIS IS WHERE BIG WAIT HAPPENS!! Goes with redmarked info in previous section!!(7)

.....

0:00:11.926813256 [336m25649 [00m 0x7f655c0035e0 [37mDEBUG   [00m [00;01;33m           GST_CLOCK gstclock.c:557:gst_clock_id_wait:<GstSystemClock> [00m waiting on clock entry 0x10cb130
0:00:11.926827290 [336m25649 [00m 0x7f655c0035e0 [37mDEBUG   [00m [00;01;33m           GST_CLOCK gstclock.c:1092:gst_clock_get_internal_time:<GstSystemClock> [00m internal time 146:24:48.706546242
0:00:11.926846159 [336m25649 [00m 0x7f655c0035e0 [37mDEBUG   [00m [00;01;33m           GST_CLOCK gstclock.c:1137:gst_clock_get_time:<GstSystemClock> [00m adjusted time 146:24:48.706546242
0:00:11.926863177 [336m25649 [00m 0x7f655c0035e0 [37mDEBUG   [00m [00;01;33m           GST_CLOCK gstsystemclock.c:714:gst_system_clock_id_wait_jitter_unlocked: [00m entry 0x10cb130 time 146:27:39.092172263 now 146:24:48.706546242 diff (time-now) 170385626021
0:00:11.926876486 [336m25649 [00m 0x7f655c0035e0 [37mDEBUG   [00m [00m            GST_POLL gstpoll.c:1414:gst_poll_wait: [00m 0x10268a0: timeout :0:02:50.385626021
0:03:02.328324076 [336m25649 [00m 0x7f655c0035e0 [37mDEBUG   [00m [00;01;33m           GST_CLOCK gstsystemclock.c:742:gst_system_clock_id_wait_jitter_unlocked: [00m entry 0x10cb130 unlocked, status 3, ret 0
0:03:02.328372880 [336m25649 [00m 0x7f655c0035e0 [37mDEBUG   [00m [00;01;33m           GST_CLOCK gstsystemclock.c:766:gst_system_clock_id_wait_jitter_unlocked: [00m entry 0x10cb130 unlocked after timeout
0:03:02.328393387 [336m25649 [00m 0x7f655c0035e0 [37mDEBUG   [00m [00;01;33m           GST_CLOCK gstclock.c:1092:gst_clock_get_internal_time:<GstSystemClock> [00m internal time 146:27:39.108108927

_______________________________________________
gstreamer-devel mailing list
[hidden email]
https://lists.freedesktop.org/mailman/listinfo/gstreamer-devel