GStreamer学习十三（GStreamer状态机分析）

最新推荐文章于 2024-07-25 22:04:04 发布

冰山一脚2013

最新推荐文章于 2024-07-25 22:04:04 发布

阅读量1.2k

点赞数

分类专栏： GStreamer

本文链接：https://blog.csdn.net/cai742925624/article/details/112060737

版权

GStreamer 专栏收录该内容

31 篇文章 23 订阅

订阅专栏

分析对象：gst-launch-1.0 videotestsrc ! testsink

1、准备创建/添加

2、、NULL --> READY

1、pipeline的设置

0:00:50.863741000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2827:gst_element_set_state_func:<my-pipeline1> set_state to READY 开始设置pipeline

0:00:50.864048000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2852:gst_element_set_state_func:<my-pipeline1> setting target state to READY

0:00:50.864437000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2865:gst_element_set_state_func:<my-pipeline1> current NULL, old_pending VOID_PENDING, next VOID_PENDING, old return SUCCESS

0:00:50.864860000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2899:gst_element_set_state_func:<my-pipeline1> final: setting state from NULL to READY

0:00:50.865214000 15216 00000189D4A09000 DEBUG GST_BUS gstbus.c:470:gst_bus_set_flushing:<bus1> unset bus flushing

0:00:50.865506000 15216 00000189D4A09000 DEBUG GST_STATES gstbin.c:2851:gst_bin_change_state_func:<my-pipeline1> changing state of children from NULL to READY

0:00:50.865838000 15216 00000189D4A09000 DEBUG bin gstbin.c:2888:gst_bin_change_state_func:<my-pipeline1> clearing all cached messages

0:00:50.866147000 15216 00000189D4A09000 DEBUG bin gstbin.c:2696:gst_bin_src_pads_activate:<my-pipeline1> deactivate pads

0:00:50.866429000 15216 00000189D4A09000 DEBUG bin gstbin.c:2704:gst_bin_src_pads_activate:<my-pipeline1> pad deactivation successful

0:00:50.866726000 15216 00000189D4A09000 DEBUG bin gstbin.c:2382:gst_bin_sort_iterator_resync:<my-pipeline1> resync

0:00:50.866987000 15216 00000189D4A09000 DEBUG bin gstbin.c:2162:add_to_queue:<my-pipeline1> adding 'sink' to queue

0:00:50.867250000 15216 00000189D4A09000 DEBUG bin gstbin.c:882:find_message:<my-pipeline1> no message found matching types 00001000

0:00:50.867546000 15216 00000189D4A09000 DEBUG bin gstbin.c:889:find_message:<my-pipeline1> structure-change

0:00:50.867806000 15216 00000189D4A09000 DEBUG bin gstbin.c:2279:update_degree:<my-pipeline1> change element source, degree 0->1, linked to sink

0:00:50.868126000 15216 00000189D4A09000 DEBUG bin gstbin.c:2302:update_degree:<my-pipeline1> element source not linked on any sinkpads

0:00:50.868432000 15216 00000189D4A09000 DEBUG bin gstbin.c:2369:gst_bin_sort_iterator_next:<my-pipeline1> queue head gives sink

0:00:50.868719000 15216 00000189D4A09000 DEBUG bin gstbin.c:882:find_message:<my-pipeline1> no message found matching types 00001000

0:00:50.869012000 15216 00000189D4A09000 DEBUG bin gstbin.c:889:find_message:<my-pipeline1> structure-change

0:00:50.869266000 15216 00000189D4A09000 DEBUG bin gstbin.c:2279:update_degree:<my-pipeline1> change element source, degree 1->0, linked to sink

0:00:50.869632000 15216 00000189D4A09000 DEBUG bin gstbin.c:2162:add_to_queue:<my-pipeline1> adding 'source' to queue

2、sink的设置

0:00:50.869905000 15216 00000189D4A09000 INFO GST_STATES gstbin.c:2503:gst_bin_element_set_state:<sink> current NULL pending VOID_PENDING, desired next READY

0:00:50.870236000 15216 00000189D4A09000 DEBUG bin gstbin.c:882:find_message:<my-pipeline1> no message found matching types 00100000

0:00:50.870584000 15216 00000189D4A09000 DEBUG bin gstbin.c:889:find_message:<my-pipeline1> async-start

0:00:50.870848000 15216 00000189D4A09000 DEBUG bin gstbin.c:2598:gst_bin_element_set_state:<my-pipeline1> setting element sink to READY, base_time 0:00:00.000000000

0:00:50.871208000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2827:gst_element_set_state_func:<sink> set_state to READY 开始设置sink

0:00:50.871514000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2852:gst_element_set_state_func:<sink> setting target state to READY

0:00:50.871813000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2865:gst_element_set_state_func:<sink> current NULL, old_pending VOID_PENDING, next VOID_PENDING, old return SUCCESS

0:00:50.872209000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2899:gst_element_set_state_func:<sink> final: setting state from NULL to READY

0:00:50.872581000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2988:gst_element_change_state:<sink> element changed state SUCCESS

0:00:50.872837000 15216 00000189D4A09000 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<sink> completed state change to READY

0:00:50.873098000 15216 00000189D4A09000 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<sink> notifying about state-changed NULL to READY (VOID_PENDING pending)

0:00:50.873485000 15216 00000189D4A09000 DEBUG GST_BUS gstbus.c:316:gst_bus_post:<bus0> [msg 00000189D7F19730] posting on bus state-changed message: 00000189D7F19730, time 99:99:99.999999999, seq-num 4, element 'sink', GstMessageStateChanged, old-state=(GstState)GST_STATE_NULL, new-state=(GstState)GST_STATE_READY, pending-state=(GstState)GST_STATE_VOID_PENDING;

0:00:50.874125000 15216 00000189D4A09000 DEBUG bin gstbin.c:3716:gst_bin_handle_message_func:<my-pipeline1> [msg 00000189D7F19730] handling child sink message of type state-changed

0:00:50.874518000 15216 00000189D4A09000 DEBUG bin gstbin.c:4053:gst_bin_handle_message_func:<my-pipeline1> posting message upward

0:00:50.874800000 15216 00000189D4A09000 DEBUG GST_BUS gstbus.c:316:gst_bus_post:<bus1> [msg 00000189D7F19730] posting on bus state-changed message: 00000189D7F19730, time 99:99:99.999999999, seq-num 4, element 'sink', GstMessageStateChanged, old-state=(GstState)GST_STATE_NULL, new-state=(GstState)GST_STATE_READY, pending-state=(GstState)GST_STATE_VOID_PENDING;

0:00:50.875517000 15216 00000189D4A09000 DEBUG GST_BUS gstbus.c:355:gst_bus_post:<bus1> [msg 00000189D7F19730] pushing on async queue

0:00:50.875801000 15216 00000189D4A09000 DEBUG GST_BUS gstbus.c:358:gst_bus_post:<bus1> [msg 00000189D7F19730] pushed on async queue

0:00:50.876050000 15216 00000189D4A09000 DEBUG GST_BUS gstbus.c:351:gst_bus_post:<bus0> [msg 00000189D7F19730] dropped

0:00:50.876273000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2911:gst_element_set_state_func:<sink> returned SUCCESS 结束设置sink

0:00:50.876573000 15216 00000189D4A09000 INFO GST_STATES gstbin.c:2951:gst_bin_change_state_func:<my-pipeline1> child 'sink' changed state to 2(READY) successfully

3、source的设置

0:00:50.876932000 15216 00000189D4A09000 DEBUG bin gstbin.c:2369:gst_bin_sort_iterator_next:<my-pipeline1> queue head gives source

0:00:50.877182000 15216 00000189D4A09000 DEBUG bin gstbin.c:2302:update_degree:<my-pipeline1> element source not linked on any sinkpads

0:00:50.877446000 15216 00000189D4A09000 INFO GST_STATES gstbin.c:2503:gst_bin_element_set_state:<source> current NULL pending VOID_PENDING, desired next READY

0:00:50.877739000 15216 00000189D4A09000 DEBUG bin gstbin.c:882:find_message:<my-pipeline1> no message found matching types 00100000

0:00:50.878001000 15216 00000189D4A09000 DEBUG bin gstbin.c:889:find_message:<my-pipeline1> async-start

0:00:50.878225000 15216 00000189D4A09000 DEBUG bin gstbin.c:2598:gst_bin_element_set_state:<my-pipeline1> setting element source to READY, base_time 0:00:00.000000000

0:00:50.878564000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2827:gst_element_set_state_func:<source> set_state to READY 开始设置source

0:00:50.878804000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2852:gst_element_set_state_func:<source> setting target state to READY

0:00:50.879063000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2865:gst_element_set_state_func:<source> current NULL, old_pending VOID_PENDING, next VOID_PENDING, old return SUCCESS

0:00:50.879452000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2899:gst_element_set_state_func:<source> final: setting state from NULL to READY

0:00:50.880599000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2988:gst_element_change_state:<source> element changed state SUCCESS

0:00:50.880855000 15216 00000189D4A09000 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<source> completed state change to READY

0:00:50.881116000 15216 00000189D4A09000 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<source> notifying about state-changed NULL to READY (VOID_PENDING pending)

0:00:50.881524000 15216 00000189D4A09000 DEBUG GST_BUS gstbus.c:316:gst_bus_post:<bus0> [msg 00000189D7F197B0] posting on bus state-changed message: 00000189D7F197B0, time 99:99:99.999999999, seq-num 5, element 'source', GstMessageStateChanged, old-state=(GstState)GST_STATE_NULL, new-state=(GstState)GST_STATE_READY, pending-state=(GstState)GST_STATE_VOID_PENDING;

0:00:50.882148000 15216 00000189D4A09000 DEBUG bin gstbin.c:3716:gst_bin_handle_message_func:<my-pipeline1> [msg 00000189D7F197B0] handling child source message of type state-changed

0:00:50.882522000 15216 00000189D4A09000 DEBUG bin gstbin.c:4053:gst_bin_handle_message_func:<my-pipeline1> posting message upward

0:00:50.883049000 15216 00000189D4A09000 DEBUG GST_BUS gstbus.c:316:gst_bus_post:<bus1> [msg 00000189D7F197B0] posting on bus state-changed message: 00000189D7F197B0, time 99:99:99.999999999, seq-num 5, element 'source', GstMessageStateChanged, old-state=(GstState)GST_STATE_NULL, new-state=(GstState)GST_STATE_READY, pending-state=(GstState)GST_STATE_VOID_PENDING;

0:00:50.883726000 15216 00000189D4A09000 DEBUG GST_BUS gstbus.c:355:gst_bus_post:<bus1> [msg 00000189D7F197B0] pushing on async queue

0:00:50.883977000 15216 00000189D4A09000 DEBUG GST_BUS gstbus.c:358:gst_bus_post:<bus1> [msg 00000189D7F197B0] pushed on async queue

0:00:50.884227000 15216 00000189D4A09000 DEBUG GST_BUS gstbus.c:351:gst_bus_post:<bus0> [msg 00000189D7F197B0] dropped

0:00:50.884494000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2911:gst_element_set_state_func:<source> returned SUCCESS 结束设置source

0:00:50.884757000 15216 00000189D4A09000 INFO GST_STATES gstbin.c:2951:gst_bin_change_state_func:<my-pipeline1> child 'source' changed state to 2(READY) successfully

0:00:50.885062000 15216 00000189D4A09000 DEBUG bin gstbin.c:2358:gst_bin_sort_iterator_next:<my-pipeline1> queue empty, elements exhausted

0:00:50.885329000 15216 00000189D4A09000 DEBUG GST_STATES gstbin.c:3010:gst_bin_change_state_func:<my-pipeline1> iterator done

0:00:50.885563000 15216 00000189D4A09000 DEBUG bin gstbin.c:2400:gst_bin_sort_iterator_free:<my-pipeline1> free

0:00:50.885787000 15216 00000189D4A09000 DEBUG bin gstbin.c:3045:gst_bin_change_state_func:<my-pipeline1> no async elements

0:00:50.886032000 15216 00000189D4A09000 DEBUG GST_STATES gstbin.c:3079:gst_bin_change_state_func:<my-pipeline1> done changing bin's state from NULL to READY, now in NULL, ret SUCCESS

0:00:50.886391000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2988:gst_element_change_state:<my-pipeline1> element changed state SUCCESS

0:00:50.886652000 15216 00000189D4A09000 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<my-pipeline1> completed state change to READY

0:00:50.886921000 15216 00000189D4A09000 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<my-pipeline1> notifying about state-changed NULL to READY (VOID_PENDING pending)

0:00:50.887275000 15216 00000189D4A09000 DEBUG GST_BUS gstbus.c:316:gst_bus_post:<bus1> [msg 00000189D7F19830] posting on bus state-changed message: 00000189D7F19830, time 99:99:99.999999999, seq-num 6, element 'my-pipeline1', GstMessageStateChanged, old-state=(GstState)GST_STATE_NULL, new-state=(GstState)GST_STATE_READY, pending-state=(GstState)GST_STATE_VOID_PENDING;

0:00:50.887905000 15216 00000189D4A09000 DEBUG GST_BUS gstbus.c:355:gst_bus_post:<bus1> [msg 00000189D7F19830] pushing on async queue

0:00:50.888151000 15216 00000189D4A09000 DEBUG GST_BUS gstbus.c:358:gst_bus_post:<bus1> [msg 00000189D7F19830] pushed on async queue

0:00:50.888468000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2911:gst_element_set_state_func:<my-pipeline1> returned SUCCESS 结束设置pipeline

3、、READY--> PAUSE

0:12:58.583930000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2827:gst_element_set_state_func:<my-pipeline1> set_state to PAUSED

0:12:58.584232000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2852:gst_element_set_state_func:<my-pipeline1> setting target state to PAUSED

0:12:58.584610000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2865:gst_element_set_state_func:<my-pipeline1> current READY, old_pending VOID_PENDING, next VOID_PENDING, old return SUCCESS

0:12:58.585012000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2899:gst_element_set_state_func:<my-pipeline1> final: setting state from READY to PAUSED

0:12:58.585348000 15216 00000189D4A09000 DEBUG pipeline gstpipeline.c:302:reset_start_time:<my-pipeline1> reset start_time to 0

0:12:58.585660000 15216 00000189D4A09000 DEBUG GST_STATES gstbin.c:2851:gst_bin_change_state_func:<my-pipeline1> changing state of children from READY to PAUSED

0:12:58.585992000 15216 00000189D4A09000 DEBUG bin gstbin.c:2875:gst_bin_change_state_func:<my-pipeline1> clearing EOS elements

0:12:58.586276000 15216 00000189D4A09000 DEBUG bin gstbin.c:2696:gst_bin_src_pads_activate:<my-pipeline1> activate pads

0:12:58.586597000 15216 00000189D4A09000 DEBUG bin gstbin.c:2704:gst_bin_src_pads_activate:<my-pipeline1> pad activation successful

0:12:58.586872000 15216 00000189D4A09000 DEBUG bin gstbin.c:2382:gst_bin_sort_iterator_resync:<my-pipeline1> resync

0:12:58.587123000 15216 00000189D4A09000 DEBUG bin gstbin.c:2162:add_to_queue:<my-pipeline1> adding 'sink' to queue

0:12:58.587369000 15216 00000189D4A09000 DEBUG bin gstbin.c:882:find_message:<my-pipeline1> no message found matching types 00001000

0:12:58.587673000 15216 00000189D4A09000 DEBUG bin gstbin.c:889:find_message:<my-pipeline1> structure-change

0:12:58.587915000 15216 00000189D4A09000 DEBUG bin gstbin.c:2279:update_degree:<my-pipeline1> change element source, degree 0->1, linked to sink

0:12:58.588197000 15216 00000189D4A09000 DEBUG bin gstbin.c:2302:update_degree:<my-pipeline1> element source not linked on any sinkpads

0:12:58.588473000 15216 00000189D4A09000 DEBUG bin gstbin.c:2369:gst_bin_sort_iterator_next:<my-pipeline1> queue head gives sink

0:12:58.588731000 15216 00000189D4A09000 DEBUG bin gstbin.c:882:find_message:<my-pipeline1> no message found matching types 00001000

0:12:58.588990000 15216 00000189D4A09000 DEBUG bin gstbin.c:889:find_message:<my-pipeline1> structure-change

0:12:58.589223000 15216 00000189D4A09000 DEBUG bin gstbin.c:2279:update_degree:<my-pipeline1> change element source, degree 1->0, linked to sink

0:12:58.589520000 15216 00000189D4A09000 DEBUG bin gstbin.c:2162:add_to_queue:<my-pipeline1> adding 'source' to queue

0:12:58.589801000 15216 00000189D4A09000 INFO GST_STATES gstbin.c:2503:gst_bin_element_set_state:<sink> current READY pending VOID_PENDING, desired next PAUSED

0:12:58.590122000 15216 00000189D4A09000 DEBUG bin gstbin.c:882:find_message:<my-pipeline1> no message found matching types 00100000

0:12:58.590388000 15216 00000189D4A09000 DEBUG bin gstbin.c:889:find_message:<my-pipeline1> async-start

0:12:58.591090000 15216 00000189D4A09000 DEBUG bin gstbin.c:2598:gst_bin_element_set_state:<my-pipeline1> setting element sink to PAUSED, base_time 0:00:00.000000000

//开始设置sink状态为PAUSE

0:12:58.591428000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2827:gst_element_set_state_func:<sink> set_state to PAUSED

0:12:58.591697000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2852:gst_element_set_state_func:<sink> setting target state to PAUSED

0:12:58.591959000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2865:gst_element_set_state_func:<sink> current READY, old_pending VOID_PENDING, next VOID_PENDING, old return SUCCESS

0:12:58.592470000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2899:gst_element_set_state_func:<sink> final: setting state from READY to PAUSED

0:12:58.592761000 15216 00000189D4A09000 DEBUG basesink gstbasesink.c:5168:gst_base_sink_change_state:<sink> READY to PAUSED

0:12:58.593010000 15216 00000189D4A09000 DEBUG basesink gstbasesink.c:5189:gst_base_sink_change_state:<sink> doing async state change

0:12:58.593281000 15216 00000189D4A09000 DEBUG GST_BUS gstbus.c:316:gst_bus_post:<bus0> [msg 00000189D7F198B0] posting on bus async-start message: 00000189D7F198B0, time 99:99:99.999999999, seq-num 7, element 'sink', (NULL)

0:12:58.593700000 15216 00000189D4A09000 DEBUG bin gstbin.c:3716:gst_bin_handle_message_func:<my-pipeline1> [msg 00000189D7F198B0] handling child sink message of type async-start

0:12:58.594038000 15216 00000189D4A09000 DEBUG bin gstbin.c:3906:gst_bin_handle_message_func:<my-pipeline1> ASYNC_START message 00000189D7F198B0, sink

0:12:58.594323000 15216 00000189D4A09000 DEBUG bin gstbin.c:882:find_message:<my-pipeline1> no message found matching types 00100000

0:12:58.594584000 15216 00000189D4A09000 DEBUG bin gstbin.c:889:find_message:<my-pipeline1> async-start

0:12:58.594799000 15216 00000189D4A09000 DEBUG bin gstbin.c:929:bin_replace_message:<my-pipeline1> got new message 00000189D7F198B0, async-start from sink

0:12:58.595092000 15216 00000189D4A09000 DEBUG GST_STATES gstbin.c:3364:bin_handle_async_start:<my-pipeline1> state change busy

0:12:58.595330000 15216 00000189D4A09000 DEBUG GST_BUS gstbus.c:351:gst_bus_post:<bus0> [msg 00000189D7F198B0] dropped

0:12:58.595566000 15216 00000189D4A09000 DEBUG GST_ELEMENT_PADS gstelement.c:3097:gst_element_pads_activate:<sink> activate pads //sink的sinkpad激活模式

0:12:58.595803000 15216 00000189D4A09000 DEBUG GST_PADS gstpad.c:1099:gst_pad_set_active:<sink:sink> activating pad from none

0:12:58.596046000 15216 00000189D4A09000 DEBUG basesink gstbasesink.c:4310:gst_base_sink_pad_activate:<sink> Trying pull mode first

0:12:58.596294000 15216 00000189D4A09000 DEBUG basesink gstbasesink.c:4316:gst_base_sink_pad_activate:<sink> pull mode disabled

0:12:58.596547000 15216 00000189D4A09000 DEBUG basesink gstbasesink.c:4366:gst_base_sink_pad_activate:<sink> Falling back to push mode

0:12:58.596903000 15216 00000189D4A09000 DEBUG GST_PADS gstpad.c:1005:pre_activate:<sink:sink> setting pad into push mode, unset flushing

0:12:58.597167000 15216 00000189D4A09000 DEBUG GST_PADS gstpad.c:1017:pre_activate:<sink:sink> reschedule events on peer source:src

0:12:58.597424000 15216 00000189D4A09000 DEBUG GST_PADS gstpad.c:1228:activate_mode_internal:<sink:sink> activated in push mode

0:12:58.597671000 15216 00000189D4A09000 DEBUG basesink gstbasesink.c:4368:gst_base_sink_pad_activate:<sink> Success activating push mode

0:12:58.597962000 15216 00000189D4A09000 DEBUG GST_ELEMENT_PADS gstelement.c:3116:gst_element_pads_activate:<sink> pad activation successful //激活完成

0:12:58.598943000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2970:gst_element_change_state:<sink> element will change state ASYNC

0:12:58.599197000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2911:gst_element_set_state_func:<sink> returned ASYNC

0:12:58.599455000 15216 00000189D4A09000 INFO GST_STATES gstbin.c:2957:gst_bin_change_state_func:<my-pipeline1> child 'sink' is changing state asynchronously to PAUSED

0:12:58.599782000 15216 00000189D4A09000 DEBUG bin gstbin.c:2369:gst_bin_sort_iterator_next:<my-pipeline1> queue head gives source

0:12:58.600059000 15216 00000189D4A09000 DEBUG bin gstbin.c:2302:update_degree:<my-pipeline1> element source not linked on any sinkpads

0:12:58.600319000 15216 00000189D4A09000 INFO GST_STATES gstbin.c:2503:gst_bin_element_set_state:<source> current READY pending VOID_PENDING, desired next PAUSED

0:12:58.600659000 15216 00000189D4A09000 DEBUG bin gstbin.c:882:find_message:<my-pipeline1> no message found matching types 00100000

0:12:58.600916000 15216 00000189D4A09000 DEBUG bin gstbin.c:889:find_message:<my-pipeline1> async-start

0:12:58.601134000 15216 00000189D4A09000 DEBUG bin gstbin.c:2598:gst_bin_element_set_state:<my-pipeline1> setting element source to PAUSED, base_time 0:00:00.000000000

//开始设置source状态为PAUSE

0:12:58.601744000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2827:gst_element_set_state_func:<source> set_state to PAUSED

0:12:58.601985000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2852:gst_element_set_state_func:<source> setting target state to PAUSED

0:12:58.602247000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2865:gst_element_set_state_func:<source> current READY, old_pending VOID_PENDING, next VOID_PENDING, old return SUCCESS

0:12:58.602644000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2899:gst_element_set_state_func:<source> final: setting state from READY to PAUSED

0:12:58.602947000 15216 00000189D4A09000 DEBUG GST_ELEMENT_PADS gstelement.c:3097:gst_element_pads_activate:<source> activate pads //source的srcpad激活模式

0:12:58.603282000 15216 00000189D4A09000 DEBUG GST_PADS gstpad.c:1099:gst_pad_set_active:<source:src> activating pad from none

0:12:58.603553000 15216 00000189D4A09000 DEBUG GST_PADS gstpad.c:1005:pre_activate:<source:src> setting pad into push mode, unset flushing

0:12:58.603855000 15216 00000189D4A09000 DEBUG basesrc gstbasesrc.c:3875:gst_base_src_activate_mode:<source:src> activating in mode 1

0:12:58.616737000 15216 00000189D4A09000 DEBUG basesrc gstbasesrc.c:3801:gst_base_src_activate_push:<source> Activating in push mode

0:12:58.617065000 15216 00000189D4A09000 DEBUG basesrc gstbasesrc.c:3498:gst_base_src_start_complete:<source> starting source

0:12:58.617310000 15216 00000189D4A09000 DEBUG basesrc gstbasesrc.c:3522:gst_base_src_start_complete:<source> format: time, have size: 0, size: 18446744073709551615, duration: -1

0:12:58.617756000 15216 00000189D4A09000 DEBUG basesrc gstbasesrc.c:3525:gst_base_src_start_complete:<source> is seekable: 1

0:12:58.617989000 15216 00000189D4A09000 DEBUG basesrc gstbasesrc.c:3530:gst_base_src_start_complete:<source> is random_access: 0

0:12:58.618234000 15216 00000189D4A09000 DEBUG basesrc gstbasesrc.c:1630:gst_base_src_perform_seek:<source> doing seek: (NULL)

0:12:58.618479000 15216 00000189D4A09000 DEBUG GST_PADS gstpad.c:6205:gst_pad_pause_task:<source:src> pause task

0:12:58.618693000 15216 00000189D4A09000 DEBUG GST_PADS gstpad.c:6226:gst_pad_pause_task:<source:src> pad has no task

0:12:58.618910000 15216 00000189D4A09000 DEBUG basesrc gstbasesrc.c:1686:gst_base_src_perform_seek:<source> seek with seqnum 9

0:12:58.619148000 15216 00000189D4A09000 DEBUG basesrc gstbasesrc.c:1723:gst_base_src_perform_seek:<source> segment configured from 0 to -1, position 0

0:12:58.619445000 15216 00000189D4A09000 INFO basesrc gstbasesrc.c:1373:gst_base_src_do_seek:<source> seeking: time segment start=0:00:00.000000000, offset=0:00:00.000000000, stop=99:99:99.999999999, rate=1.000000, applied_rate=1.000000, flags=0x00, time=0:00:00.000000000, base=0:00:00.000000000, position 0:00:00.000000000, duration 99:99:99.999999999

0:12:58.620081000 15216 00000189D4A09000 DEBUG GST_PADS gstpad.c:6149:gst_pad_start_task:<source:src> start task

0:12:58.620348000 15216 00000189D4A09000 DEBUG task gsttask.c:424:gst_task_new: Created task 00000189D8080050

0:12:58.620574000 15216 00000189D4A09000 INFO task gsttask.c:453:gst_task_set_lock: setting stream lock 00000189D7DD1150 on task 00000189D8080050

0:12:58.620868000 15216 00000189D4A09000 INFO GST_PADS gstpad.c:6158:gst_pad_start_task:<source:src> created task 00000189D8080050

0:12:58.621114000 15216 00000189D4A09000 DEBUG GST_PADS gstpad.c:6075:do_stream_status:<source:src> doing stream-status 0

0:12:58.621373000 15216 00000189D4A09000 DEBUG GST_PADS gstpad.c:6104:do_stream_status:<source:src> posting stream-status 0

0:12:58.621649000 15216 00000189D4A09000 DEBUG GST_BUS gstbus.c:316:gst_bus_post:<bus0> [msg 00000189D7F19930] posting on bus stream-status message: 00000189D7F19930, time 99:99:99.999999999, seq-num 10, element 'src', GstMessageStreamStatus, type=(GstStreamStatusType)GST_STREAM_STATUS_TYPE_CREATE, owner=(GstElement)"\(GstVideoTestSrc\)\ source", object=(GstTask)"\(GstTask\)\ task0";

0:12:58.622340000 15216 00000189D4A09000 DEBUG bin gstbin.c:3716:gst_bin_handle_message_func:<my-pipeline1> [msg 00000189D7F19930] handling child src message of type stream-status

0:12:58.622685000 15216 00000189D4A09000 DEBUG bin gstbin.c:4053:gst_bin_handle_message_func:<my-pipeline1> posting message upward

0:12:58.622950000 15216 00000189D4A09000 DEBUG GST_BUS gstbus.c:316:gst_bus_post:<bus1> [msg 00000189D7F19930] posting on bus stream-status message: 00000189D7F19930, time 99:99:99.999999999, seq-num 10, element 'src', GstMessageStreamStatus, type=(GstStreamStatusType)GST_STREAM_STATUS_TYPE_CREATE, owner=(GstElement)"\(GstVideoTestSrc\)\ source", object=(GstTask)"\(GstTask\)\ task0";

0:12:58.623613000 15216 00000189D4A09000 DEBUG GST_BUS gstbus.c:355:gst_bus_post:<bus1> [msg 00000189D7F19930] pushing on async queue

0:12:58.623864000 15216 00000189D4A09000 DEBUG GST_BUS gstbus.c:358:gst_bus_post:<bus1> [msg 00000189D7F19930] pushed on async queue

0:12:58.624114000 15216 00000189D4A09000 DEBUG GST_BUS gstbus.c:351:gst_bus_post:<bus0> [msg 00000189D7F19930] dropped

0:12:58.624368000 15216 00000189D4A09000 DEBUG task gsttask.c:684:gst_task_set_state:<task0> Changing task 00000189D8080050 to state 0

0:12:58.624715000 15216 00000189D4A09000 DEBUG basesrc gstbasesrc.c:3635:gst_base_src_start_wait:<source> got ok

0:12:58.624937000 15216 00000189D4A09000 DEBUG GST_PADS gstpad.c:1228:activate_mode_internal:<source:src> activated in push mode//激活完成

0:12:58.625181000 15216 00000189D4A09000 DEBUG GST_ELEMENT_PADS gstelement.c:3116:gst_element_pads_activate:<source> pad activation successful

0:12:58.625431000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2988:gst_element_change_state:<source> element changed state SUCCESS

0:12:58.625682000 15216 00000189D4A09000 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<source> completed state change to PAUSED

0:12:58.625943000 15216 00000189D4A09000 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<source> notifying about state-changed READY to PAUSED (VOID_PENDING pending)

0:12:58.626290000 15216 00000189D4A09000 DEBUG GST_BUS gstbus.c:316:gst_bus_post:<bus0> [msg 00000189D7F199B0] posting on bus state-changed message: 00000189D7F199B0, time 99:99:99.999999999, seq-num 11, element 'source', GstMessageStateChanged, old-state=(GstState)GST_STATE_READY, new-state=(GstState)GST_STATE_PAUSED, pending-state=(GstState)GST_STATE_VOID_PENDING;

0:12:58.628150000 15216 00000189D4A09000 DEBUG bin gstbin.c:3716:gst_bin_handle_message_func:<my-pipeline1> [msg 00000189D7F199B0] handling child source message of type state-changed

0:12:58.628565000 15216 00000189D4A09000 DEBUG bin gstbin.c:4053:gst_bin_handle_message_func:<my-pipeline1> posting message upward

0:12:58.628838000 15216 00000189D4A09000 DEBUG GST_BUS gstbus.c:316:gst_bus_post:<bus1> [msg 00000189D7F199B0] posting on bus state-changed message: 00000189D7F199B0, time 99:99:99.999999999, seq-num 11, element 'source', GstMessageStateChanged, old-state=(GstState)GST_STATE_READY, new-state=(GstState)GST_STATE_PAUSED, pending-state=(GstState)GST_STATE_VOID_PENDING;

0:12:58.629479000 15216 00000189D4A09000 DEBUG GST_BUS gstbus.c:355:gst_bus_post:<bus1> [msg 00000189D7F199B0] pushing on async queue

0:12:58.629729000 15216 00000189D4A09000 DEBUG GST_BUS gstbus.c:358:gst_bus_post:<bus1> [msg 00000189D7F199B0] pushed on async queue

0:12:58.629978000 15216 00000189D4A09000 DEBUG GST_BUS gstbus.c:351:gst_bus_post:<bus0> [msg 00000189D7F199B0] dropped

0:12:58.630205000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2911:gst_element_set_state_func:<source> returned SUCCESS

//启动任务

0:12:58.625020000 15216 00000189D7EE2F80 DEBUG task gsttask.c:283:gst_task_func: Entering task 00000189D8080050, thread 00000189D7EE2F80

0:12:58.630879000 15216 00000189D7EE2F80 DEBUG GST_PADS gstpad.c:6075:do_stream_status:<source:src> doing stream-status 1

0:12:58.631128000 15216 00000189D7EE2F80 DEBUG GST_PADS gstpad.c:6104:do_stream_status:<source:src> posting stream-status 1

0:12:58.630484000 15216 00000189D4A09000 INFO GST_STATES gstbin.c:2951:gst_bin_change_state_func:<my-pipeline1> child 'source' changed state to 3(PAUSED) successfully

0:12:58.632192000 15216 00000189D4A09000 DEBUG bin gstbin.c:2358:gst_bin_sort_iterator_next:<my-pipeline1> queue empty, elements exhausted

0:12:58.632505000 15216 00000189D4A09000 DEBUG GST_STATES gstbin.c:3010:gst_bin_change_state_func:<my-pipeline1> iterator done

0:12:58.632743000 15216 00000189D4A09000 DEBUG GST_ELEMENT_PADS gstelement.c:3097:gst_element_pads_activate:<my-pipeline1> activate pads

0:12:58.632989000 15216 00000189D4A09000 DEBUG GST_ELEMENT_PADS gstelement.c:3116:gst_element_pads_activate:<my-pipeline1> pad activation successful

0:12:58.633248000 15216 00000189D4A09000 DEBUG GST_STATES gstbin.c:3028:gst_bin_change_state_func:<my-pipeline1> we have ASYNC elements SUCCESS -> ASYNC

0:12:58.633558000 15216 00000189D4A09000 DEBUG bin gstbin.c:2400:gst_bin_sort_iterator_free:<my-pipeline1> free

0:12:58.633780000 15216 00000189D4A09000 DEBUG bin gstbin.c:3056:gst_bin_change_state_func:<my-pipeline1> check async elements

0:12:58.634028000 15216 00000189D4A09000 DEBUG bin gstbin.c:880:find_message:<my-pipeline1> we found a message 00000189D7F198B0 from sink matching types 00100000

0:12:58.631448000 15216 00000189D7EE2F80 DEBUG GST_BUS gstbus.c:316:gst_bus_post:<bus0> [msg 00000189D7F19A30] posting on bus stream-status message: 00000189D7F19A30, time 99:99:99.999999999, seq-num 12, element 'src', GstMessageStreamStatus, type=(GstStreamStatusType)GST_STREAM_STATUS_TYPE_ENTER, owner=(GstElement)"\(GstVideoTestSrc\)\ source", object=(GstTask)"\(GstTask\)\ source:src";

0:12:58.634386000 15216 00000189D4A09000 DEBUG GST_STATES gstbin.c:3079:gst_bin_change_state_func:<my-pipeline1> done changing bin's state from READY to PAUSED, now in READY, ret ASYNC

0:12:58.635682000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2970:gst_element_change_state:<my-pipeline1> element will change state ASYNC

0:12:58.635967000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2911:gst_element_set_state_func:<my-pipeline1> returned ASYNC

0:12:58.635313000 15216 00000189D7EE2F80 DEBUG bin gstbin.c:3716:gst_bin_handle_message_func:<my-pipeline1> [msg 00000189D7F19A30] handling child src message of type stream-status

0:12:58.636714000 15216 00000189D7EE2F80 DEBUG bin gstbin.c:4053:gst_bin_handle_message_func:<my-pipeline1> posting message upward

0:12:58.637018000 15216 00000189D7EE2F80 DEBUG GST_BUS gstbus.c:316:gst_bus_post:<bus1> [msg 00000189D7F19A30] posting on bus stream-status message: 00000189D7F19A30, time 99:99:99.999999999, seq-num 12, element 'src', GstMessageStreamStatus, type=(GstStreamStatusType)GST_STREAM_STATUS_TYPE_ENTER, owner=(GstElement)"\(GstVideoTestSrc\)\ source", object=(GstTask)"\(GstTask\)\ source:src";

0:12:58.637756000 15216 00000189D7EE2F80 DEBUG GST_BUS gstbus.c:355:gst_bus_post:<bus1> [msg 00000189D7F19A30] pushing on async queue

0:12:58.638010000 15216 00000189D7EE2F80 DEBUG GST_BUS gstbus.c:358:gst_bus_post:<bus1> [msg 00000189D7F19A30] pushed on async queue

0:12:58.638278000 15216 00000189D7EE2F80 DEBUG GST_BUS gstbus.c:351:gst_bus_post:<bus0> [msg 00000189D7F19A30] dropped

0:12:58.638517000 15216 00000189D7EE2F80 DEBUG task gsttask.c:267:gst_task_configure_name:<source:src> Setting thread name to 'source:src'

0:12:58.638834000 15216 00000189D7EE2F80 INFO GST_ELEMENT_PADS gstelement.c:913:gst_element_get_static_pad: no such pad 'sink' in element "source"

0:12:58.639098000 15216 00000189D7EE2F80 DEBUG query gstquery.c:679:gst_query_new_custom: creating new query 00000189D7F11CA0 uri

0:12:58.639393000 15216 00000189D7EE2F80 DEBUG GST_ELEMENT_PADS gstelement.c:1958:gst_element_query: send query on element source

0:12:58.639620000 15216 00000189D7EE2F80 DEBUG GST_ELEMENT_PADS gstelement.c:1742:gst_element_get_random_pad: getting a random pad

0:12:58.639848000 15216 00000189D7EE2F80 DEBUG GST_ELEMENT_PADS gstelement.c:1761:gst_element_get_random_pad: checking pad source:src

0:12:58.641032000 15216 00000189D7EE2F80 DEBUG GST_ELEMENT_PADS gstelement.c:1773:gst_element_get_random_pad: found pad source:src

0:12:58.641332000 15216 00000189D7EE2F80 DEBUG GST_PADS gstpad.c:4053:gst_pad_query:<source:src> doing query 00000189D7F11CA0 (uri)

0:12:58.641671000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:1325:gst_base_src_default_query:<source> query uri returns 0

0:12:58.641934000 15216 00000189D7EE2F80 DEBUG GST_PADS gstpad.c:4076:gst_pad_query:<source:src> sent query 00000189D7F11CA0 (uri), result 0

0:12:58.642274000 15216 00000189D7EE2F80 DEBUG GST_PADS gstpad.c:4121:gst_pad_query:<source:src> query failed

0:12:58.642588000 15216 00000189D7EE2F80 FIXME default gstutils.c:3981:gst_pad_create_stream_id_internal:<source:src> Creating random stream-id, consider implementing a deterministic way of creating a stream-id

0:12:58.643075000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:912:gst_base_src_send_stream_start:<source> Pushing STREAM_START

0:12:58.643438000 15216 00000189D7EE2F80 DEBUG GST_EVENT gstevent.c:309:gst_event_new_custom: creating new event 00000189D7F13D90 stream-start 10254

0:12:58.643733000 15216 00000189D7EE2F80 DEBUG GST_PADS gstpad.c:3984:check_sticky:<source:src> pushing all sticky events

0:12:58.643996000 15216 00000189D7EE2F80 DEBUG GST_EVENT gstpad.c:5697:gst_pad_send_event_unchecked:<sink:sink> have event type stream-start event: 00000189D7F13D90, time 99:99:99.999999999, seq-num 13, GstEventStreamStart, stream-id=(string)71ae5a3d1ae00d3179ce5264a2332959, flags=(GstStreamFlags)GST_STREAM_FLAG_NONE, group-id=(uint)1;

0:12:58.644624000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3355:gst_base_sink_event:<sink> received event 00000189D7F13D90 stream-start event: 00000189D7F13D90, time 99:99:99.999999999, seq-num 13, GstEventStreamStart, stream-id=(string)71ae5a3d1ae00d3179ce5264a2332959, flags=(GstStreamFlags)GST_STREAM_FLAG_NONE, group-id=(uint)1;

0:12:58.645233000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3241:gst_base_sink_default_event:<sink> Now posting STREAM_START (seqnum:13)

0:12:58.645526000 15216 00000189D7EE2F80 DEBUG GST_BUS gstbus.c:316:gst_bus_post:<bus0> [msg 00000189D7F19AB0] posting on bus stream-start message: 00000189D7F19AB0, time 99:99:99.999999999, seq-num 13, element 'sink', GstMessageStreamStart, group-id=(uint)1;

0:12:58.645984000 15216 00000189D7EE2F80 DEBUG bin gstbin.c:3716:gst_bin_handle_message_func:<my-pipeline1> [msg 00000189D7F19AB0] handling child sink message of type stream-start

0:12:58.646868000 15216 00000189D7EE2F80 DEBUG bin gstbin.c:882:find_message:<my-pipeline1> no message found matching types 10000000

0:12:58.647135000 15216 00000189D7EE2F80 DEBUG bin gstbin.c:889:find_message:<my-pipeline1> stream-start

0:12:58.647379000 15216 00000189D7EE2F80 DEBUG bin gstbin.c:929:bin_replace_message:<my-pipeline1> got new message 00000189D7F19AB0, stream-start from sink

0:12:58.647801000 15216 00000189D7EE2F80 DEBUG GST_STATES gstbin.c:1968:bin_element_is_sink:<my-pipeline1> child sink is sink

0:12:58.648034000 15216 00000189D7EE2F80 DEBUG bin gstbin.c:880:find_message:<my-pipeline1> we found a message 00000189D7F19AB0 from sink matching types 10000000

0:12:58.648338000 15216 00000189D7EE2F80 DEBUG bin gstbin.c:1036:is_stream_start: sink 'sink' posted STREAM_START

0:12:58.648565000 15216 00000189D7EE2F80 DEBUG GST_STATES gstbin.c:1968:bin_element_is_sink:<my-pipeline1> child source is not sink

0:12:58.648812000 15216 00000189D7EE2F80 DEBUG bin gstbin.c:958:bin_remove_messages:<sink> deleting message 00000189D7F19AB0 of type stream-start (types 0x10000000)

0:12:58.649126000 15216 00000189D7EE2F80 DEBUG bin gstbin.c:964:bin_remove_messages:<sink> not deleting message 00000189D7F198B0 of type 0x00100000

0:12:58.649412000 15216 00000189D7EE2F80 DEBUG bin gstbin.c:3585:bin_do_stream_start:<my-pipeline1> all sinks posted STREAM_START, posting seqnum #13

0:12:58.649710000 15216 00000189D7EE2F80 DEBUG GST_BUS gstbus.c:316:gst_bus_post:<bus1> [msg 00000189D7F19B30] posting on bus stream-start message: 00000189D7F19B30, time 99:99:99.999999999, seq-num 13, element 'my-pipeline1', GstMessageStreamStart, group-id=(uint)1;

0:12:58.650182000 15216 00000189D7EE2F80 DEBUG GST_BUS gstbus.c:355:gst_bus_post:<bus1> [msg 00000189D7F19B30] pushing on async queue

0:12:58.650468000 15216 00000189D7EE2F80 DEBUG GST_BUS gstbus.c:358:gst_bus_post:<bus1> [msg 00000189D7F19B30] pushed on async queue

0:12:58.650717000 15216 00000189D7EE2F80 DEBUG GST_BUS gstbus.c:351:gst_bus_post:<bus0> [msg 00000189D7F19AB0] dropped

0:12:58.650945000 15216 00000189D7EE2F80 DEBUG GST_PADS gstpad.c:5780:gst_pad_send_event_unchecked:<sink:sink> sent event, ret ok

0:12:58.651189000 15216 00000189D7EE2F80 DEBUG GST_PADS gstpad.c:3936:push_sticky:<source:src> event stream-start marked received

//CAPS协商

0:12:58.651472000 15216 00000189D7EE2F80 DEBUG GST_PADS gstpad.c:1673:gst_pad_check_reconfigure:<source:src> remove RECONFIGURE flag

0:12:58.651725000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:3384:gst_base_src_negotiate:<source> starting negotiation

0:12:58.651963000 15216 00000189D7EE2F80 DEBUG GST_CAPS gstutils.c:3058:gst_pad_query_caps:<source:src> get pad caps with filter (NULL) 获取srcpad的过滤器

0:12:58.652216000 15216 00000189D7EE2F80 DEBUG query gstquery.c:679:gst_query_new_custom: creating new query 00000189D7F11CF0 caps

0:12:58.652606000 15216 00000189D7EE2F80 DEBUG GST_PADS gstpad.c:4053:gst_pad_query:<source:src> doing query 00000189D7F11CF0 (caps)

0:12:58.652908000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:1325:gst_base_src_default_query:<source> query caps returns 1

0:12:58.653217000 15216 00000189D7EE2F80 DEBUG GST_PADS gstpad.c:4076:gst_pad_query:<source:src> sent query 00000189D7F11CF0 (caps), result 1

0:12:58.653554000 15216 00000189D7EE2F80 DEBUG GST_CAPS gstutils.c:3065:gst_pad_query_caps:<source:src> query returned video/x-raw, format=(string){ I420, YV12, YUY2, UYVY, AYUV, VUYA, RGBx, BGRx, xRGB, xBGR, RGBA, BGRA, ARGB, ABGR, RGB, BGR, Y41B, Y42B, YVYU, Y444, v210, v216, Y210, Y410, NV12, NV21, GRAY8, GRAY16_BE, GRAY16_LE, v308, RGB16, BGR16, RGB15, BGR15, UYVP, A420, RGB8P, YUV9, YVU9, IYU1, ARGB64, AYUV64, r210, I420_10BE, I420_10LE, I422_10BE, I422_10LE, Y444_10BE, Y444_10LE, GBR, GBR_10BE, GBR_10LE, NV16, NV24, NV12_64Z32, A420_10BE, A420_10LE, A422_10BE, A422_10LE, A444_10BE, A444_10LE, NV61, P010_10BE, P010_10LE, IYU2, VYUY, GBRA, GBRA_10BE, GBRA_10LE, BGR10A2_LE, GBR_12BE, GBR_12LE, GBRA_12BE, GBRA_12LE, I420_12BE, I420_12LE, I422_12BE, I422_12LE, Y444_12BE, Y444_12LE, GRAY10_LE32, NV12_10LE32, NV16_10LE32, NV12_10LE40 }, width=(int)[ 1, 2147483647 ], height=(int)[ 1, 2147483647 ], framerate=(fraction)[ 0/1, 2147483647/1 ], multiview-mode=(string){ mono, left, right }; video/x-bayer, format=(string){ bggr, rggb, grbg, gbrg }, width=(int)[ 1, 2147483647 ], height=(int)[ 1, 2147483647 ], framerate=(fraction)[ 0/1, 2147483647/1 ], multiview-mode=(string){ mono, left, right }

0:12:58.656585000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:3314:gst_base_src_default_negotiate:<source> caps of src: video/x-raw, format=(string){ I420, YV12, YUY2, UYVY, AYUV, VUYA, RGBx, BGRx, xRGB, xBGR, RGBA, BGRA, ARGB, ABGR, RGB, BGR, Y41B, Y42B, YVYU, Y444, v210, v216, Y210, Y410, NV12, NV21, GRAY8, GRAY16_BE, GRAY16_LE, v308, RGB16, BGR16, RGB15, BGR15, UYVP, A420, RGB8P, YUV9, YVU9, IYU1, ARGB64, AYUV64, r210, I420_10BE, I420_10LE, I422_10BE, I422_10LE, Y444_10BE, Y444_10LE, GBR, GBR_10BE, GBR_10LE, NV16, NV24, NV12_64Z32, A420_10BE, A420_10LE, A422_10BE, A422_10LE, A444_10BE, A444_10LE, NV61, P010_10BE, P010_10LE, IYU2, VYUY, GBRA, GBRA_10BE, GBRA_10LE, BGR10A2_LE, GBR_12BE, GBR_12LE, GBRA_12BE, GBRA_12LE, I420_12BE, I420_12LE, I422_12BE, I422_12LE, Y444_12BE, Y444_12LE, GRAY10_LE32, NV12_10LE32, NV16_10LE32, NV12_10LE40 }, width=(int)[ 1, 2147483647 ], height=(int)[ 1, 2147483647 ], framerate=(fraction)[ 0/1, 2147483647/1 ], multiview-mode=(string){ mono, left, right }; video/x-bayer, format=(string){ bggr, rggb, grbg, gbrg }, width=(int)[ 1, 2147483647 ], height=(int)[ 1, 2147483647 ], framerate=(fraction)[ 0/1, 2147483647/1 ], multiview-mode=(string){ mono, left, right }

0:12:58.659044000 15216 00000189D7EE2F80 DEBUG GST_CAPS gstutils.c:3104:gst_pad_peer_query_caps:<source:src> get pad peer caps with filter video/x-raw, format=(string){ I420, YV12, YUY2, UYVY, AYUV, VUYA, RGBx, BGRx, xRGB, xBGR, RGBA, BGRA, ARGB, ABGR, RGB, BGR, Y41B, Y42B, YVYU, Y444, v210, v216, Y210, Y410, NV12, NV21, GRAY8, GRAY16_BE, GRAY16_LE, v308, RGB16, BGR16, RGB15, BGR15, UYVP, A420, RGB8P, YUV9, YVU9, IYU1, ARGB64, AYUV64, r210, I420_10BE, I420_10LE, I422_10BE, I422_10LE, Y444_10BE, Y444_10LE, GBR, GBR_10BE, GBR_10LE, NV16, NV24, NV12_64Z32, A420_10BE, A420_10LE, A422_10BE, A422_10LE, A444_10BE, A444_10LE, NV61, P010_10BE, P010_10LE, IYU2, VYUY, GBRA, GBRA_10BE, GBRA_10LE, BGR10A2_LE, GBR_12BE, GBR_12LE, GBRA_12BE, GBRA_12LE, I420_12BE, I420_12LE, I422_12BE, I422_12LE, Y444_12BE, Y444_12LE, GRAY10_LE32, NV12_10LE32, NV16_10LE32, NV12_10LE40 }, width=(int)[ 1, 2147483647 ], height=(int)[ 1, 2147483647 ], framerate=(fraction)[ 0/1, 2147483647/1 ], multiview-mode=(string){ mono, left, right }; video/x-bayer, format=(string){ bggr, rggb, grbg, gbrg }, width=(int)[ 1, 2147483647 ], height=(int)[ 1, 2147483647 ], framerate=(fraction)[ 0/1, 2147483647/1 ], multiview-mode=(string){ mono, left, right }

0:12:58.661113000 15216 00000189D7EE2F80 DEBUG query gstquery.c:679:gst_query_new_custom: creating new query 00000189D7F11D40 caps

0:12:58.661410000 15216 00000189D7EE2F80 DEBUG GST_PADS gstpad.c:4180:gst_pad_peer_query:<source:src> peer query 00000189D7F11D40 (caps)

0:12:58.661664000 15216 00000189D7EE2F80 DEBUG GST_PADS gstpad.c:4053:gst_pad_query:<sink:sink> doing query 00000189D7F11D40 (caps)

0:12:58.661916000 15216 00000189D7EE2F80 DEBUG GST_PADS gstpad.c:4076:gst_pad_query:<sink:sink> sent query 00000189D7F11D40 (caps), result 1

0:12:58.662205000 15216 00000189D7EE2F80 DEBUG GST_CAPS gstutils.c:3111:gst_pad_peer_query_caps:<source:src> peer query returned video/x-raw, format=(string){ I420, YV12, YUY2, UYVY, AYUV, VUYA, RGBx, BGRx, xRGB, xBGR, RGBA, BGRA, ARGB, ABGR, RGB, BGR, Y41B, Y42B, YVYU, Y444, v210, v216, Y210, Y410, NV12, NV21, GRAY8, GRAY16_BE, GRAY16_LE, v308, RGB16, BGR16, RGB15, BGR15, UYVP, A420, RGB8P, YUV9, YVU9, IYU1, ARGB64, AYUV64, r210, I420_10BE, I420_10LE, I422_10BE, I422_10LE, Y444_10BE, Y444_10LE, GBR, GBR_10BE, GBR_10LE, NV16, NV24, NV12_64Z32, A420_10BE, A420_10LE, A422_10BE, A422_10LE, A444_10BE, A444_10LE, NV61, P010_10BE, P010_10LE, IYU2, VYUY, GBRA, GBRA_10BE, GBRA_10LE, BGR10A2_LE, GBR_12BE, GBR_12LE, GBRA_12BE, GBRA_12LE, I420_12BE, I420_12LE, I422_12BE, I422_12LE, Y444_12BE, Y444_12LE, GRAY10_LE32, NV12_10LE32, NV16_10LE32, NV12_10LE40 }, width=(int)[ 1, 2147483647 ], height=(int)[ 1, 2147483647 ], framerate=(fraction)[ 0/1, 2147483647/1 ], multiview-mode=(string){ mono, left, right }; video/x-bayer, format=(string){ bggr, rggb, grbg, gbrg }, width=(int)[ 1, 2147483647 ], height=(int)[ 1, 2147483647 ], framerate=(fraction)[ 0/1, 2147483647/1 ], multiview-mode=(string){ mono, left, right }

0:12:58.664506000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:3324:gst_base_src_default_negotiate:<source> caps of peer: video/x-raw, format=(string){ I420, YV12, YUY2, UYVY, AYUV, VUYA, RGBx, BGRx, xRGB, xBGR, RGBA, BGRA, ARGB, ABGR, RGB, BGR, Y41B, Y42B, YVYU, Y444, v210, v216, Y210, Y410, NV12, NV21, GRAY8, GRAY16_BE, GRAY16_LE, v308, RGB16, BGR16, RGB15, BGR15, UYVP, A420, RGB8P, YUV9, YVU9, IYU1, ARGB64, AYUV64, r210, I420_10BE, I420_10LE, I422_10BE, I422_10LE, Y444_10BE, Y444_10LE, GBR, GBR_10BE, GBR_10LE, NV16, NV24, NV12_64Z32, A420_10BE, A420_10LE, A422_10BE, A422_10LE, A444_10BE, A444_10LE, NV61, P010_10BE, P010_10LE, IYU2, VYUY, GBRA, GBRA_10BE, GBRA_10LE, BGR10A2_LE, GBR_12BE, GBR_12LE, GBRA_12BE, GBRA_12LE, I420_12BE, I420_12LE, I422_12BE, I422_12LE, Y444_12BE, Y444_12LE, GRAY10_LE32, NV12_10LE32, NV16_10LE32, NV12_10LE40 }, width=(int)[ 1, 2147483647 ], height=(int)[ 1, 2147483647 ], framerate=(fraction)[ 0/1, 2147483647/1 ], multiview-mode=(string){ mono, left, right }; video/x-bayer, format=(string){ bggr, rggb, grbg, gbrg }, width=(int)[ 1, 2147483647 ], height=(int)[ 1, 2147483647 ], framerate=(fraction)[ 0/1, 2147483647/1 ], multiview-mode=(string){ mono, left, right }

0:12:58.666941000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:3335:gst_base_src_default_negotiate:<source> have caps: video/x-raw, format=(string){ I420, YV12, YUY2, UYVY, AYUV, VUYA, RGBx, BGRx, xRGB, xBGR, RGBA, BGRA, ARGB, ABGR, RGB, BGR, Y41B, Y42B, YVYU, Y444, v210, v216, Y210, Y410, NV12, NV21, GRAY8, GRAY16_BE, GRAY16_LE, v308, RGB16, BGR16, RGB15, BGR15, UYVP, A420, RGB8P, YUV9, YVU9, IYU1, ARGB64, AYUV64, r210, I420_10BE, I420_10LE, I422_10BE, I422_10LE, Y444_10BE, Y444_10LE, GBR, GBR_10BE, GBR_10LE, NV16, NV24, NV12_64Z32, A420_10BE, A420_10LE, A422_10BE, A422_10LE, A444_10BE, A444_10LE, NV61, P010_10BE, P010_10LE, IYU2, VYUY, GBRA, GBRA_10BE, GBRA_10LE, BGR10A2_LE, GBR_12BE, GBR_12LE, GBRA_12BE, GBRA_12LE, I420_12BE, I420_12LE, I422_12BE, I422_12LE, Y444_12BE, Y444_12LE, GRAY10_LE32, NV12_10LE32, NV16_10LE32, NV12_10LE40 }, width=(int)[ 1, 2147483647 ], height=(int)[ 1, 2147483647 ], framerate=(fraction)[ 0/1, 2147483647/1 ], multiview-mode=(string){ mono, left, right }; video/x-bayer, format=(string){ bggr, rggb, grbg, gbrg }, width=(int)[ 1, 2147483647 ], height=(int)[ 1, 2147483647 ], framerate=(fraction)[ 0/1, 2147483647/1 ], multiview-mode=(string){ mono, left, right }

0:12:58.670834000 15216 00000189D7EE2F80 DEBUG GST_PERFORMANCE gstcaps.c:179:_gst_caps_copy:video/x-raw, format=(string){ I420, YV12, YUY2, UYVY, AYUV, VUYA, RGBx, BGRx, xRGB, xBGR, RGBA, BGRA, ARGB, ABGR, RGB, BGR, Y41B, Y42B, YVYU, Y444, v210, v216, Y210, Y410, NV12, NV21, GRAY8, GRAY16_BE, GRAY16_LE, v308, RGB16, BGR16, RGB15, BGR15, UYVP, A420, RGB8P, YUV9, YVU9, IYU1, ARGB64, AYUV64, r210, I420_10BE, I420_10LE, I422_10BE, I422_10LE, Y444_10BE, Y444_10LE, GBR, GBR_10BE, GBR_10LE, NV16, NV24, NV12_64Z32, A420_10BE, A420_10LE, A422_10BE, A422_10LE, A444_10BE, A444_10LE, NV61, P010_10BE, P010_10LE, IYU2, VYUY, GBRA, GBRA_10BE, GBRA_10LE, BGR10A2_LE, GBR_12BE, GBR_12LE, GBRA_12BE, GBRA_12LE, I420_12BE, I420_12LE, I422_12BE, I422_12LE, Y444_12BE, Y444_12LE, GRAY10_LE32, NV12_10LE32, NV16_10LE32, NV12_10LE40 }, width=(int)[ 1, 2147483647 ], height=(int)[ 1, 2147483647 ], framerate=(fraction)[ 0/1, 2147483647/1 ], multiview-mode=(string){ mono, left, right }; video/x-bayer, format=(string){ bggr, rggb, grbg, gbrg }, width=(int)[ 1, 2147483647 ], height=(int)[ 1, 2147483647 ], framerate=(fraction)[ 0/1, 2147483647/1 ], multiview-mode=(string){ mono, left, right } doing copy 00000189D7EDBB60 -> 00000189D7F11D90

0:12:58.673007000 15216 00000189D7EE2F80 DEBUG GST_PERFORMANCE gstminiobject.c:428:gst_mini_object_make_writable: copy GstCaps miniobject 00000189D7EDBB60 -> 00000189D7F11D90

0:12:58.673377000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:993:gst_base_src_default_fixate:<source> using default caps fixate function

0:12:58.673672000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:3343:gst_base_src_default_negotiate:<source> fixated to: video/x-raw, format=(string)I420, width=(int)320, height=(int)240, framerate=(fraction)30/1, multiview-mode=(string)mono, pixel-aspect-ratio=(fraction)1/1, interlace-mode=(string)progressive

0:12:58.674277000 15216 00000189D7EE2F80 DEBUG GST_CAPS gstpad.c:2733:gst_pad_get_current_caps:<source:src> get current pad caps (NULL)

0:12:58.674610000 15216 00000189D7EE2F80 DEBUG video-info video-info.c:403:gst_video_info_from_caps: parsing caps video/x-raw, format=(string)I420, width=(int)320, height=(int)240, framerate=(fraction)30/1, multiview-mode=(string)mono, pixel-aspect-ratio=(fraction)1/1, interlace-mode=(string)progressive

0:12:58.675165000 15216 00000189D7EE2F80 DEBUG video-info video-info.c:526:gst_video_info_from_caps: no colorimetry, using default

0:12:58.675428000 15216 00000189D7EE2F80 DEBUG video-chroma video-chroma.c:972:gst_video_chroma_resample_new: h_resample 2, factor -1, cosite 0

0:12:58.675691000 15216 00000189D7EE2F80 DEBUG video-chroma video-chroma.c:985:gst_video_chroma_resample_new: v_resample 2, factor -1, cosite 0

0:12:58.675955000 15216 00000189D7EE2F80 DEBUG video-chroma video-chroma.c:1000:gst_video_chroma_resample_new: resample 00000189D7F17F60, bits 8, n_lines 2, offset 0

0:12:58.676918000 15216 00000189D7EE2F80 DEBUG videotestsrc gstvideotestsrc.c:938:gst_video_test_src_setcaps:<source> size 320x240, 30/1 fps

0:12:58.677215000 15216 00000189D7EE2F80 INFO GST_EVENT gstevent.c:820:gst_event_new_caps: creating caps event video/x-raw, format=(string)I420, width=(int)320, height=(int)240, framerate=(fraction)30/1, multiview-mode=(string)mono, pixel-aspect-ratio=(fraction)1/1, interlace-mode=(string)progressive

0:12:58.677760000 15216 00000189D7EE2F80 DEBUG GST_EVENT gstevent.c:309:gst_event_new_custom: creating new event 00000189D7F13E00 caps 12814

0:12:58.678032000 15216 00000189D7EE2F80 DEBUG GST_PADS gstpad.c:5229:store_sticky_event:<source:src> notify caps

0:12:58.678278000 15216 00000189D7EE2F80 DEBUG GST_PADS gstpad.c:3984:check_sticky:<source:src> pushing all sticky events

0:12:58.678520000 15216 00000189D7EE2F80 DEBUG GST_PADS gstpad.c:3914:push_sticky:<source:src> event stream-start was already received

0:12:58.678789000 15216 00000189D7EE2F80 DEBUG GST_EVENT gstpad.c:5697:gst_pad_send_event_unchecked:<sink:sink> have event type caps event: 00000189D7F13E00, time 99:99:99.999999999, seq-num 16, GstEventCaps, caps=(GstCaps)"video/x-raw\,\ format\=\(string\)I420\,\ width\=\(int\)320\,\ height\=\(int\)240\,\ framerate\=\(fraction\)30/1\,\ multiview-mode\=\(string\)mono\,\ pixel-aspect-ratio\=\(fraction\)1/1\,\ interlace-mode\=\(string\)progressive";

0:12:58.679611000 15216 00000189D7EE2F80 DEBUG GST_CAPS gstutils.c:3141:gst_pad_query_accept_caps:<sink:sink> accept caps of video/x-raw, format=(string)I420, width=(int)320, height=(int)240, framerate=(fraction)30/1, multiview-mode=(string)mono, pixel-aspect-ratio=(fraction)1/1, interlace-mode=(string)progressive

0:12:58.680183000 15216 00000189D7EE2F80 DEBUG query gstquery.c:679:gst_query_new_custom: creating new query 00000189D7F11DE0 accept-caps

0:12:58.680574000 15216 00000189D7EE2F80 DEBUG GST_PADS gstpad.c:4053:gst_pad_query:<sink:sink> doing query 00000189D7F11DE0 (accept-caps)

0:12:58.680928000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:5102:gst_base_sink_default_query:<sink> Checking if requested caps video/x-raw, format=(string)I420, width=(int)320, height=(int)240, framerate=(fraction)30/1, multiview-mode=(string)mono, pixel-aspect-ratio=(fraction)1/1, interlace-mode=(string)progressive are a subset of pad caps ANY result 1

0:12:58.681595000 15216 00000189D7EE2F80 DEBUG GST_PADS gstpad.c:4076:gst_pad_query:<sink:sink> sent query 00000189D7F11DE0 (accept-caps), result 1

0:12:58.681866000 15216 00000189D7EE2F80 DEBUG default gstutils.c:3146:gst_pad_query_accept_caps:<sink:sink> query returned 1

0:12:58.682119000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3355:gst_base_sink_event:<sink> received event 00000189D7F13E00 caps event: 00000189D7F13E00, time 99:99:99.999999999, seq-num 16, GstEventCaps, caps=(GstCaps)"video/x-raw\,\ format\=\(string\)I420\,\ width\=\(int\)320\,\ height\=\(int\)240\,\ framerate\=\(fraction\)30/1\,\ multiview-mode\=\(string\)mono\,\ pixel-aspect-ratio\=\(fraction\)1/1\,\ interlace-mode\=\(string\)progressive";

0:12:58.682942000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3258:gst_base_sink_default_event:<sink> caps 00000189D7F13E00

0:12:58.683236000 15216 00000189D7EE2F80 DEBUG GST_CAPS gstpad.c:2733:gst_pad_get_current_caps:<sink:sink> get current pad caps (NULL)

0:12:58.683489000 15216 00000189D7EE2F80 DEBUG GST_PADS gstpad.c:5780:gst_pad_send_event_unchecked:<sink:sink> sent event, ret ok

0:12:58.683731000 15216 00000189D7EE2F80 DEBUG GST_PADS gstpad.c:5229:store_sticky_event:<sink:sink> notify caps

0:12:58.683947000 15216 00000189D7EE2F80 DEBUG GST_PADS gstpad.c:3936:push_sticky:<source:src> event caps marked received

0:12:58.684222000 15216 00000189D7EE2F80 DEBUG GST_CAPS gstpad.c:2733:gst_pad_get_current_caps:<source:src> get current pad caps video/x-raw, format=(string)I420, width=(int)320, height=(int)240, framerate=(fraction)30/1, multiview-mode=(string)mono, pixel-aspect-ratio=(fraction)1/1, interlace-mode=(string)progressive

0:12:58.684773000 15216 00000189D7EE2F80 DEBUG query gstquery.c:679:gst_query_new_custom: creating new query 00000189D7F11E30 allocation

0:12:58.685029000 15216 00000189D7EE2F80 DEBUG GST_PADS gstpad.c:4180:gst_pad_peer_query:<source:src> peer query 00000189D7F11E30 (allocation)

0:12:58.685293000 15216 00000189D7EE2F80 DEBUG GST_PADS gstpad.c:4053:gst_pad_query:<sink:sink> doing query 00000189D7F11E30 (allocation)

0:12:58.685557000 15216 00000189D7EE2F80 DEBUG GST_PADS gstpad.c:4076:gst_pad_query:<sink:sink> sent query 00000189D7F11E30 (allocation), result 0

0:12:58.687144000 15216 00000189D7EE2F80 DEBUG GST_PADS gstpad.c:4121:gst_pad_query:<sink:sink> query failed

0:12:58.687401000 15216 00000189D7EE2F80 DEBUG GST_PADS gstpad.c:4242:gst_pad_peer_query:<source:src> query failed

0:12:58.687617000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:3254:gst_base_src_prepare_allocation:<source> peer ALLOCATION query failed

0:12:58.687940000 15216 00000189D7EE2F80 DEBUG GST_POLL gstpoll.c:681:gst_poll_new: 00000189D807D240: new controllable : 1

0:12:58.688225000 15216 00000189D7EE2F80 DEBUG bufferpool gstbufferpool.c:180:gst_buffer_pool_init:<GstBufferPool@00000189D7F423B0> created

0:12:58.688524000 15216 00000189D7EE2F80 DEBUG GST_META gstmeta.c:88:gst_meta_api_type_register: register API "GstVideoMetaAPI"

0:12:58.688765000 15216 00000189D7EE2F80 DEBUG GST_META gstmeta.c:95:gst_meta_api_type_register: adding tag "video"

0:12:58.688985000 15216 00000189D7EE2F80 DEBUG GST_META gstmeta.c:95:gst_meta_api_type_register: adding tag "memory"

0:12:58.689246000 15216 00000189D7EE2F80 DEBUG GST_META gstmeta.c:95:gst_meta_api_type_register: adding tag "colorspace"

0:12:58.689504000 15216 00000189D7EE2F80 DEBUG GST_META gstmeta.c:95:gst_meta_api_type_register: adding tag "size"

0:12:58.689740000 15216 00000189D7EE2F80 DEBUG video-info video-info.c:403:gst_video_info_from_caps: parsing caps video/x-raw, format=(string)I420, width=(int)320, height=(int)240, framerate=(fraction)30/1, multiview-mode=(string)mono, pixel-aspect-ratio=(fraction)1/1, interlace-mode=(string)progressive

0:12:58.690304000 15216 00000189D7EE2F80 DEBUG video-info video-info.c:526:gst_video_info_from_caps: no colorimetry, using default

0:12:58.690927000 15216 00000189D7EE2F80 WARN structure gststructure.c:1863:priv_gst_structure_append_to_gstring: No value transform to serialize field 'params' of type 'GstAllocationParams'

0:12:58.691336000 15216 00000189D7EE2F80 DEBUG bufferpool gstbufferpool.c:609:default_set_config:<videobufferpool0> config GstBufferPoolConfig, caps=(GstCaps)"video/x-raw\,\ format\=\(string\)I420\,\ width\=\(int\)320\,\ height\=\(int\)240\,\ framerate\=\(fraction\)30/1\,\ multiview-mode\=\(string\)mono\,\ pixel-aspect-ratio\=\(fraction\)1/1\,\ interlace-mode\=\(string\)progressive", size=(uint)115200, min-buffers=(uint)0, max-buffers=(uint)0, allocator=(GstAllocator)"NULL", params=(GstAllocationParams)NULL;

0:12:58.692268000 15216 00000189D7EE2F80 WARN structure gststructure.c:1863:priv_gst_structure_append_to_gstring: No value transform to serialize field 'pool' of type 'GArray'

0:12:58.692594000 15216 00000189D7EE2F80 WARN structure gststructure.c:1863:priv_gst_structure_append_to_gstring: No value transform to serialize field 'meta' of type 'GArray'

0:12:58.692917000 15216 00000189D7EE2F80 WARN structure gststructure.c:1863:priv_gst_structure_append_to_gstring: No value transform to serialize field 'allocator' of type 'GArray'

0:12:58.693252000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:3261:gst_base_src_prepare_allocation:<source> ALLOCATION (1) params: allocation query: 00000189D7F11E30, GstQueryAllocation, caps=(GstCaps)"video/x-raw\,\ format\=\(string\)I420\,\ width\=\(int\)320\,\ height\=\(int\)240\,\ framerate\=\(fraction\)30/1\,\ multiview-mode\=\(string\)mono\,\ pixel-aspect-ratio\=\(fraction\)1/1\,\ interlace-mode\=\(string\)progressive", need-pool=(boolean)true, pool=(GArray)NULL, meta=(GArray)NULL, allocator=(GArray)NULL;

0:12:58.694161000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:3088:gst_base_src_set_allocation:<source> activate pool

0:12:58.694411000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:2521:gst_base_src_get_range:<source> calling create offset 18446744073709551615 length 4096, time 0

0:12:58.694717000 15216 00000189D7EE2F80 DEBUG videopool gstvideopool.c:248:video_buffer_pool_alloc:<videobufferpool0> alloc 115200

0:12:58.694970000 15216 00000189D7EE2F80 DEBUG GST_MEMORY gstmemory.c:140:gst_memory_init: new memory 00000189D808CA20, maxsize:115207 offset:0 size:115200

0:12:58.695261000 15216 00000189D7EE2F80 DEBUG GST_META gstmeta.c:198:gst_meta_register: register "GstVideoMeta" implementing "GstVideoMetaAPI" of size 112

0:12:58.696804000 15216 00000189D7EE2F80 DEBUG videotestsrc gstvideotestsrc.c:1169:gst_video_test_src_fill:<source> Timestamp: 0:00:00.000000000 = accumulated 0:00:00.000000000 + offset: 0:00:00.000000000 + running time: 0:00:00.000000000

0:12:58.697254000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:2369:gst_base_src_do_sync:<source> we have no clock

0:12:58.697492000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:2612:gst_base_src_get_range:<source> buffer ok

0:12:58.697757000 15216 00000189D7EE2F80 INFO GST_EVENT gstevent.c:901:gst_event_new_segment: creating segment event time segment start=0:00:00.000000000, offset=0:00:00.000000000, stop=99:99:99.999999999, rate=1.000000, applied_rate=1.000000, flags=0x00, time=0:00:00.000000000, base=0:00:00.000000000, position 0:00:00.000000000, duration 99:99:99.999999999

0:12:58.699196000 15216 00000189D7EE2F80 DEBUG GST_EVENT gstevent.c:309:gst_event_new_custom: creating new event 00000189D7F13E70 segment 17934

0:12:58.699462000 15216 00000189D7EE2F80 DEBUG GST_PADS gstpad.c:3984:check_sticky:<source:src> pushing all sticky events

0:12:58.699689000 15216 00000189D7EE2F80 DEBUG GST_PADS gstpad.c:3914:push_sticky:<source:src> event stream-start was already received

0:12:58.699936000 15216 00000189D7EE2F80 DEBUG GST_PADS gstpad.c:3914:push_sticky:<source:src> event caps was already received

0:12:58.700257000 15216 00000189D7EE2F80 DEBUG GST_EVENT gstpad.c:5697:gst_pad_send_event_unchecked:<sink:sink> have event type segment event: 00000189D7F13E70, time 99:99:99.999999999, seq-num 9, GstEventSegment, segment=(GstSegment)"GstSegment, flags=(GstSegmentFlags)GST_SEGMENT_FLAG_NONE, rate=(double)1, applied-rate=(double)1, format=(GstFormat)GST_FORMAT_TIME, base=(guint64)0, offset=(guint64)0, start=(guint64)0, stop=(guint64)18446744073709551615, time=(guint64)0, position=(guint64)0, duration=(guint64)18446744073709551615;";

0:12:58.701248000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3355:gst_base_sink_event:<sink> received event 00000189D7F13E70 segment event: 00000189D7F13E70, time 99:99:99.999999999, seq-num 9, GstEventSegment, segment=(GstSegment)"GstSegment, flags=(GstSegmentFlags)GST_SEGMENT_FLAG_NONE, rate=(double)1, applied-rate=(double)1, format=(GstFormat)GST_FORMAT_TIME, base=(guint64)0, offset=(guint64)0, start=(guint64)0, stop=(guint64)18446744073709551615, time=(guint64)0, position=(guint64)0, duration=(guint64)18446744073709551615;";

0:12:58.702305000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3290:gst_base_sink_default_event:<sink> configured segment time segment start=0:00:00.000000000, offset=0:00:00.000000000, stop=99:99:99.999999999, rate=1.000000, applied_rate=1.000000, flags=0x00, time=0:00:00.000000000, base=0:00:00.000000000, position 0:00:00.000000000, duration 99:99:99.999999999

0:12:58.703438000 15216 00000189D7EE2F80 DEBUG GST_PADS gstpad.c:5780:gst_pad_send_event_unchecked:<sink:sink> sent event, ret ok

0:12:58.703698000 15216 00000189D7EE2F80 DEBUG GST_PADS gstpad.c:3936:push_sticky:<source:src> event segment marked received

0:12:58.703981000 15216 00000189D7EE2F80 INFO basesrc gstbasesrc.c:2962:gst_base_src_loop:<source> marking pending DISCONT

0:12:58.704295000 15216 00000189D7EE2F80 DEBUG GST_SCHEDULING gstpad.c:4324:gst_pad_chain_data_unchecked:<sink:sink> calling chainfunction &gst_base_sink_chain with buffer buffer: 00000189D8080480, pts 0:00:00.000000000, dts 99:99:99.999999999, dur 0:00:00.033333333, size 115200, offset 0, offset_end 1, flags 0x40

0:12:58.704846000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3524:gst_base_sink_chain_unlocked:<sink> got times start: 0:00:00.000000000, end: 0:00:00.033333333

0:12:58.705263000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2112:gst_base_sink_get_sync_times:<sink> got times start: 0:00:00.000000000, stop: 0:00:00.033333333, do_sync 1

0:12:58.705605000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2415:gst_base_sink_do_preroll:<sink> prerolling object 00000189D8080480

0:12:58.706068000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:1014:gst_base_sink_set_last_buffer_unlocked:<sink> setting last buffer to 00000189D8080480

0:12:58.706414000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2438:gst_base_sink_do_preroll:<sink> preroll buffer 0:00:00.000000000

0:12:58.706777000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:1657:gst_base_sink_commit_state:<sink> committing state to PAUSED

0:12:58.707028000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:1682:gst_base_sink_commit_state:<sink> posting PAUSED state change message

0:12:58.707344000 15216 00000189D7EE2F80 DEBUG GST_BUS gstbus.c:316:gst_bus_post:<bus0> [msg 00000189D7F19C30] posting on bus state-changed message: 00000189D7F19C30, time 99:99:99.999999999, seq-num 19, element 'sink', GstMessageStateChanged, old-state=(GstState)GST_STATE_READY, new-state=(GstState)GST_STATE_PAUSED, pending-state=(GstState)GST_STATE_VOID_PENDING;

0:12:58.707992000 15216 00000189D7EE2F80 DEBUG bin gstbin.c:3716:gst_bin_handle_message_func:<my-pipeline1> [msg 00000189D7F19C30] handling child sink message of type state-changed

0:12:58.708356000 15216 00000189D7EE2F80 DEBUG bin gstbin.c:4053:gst_bin_handle_message_func:<my-pipeline1> posting message upward

0:12:58.708615000 15216 00000189D7EE2F80 DEBUG GST_BUS gstbus.c:316:gst_bus_post:<bus1> [msg 00000189D7F19C30] posting on bus state-changed message: 00000189D7F19C30, time 99:99:99.999999999, seq-num 19, element 'sink', GstMessageStateChanged, old-state=(GstState)GST_STATE_READY, new-state=(GstState)GST_STATE_PAUSED, pending-state=(GstState)GST_STATE_VOID_PENDING;

0:12:58.709278000 15216 00000189D7EE2F80 DEBUG GST_BUS gstbus.c:355:gst_bus_post:<bus1> [msg 00000189D7F19C30] pushing on async queue

0:12:58.709609000 15216 00000189D7EE2F80 DEBUG GST_BUS gstbus.c:358:gst_bus_post:<bus1> [msg 00000189D7F19C30] pushed on async queue

0:12:58.709921000 15216 00000189D7EE2F80 DEBUG GST_BUS gstbus.c:351:gst_bus_post:<bus0> [msg 00000189D7F19C30] dropped

0:12:58.710160000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:1688:gst_base_sink_commit_state:<sink> posting async-done message

0:12:58.710465000 15216 00000189D7EE2F80 DEBUG GST_BUS gstbus.c:316:gst_bus_post:<bus0> [msg 00000189D7F19CB0] posting on bus async-done message: 00000189D7F19CB0, time 99:99:99.999999999, seq-num 20, element 'sink', GstMessageAsyncDone, running-time=(guint64)18446744073709551615;

0:12:58.712018000 15216 00000189D7EE2F80 DEBUG bin gstbin.c:3716:gst_bin_handle_message_func:<my-pipeline1> [msg 00000189D7F19CB0] handling child sink message of type async-done

0:12:58.712384000 15216 00000189D7EE2F80 DEBUG bin gstbin.c:3937:gst_bin_handle_message_func:<my-pipeline1> ASYNC_DONE message 00000189D7F19CB0, sink

0:12:58.712668000 15216 00000189D7EE2F80 DEBUG bin gstbin.c:880:find_message:<my-pipeline1> we found a message 00000189D7F198B0 from sink matching types 00100000

0:12:58.712967000 15216 00000189D7EE2F80 DEBUG bin gstbin.c:921:bin_replace_message:<my-pipeline1> replace old message async-start from sink with async-done message

0:12:58.713333000 15216 00000189D7EE2F80 DEBUG bin gstbin.c:882:find_message:<my-pipeline1> no message found matching types 00100000

0:12:58.713601000 15216 00000189D7EE2F80 DEBUG bin gstbin.c:889:find_message:<my-pipeline1> async-start

0:12:58.713814000 15216 00000189D7EE2F80 DEBUG bin gstbin.c:958:bin_remove_messages:<sink> deleting message 00000189D7F19CB0 of type async-done (types 0x00200000)

0:12:58.714151000 15216 00000189D7EE2F80 DEBUG bin gstbin.c:3956:gst_bin_handle_message_func:<my-pipeline1> async elements committed

0:12:58.714407000 15216 00000189D7EE2F80 INFO GST_STATES gstbin.c:3421:bin_handle_async_done:<my-pipeline1> committing state from READY to PAUSED, old pending PAUSED

0:12:58.714999000 15216 00000189D7EE2F80 INFO GST_STATES gstbin.c:3441:bin_handle_async_done:<my-pipeline1> completed state change, pending VOID

0:12:58.715347000 15216 00000189D7EE2F80 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<my-pipeline1> notifying about state-changed READY to PAUSED (VOID_PENDING pending)

0:12:58.715764000 15216 00000189D7EE2F80 DEBUG GST_BUS gstbus.c:316:gst_bus_post:<bus1> [msg 00000189D7F198B0] posting on bus state-changed message: 00000189D7F198B0, time 99:99:99.999999999, seq-num 22, element 'my-pipeline1', GstMessageStateChanged, old-state=(GstState)GST_STATE_READY, new-state=(GstState)GST_STATE_PAUSED, pending-state=(GstState)GST_STATE_VOID_PENDING;

0:12:58.716451000 15216 00000189D7EE2F80 DEBUG GST_BUS gstbus.c:355:gst_bus_post:<bus1> [msg 00000189D7F198B0] pushing on async queue

0:12:58.716702000 15216 00000189D7EE2F80 DEBUG GST_BUS gstbus.c:358:gst_bus_post:<bus1> [msg 00000189D7F198B0] pushed on async queue

0:12:58.716952000 15216 00000189D7EE2F80 DEBUG bin gstbin.c:3476:bin_handle_async_done:<my-pipeline1> posting ASYNC_DONE to parent

0:12:58.717257000 15216 00000189D7EE2F80 DEBUG GST_BUS gstbus.c:316:gst_bus_post:<bus1> [msg 00000189D7F19CB0] posting on bus async-done message: 00000189D7F19CB0, time 99:99:99.999999999, seq-num 21, element 'my-pipeline1', GstMessageAsyncDone, running-time=(guint64)18446744073709551615;

0:12:58.717913000 15216 00000189D7EE2F80 DEBUG GST_BUS gstbus.c:355:gst_bus_post:<bus1> [msg 00000189D7F19CB0] pushing on async queue

0:12:58.718225000 15216 00000189D7EE2F80 DEBUG GST_BUS gstbus.c:358:gst_bus_post:<bus1> [msg 00000189D7F19CB0] pushed on async queue

0:12:58.718475000 15216 00000189D7EE2F80 DEBUG bin gstbin.c:3486:bin_handle_async_done:<my-pipeline1> state change complete

0:12:58.718716000 15216 00000189D7EE2F80 DEBUG GST_BUS gstbus.c:351:gst_bus_post:<bus0> [msg 00000189D7F19CB0] dropped

0:12:58.718947000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2368:gst_base_sink_wait_preroll:<sink> waiting in preroll for flush or PLAYING

4、PAUSE-->PLAY

0:15:33.878874000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2827:gst_element_set_state_func:<my-pipeline1> set_state to PLAYING

0:15:33.879182000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2852:gst_element_set_state_func:<my-pipeline1> setting target state to PLAYING

0:15:33.879567000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2865:gst_element_set_state_func:<my-pipeline1> current PAUSED, old_pending VOID_PENDING, next VOID_PENDING, old return SUCCESS

0:15:33.879953000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2899:gst_element_set_state_func:<my-pipeline1> final: setting state from PAUSED to PLAYING

0:15:33.880277000 15216 00000189D4A09000 DEBUG pipeline gstpipeline.c:408:gst_pipeline_change_state:<my-pipeline1> selecting clock and base_time //设置时钟

0:15:33.880577000 15216 00000189D4A09000 DEBUG pipeline gstpipeline.c:429:gst_pipeline_change_state:<my-pipeline1> Need to update start_time

0:15:33.881060000 15216 00000189D4A09000 DEBUG pipeline gstpipeline.c:434:gst_pipeline_change_state:<my-pipeline1> Need to update clock.

0:15:33.881340000 15216 00000189D4A09000 DEBUG bin gstbin.c:834:gst_bin_provide_clock_func:<my-pipeline1> returning old clock 0000000000000000

0:15:33.881642000 15216 00000189D4A09000 DEBUG GST_CLOCK gstsystemclock.c:360:gst_system_clock_obtain: returning static system clock

0:15:33.882064000 15216 00000189D4A09000 DEBUG GST_CLOCK gstpipeline.c:728:gst_pipeline_provide_clock_func: pipeline obtained system clock: 00000189D80830F0 (GstSystemClock)

0:15:33.882537000 15216 00000189D4A09000 DEBUG GST_CLOCK gstclock.c:1092:gst_clock_get_internal_time:<GstSystemClock> internal time 0:01:25.359656100

0:15:33.882841000 15216 00000189D4A09000 DEBUG GST_CLOCK gstclock.c:1137:gst_clock_get_time:<GstSystemClock> adjusted time 0:01:25.359656100

0:15:33.883128000 15216 00000189D4A09000 DEBUG pipeline gstpipeline.c:474:gst_pipeline_change_state:<my-pipeline1> start_time=0:00:10.858184600, now=0:01:25.359656100, base_time 0:01:14.501471500

0:15:33.883513000 15216 00000189D4A09000 DEBUG GST_CLOCK gstelement.c:489:gst_element_set_base_time:<my-pipeline1> set base_time=0:01:14.501471500, old 0:00:00.000329700

0:15:33.883848000 15216 00000189D4A09000 DEBUG GST_STATES gstbin.c:2851:gst_bin_change_state_func:<my-pipeline1> changing state of children from PAUSED to PLAYING

0:15:33.884179000 15216 00000189D4A09000 DEBUG bin gstbin.c:2754:gst_bin_do_latency_func:<my-pipeline1> querying latency

0:15:33.884450000 15216 00000189D4A09000 DEBUG query gstquery.c:679:gst_query_new_custom: creating new query 00000189D7F118E0 latency

0:15:33.884724000 15216 00000189D4A09000 DEBUG GST_ELEMENT_PADS gstelement.c:1958:gst_element_query: send query on element my-pipeline1

0:15:33.884989000 15216 00000189D4A09000 DEBUG bin gstbin.c:4374:gst_bin_query:<my-pipeline1> Sending query 00000189D7F118E0 (type latency) to sink children

0:15:33.885317000 15216 00000189D4A09000 DEBUG GST_STATES gstbin.c:1968:bin_element_is_sink:<my-pipeline1> child sink is sink

0:15:33.885562000 15216 00000189D4A09000 DEBUG GST_ELEMENT_PADS gstelement.c:1958:gst_element_query: send query on element sink

0:15:33.885791000 15216 00000189D4A09000 DEBUG basesink gstbasesink.c:1189:gst_base_sink_query_latency:<sink> we are ready for LATENCY query //设置延时

0:15:33.886053000 15216 00000189D4A09000 DEBUG query gstquery.c:679:gst_query_new_custom: creating new query 00000189D7F11930 latency

0:15:33.886371000 15216 00000189D4A09000 DEBUG GST_PADS gstpad.c:4180:gst_pad_peer_query:<sink:sink> peer query 00000189D7F11930 (latency)

0:15:33.886671000 15216 00000189D4A09000 DEBUG GST_PADS gstpad.c:4053:gst_pad_query:<source:src> doing query 00000189D7F11930 (latency)

0:15:33.886940000 15216 00000189D4A09000 DEBUG videotestsrc gstvideotestsrc.c:1011:gst_video_test_src_query:<source> Reporting latency of 0:00:00.033333333

0:15:33.887876000 15216 00000189D4A09000 DEBUG GST_PADS gstpad.c:4076:gst_pad_query:<source:src> sent query 00000189D7F11930 (latency), result 1

0:15:33.888165000 15216 00000189D4A09000 DEBUG basesink gstbasesink.c:1249:gst_base_sink_query_latency:<sink> latency query: live: 1, have_latency 1, upstream: 0, min 0:00:00.000000000, max 99:99:99.999999999

0:15:33.888550000 15216 00000189D4A09000 DEBUG basesink gstbasesink.c:5038:default_element_query:<sink> query latency returns 1

0:15:33.888798000 15216 00000189D4A09000 DEBUG bin gstbin.c:4189:bin_query_latency_fold:<sink> got latency min 0:00:00.000000000, max 99:99:99.999999999, live 1

0:15:33.889110000 15216 00000189D4A09000 DEBUG GST_STATES gstbin.c:1968:bin_element_is_sink:<my-pipeline1> child source is not sink

0:15:33.889364000 15216 00000189D4A09000 DEBUG bin gstbin.c:4220:bin_query_latency_done:<my-pipeline1> latency min 0:00:00.000000000, max 99:99:99.999999999, live 1

0:15:33.889926000 15216 00000189D4A09000 DEBUG bin gstbin.c:4396:gst_bin_query:<my-pipeline1> query 00000189D7F118E0 result 1

0:15:33.890262000 15216 00000189D4A09000 DEBUG bin gstbin.c:2765:gst_bin_do_latency_func:<my-pipeline1> got min latency 0:00:00.000000000, max latency 99:99:99.999999999, live 1

0:15:33.890614000 15216 00000189D4A09000 INFO GST_EVENT gstevent.c:1450:gst_event_new_latency: creating latency event 0:00:00.000000000

0:15:33.890883000 15216 00000189D4A09000 DEBUG GST_EVENT gstevent.c:309:gst_event_new_custom: creating new event 00000189D8082150 latency 56321

0:15:33.891157000 15216 00000189D4A09000 DEBUG GST_ELEMENT_PADS gstelement.c:1852:gst_element_send_event: send latency event on element my-pipeline1

0:15:33.891434000 15216 00000189D4A09000 DEBUG bin gstbin.c:3136:gst_bin_send_event:<my-pipeline1> Sending latency event to sink children

0:15:33.891714000 15216 00000189D4A09000 DEBUG GST_STATES gstbin.c:1968:bin_element_is_sink:<my-pipeline1> child sink is sink

0:15:33.891958000 15216 00000189D4A09000 DEBUG GST_ELEMENT_PADS gstelement.c:1852:gst_element_send_event: send latency event on element sink

0:15:33.892236000 15216 00000189D4A09000 DEBUG basesink gstbasesink.c:4573:gst_base_sink_send_event:<sink> handling event 00000189D8082150 latency event: 00000189D8082150, time 99:99:99.999999999, seq-num 34, GstEventLatency, latency=(guint64)0;

0:15:33.892692000 15216 00000189D4A09000 DEBUG basesink gstbasesink.c:4590:gst_base_sink_send_event:<sink> latency set to 0:00:00.000000000

0:15:33.892955000 15216 00000189D4A09000 DEBUG basesink gstbasesink.c:4612:gst_base_sink_send_event:<sink> sending event 00000189D8082150 latency event: 00000189D8082150, time 99:99:99.999999999, seq-num 34, GstEventLatency, latency=(guint64)0;

0:15:33.893426000 15216 00000189D4A09000 DEBUG GST_EVENT gstpad.c:5697:gst_pad_send_event_unchecked:<source:src> have event type latency event: 00000189D8082150, time 99:99:99.999999999, seq-num 34, GstEventLatency, latency=(guint64)0;

0:15:33.893841000 15216 00000189D4A09000 DEBUG basesrc gstbasesrc.c:2042:gst_base_src_default_event:<source> handle event latency event: 00000189D8082150, time 99:99:99.999999999, seq-num 34, GstEventLatency, latency=(guint64)0;

0:15:33.894293000 15216 00000189D4A09000 DEBUG GST_PADS gstpad.c:5780:gst_pad_send_event_unchecked:<source:src> sent event, ret ok

0:15:33.894535000 15216 00000189D4A09000 DEBUG basesink gstbasesink.c:4621:gst_base_sink_send_event:<sink> handled event: 1

0:15:33.894770000 15216 00000189D4A09000 DEBUG GST_STATES gstbin.c:1968:bin_element_is_sink:<my-pipeline1> child source is not sink

0:15:33.895014000 15216 00000189D4A09000 DEBUG bin gstbin.c:3176:gst_bin_send_event:<my-pipeline1> Sending latency event to src pads

0:15:33.895314000 15216 00000189D4A09000 INFO bin gstbin.c:2780:gst_bin_do_latency_func:<my-pipeline1> configured latency of 0:00:00.000000000

0:15:33.895590000 15216 00000189D4A09000 DEBUG bin gstbin.c:327:_gst_boolean_accumulator: invocation 2, 1

0:15:33.895809000 15216 00000189D4A09000 DEBUG bin gstbin.c:2737:gst_bin_recalculate_latency:<my-pipeline1> latency returned 1

0:15:33.896064000 15216 00000189D4A09000 DEBUG bin gstbin.c:2382:gst_bin_sort_iterator_resync:<my-pipeline1> resync

0:15:33.897052000 15216 00000189D4A09000 DEBUG bin gstbin.c:2162:add_to_queue:<my-pipeline1> adding 'sink' to queue

0:15:33.897289000 15216 00000189D4A09000 DEBUG bin gstbin.c:882:find_message:<my-pipeline1> no message found matching types 00001000

0:15:33.897576000 15216 00000189D4A09000 DEBUG bin gstbin.c:889:find_message:<my-pipeline1> structure-change

0:15:33.897802000 15216 00000189D4A09000 DEBUG bin gstbin.c:2279:update_degree:<my-pipeline1> change element source, degree 0->1, linked to sink

0:15:33.898079000 15216 00000189D4A09000 DEBUG bin gstbin.c:2302:update_degree:<my-pipeline1> element source not linked on any sinkpads

0:15:33.898376000 15216 00000189D4A09000 DEBUG bin gstbin.c:2369:gst_bin_sort_iterator_next:<my-pipeline1> queue head gives sink

0:15:33.898644000 15216 00000189D4A09000 DEBUG bin gstbin.c:882:find_message:<my-pipeline1> no message found matching types 00001000

0:15:33.898924000 15216 00000189D4A09000 DEBUG bin gstbin.c:889:find_message:<my-pipeline1> structure-change

0:15:33.899643000 15216 00000189D4A09000 DEBUG bin gstbin.c:2279:update_degree:<my-pipeline1> change element source, degree 1->0, linked to sink

0:15:33.900011000 15216 00000189D4A09000 DEBUG bin gstbin.c:2162:add_to_queue:<my-pipeline1> adding 'source' to queue

0:15:33.900285000 15216 00000189D4A09000 INFO GST_STATES gstbin.c:2503:gst_bin_element_set_state:<sink> current PAUSED pending VOID_PENDING, desired next PLAYING

0:15:33.900578000 15216 00000189D4A09000 DEBUG bin gstbin.c:882:find_message:<my-pipeline1> no message found matching types 00100000

0:15:33.900835000 15216 00000189D4A09000 DEBUG bin gstbin.c:889:find_message:<my-pipeline1> async-start

0:15:33.901055000 15216 00000189D4A09000 DEBUG bin gstbin.c:2598:gst_bin_element_set_state:<my-pipeline1> setting element sink to PLAYING, base_time 0:01:14.501471500

//设置sink状态为PLAY

0:15:33.901415000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2827:gst_element_set_state_func:<sink> set_state to PLAYING

0:15:33.901658000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2852:gst_element_set_state_func:<sink> setting target state to PLAYING

0:15:33.901919000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2865:gst_element_set_state_func:<sink> current PAUSED, old_pending VOID_PENDING, next VOID_PENDING, old return SUCCESS

0:15:33.902296000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2899:gst_element_set_state_func:<sink> final: setting state from PAUSED to PLAYING

0:15:33.902585000 15216 00000189D4A09000 DEBUG basesink gstbasesink.c:3444:gst_base_sink_needs_preroll:<sink> have_preroll: 1, EOS: 0 => needs preroll: 0

0:15:33.902874000 15216 00000189D4A09000 DEBUG basesink gstbasesink.c:5204:gst_base_sink_change_state:<sink> PAUSED to PLAYING, don't need preroll

0:15:33.903144000 15216 00000189D4A09000 DEBUG basesink gstbasesink.c:5217:gst_base_sink_change_state:<sink> signal preroll

0:15:33.903419000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2988:gst_element_change_state:<sink> element changed state SUCCESS

0:15:33.903672000 15216 00000189D4A09000 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<sink> completed state change to PLAYING

0:15:33.903934000 15216 00000189D4A09000 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<sink> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending)

0:15:33.903462000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2376:gst_base_sink_wait_preroll:<sink> continue after preroll

0:15:33.904596000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2694:gst_base_sink_do_sync:<sink> reset rc_time to time 0:00:10.833333333

0:15:33.904867000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2706:gst_base_sink_do_sync:<sink> possibly waiting for clock to reach 0:00:10.833333333, adjusted 0:00:10.833333333

0:15:33.905223000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:557:gst_clock_id_wait:<GstSystemClock> waiting on clock entry 00000189D7F19AB0

0:15:33.905514000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1092:gst_clock_get_internal_time:<GstSystemClock> internal time 0:01:25.382643000

0:15:33.906561000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1137:gst_clock_get_time:<GstSystemClock> adjusted time 0:01:25.382643000

0:15:33.906822000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstsystemclock.c:714:gst_system_clock_id_wait_jitter_unlocked: entry 00000189D7F19AB0 time 0:01:25.334804833 now 0:01:25.382643000 diff (time-now) -47838167

0:15:33.904334000 15216 00000189D4A09000 DEBUG GST_BUS gstbus.c:316:gst_bus_post:<bus0> [msg 00000189D80843C0] posting on bus state-changed message: 00000189D80843C0, time 99:99:99.999999999, seq-num 35, element 'sink', GstMessageStateChanged, old-state=(GstState)GST_STATE_PAUSED, new-state=(GstState)GST_STATE_PLAYING, pending-state=(GstState)GST_STATE_VOID_PENDING;

0:15:33.907896000 15216 00000189D4A09000 DEBUG bin gstbin.c:3716:gst_bin_handle_message_func:<my-pipeline1> [msg 00000189D80843C0] handling child sink message of type state-changed

0:15:33.908262000 15216 00000189D4A09000 DEBUG bin gstbin.c:4053:gst_bin_handle_message_func:<my-pipeline1> posting message upward

0:15:33.908537000 15216 00000189D4A09000 DEBUG GST_BUS gstbus.c:316:gst_bus_post:<bus1> [msg 00000189D80843C0] posting on bus state-changed message: 00000189D80843C0, time 99:99:99.999999999, seq-num 35, element 'sink', GstMessageStateChanged, old-state=(GstState)GST_STATE_PAUSED, new-state=(GstState)GST_STATE_PLAYING, pending-state=(GstState)GST_STATE_VOID_PENDING;

0:15:33.909423000 15216 00000189D4A09000 DEBUG GST_BUS gstbus.c:355:gst_bus_post:<bus1> [msg 00000189D80843C0] pushing on async queue

0:15:33.909674000 15216 00000189D4A09000 DEBUG GST_BUS gstbus.c:358:gst_bus_post:<bus1> [msg 00000189D80843C0] pushed on async queue

0:15:33.909923000 15216 00000189D4A09000 DEBUG GST_BUS gstbus.c:351:gst_bus_post:<bus0> [msg 00000189D80843C0] dropped

0:15:33.910148000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2911:gst_element_set_state_func:<sink> returned SUCCESS

//设置source状态为PLAY

0:15:33.910426000 15216 00000189D4A09000 INFO GST_STATES gstbin.c:2951:gst_bin_change_state_func:<my-pipeline1> child 'sink' changed state to 4(PLAYING) successfully

0:15:33.910727000 15216 00000189D4A09000 DEBUG bin gstbin.c:2369:gst_bin_sort_iterator_next:<my-pipeline1> queue head gives source

0:15:33.910977000 15216 00000189D4A09000 DEBUG bin gstbin.c:2302:update_degree:<my-pipeline1> element source not linked on any sinkpads

0:15:33.911279000 15216 00000189D4A09000 INFO GST_STATES gstbin.c:2503:gst_bin_element_set_state:<source> current PAUSED pending VOID_PENDING, desired next PLAYING

0:15:33.911575000 15216 00000189D4A09000 DEBUG bin gstbin.c:882:find_message:<my-pipeline1> no message found matching types 00100000

0:15:33.911828000 15216 00000189D4A09000 DEBUG bin gstbin.c:889:find_message:<my-pipeline1> async-start

0:15:33.912041000 15216 00000189D4A09000 DEBUG bin gstbin.c:2598:gst_bin_element_set_state:<my-pipeline1> setting element source to PLAYING, base_time 0:01:14.501471500

0:15:33.912388000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2827:gst_element_set_state_func:<source> set_state to PLAYING

0:15:33.912632000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2852:gst_element_set_state_func:<source> setting target state to PLAYING

0:15:33.912892000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2865:gst_element_set_state_func:<source> current PAUSED, old_pending VOID_PENDING, next VOID_PENDING, old return SUCCESS

0:15:33.913237000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2899:gst_element_set_state_func:<source> final: setting state from PAUSED to PLAYING

0:15:33.913517000 15216 00000189D4A09000 DEBUG basesrc gstbasesrc.c:3910:gst_base_src_change_state:<source> PAUSED->PLAYING

0:15:33.913749000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2988:gst_element_change_state:<source> element changed state SUCCESS

0:15:33.914035000 15216 00000189D4A09000 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<source> completed state change to PLAYING

0:15:33.907220000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:567:gst_clock_id_wait:<GstSystemClock> done waiting entry 00000189D7F19AB0, res: 1 (early)

0:15:33.915373000 15216 00000189D4A09000 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<source> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending)

0:15:33.915680000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2713:gst_base_sink_do_sync:<sink> clock returned 1, jitter 0:00:00.047838167

0:15:33.916277000 15216 00000189D4A09000 DEBUG GST_BUS gstbus.c:316:gst_bus_post:<bus0> [msg 00000189D8084440] posting on bus state-changed message: 00000189D8084440, time 99:99:99.999999999, seq-num 36, element 'source', GstMessageStateChanged, old-state=(GstState)GST_STATE_PAUSED, new-state=(GstState)GST_STATE_PLAYING, pending-state=(GstState)GST_STATE_VOID_PENDING;

0:15:33.916609000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3029:gst_base_sink_is_too_late:<sink> frame dropping disabled

0:15:33.917895000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3641:gst_base_sink_chain_unlocked:<sink> rendering object 00000189D80805A0

0:15:33.917608000 15216 00000189D4A09000 DEBUG bin gstbin.c:3716:gst_bin_handle_message_func:<my-pipeline1> [msg 00000189D8084440] handling child source message of type state-changed

0:15:33.918609000 15216 00000189D4A09000 DEBUG bin gstbin.c:4053:gst_bin_handle_message_func:<my-pipeline1> posting message upward

0:15:33.918443000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3680:gst_base_sink_chain_unlocked:<sink> object unref after render 00000189D80805A0

0:15:33.918909000 15216 00000189D4A09000 DEBUG GST_BUS gstbus.c:316:gst_bus_post:<bus1> [msg 00000189D8084440] posting on bus state-changed message: 00000189D8084440, time 99:99:99.999999999, seq-num 36, element 'source', GstMessageStateChanged, old-state=(GstState)GST_STATE_PAUSED, new-state=(GstState)GST_STATE_PLAYING, pending-state=(GstState)GST_STATE_VOID_PENDING;

0:15:33.919983000 15216 00000189D4A09000 DEBUG GST_BUS gstbus.c:355:gst_bus_post:<bus1> [msg 00000189D8084440] pushing on async queue

0:15:33.920287000 15216 00000189D4A09000 DEBUG GST_BUS gstbus.c:358:gst_bus_post:<bus1> [msg 00000189D8084440] pushed on async queue

0:15:33.920579000 15216 00000189D4A09000 DEBUG GST_BUS gstbus.c:351:gst_bus_post:<bus0> [msg 00000189D8084440] dropped

0:15:33.919247000 15216 00000189D7EE2F80 DEBUG GST_SCHEDULING gstpad.c:4330:gst_pad_chain_data_unchecked:<sink:sink> called chainfunction &gst_base_sink_chain with buffer 00000189D80805A0, returned ok

0:15:33.921208000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2911:gst_element_set_state_func:<source> returned SUCCESS

0:15:33.921952000 15216 00000189D4A09000 INFO GST_STATES gstbin.c:2951:gst_bin_change_state_func:<my-pipeline1> child 'source' changed state to 4(PLAYING) successfully

0:15:33.922390000 15216 00000189D4A09000 DEBUG bin gstbin.c:2358:gst_bin_sort_iterator_next:<my-pipeline1> queue empty, elements exhausted

0:15:33.922688000 15216 00000189D4A09000 DEBUG GST_STATES gstbin.c:3010:gst_bin_change_state_func:<my-pipeline1> iterator done

0:15:33.922951000 15216 00000189D4A09000 DEBUG bin gstbin.c:2400:gst_bin_sort_iterator_free:<my-pipeline1> free

0:15:33.923249000 15216 00000189D4A09000 DEBUG bin gstbin.c:3045:gst_bin_change_state_func:<my-pipeline1> no async elements

0:15:33.923519000 15216 00000189D4A09000 DEBUG GST_STATES gstbin.c:3079:gst_bin_change_state_func:<my-pipeline1> done changing bin's state from PAUSED to PLAYING, now in PAUSED, ret SUCCESS

0:15:33.923898000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2988:gst_element_change_state:<my-pipeline1> element changed state SUCCESS

0:15:33.921681000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:2521:gst_base_src_get_range:<source> calling create offset 18446744073709551615 length 4096, time 0

0:15:33.924229000 15216 00000189D4A09000 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<my-pipeline1> completed state change to PLAYING

0:15:33.924776000 15216 00000189D7EE2F80 DEBUG videotestsrc gstvideotestsrc.c:1169:gst_video_test_src_fill:<source> Timestamp: 0:00:10.866666666 = accumulated 0:00:00.000000000 + offset: 0:00:00.000000000 + running time: 0:00:10.866666666

0:15:33.924934000 15216 00000189D4A09000 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<my-pipeline1> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending)

0:15:33.925423000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:2375:gst_base_src_do_sync:<source> no sync needed

0:15:33.926072000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:2612:gst_base_src_get_range:<source> buffer ok

0:15:33.925829000 15216 00000189D4A09000 DEBUG GST_BUS gstbus.c:316:gst_bus_post:<bus1> [msg 00000189D80844C0] posting on bus state-changed message: 00000189D80844C0, time 99:99:99.999999999, seq-num 37, element 'my-pipeline1', GstMessageStateChanged, old-state=(GstState)GST_STATE_PAUSED, new-state=(GstState)GST_STATE_PLAYING, pending-state=(GstState)GST_STATE_VOID_PENDING;

0:15:33.927014000 15216 00000189D4A09000 DEBUG GST_BUS gstbus.c:355:gst_bus_post:<bus1> [msg 00000189D80844C0] pushing on async queue

0:15:33.926342000 15216 00000189D7EE2F80 DEBUG GST_SCHEDULING gstpad.c:4324:gst_pad_chain_data_unchecked:<sink:sink> calling chainfunction &gst_base_sink_chain with buffer buffer: 00000189D8080480, pts 0:00:10.866666666, dts 99:99:99.999999999, dur 0:00:00.033333334, size 115200, offset 326, offset_end 327, flags 0x0

0:15:33.927307000 15216 00000189D4A09000 DEBUG GST_BUS gstbus.c:358:gst_bus_post:<bus1> [msg 00000189D80844C0] pushed on async queue

0:15:33.927901000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3524:gst_base_sink_chain_unlocked:<sink> got times start: 0:00:10.866666666, end: 0:00:10.900000000

0:15:33.928535000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2112:gst_base_sink_get_sync_times:<sink> got times start: 0:00:10.866666666, stop: 0:00:10.900000000, do_sync 1

0:15:33.928202000 15216 00000189D4A09000 DEBUG GST_STATES gstbin.c:1968:bin_element_is_sink:<my-pipeline1> child sink is sink

0:15:33.929973000 15216 00000189D4A09000 DEBUG bin gstbin.c:882:find_message:<my-pipeline1> no message found matching types 00000001

0:15:33.930011000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2694:gst_base_sink_do_sync:<sink> reset rc_time to time 0:00:10.866666666

0:15:33.930640000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2706:gst_base_sink_do_sync:<sink> possibly waiting for clock to reach 0:00:10.866666666, adjusted 0:00:10.866666666

0:15:33.930980000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:557:gst_clock_id_wait:<GstSystemClock> waiting on clock entry 00000189D7F19AB0

0:15:33.931282000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1092:gst_clock_get_internal_time:<GstSystemClock> internal time 0:01:25.408409800

0:15:33.930313000 15216 00000189D4A09000 DEBUG bin gstbin.c:889:find_message:<my-pipeline1> eos

0:15:33.931952000 15216 00000189D4A09000 DEBUG bin gstbin.c:995:is_eos: sink 'sink' did not post EOS yet

0:15:33.932228000 15216 00000189D4A09000 DEBUG GST_STATES gstelement.c:2911:gst_element_set_state_func:<my-pipeline1> returned SUCCESS

//开始发送数据

0:15:33.931699000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1137:gst_clock_get_time:<GstSystemClock> adjusted time 0:01:25.408409800

0:15:33.932922000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstsystemclock.c:714:gst_system_clock_id_wait_jitter_unlocked: entry 00000189D7F19AB0 time 0:01:25.368138166 now 0:01:25.408409800 diff (time-now) -40271634

0:15:33.933811000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:567:gst_clock_id_wait:<GstSystemClock> done waiting entry 00000189D7F19AB0, res: 1 (early)

0:15:33.934228000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2713:gst_base_sink_do_sync:<sink> clock returned 1, jitter 0:00:00.040271634

0:15:33.934501000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3029:gst_base_sink_is_too_late:<sink> frame dropping disabled

0:15:33.934750000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3641:gst_base_sink_chain_unlocked:<sink> rendering object 00000189D8080480

0:15:33.935017000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:1014:gst_base_sink_set_last_buffer_unlocked:<sink> setting last buffer to 00000189D8080480

0:15:33.935315000 15216 00000189D7EE2F80 DEBUG GST_BUFFER gstbuffer.c:1448:gst_buffer_is_memory_range_writable: idx 0, length -1

0:15:33.935760000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3680:gst_base_sink_chain_unlocked:<sink> object unref after render 00000189D8080480

0:15:33.936055000 15216 00000189D7EE2F80 DEBUG GST_SCHEDULING gstpad.c:4330:gst_pad_chain_data_unchecked:<sink:sink> called chainfunction &gst_base_sink_chain with buffer 00000189D8080480, returned ok

0:15:33.936455000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:2521:gst_base_src_get_range:<source> calling create offset 18446744073709551615 length 4096, time 0

0:15:33.936910000 15216 00000189D7EE2F80 DEBUG videotestsrc gstvideotestsrc.c:1169:gst_video_test_src_fill:<source> Timestamp: 0:00:10.900000000 = accumulated 0:00:00.000000000 + offset: 0:00:00.000000000 + running time: 0:00:10.900000000

0:15:33.937399000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:2375:gst_base_src_do_sync:<source> no sync needed

0:15:33.937619000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:2612:gst_base_src_get_range:<source> buffer ok

0:15:33.937850000 15216 00000189D7EE2F80 DEBUG GST_SCHEDULING gstpad.c:4324:gst_pad_chain_data_unchecked:<sink:sink> calling chainfunction &gst_base_sink_chain with buffer buffer: 00000189D80805A0, pts 0:00:10.900000000, dts 99:99:99.999999999, dur 0:00:00.033333333, size 115200, offset 327, offset_end 328, flags 0x0

0:15:33.938433000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3524:gst_base_sink_chain_unlocked:<sink> got times start: 0:00:10.900000000, end: 0:00:10.933333333

0:15:33.938743000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2112:gst_base_sink_get_sync_times:<sink> got times start: 0:00:10.900000000, stop: 0:00:10.933333333, do_sync 1

0:15:33.939071000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2694:gst_base_sink_do_sync:<sink> reset rc_time to time 0:00:10.900000000

0:15:33.939377000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2706:gst_base_sink_do_sync:<sink> possibly waiting for clock to reach 0:00:10.900000000, adjusted 0:00:10.900000000

0:15:33.939766000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:557:gst_clock_id_wait:<GstSystemClock> waiting on clock entry 00000189D7F19AB0

0:15:33.940034000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1092:gst_clock_get_internal_time:<GstSystemClock> internal time 0:01:25.417162700

0:15:33.940314000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1137:gst_clock_get_time:<GstSystemClock> adjusted time 0:01:25.417162700

0:15:33.941426000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstsystemclock.c:714:gst_system_clock_id_wait_jitter_unlocked: entry 00000189D7F19AB0 time 0:01:25.401471500 now 0:01:25.417162700 diff (time-now) -15691200

0:15:33.941902000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:567:gst_clock_id_wait:<GstSystemClock> done waiting entry 00000189D7F19AB0, res: 1 (early)

0:15:33.942250000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2713:gst_base_sink_do_sync:<sink> clock returned 1, jitter 0:00:00.015691200

0:15:33.942523000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3029:gst_base_sink_is_too_late:<sink> frame dropping disabled

0:15:33.942766000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3641:gst_base_sink_chain_unlocked:<sink> rendering object 00000189D80805A0

0:15:33.943029000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:1014:gst_base_sink_set_last_buffer_unlocked:<sink> setting last buffer to 00000189D80805A0

0:15:33.943365000 15216 00000189D7EE2F80 DEBUG GST_BUFFER gstbuffer.c:1448:gst_buffer_is_memory_range_writable: idx 0, length -1

0:15:33.943811000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3680:gst_base_sink_chain_unlocked:<sink> object unref after render 00000189D80805A0

0:15:33.944126000 15216 00000189D7EE2F80 DEBUG GST_SCHEDULING gstpad.c:4330:gst_pad_chain_data_unchecked:<sink:sink> called chainfunction &gst_base_sink_chain with buffer 00000189D80805A0, returned ok

0:15:33.944832000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:2521:gst_base_src_get_range:<source> calling create offset 18446744073709551615 length 4096, time 0

0:15:33.945333000 15216 00000189D7EE2F80 DEBUG videotestsrc gstvideotestsrc.c:1169:gst_video_test_src_fill:<source> Timestamp: 0:00:10.933333333 = accumulated 0:00:00.000000000 + offset: 0:00:00.000000000 + running time: 0:00:10.933333333

0:15:33.945752000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:2375:gst_base_src_do_sync:<source> no sync needed

0:15:33.945976000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:2612:gst_base_src_get_range:<source> buffer ok

0:15:33.946248000 15216 00000189D7EE2F80 DEBUG GST_SCHEDULING gstpad.c:4324:gst_pad_chain_data_unchecked:<sink:sink> calling chainfunction &gst_base_sink_chain with buffer buffer: 00000189D8080480, pts 0:00:10.933333333, dts 99:99:99.999999999, dur 0:00:00.033333333, size 115200, offset 328, offset_end 329, flags 0x0

0:15:33.946796000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3524:gst_base_sink_chain_unlocked:<sink> got times start: 0:00:10.933333333, end: 0:00:10.966666666

0:15:33.947141000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2112:gst_base_sink_get_sync_times:<sink> got times start: 0:00:10.933333333, stop: 0:00:10.966666666, do_sync 1

0:15:33.947482000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2694:gst_base_sink_do_sync:<sink> reset rc_time to time 0:00:10.933333333

0:15:33.947755000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2706:gst_base_sink_do_sync:<sink> possibly waiting for clock to reach 0:00:10.933333333, adjusted 0:00:10.933333333

0:15:33.948145000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:557:gst_clock_id_wait:<GstSystemClock> waiting on clock entry 00000189D7F19AB0

0:15:33.948438000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1092:gst_clock_get_internal_time:<GstSystemClock> internal time 0:01:25.425565500

0:15:33.948735000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1137:gst_clock_get_time:<GstSystemClock> adjusted time 0:01:25.425565500

0:15:33.949017000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstsystemclock.c:714:gst_system_clock_id_wait_jitter_unlocked: entry 00000189D7F19AB0 time 0:01:25.434804833 now 0:01:25.425565500 diff (time-now) 9239333

0:15:33.949424000 15216 00000189D7EE2F80 DEBUG GST_POLL gstpoll.c:1414:gst_poll_wait: 00000189D4A06EA0: timeout :0:00:00.009239333

0:15:33.959090000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstsystemclock.c:742:gst_system_clock_id_wait_jitter_unlocked: entry 00000189D7F19AB0 unlocked, status 3, ret 0

0:15:33.959428000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstsystemclock.c:766:gst_system_clock_id_wait_jitter_unlocked: entry 00000189D7F19AB0 unlocked after timeout

0:15:33.959742000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1092:gst_clock_get_internal_time:<GstSystemClock> internal time 0:01:25.436860900

0:15:33.960141000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1137:gst_clock_get_time:<GstSystemClock> adjusted time 0:01:25.436860900

0:15:33.960403000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstsystemclock.c:788:gst_system_clock_id_wait_jitter_unlocked: entry 00000189D7F19AB0 finished, diff -2056067

0:15:33.960702000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:567:gst_clock_id_wait:<GstSystemClock> done waiting entry 00000189D7F19AB0, res: 0 (ok)

0:15:33.961139000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2713:gst_base_sink_do_sync:<sink> clock returned 0, jitter -0:00:00.009239333

0:15:33.961406000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3024:gst_base_sink_is_too_late:<sink> object was scheduled in time

0:15:33.961664000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3641:gst_base_sink_chain_unlocked:<sink> rendering object 00000189D8080480

0:15:33.961933000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:1014:gst_base_sink_set_last_buffer_unlocked:<sink> setting last buffer to 00000189D8080480

0:15:33.962312000 15216 00000189D7EE2F80 DEBUG GST_BUFFER gstbuffer.c:1448:gst_buffer_is_memory_range_writable: idx 0, length -1

0:15:33.962772000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3680:gst_base_sink_chain_unlocked:<sink> object unref after render 00000189D8080480

0:15:33.963087000 15216 00000189D7EE2F80 DEBUG GST_SCHEDULING gstpad.c:4330:gst_pad_chain_data_unchecked:<sink:sink> called chainfunction &gst_base_sink_chain with buffer 00000189D8080480, returned ok

0:15:33.963436000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:2521:gst_base_src_get_range:<source> calling create offset 18446744073709551615 length 4096, time 0

0:15:33.963925000 15216 00000189D7EE2F80 DEBUG videotestsrc gstvideotestsrc.c:1169:gst_video_test_src_fill:<source> Timestamp: 0:00:10.966666666 = accumulated 0:00:00.000000000 + offset: 0:00:00.000000000 + running time: 0:00:10.966666666

0:15:33.964339000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:2375:gst_base_src_do_sync:<source> no sync needed

0:15:33.964565000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:2612:gst_base_src_get_range:<source> buffer ok

0:15:33.964801000 15216 00000189D7EE2F80 DEBUG GST_SCHEDULING gstpad.c:4324:gst_pad_chain_data_unchecked:<sink:sink> calling chainfunction &gst_base_sink_chain with buffer buffer: 00000189D80805A0, pts 0:00:10.966666666, dts 99:99:99.999999999, dur 0:00:00.033333334, size 115200, offset 329, offset_end 330, flags 0x0

0:15:33.965545000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3524:gst_base_sink_chain_unlocked:<sink> got times start: 0:00:10.966666666, end: 0:00:11.000000000

0:15:33.965939000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2112:gst_base_sink_get_sync_times:<sink> got times start: 0:00:10.966666666, stop: 0:00:11.000000000, do_sync 1

0:15:33.966344000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2694:gst_base_sink_do_sync:<sink> reset rc_time to time 0:00:10.966666666

0:15:33.966629000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2706:gst_base_sink_do_sync:<sink> possibly waiting for clock to reach 0:00:10.966666666, adjusted 0:00:10.966666666

0:15:33.967666000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:557:gst_clock_id_wait:<GstSystemClock> waiting on clock entry 00000189D7F19AB0

0:15:33.967945000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1092:gst_clock_get_internal_time:<GstSystemClock> internal time 0:01:25.445071600

0:15:33.968266000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1137:gst_clock_get_time:<GstSystemClock> adjusted time 0:01:25.445071600

0:15:33.968527000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstsystemclock.c:714:gst_system_clock_id_wait_jitter_unlocked: entry 00000189D7F19AB0 time 0:01:25.468138166 now 0:01:25.445071600 diff (time-now) 23066566

0:15:33.968902000 15216 00000189D7EE2F80 DEBUG GST_POLL gstpoll.c:1414:gst_poll_wait: 00000189D4A06EA0: timeout :0:00:00.023066566

0:15:33.992089000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstsystemclock.c:742:gst_system_clock_id_wait_jitter_unlocked: entry 00000189D7F19AB0 unlocked, status 3, ret 0

0:15:33.992523000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstsystemclock.c:766:gst_system_clock_id_wait_jitter_unlocked: entry 00000189D7F19AB0 unlocked after timeout

0:15:33.992876000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1092:gst_clock_get_internal_time:<GstSystemClock> internal time 0:01:25.469998700

0:15:33.993249000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1137:gst_clock_get_time:<GstSystemClock> adjusted time 0:01:25.469998700

0:15:33.993542000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstsystemclock.c:788:gst_system_clock_id_wait_jitter_unlocked: entry 00000189D7F19AB0 finished, diff -1860534

0:15:33.993891000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:567:gst_clock_id_wait:<GstSystemClock> done waiting entry 00000189D7F19AB0, res: 0 (ok)

0:15:33.994287000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2713:gst_base_sink_do_sync:<sink> clock returned 0, jitter -0:00:00.023066566

0:15:33.994615000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3024:gst_base_sink_is_too_late:<sink> object was scheduled in time

0:15:33.994907000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3641:gst_base_sink_chain_unlocked:<sink> rendering object 00000189D80805A0

0:15:33.995249000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:1014:gst_base_sink_set_last_buffer_unlocked:<sink> setting last buffer to 00000189D80805A0

0:15:33.995591000 15216 00000189D7EE2F80 DEBUG GST_BUFFER gstbuffer.c:1448:gst_buffer_is_memory_range_writable: idx 0, length -1

0:15:33.996076000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3680:gst_base_sink_chain_unlocked:<sink> object unref after render 00000189D80805A0

0:15:33.996367000 15216 00000189D7EE2F80 DEBUG GST_SCHEDULING gstpad.c:4330:gst_pad_chain_data_unchecked:<sink:sink> called chainfunction &gst_base_sink_chain with buffer 00000189D80805A0, returned ok

0:15:33.996717000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:2521:gst_base_src_get_range:<source> calling create offset 18446744073709551615 length 4096, time 0

0:15:33.997253000 15216 00000189D7EE2F80 DEBUG videotestsrc gstvideotestsrc.c:1169:gst_video_test_src_fill:<source> Timestamp: 0:00:11.000000000 = accumulated 0:00:00.000000000 + offset: 0:00:00.000000000 + running time: 0:00:11.000000000

0:15:33.997803000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:2375:gst_base_src_do_sync:<source> no sync needed

0:15:33.998069000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:2612:gst_base_src_get_range:<source> buffer ok

0:15:33.998315000 15216 00000189D7EE2F80 DEBUG GST_SCHEDULING gstpad.c:4324:gst_pad_chain_data_unchecked:<sink:sink> calling chainfunction &gst_base_sink_chain with buffer buffer: 00000189D8080480, pts 0:00:11.000000000, dts 99:99:99.999999999, dur 0:00:00.033333333, size 115200, offset 330, offset_end 331, flags 0x0

0:15:33.998955000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3524:gst_base_sink_chain_unlocked:<sink> got times start: 0:00:11.000000000, end: 0:00:11.033333333

0:15:33.999307000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2112:gst_base_sink_get_sync_times:<sink> got times start: 0:00:11.000000000, stop: 0:00:11.033333333, do_sync 1

0:15:33.999634000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2694:gst_base_sink_do_sync:<sink> reset rc_time to time 0:00:11.000000000

0:15:33.999903000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2706:gst_base_sink_do_sync:<sink> possibly waiting for clock to reach 0:00:11.000000000, adjusted 0:00:11.000000000

0:15:34.000319000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:557:gst_clock_id_wait:<GstSystemClock> waiting on clock entry 00000189D7F19AB0

0:15:34.000598000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1092:gst_clock_get_internal_time:<GstSystemClock> internal time 0:01:25.477725800

0:15:34.000874000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1137:gst_clock_get_time:<GstSystemClock> adjusted time 0:01:25.477725800

0:15:34.001175000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstsystemclock.c:714:gst_system_clock_id_wait_jitter_unlocked: entry 00000189D7F19AB0 time 0:01:25.501471500 now 0:01:25.477725800 diff (time-now) 23745700

0:15:34.001556000 15216 00000189D7EE2F80 DEBUG GST_POLL gstpoll.c:1414:gst_poll_wait: 00000189D4A06EA0: timeout :0:00:00.023745700

0:15:34.024902000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstsystemclock.c:742:gst_system_clock_id_wait_jitter_unlocked: entry 00000189D7F19AB0 unlocked, status 3, ret 0

0:15:34.026113000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstsystemclock.c:766:gst_system_clock_id_wait_jitter_unlocked: entry 00000189D7F19AB0 unlocked after timeout

0:15:34.027244000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1092:gst_clock_get_internal_time:<GstSystemClock> internal time 0:01:25.504350700

0:15:34.028053000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1137:gst_clock_get_time:<GstSystemClock> adjusted time 0:01:25.504350700

0:15:34.028755000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstsystemclock.c:788:gst_system_clock_id_wait_jitter_unlocked: entry 00000189D7F19AB0 finished, diff -2879200

0:15:34.029600000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:567:gst_clock_id_wait:<GstSystemClock> done waiting entry 00000189D7F19AB0, res: 0 (ok)

0:15:34.030416000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2713:gst_base_sink_do_sync:<sink> clock returned 0, jitter -0:00:00.023745700

0:15:34.031157000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3024:gst_base_sink_is_too_late:<sink> object was scheduled in time

0:15:34.031906000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3641:gst_base_sink_chain_unlocked:<sink> rendering object 00000189D8080480

0:15:34.032613000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:1014:gst_base_sink_set_last_buffer_unlocked:<sink> setting last buffer to 00000189D8080480

0:15:34.033256000 15216 00000189D7EE2F80 DEBUG GST_BUFFER gstbuffer.c:1448:gst_buffer_is_memory_range_writable: idx 0, length -1

0:15:34.034143000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3680:gst_base_sink_chain_unlocked:<sink> object unref after render 00000189D8080480

0:15:34.034673000 15216 00000189D7EE2F80 DEBUG GST_SCHEDULING gstpad.c:4330:gst_pad_chain_data_unchecked:<sink:sink> called chainfunction &gst_base_sink_chain with buffer 00000189D8080480, returned ok

0:15:34.035318000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:2521:gst_base_src_get_range:<source> calling create offset 18446744073709551615 length 4096, time 0

0:15:34.036157000 15216 00000189D7EE2F80 DEBUG videotestsrc gstvideotestsrc.c:1169:gst_video_test_src_fill:<source> Timestamp: 0:00:11.033333333 = accumulated 0:00:00.000000000 + offset: 0:00:00.000000000 + running time: 0:00:11.033333333

0:15:34.037178000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:2375:gst_base_src_do_sync:<source> no sync needed

0:15:34.037583000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:2612:gst_base_src_get_range:<source> buffer ok

0:15:34.037948000 15216 00000189D7EE2F80 DEBUG GST_SCHEDULING gstpad.c:4324:gst_pad_chain_data_unchecked:<sink:sink> calling chainfunction &gst_base_sink_chain with buffer buffer: 00000189D80805A0, pts 0:00:11.033333333, dts 99:99:99.999999999, dur 0:00:00.033333333, size 115200, offset 331, offset_end 332, flags 0x0

0:15:34.038779000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3524:gst_base_sink_chain_unlocked:<sink> got times start: 0:00:11.033333333, end: 0:00:11.066666666

0:15:34.039261000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2112:gst_base_sink_get_sync_times:<sink> got times start: 0:00:11.033333333, stop: 0:00:11.066666666, do_sync 1

0:15:34.039763000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2694:gst_base_sink_do_sync:<sink> reset rc_time to time 0:00:11.033333333

0:15:34.040180000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2706:gst_base_sink_do_sync:<sink> possibly waiting for clock to reach 0:00:11.033333333, adjusted 0:00:11.033333333

0:15:34.040710000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:557:gst_clock_id_wait:<GstSystemClock> waiting on clock entry 00000189D7F19AB0

0:15:34.041155000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1092:gst_clock_get_internal_time:<GstSystemClock> internal time 0:01:25.518279700

0:15:34.041585000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1137:gst_clock_get_time:<GstSystemClock> adjusted time 0:01:25.518279700

0:15:34.042018000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstsystemclock.c:714:gst_system_clock_id_wait_jitter_unlocked: entry 00000189D7F19AB0 time 0:01:25.534804833 now 0:01:25.518279700 diff (time-now) 16525133

0:15:34.042593000 15216 00000189D7EE2F80 DEBUG GST_POLL gstpoll.c:1414:gst_poll_wait: 00000189D4A06EA0: timeout :0:00:00.016525133

0:15:34.059835000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstsystemclock.c:742:gst_system_clock_id_wait_jitter_unlocked: entry 00000189D7F19AB0 unlocked, status 3, ret 0

0:15:34.060256000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstsystemclock.c:766:gst_system_clock_id_wait_jitter_unlocked: entry 00000189D7F19AB0 unlocked after timeout

0:15:34.060620000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1092:gst_clock_get_internal_time:<GstSystemClock> internal time 0:01:25.537741900

0:15:34.060902000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1137:gst_clock_get_time:<GstSystemClock> adjusted time 0:01:25.537741900

0:15:34.061162000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstsystemclock.c:788:gst_system_clock_id_wait_jitter_unlocked: entry 00000189D7F19AB0 finished, diff -2937067

0:15:34.061578000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:567:gst_clock_id_wait:<GstSystemClock> done waiting entry 00000189D7F19AB0, res: 0 (ok)

0:15:34.061918000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2713:gst_base_sink_do_sync:<sink> clock returned 0, jitter -0:00:00.016525133

0:15:34.062229000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3024:gst_base_sink_is_too_late:<sink> object was scheduled in time

0:15:34.062521000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3641:gst_base_sink_chain_unlocked:<sink> rendering object 00000189D80805A0

0:15:34.062829000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:1014:gst_base_sink_set_last_buffer_unlocked:<sink> setting last buffer to 00000189D80805A0

0:15:34.063170000 15216 00000189D7EE2F80 DEBUG GST_BUFFER gstbuffer.c:1448:gst_buffer_is_memory_range_writable: idx 0, length -1

0:15:34.063644000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3680:gst_base_sink_chain_unlocked:<sink> object unref after render 00000189D80805A0

0:15:34.063969000 15216 00000189D7EE2F80 DEBUG GST_SCHEDULING gstpad.c:4330:gst_pad_chain_data_unchecked:<sink:sink> called chainfunction &gst_base_sink_chain with buffer 00000189D80805A0, returned ok

0:15:34.064318000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:2521:gst_base_src_get_range:<source> calling create offset 18446744073709551615 length 4096, time 0

0:15:34.064786000 15216 00000189D7EE2F80 DEBUG videotestsrc gstvideotestsrc.c:1169:gst_video_test_src_fill:<source> Timestamp: 0:00:11.066666666 = accumulated 0:00:00.000000000 + offset: 0:00:00.000000000 + running time: 0:00:11.066666666

0:15:34.065271000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:2375:gst_base_src_do_sync:<source> no sync needed

0:15:34.065498000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:2612:gst_base_src_get_range:<source> buffer ok

0:15:34.065820000 15216 00000189D7EE2F80 DEBUG GST_SCHEDULING gstpad.c:4324:gst_pad_chain_data_unchecked:<sink:sink> calling chainfunction &gst_base_sink_chain with buffer buffer: 00000189D8080480, pts 0:00:11.066666666, dts 99:99:99.999999999, dur 0:00:00.033333334, size 115200, offset 332, offset_end 333, flags 0x0

0:15:34.066413000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3524:gst_base_sink_chain_unlocked:<sink> got times start: 0:00:11.066666666, end: 0:00:11.100000000

0:15:34.066725000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2112:gst_base_sink_get_sync_times:<sink> got times start: 0:00:11.066666666, stop: 0:00:11.100000000, do_sync 1

0:15:34.067156000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2694:gst_base_sink_do_sync:<sink> reset rc_time to time 0:00:11.066666666

0:15:34.067425000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2706:gst_base_sink_do_sync:<sink> possibly waiting for clock to reach 0:00:11.066666666, adjusted 0:00:11.066666666

0:15:34.067790000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:557:gst_clock_id_wait:<GstSystemClock> waiting on clock entry 00000189D7F19AB0

0:15:34.068075000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1092:gst_clock_get_internal_time:<GstSystemClock> internal time 0:01:25.545203700

0:15:34.068350000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1137:gst_clock_get_time:<GstSystemClock> adjusted time 0:01:25.545203700

0:15:34.068611000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstsystemclock.c:714:gst_system_clock_id_wait_jitter_unlocked: entry 00000189D7F19AB0 time 0:01:25.568138166 now 0:01:25.545203700 diff (time-now) 22934466

0:15:34.069033000 15216 00000189D7EE2F80 DEBUG GST_POLL gstpoll.c:1414:gst_poll_wait: 00000189D4A06EA0: timeout :0:00:00.022934466

0:15:34.091756000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstsystemclock.c:742:gst_system_clock_id_wait_jitter_unlocked: entry 00000189D7F19AB0 unlocked, status 3, ret 0

0:15:34.092173000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstsystemclock.c:766:gst_system_clock_id_wait_jitter_unlocked: entry 00000189D7F19AB0 unlocked after timeout

0:15:34.092524000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1092:gst_clock_get_internal_time:<GstSystemClock> internal time 0:01:25.569647700

0:15:34.092841000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1137:gst_clock_get_time:<GstSystemClock> adjusted time 0:01:25.569647700

0:15:34.093100000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstsystemclock.c:788:gst_system_clock_id_wait_jitter_unlocked: entry 00000189D7F19AB0 finished, diff -1509534

0:15:34.093513000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:567:gst_clock_id_wait:<GstSystemClock> done waiting entry 00000189D7F19AB0, res: 0 (ok)

0:15:34.093882000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2713:gst_base_sink_do_sync:<sink> clock returned 0, jitter -0:00:00.022934466

0:15:34.094190000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3024:gst_base_sink_is_too_late:<sink> object was scheduled in time

0:15:34.094482000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3641:gst_base_sink_chain_unlocked:<sink> rendering object 00000189D8080480

0:15:34.094788000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:1014:gst_base_sink_set_last_buffer_unlocked:<sink> setting last buffer to 00000189D8080480

0:15:34.095128000 15216 00000189D7EE2F80 DEBUG GST_BUFFER gstbuffer.c:1448:gst_buffer_is_memory_range_writable: idx 0, length -1

0:15:34.095607000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3680:gst_base_sink_chain_unlocked:<sink> object unref after render 00000189D8080480

0:15:34.095934000 15216 00000189D7EE2F80 DEBUG GST_SCHEDULING gstpad.c:4330:gst_pad_chain_data_unchecked:<sink:sink> called chainfunction &gst_base_sink_chain with buffer 00000189D8080480, returned ok

0:15:34.096283000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:2521:gst_base_src_get_range:<source> calling create offset 18446744073709551615 length 4096, time 0

0:15:34.096788000 15216 00000189D7EE2F80 DEBUG videotestsrc gstvideotestsrc.c:1169:gst_video_test_src_fill:<source> Timestamp: 0:00:11.100000000 = accumulated 0:00:00.000000000 + offset: 0:00:00.000000000 + running time: 0:00:11.100000000

0:15:34.097257000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:2375:gst_base_src_do_sync:<source> no sync needed

0:15:34.097486000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:2612:gst_base_src_get_range:<source> buffer ok

0:15:34.097765000 15216 00000189D7EE2F80 DEBUG GST_SCHEDULING gstpad.c:4324:gst_pad_chain_data_unchecked:<sink:sink> calling chainfunction &gst_base_sink_chain with buffer buffer: 00000189D80805A0, pts 0:00:11.100000000, dts 99:99:99.999999999, dur 0:00:00.033333333, size 115200, offset 333, offset_end 334, flags 0x0

0:15:34.098326000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3524:gst_base_sink_chain_unlocked:<sink> got times start: 0:00:11.100000000, end: 0:00:11.133333333

0:15:34.098675000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2112:gst_base_sink_get_sync_times:<sink> got times start: 0:00:11.100000000, stop: 0:00:11.133333333, do_sync 1

0:15:34.099113000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2694:gst_base_sink_do_sync:<sink> reset rc_time to time 0:00:11.100000000

0:15:34.099438000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2706:gst_base_sink_do_sync:<sink> possibly waiting for clock to reach 0:00:11.100000000, adjusted 0:00:11.100000000

0:15:34.099774000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:557:gst_clock_id_wait:<GstSystemClock> waiting on clock entry 00000189D7F19AB0

0:15:34.100043000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1092:gst_clock_get_internal_time:<GstSystemClock> internal time 0:01:25.577171700

0:15:34.100318000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1137:gst_clock_get_time:<GstSystemClock> adjusted time 0:01:25.577171700

0:15:34.100578000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstsystemclock.c:714:gst_system_clock_id_wait_jitter_unlocked: entry 00000189D7F19AB0 time 0:01:25.601471500 now 0:01:25.577171700 diff (time-now) 24299800

0:15:34.100997000 15216 00000189D7EE2F80 DEBUG GST_POLL gstpoll.c:1414:gst_poll_wait: 00000189D4A06EA0: timeout :0:00:00.024299800

0:15:34.125614000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstsystemclock.c:742:gst_system_clock_id_wait_jitter_unlocked: entry 00000189D7F19AB0 unlocked, status 3, ret 0

0:15:34.126073000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstsystemclock.c:766:gst_system_clock_id_wait_jitter_unlocked: entry 00000189D7F19AB0 unlocked after timeout

0:15:34.126395000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1092:gst_clock_get_internal_time:<GstSystemClock> internal time 0:01:25.603517400

0:15:34.126857000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1137:gst_clock_get_time:<GstSystemClock> adjusted time 0:01:25.603517400

0:15:34.127115000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstsystemclock.c:788:gst_system_clock_id_wait_jitter_unlocked: entry 00000189D7F19AB0 finished, diff -2045900

0:15:34.127416000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:567:gst_clock_id_wait:<GstSystemClock> done waiting entry 00000189D7F19AB0, res: 0 (ok)

0:15:34.127737000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2713:gst_base_sink_do_sync:<sink> clock returned 0, jitter -0:00:00.024299800

0:15:34.128011000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3024:gst_base_sink_is_too_late:<sink> object was scheduled in time

0:15:34.128261000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3641:gst_base_sink_chain_unlocked:<sink> rendering object 00000189D80805A0

0:15:34.128526000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:1014:gst_base_sink_set_last_buffer_unlocked:<sink> setting last buffer to 00000189D80805A0

0:15:34.128822000 15216 00000189D7EE2F80 DEBUG GST_BUFFER gstbuffer.c:1448:gst_buffer_is_memory_range_writable: idx 0, length -1

0:15:34.129264000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3680:gst_base_sink_chain_unlocked:<sink> object unref after render 00000189D80805A0

0:15:34.129549000 15216 00000189D7EE2F80 DEBUG GST_SCHEDULING gstpad.c:4330:gst_pad_chain_data_unchecked:<sink:sink> called chainfunction &gst_base_sink_chain with buffer 00000189D80805A0, returned ok

0:15:34.129939000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:2521:gst_base_src_get_range:<source> calling create offset 18446744073709551615 length 4096, time 0

0:15:34.130392000 15216 00000189D7EE2F80 DEBUG videotestsrc gstvideotestsrc.c:1169:gst_video_test_src_fill:<source> Timestamp: 0:00:11.133333333 = accumulated 0:00:00.000000000 + offset: 0:00:00.000000000 + running time: 0:00:11.133333333

0:15:34.130843000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:2375:gst_base_src_do_sync:<source> no sync needed

0:15:34.131063000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:2612:gst_base_src_get_range:<source> buffer ok

0:15:34.131293000 15216 00000189D7EE2F80 DEBUG GST_SCHEDULING gstpad.c:4324:gst_pad_chain_data_unchecked:<sink:sink> calling chainfunction &gst_base_sink_chain with buffer buffer: 00000189D8080480, pts 0:00:11.133333333, dts 99:99:99.999999999, dur 0:00:00.033333333, size 115200, offset 334, offset_end 335, flags 0x0

0:15:34.131907000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3524:gst_base_sink_chain_unlocked:<sink> got times start: 0:00:11.133333333, end: 0:00:11.166666666

0:15:34.132272000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2112:gst_base_sink_get_sync_times:<sink> got times start: 0:00:11.133333333, stop: 0:00:11.166666666, do_sync 1

0:15:34.133343000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2694:gst_base_sink_do_sync:<sink> reset rc_time to time 0:00:11.133333333

0:15:34.133672000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2706:gst_base_sink_do_sync:<sink> possibly waiting for clock to reach 0:00:11.133333333, adjusted 0:00:11.133333333

0:15:34.134109000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:557:gst_clock_id_wait:<GstSystemClock> waiting on clock entry 00000189D7F19AB0

0:15:34.134393000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1092:gst_clock_get_internal_time:<GstSystemClock> internal time 0:01:25.611521200

0:15:34.134720000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1137:gst_clock_get_time:<GstSystemClock> adjusted time 0:01:25.611521200

0:15:34.134997000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstsystemclock.c:714:gst_system_clock_id_wait_jitter_unlocked: entry 00000189D7F19AB0 time 0:01:25.634804833 now 0:01:25.611521200 diff (time-now) 23283633

0:15:34.135407000 15216 00000189D7EE2F80 DEBUG GST_POLL gstpoll.c:1414:gst_poll_wait: 00000189D4A06EA0: timeout :0:00:00.023283633

0:15:34.159557000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstsystemclock.c:742:gst_system_clock_id_wait_jitter_unlocked: entry 00000189D7F19AB0 unlocked, status 3, ret 0

0:15:34.160721000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstsystemclock.c:766:gst_system_clock_id_wait_jitter_unlocked: entry 00000189D7F19AB0 unlocked after timeout

0:15:34.161855000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1092:gst_clock_get_internal_time:<GstSystemClock> internal time 0:01:25.638963700

0:15:34.162784000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1137:gst_clock_get_time:<GstSystemClock> adjusted time 0:01:25.638963700

0:15:34.163501000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstsystemclock.c:788:gst_system_clock_id_wait_jitter_unlocked: entry 00000189D7F19AB0 finished, diff -4158867

0:15:34.164324000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:567:gst_clock_id_wait:<GstSystemClock> done waiting entry 00000189D7F19AB0, res: 0 (ok)

0:15:34.167397000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2713:gst_base_sink_do_sync:<sink> clock returned 0, jitter -0:00:00.023283633

0:15:34.168122000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3024:gst_base_sink_is_too_late:<sink> object was scheduled in time

0:15:34.168666000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3641:gst_base_sink_chain_unlocked:<sink> rendering object 00000189D8080480

0:15:34.169241000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:1014:gst_base_sink_set_last_buffer_unlocked:<sink> setting last buffer to 00000189D8080480

0:15:34.169871000 15216 00000189D7EE2F80 DEBUG GST_BUFFER gstbuffer.c:1448:gst_buffer_is_memory_range_writable: idx 0, length -1

0:15:34.170768000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3680:gst_base_sink_chain_unlocked:<sink> object unref after render 00000189D8080480

0:15:34.171297000 15216 00000189D7EE2F80 DEBUG GST_SCHEDULING gstpad.c:4330:gst_pad_chain_data_unchecked:<sink:sink> called chainfunction &gst_base_sink_chain with buffer 00000189D8080480, returned ok

0:15:34.171944000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:2521:gst_base_src_get_range:<source> calling create offset 18446744073709551615 length 4096, time 0

0:15:34.172753000 15216 00000189D7EE2F80 DEBUG videotestsrc gstvideotestsrc.c:1169:gst_video_test_src_fill:<source> Timestamp: 0:00:11.166666666 = accumulated 0:00:00.000000000 + offset: 0:00:00.000000000 + running time: 0:00:11.166666666

0:15:34.173391000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:2375:gst_base_src_do_sync:<source> no sync needed

0:15:34.173735000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:2612:gst_base_src_get_range:<source> buffer ok

0:15:34.174094000 15216 00000189D7EE2F80 DEBUG GST_SCHEDULING gstpad.c:4324:gst_pad_chain_data_unchecked:<sink:sink> calling chainfunction &gst_base_sink_chain with buffer buffer: 00000189D80805A0, pts 0:00:11.166666666, dts 99:99:99.999999999, dur 0:00:00.033333334, size 115200, offset 335, offset_end 336, flags 0x0

0:15:34.174927000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3524:gst_base_sink_chain_unlocked:<sink> got times start: 0:00:11.166666666, end: 0:00:11.200000000

0:15:34.175406000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2112:gst_base_sink_get_sync_times:<sink> got times start: 0:00:11.166666666, stop: 0:00:11.200000000, do_sync 1

0:15:34.175912000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2694:gst_base_sink_do_sync:<sink> reset rc_time to time 0:00:11.166666666

0:15:34.176322000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2706:gst_base_sink_do_sync:<sink> possibly waiting for clock to reach 0:00:11.166666666, adjusted 0:00:11.166666666

0:15:34.176840000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:557:gst_clock_id_wait:<GstSystemClock> waiting on clock entry 00000189D7F19AB0

0:15:34.177253000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1092:gst_clock_get_internal_time:<GstSystemClock> internal time 0:01:25.654379100

0:15:34.177662000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1137:gst_clock_get_time:<GstSystemClock> adjusted time 0:01:25.654379100

0:15:34.178002000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstsystemclock.c:714:gst_system_clock_id_wait_jitter_unlocked: entry 00000189D7F19AB0 time 0:01:25.668138166 now 0:01:25.654379100 diff (time-now) 13759066

0:15:34.178493000 15216 00000189D7EE2F80 DEBUG GST_POLL gstpoll.c:1414:gst_poll_wait: 00000189D4A06EA0: timeout :0:00:00.013759066

0:15:34.192464000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstsystemclock.c:742:gst_system_clock_id_wait_jitter_unlocked: entry 00000189D7F19AB0 unlocked, status 3, ret 0

0:15:34.193662000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstsystemclock.c:766:gst_system_clock_id_wait_jitter_unlocked: entry 00000189D7F19AB0 unlocked after timeout

0:15:34.194912000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1092:gst_clock_get_internal_time:<GstSystemClock> internal time 0:01:25.672014900

0:15:34.196056000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1137:gst_clock_get_time:<GstSystemClock> adjusted time 0:01:25.672014900

0:15:34.196869000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstsystemclock.c:788:gst_system_clock_id_wait_jitter_unlocked: entry 00000189D7F19AB0 finished, diff -3876734

0:15:34.197730000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:567:gst_clock_id_wait:<GstSystemClock> done waiting entry 00000189D7F19AB0, res: 0 (ok)

0:15:34.198808000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2713:gst_base_sink_do_sync:<sink> clock returned 0, jitter -0:00:00.013759066

0:15:34.199524000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3024:gst_base_sink_is_too_late:<sink> object was scheduled in time

0:15:34.200312000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3641:gst_base_sink_chain_unlocked:<sink> rendering object 00000189D80805A0

0:15:34.200927000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:1014:gst_base_sink_set_last_buffer_unlocked:<sink> setting last buffer to 00000189D80805A0

0:15:34.201596000 15216 00000189D7EE2F80 DEBUG GST_BUFFER gstbuffer.c:1448:gst_buffer_is_memory_range_writable: idx 0, length -1

0:15:34.202614000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3680:gst_base_sink_chain_unlocked:<sink> object unref after render 00000189D80805A0

0:15:34.203142000 15216 00000189D7EE2F80 DEBUG GST_SCHEDULING gstpad.c:4330:gst_pad_chain_data_unchecked:<sink:sink> called chainfunction &gst_base_sink_chain with buffer 00000189D80805A0, returned ok

0:15:34.203789000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:2521:gst_base_src_get_range:<source> calling create offset 18446744073709551615 length 4096, time 0

0:15:34.204622000 15216 00000189D7EE2F80 DEBUG videotestsrc gstvideotestsrc.c:1169:gst_video_test_src_fill:<source> Timestamp: 0:00:11.200000000 = accumulated 0:00:00.000000000 + offset: 0:00:00.000000000 + running time: 0:00:11.200000000

0:15:34.205377000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:2375:gst_base_src_do_sync:<source> no sync needed

0:15:34.205781000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:2612:gst_base_src_get_range:<source> buffer ok

0:15:34.206207000 15216 00000189D7EE2F80 DEBUG GST_SCHEDULING gstpad.c:4324:gst_pad_chain_data_unchecked:<sink:sink> calling chainfunction &gst_base_sink_chain with buffer buffer: 00000189D8080480, pts 0:00:11.200000000, dts 99:99:99.999999999, dur 0:00:00.033333333, size 115200, offset 336, offset_end 337, flags 0x0

0:15:34.207204000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3524:gst_base_sink_chain_unlocked:<sink> got times start: 0:00:11.200000000, end: 0:00:11.233333333

0:15:34.207741000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2112:gst_base_sink_get_sync_times:<sink> got times start: 0:00:11.200000000, stop: 0:00:11.233333333, do_sync 1

0:15:34.208239000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2694:gst_base_sink_do_sync:<sink> reset rc_time to time 0:00:11.200000000

0:15:34.208656000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2706:gst_base_sink_do_sync:<sink> possibly waiting for clock to reach 0:00:11.200000000, adjusted 0:00:11.200000000

0:15:34.209169000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:557:gst_clock_id_wait:<GstSystemClock> waiting on clock entry 00000189D7F19AB0

0:15:34.209585000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1092:gst_clock_get_internal_time:<GstSystemClock> internal time 0:01:25.686711000

0:15:34.210012000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1137:gst_clock_get_time:<GstSystemClock> adjusted time 0:01:25.686711000

0:15:34.210417000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstsystemclock.c:714:gst_system_clock_id_wait_jitter_unlocked: entry 00000189D7F19AB0 time 0:01:25.701471500 now 0:01:25.686711000 diff (time-now) 14760500

0:15:34.212113000 15216 00000189D7EE2F80 DEBUG GST_POLL gstpoll.c:1414:gst_poll_wait: 00000189D4A06EA0: timeout :0:00:00.014760500

0:15:34.227329000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstsystemclock.c:742:gst_system_clock_id_wait_jitter_unlocked: entry 00000189D7F19AB0 unlocked, status 3, ret 0

0:15:34.227664000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstsystemclock.c:766:gst_system_clock_id_wait_jitter_unlocked: entry 00000189D7F19AB0 unlocked after timeout

0:15:34.227995000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1092:gst_clock_get_internal_time:<GstSystemClock> internal time 0:01:25.705110500

0:15:34.228411000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1137:gst_clock_get_time:<GstSystemClock> adjusted time 0:01:25.705110500

0:15:34.228680000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstsystemclock.c:788:gst_system_clock_id_wait_jitter_unlocked: entry 00000189D7F19AB0 finished, diff -3639000

0:15:34.229000000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:567:gst_clock_id_wait:<GstSystemClock> done waiting entry 00000189D7F19AB0, res: 0 (ok)

0:15:34.229421000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2713:gst_base_sink_do_sync:<sink> clock returned 0, jitter -0:00:00.014760500

0:15:34.229704000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3024:gst_base_sink_is_too_late:<sink> object was scheduled in time

0:15:34.229967000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3641:gst_base_sink_chain_unlocked:<sink> rendering object 00000189D8080480

0:15:34.230244000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:1014:gst_base_sink_set_last_buffer_unlocked:<sink> setting last buffer to 00000189D8080480

0:15:34.230580000 15216 00000189D7EE2F80 DEBUG GST_BUFFER gstbuffer.c:1448:gst_buffer_is_memory_range_writable: idx 0, length -1

0:15:34.231041000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3680:gst_base_sink_chain_unlocked:<sink> object unref after render 00000189D8080480

0:15:34.231352000 15216 00000189D7EE2F80 DEBUG GST_SCHEDULING gstpad.c:4330:gst_pad_chain_data_unchecked:<sink:sink> called chainfunction &gst_base_sink_chain with buffer 00000189D8080480, returned ok

0:15:34.231728000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:2521:gst_base_src_get_range:<source> calling create offset 18446744073709551615 length 4096, time 0

0:15:34.232207000 15216 00000189D7EE2F80 DEBUG videotestsrc gstvideotestsrc.c:1169:gst_video_test_src_fill:<source> Timestamp: 0:00:11.233333333 = accumulated 0:00:00.000000000 + offset: 0:00:00.000000000 + running time: 0:00:11.233333333

0:15:34.232651000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:2375:gst_base_src_do_sync:<source> no sync needed

0:15:34.232874000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:2612:gst_base_src_get_range:<source> buffer ok

0:15:34.233109000 15216 00000189D7EE2F80 DEBUG GST_SCHEDULING gstpad.c:4324:gst_pad_chain_data_unchecked:<sink:sink> calling chainfunction &gst_base_sink_chain with buffer buffer: 00000189D80805A0, pts 0:00:11.233333333, dts 99:99:99.999999999, dur 0:00:00.033333333, size 115200, offset 337, offset_end 338, flags 0x0

0:15:34.233686000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3524:gst_base_sink_chain_unlocked:<sink> got times start: 0:00:11.233333333, end: 0:00:11.266666666

0:15:34.234005000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2112:gst_base_sink_get_sync_times:<sink> got times start: 0:00:11.233333333, stop: 0:00:11.266666666, do_sync 1

0:15:34.234351000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2694:gst_base_sink_do_sync:<sink> reset rc_time to time 0:00:11.233333333

0:15:34.234634000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2706:gst_base_sink_do_sync:<sink> possibly waiting for clock to reach 0:00:11.233333333, adjusted 0:00:11.233333333

0:15:34.234969000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:557:gst_clock_id_wait:<GstSystemClock> waiting on clock entry 00000189D7F19AB0

0:15:34.235274000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1092:gst_clock_get_internal_time:<GstSystemClock> internal time 0:01:25.712402400

0:15:34.235551000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1137:gst_clock_get_time:<GstSystemClock> adjusted time 0:01:25.712402400

0:15:34.235813000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstsystemclock.c:714:gst_system_clock_id_wait_jitter_unlocked: entry 00000189D7F19AB0 time 0:01:25.734804833 now 0:01:25.712402400 diff (time-now) 22402433

0:15:34.236189000 15216 00000189D7EE2F80 DEBUG GST_POLL gstpoll.c:1414:gst_poll_wait: 00000189D4A06EA0: timeout :0:00:00.022402433

0:15:34.258874000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstsystemclock.c:742:gst_system_clock_id_wait_jitter_unlocked: entry 00000189D7F19AB0 unlocked, status 3, ret 0

0:15:34.259356000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstsystemclock.c:766:gst_system_clock_id_wait_jitter_unlocked: entry 00000189D7F19AB0 unlocked after timeout

0:15:34.259715000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1092:gst_clock_get_internal_time:<GstSystemClock> internal time 0:01:25.736836600

0:15:34.260065000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1137:gst_clock_get_time:<GstSystemClock> adjusted time 0:01:25.736836600

0:15:34.260364000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstsystemclock.c:788:gst_system_clock_id_wait_jitter_unlocked: entry 00000189D7F19AB0 finished, diff -2031767

0:15:34.260709000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:567:gst_clock_id_wait:<GstSystemClock> done waiting entry 00000189D7F19AB0, res: 0 (ok)

0:15:34.261070000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2713:gst_base_sink_do_sync:<sink> clock returned 0, jitter -0:00:00.022402433

0:15:34.261382000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3024:gst_base_sink_is_too_late:<sink> object was scheduled in time

0:15:34.261682000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3641:gst_base_sink_chain_unlocked:<sink> rendering object 00000189D80805A0

0:15:34.262018000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:1014:gst_base_sink_set_last_buffer_unlocked:<sink> setting last buffer to 00000189D80805A0

0:15:34.262361000 15216 00000189D7EE2F80 DEBUG GST_BUFFER gstbuffer.c:1448:gst_buffer_is_memory_range_writable: idx 0, length -1

0:15:34.262842000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3680:gst_base_sink_chain_unlocked:<sink> object unref after render 00000189D80805A0

0:15:34.263168000 15216 00000189D7EE2F80 DEBUG GST_SCHEDULING gstpad.c:4330:gst_pad_chain_data_unchecked:<sink:sink> called chainfunction &gst_base_sink_chain with buffer 00000189D80805A0, returned ok

0:15:34.263527000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:2521:gst_base_src_get_range:<source> calling create offset 18446744073709551615 length 4096, time 0

0:15:34.264033000 15216 00000189D7EE2F80 DEBUG videotestsrc gstvideotestsrc.c:1169:gst_video_test_src_fill:<source> Timestamp: 0:00:11.266666666 = accumulated 0:00:00.000000000 + offset: 0:00:00.000000000 + running time: 0:00:11.266666666

0:15:34.264654000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:2375:gst_base_src_do_sync:<source> no sync needed

0:15:34.265064000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:2612:gst_base_src_get_range:<source> buffer ok

0:15:34.265309000 15216 00000189D7EE2F80 DEBUG GST_SCHEDULING gstpad.c:4324:gst_pad_chain_data_unchecked:<sink:sink> calling chainfunction &gst_base_sink_chain with buffer buffer: 00000189D8080480, pts 0:00:11.266666666, dts 99:99:99.999999999, dur 0:00:00.033333334, size 115200, offset 338, offset_end 339, flags 0x0

0:15:34.265995000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3524:gst_base_sink_chain_unlocked:<sink> got times start: 0:00:11.266666666, end: 0:00:11.300000000

0:15:34.266309000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2112:gst_base_sink_get_sync_times:<sink> got times start: 0:00:11.266666666, stop: 0:00:11.300000000, do_sync 1

0:15:34.266636000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2694:gst_base_sink_do_sync:<sink> reset rc_time to time 0:00:11.266666666

0:15:34.266918000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2706:gst_base_sink_do_sync:<sink> possibly waiting for clock to reach 0:00:11.266666666, adjusted 0:00:11.266666666

0:15:34.267260000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:557:gst_clock_id_wait:<GstSystemClock> waiting on clock entry 00000189D7F19AB0

0:15:34.267600000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1092:gst_clock_get_internal_time:<GstSystemClock> internal time 0:01:25.744728300

0:15:34.267907000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1137:gst_clock_get_time:<GstSystemClock> adjusted time 0:01:25.744728300

0:15:34.268178000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstsystemclock.c:714:gst_system_clock_id_wait_jitter_unlocked: entry 00000189D7F19AB0 time 0:01:25.768138166 now 0:01:25.744728300 diff (time-now) 23409866

0:15:34.268561000 15216 00000189D7EE2F80 DEBUG GST_POLL gstpoll.c:1414:gst_poll_wait: 00000189D4A06EA0: timeout :0:00:00.023409866

0:15:34.291841000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstsystemclock.c:742:gst_system_clock_id_wait_jitter_unlocked: entry 00000189D7F19AB0 unlocked, status 3, ret 0

0:15:34.293370000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstsystemclock.c:766:gst_system_clock_id_wait_jitter_unlocked: entry 00000189D7F19AB0 unlocked after timeout

0:15:34.294725000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1092:gst_clock_get_internal_time:<GstSystemClock> internal time 0:01:25.771829500

0:15:34.296025000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1137:gst_clock_get_time:<GstSystemClock> adjusted time 0:01:25.771829500

0:15:34.297160000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstsystemclock.c:788:gst_system_clock_id_wait_jitter_unlocked: entry 00000189D7F19AB0 finished, diff -3691334

0:15:34.298328000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:567:gst_clock_id_wait:<GstSystemClock> done waiting entry 00000189D7F19AB0, res: 0 (ok)

0:15:34.299247000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2713:gst_base_sink_do_sync:<sink> clock returned 0, jitter -0:00:00.023409866

0:15:34.300227000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3024:gst_base_sink_is_too_late:<sink> object was scheduled in time

0:15:34.300896000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3641:gst_base_sink_chain_unlocked:<sink> rendering object 00000189D8080480

0:15:34.301592000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:1014:gst_base_sink_set_last_buffer_unlocked:<sink> setting last buffer to 00000189D8080480

0:15:34.302382000 15216 00000189D7EE2F80 DEBUG GST_BUFFER gstbuffer.c:1448:gst_buffer_is_memory_range_writable: idx 0, length -1

0:15:34.303705000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3680:gst_base_sink_chain_unlocked:<sink> object unref after render 00000189D8080480

0:15:34.304305000 15216 00000189D7EE2F80 DEBUG GST_SCHEDULING gstpad.c:4330:gst_pad_chain_data_unchecked:<sink:sink> called chainfunction &gst_base_sink_chain with buffer 00000189D8080480, returned ok

0:15:34.305035000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:2521:gst_base_src_get_range:<source> calling create offset 18446744073709551615 length 4096, time 0

0:15:34.305972000 15216 00000189D7EE2F80 DEBUG videotestsrc gstvideotestsrc.c:1169:gst_video_test_src_fill:<source> Timestamp: 0:00:11.300000000 = accumulated 0:00:00.000000000 + offset: 0:00:00.000000000 + running time: 0:00:11.300000000

0:15:34.306888000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:2375:gst_base_src_do_sync:<source> no sync needed

0:15:34.307351000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:2612:gst_base_src_get_range:<source> buffer ok

0:15:34.307794000 15216 00000189D7EE2F80 DEBUG GST_SCHEDULING gstpad.c:4324:gst_pad_chain_data_unchecked:<sink:sink> calling chainfunction &gst_base_sink_chain with buffer buffer: 00000189D80805A0, pts 0:00:11.300000000, dts 99:99:99.999999999, dur 0:00:00.033333333, size 115200, offset 339, offset_end 340, flags 0x0

0:15:34.308715000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3524:gst_base_sink_chain_unlocked:<sink> got times start: 0:00:11.300000000, end: 0:00:11.333333333

0:15:34.309245000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2112:gst_base_sink_get_sync_times:<sink> got times start: 0:00:11.300000000, stop: 0:00:11.333333333, do_sync 1

0:15:34.309805000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2694:gst_base_sink_do_sync:<sink> reset rc_time to time 0:00:11.300000000

0:15:34.310254000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2706:gst_base_sink_do_sync:<sink> possibly waiting for clock to reach 0:00:11.300000000, adjusted 0:00:11.300000000

0:15:34.310815000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:557:gst_clock_id_wait:<GstSystemClock> waiting on clock entry 00000189D7F19AB0

0:15:34.311278000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1092:gst_clock_get_internal_time:<GstSystemClock> internal time 0:01:25.788403400

0:15:34.311744000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1137:gst_clock_get_time:<GstSystemClock> adjusted time 0:01:25.788403400

0:15:34.312180000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstsystemclock.c:714:gst_system_clock_id_wait_jitter_unlocked: entry 00000189D7F19AB0 time 0:01:25.801471500 now 0:01:25.788403400 diff (time-now) 13068100

0:15:34.312773000 15216 00000189D7EE2F80 DEBUG GST_POLL gstpoll.c:1414:gst_poll_wait: 00000189D4A06EA0: timeout :0:00:00.013068100

0:15:34.326754000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstsystemclock.c:742:gst_system_clock_id_wait_jitter_unlocked: entry 00000189D7F19AB0 unlocked, status 3, ret 0

0:15:34.327217000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstsystemclock.c:766:gst_system_clock_id_wait_jitter_unlocked: entry 00000189D7F19AB0 unlocked after timeout

0:15:34.327577000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1092:gst_clock_get_internal_time:<GstSystemClock> internal time 0:01:25.804699500

0:15:34.327893000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1137:gst_clock_get_time:<GstSystemClock> adjusted time 0:01:25.804699500

0:15:34.328157000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstsystemclock.c:788:gst_system_clock_id_wait_jitter_unlocked: entry 00000189D7F19AB0 finished, diff -3228000

0:15:34.328585000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:567:gst_clock_id_wait:<GstSystemClock> done waiting entry 00000189D7F19AB0, res: 0 (ok)

0:15:34.328959000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2713:gst_base_sink_do_sync:<sink> clock returned 0, jitter -0:00:00.013068100

0:15:34.329277000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3024:gst_base_sink_is_too_late:<sink> object was scheduled in time

0:15:34.329570000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3641:gst_base_sink_chain_unlocked:<sink> rendering object 00000189D80805A0

0:15:34.329917000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:1014:gst_base_sink_set_last_buffer_unlocked:<sink> setting last buffer to 00000189D80805A0

0:15:34.330256000 15216 00000189D7EE2F80 DEBUG GST_BUFFER gstbuffer.c:1448:gst_buffer_is_memory_range_writable: idx 0, length -1

0:15:34.330741000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3680:gst_base_sink_chain_unlocked:<sink> object unref after render 00000189D80805A0

0:15:34.331027000 15216 00000189D7EE2F80 DEBUG GST_SCHEDULING gstpad.c:4330:gst_pad_chain_data_unchecked:<sink:sink> called chainfunction &gst_base_sink_chain with buffer 00000189D80805A0, returned ok

0:15:34.331378000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:2521:gst_base_src_get_range:<source> calling create offset 18446744073709551615 length 4096, time 0

0:15:34.331885000 15216 00000189D7EE2F80 DEBUG videotestsrc gstvideotestsrc.c:1169:gst_video_test_src_fill:<source> Timestamp: 0:00:11.333333333 = accumulated 0:00:00.000000000 + offset: 0:00:00.000000000 + running time: 0:00:11.333333333

0:15:34.332393000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:2375:gst_base_src_do_sync:<source> no sync needed

0:15:34.332761000 15216 00000189D7EE2F80 DEBUG basesrc gstbasesrc.c:2612:gst_base_src_get_range:<source> buffer ok

0:15:34.333002000 15216 00000189D7EE2F80 DEBUG GST_SCHEDULING gstpad.c:4324:gst_pad_chain_data_unchecked:<sink:sink> calling chainfunction &gst_base_sink_chain with buffer buffer: 00000189D8080480, pts 0:00:11.333333333, dts 99:99:99.999999999, dur 0:00:00.033333333, size 115200, offset 340, offset_end 341, flags 0x0

0:15:34.333564000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:3524:gst_base_sink_chain_unlocked:<sink> got times start: 0:00:11.333333333, end: 0:00:11.366666666

0:15:34.333918000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2112:gst_base_sink_get_sync_times:<sink> got times start: 0:00:11.333333333, stop: 0:00:11.366666666, do_sync 1

0:15:34.334245000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2694:gst_base_sink_do_sync:<sink> reset rc_time to time 0:00:11.333333333

0:15:34.334509000 15216 00000189D7EE2F80 DEBUG basesink gstbasesink.c:2706:gst_base_sink_do_sync:<sink> possibly waiting for clock to reach 0:00:11.333333333, adjusted 0:00:11.333333333

0:15:34.334865000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:557:gst_clock_id_wait:<GstSystemClock> waiting on clock entry 00000189D7F19AB0

0:15:34.335195000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1092:gst_clock_get_internal_time:<GstSystemClock> internal time 0:01:25.812324100

0:15:34.335486000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstclock.c:1137:gst_clock_get_time:<GstSystemClock> adjusted time 0:01:25.812324100

0:15:34.335775000 15216 00000189D7EE2F80 DEBUG GST_CLOCK gstsystemclock.c:714:gst_system_clock_id_wait_jitter_unlocked: entry 00000189D7F19AB0 time 0:01:25.834804833 now 0:01:25.812324100 diff (time-now) 22480733

0:15:34.336153000 15216 00000189D7EE2F80 DEBUG GST_POLL gstpoll.c:1414:gst_poll_wait: 00000189D4A06EA0: timeout :0:00:00.022480733