Changing properties on a pipeline in playing state

Fri May 22 22:54:49 UTC 2020

*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
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.freedesktop.org/archives/gstreamer-devel/attachments/20200522/889e91a2/attachment-0001.htm>