Fwd: gst_pipeline_set_clock() doesn't take effect
Halley Zhao
aihua.halley.zhao at gmail.com
Mon May 20 02:23:30 UTC 2019
Hi Expert:
I created my customized pipeline as
"appsrc-->h264parse-->v4l2h264dec-->waylandsink".
then I try to use my customized clock to control the video playback (in
fact, I used the above pipeline inside a bigger/complete pipeline).
however, I found gst_pipeline_set_clock() doens't work for me.
I call gst_pipeline_set_clock() before setting the pipeline to PLAYING
state, and gst logs shows it take effect (the clock is set to each
element); but when the pipeline changed state to
PAUSED, gst_bin_provide_clock_func() return NULL (it is strange),
and gst_system_clock_obtain() is called to update the clock.
I'm not sure whether there is something wrong in my code, or potential
mistake in gst base code.
here is my sample code and gst logs(GST_DEBUG=*:6).
I filtered the log with 'clock' as key word as attachment since it is big.
the piece log with context is as following:
17526 0:00:00.750638375 8744 0xffffa4002580 DEBUG GST_BUS
gstbus.c:839:gst_bus_source_dispatch:<bus1> source 0x3d21dc00 calling
dispatch with state-changed message: 0xffff9c003400, time
99:99:99.999999999, seq-num 43, element 'my_pipeline',
GstMessageStateChanged, old-state=(GstState)GST_STATE_READY,
new-state=(GstState)GST_STATE_PAUSED,
pending-state=(GstState)GST_STATE_PLAYING;
17527 (bus_call, 87)my_pipeline state change, old state: READY, new state:
PAUSED
17528 0:00:00.750744875 8744 0x3d233770 DEBUG GST_BUS
gstbus.c:360:gst_bus_post:<bus1> [msg 0xffff9c003380] pushed on async queue
17529 0:00:00.750781500 8744 0xffffa4002580 LOG GST_MESSAGE
gstmessage.c:208:_gst_message_free: finalize message 0xffff9c003400,
state-changed from my_pipeline
17530 0:00:00.750810750 8744 0x3d233770 DEBUG bin
gstbin.c:3484:bin_handle_async_done:<my_pipeline> all async-done, starting
state continue
17531 0:00:00.750875750 8744 0xffffa4002580 DEBUG GST_BUS
gstbus.c:844:gst_bus_source_dispatch:<bus1> source 0x3d21dc00 handler
returns 1
17532 0:00:00.750890750 8744 0x3d233770 DEBUG bin
gstbin.c:3289:bin_push_state_continue:<my_pipeline> pushing continue on
thread pool
17533 0:00:00.750950875 8744 0xffffa4002580 LOG GST_BUS
gstbus.c:522:gst_bus_timed_pop_filtered:<bus1> have 1 messages
17534 0:00:00.750982000 8744 0xffffa4002580 LOG GST_POLL
gstpoll.c:314:release_wakeup: 0x3d154a30: release
17535 0:00:00.751025375 8744 0xffffa4002580 DEBUG GST_BUS
gstbus.c:546:gst_bus_timed_pop_filtered:<bus1> got message 0xffff9c003380,
async-done from my_pipeline, type mask is 4294967295
17536 0:00:00.751072625 8744 0xffffa4002580 DEBUG GST_BUS
gstbus.c:839:gst_bus_source_dispatch:<bus1> source 0x3d21dc00 calling
dispatch with async-done message: 0xffff9c003380, time 99:99:99.999999999,
seq-num 42, element 'my_pipeline',
GstMessageAsyncDone, running-time=(guint64)18446744073709551615;
17537 0:00:00.751152000 8744 0xffffa4002580 LOG GST_MESSAGE
gstmessage.c:208:_gst_message_free: finalize message 0xffff9c003380,
async-done from my_pipeline
17538 0:00:00.751184000 8744 0x3d233770 DEBUG GST_BUS
gstbus.c:353:gst_bus_post:<bus0> [msg 0xffff9c003300] dropped
17539 0:00:00.751197000 8744 0xffffa4002580 DEBUG GST_BUS
gstbus.c:844:gst_bus_source_dispatch:<bus1> source 0x3d21dc00 handler
returns 1
17540 0:00:00.751258000 8744 0x3d233770 DEBUG basesink
gstbasesink.c:2265:gst_base_sink_wait_preroll:<my_sink> waiting in preroll
for flush or PLAYING
17541 0:00:00.751328500 8744 0xffff9c007680 DEBUG bin
gstbin.c:3224:gst_bin_continue_func:<my_pipeline> waiting for state lock
17542 0:00:00.751413500 8744 0xffff9c007680 DEBUG bin
gstbin.c:3227:gst_bin_continue_func:<my_pipeline> doing state continue
17543 0:00:00.751454875 8744 0xffff9c007680 INFO GST_STATES
gstbin.c:3248:gst_bin_continue_func:<my_pipeline> continue state change
PAUSED to PLAYING, final PLAYING
17544 0:00:00.751511250 8744 0xffff9c007680 DEBUG pipeline
gstpipeline.c:412:gst_pipeline_change_state:<my_pipeline> selecting clock
and base_time
17545 0:00:00.751552375 8744 0xffff9c007680 DEBUG pipeline
gstpipeline.c:433:gst_pipeline_change_state:<my_pipeline> Need to update
start_time
17546 0:00:00.751589625 8744 0xffff9c007680 DEBUG pipeline
gstpipeline.c:438:gst_pipeline_change_state:<my_pipeline> Need to update
clock.
17547 0:00:00.751628875 8744 0xffff9c007680 DEBUG bin
gstbin.c:837:gst_bin_provide_clock_func:<my_pipeline> returning old clock
(nil)
17548 0:00:00.751669875 8744 0xffff9c007680 DEBUG GST_CLOCK
gstsystemclock.c:353:gst_system_clock_obtain: creating new static system
clock
17549 0:00:00.751782500 8744 0xffff9c007680 DEBUG GST_POLL
gstpoll.c:681:gst_poll_new: 0xffffa0003c00: new controllable : 1
17550 0:00:00.751897750 8744 0xffff9c007680 DEBUG GST_POLL
gstpoll.c:848:gst_poll_add_fd_unlocked: 0xffffa0003c00: fd (fd:120, idx:0)
17551 0:00:00.751948625 8744 0xffff9c007680 DEBUG GST_POLL
gstpoll.c:1015:gst_poll_fd_ctl_read_unlocked: 0xffffa0003c00: fd (fd:120,
idx:0), active : 1
17552 0:00:00.752028625 8744 0xffff9c007680 DEBUG GST_CLOCK
gstpipeline.c:732:gst_pipeline_provide_clock_func: pipeline obtained system
clock: 0xffffa0002160 (GstSystemClock)
17553 0:00:00.752084500 8744 0xffff9c007680 DEBUG GST_CLOCK
gstclock.c:1046:gst_clock_get_internal_time:<GstSystemClock> internal time
0:15:45.099030375
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.freedesktop.org/archives/gstreamer-devel/attachments/20190520/dd3ec18d/attachment-0001.html>
-------------- next part --------------
0:00:00.432944500 8744 0x3d0a0600 DEBUG GST_CLOCK gstelement.c:429:gst_element_set_clock:<my_appsrc> setting clock (nil)
0:00:00.433366250 8744 0x3d0a0600 DEBUG GST_CLOCK gstelement.c:429:gst_element_set_clock:<my_h264parse> setting clock (nil)
0:00:00.433700500 8744 0x3d0a0600 DEBUG GST_CLOCK gstelement.c:429:gst_element_set_clock:<my_vdec> setting clock (nil)
0:00:00.434029375 8744 0x3d0a0600 DEBUG GST_CLOCK gstelement.c:429:gst_element_set_clock:<my_sink> setting clock (nil)
0:00:00.443746125 8744 0x3d0a0600 LOG GST_DEBUG gstinfo.c:1595:gst_debug_reset_threshold: category audioclock matches pattern 0x3d0a0430 - gets set to level 6
0:00:00.444003875 8744 0x3d0a0600 DEBUG audioclock gstaudioclock.c:70:gst_audio_clock_init:<GstAudioClock at 0x3d22c0d0> init
0:00:00.444043000 8744 0x3d0a0600 DEBUG GST_CLOCK gstsystemclock.c:270:gst_system_clock_set_property: clock-type set to 2
0:00:00.444105375 8744 0x3d0a0600 DEBUG audioclock gstaudioclock.c:144:gst_audio_clock_reset:<MyClock> reset clock to 0:00:00.000000000, last 0:00:00.000000000, offset +0:00:00.000000000
0:00:00.444168125 8744 0x3d0a0600 DEBUG GST_CLOCK gstelement.c:429:gst_element_set_clock:<my_sink> setting clock 0x3d22c0d0
0:00:00.444201125 8744 0x3d0a0600 DEBUG GST_CLOCK gstelement.c:429:gst_element_set_clock:<my_vdec> setting clock 0x3d22c0d0
0:00:00.444231125 8744 0x3d0a0600 DEBUG GST_CLOCK gstelement.c:429:gst_element_set_clock:<my_h264parse> setting clock 0x3d22c0d0
0:00:00.444262500 8744 0x3d0a0600 DEBUG GST_CLOCK gstelement.c:429:gst_element_set_clock:<my_appsrc> setting clock 0x3d22c0d0
0:00:00.444291000 8744 0x3d0a0600 DEBUG bin gstbin.c:726:gst_bin_set_clock_func:<my_pipeline> iterator done
0:00:00.751511250 8744 0xffff9c007680 DEBUG pipeline gstpipeline.c:412:gst_pipeline_change_state:<my_pipeline> selecting clock and base_time
0:00:00.751589625 8744 0xffff9c007680 DEBUG pipeline gstpipeline.c:438:gst_pipeline_change_state:<my_pipeline> Need to update clock.
0:00:00.751628875 8744 0xffff9c007680 DEBUG bin gstbin.c:837:gst_bin_provide_clock_func:<my_pipeline> returning old clock (nil)
0:00:00.751669875 8744 0xffff9c007680 DEBUG GST_CLOCK gstsystemclock.c:353:gst_system_clock_obtain: creating new static system clock
0:00:00.752028625 8744 0xffff9c007680 DEBUG GST_CLOCK gstpipeline.c:732:gst_pipeline_provide_clock_func: pipeline obtained system clock: 0xffffa0002160 (GstSystemClock)
0:00:00.752084500 8744 0xffff9c007680 DEBUG GST_CLOCK gstclock.c:1046:gst_clock_get_internal_time:<GstSystemClock> internal time 0:15:45.099030375
0:00:00.752163000 8744 0xffff9c007680 DEBUG GST_CLOCK gstclock.c:1091:gst_clock_get_time:<GstSystemClock> adjusted time 0:15:45.099030375
0:00:00.752213000 8744 0xffff9c007680 DEBUG GST_CLOCK gstelement.c:429:gst_element_set_clock:<my_pipeline> setting clock 0xffffa0002160
0:00:00.752337000 8744 0xffff9c007680 DEBUG GST_CLOCK gstelement.c:429:gst_element_set_clock:<my_sink> setting clock 0xffffa0002160
0:00:00.752399000 8744 0xffff9c007680 DEBUG GST_CLOCK gstelement.c:429:gst_element_set_clock:<my_vdec> setting clock 0xffffa0002160
0:00:00.752453500 8744 0xffff9c007680 DEBUG GST_CLOCK gstelement.c:429:gst_element_set_clock:<my_h264parse> setting clock 0xffffa0002160
0:00:00.752513875 8744 0xffff9c007680 DEBUG GST_CLOCK gstelement.c:429:gst_element_set_clock:<my_appsrc> setting clock 0xffffa0002160
0:00:00.752561125 8744 0xffff9c007680 DEBUG bin gstbin.c:726:gst_bin_set_clock_func:<my_pipeline> iterator done
0:00:00.752634125 8744 0xffff9c007680 LOG GST_MESSAGE gstmessage.c:301:gst_message_new_custom: source my_pipeline: creating new message 0xffff9c003600 new-clock
0:00:00.752697375 8744 0xffff9c007680 DEBUG GST_BUS gstbus.c:318:gst_bus_post:<bus1> [msg 0xffff9c003600] posting on bus new-clock message: 0xffff9c003600, time 99:99:99.999999999, seq-num 44, element 'my_pipeline', GstMessageNewClock, clock=(GstClock)"\(GstSystemClock\)\ GstSystemClock";
0:00:00.754459125 8744 0xffffa4002580 DEBUG GST_BUS gstbus.c:546:gst_bus_timed_pop_filtered:<bus1> got message 0xffff9c003600, new-clock from my_pipeline, type mask is 4294967295
0:00:00.754521125 8744 0xffffa4002580 DEBUG GST_BUS gstbus.c:839:gst_bus_source_dispatch:<bus1> source 0x3d21dc00 calling dispatch with new-clock message: 0xffff9c003600, time 99:99:99.999999999, seq-num 44, element 'my_pipeline', GstMessageNewClock, clock=(GstClock)"\(GstSystemClock\)\ GstSystemClock";
0:00:00.754704000 8744 0xffffa4002580 LOG GST_MESSAGE gstmessage.c:208:_gst_message_free: finalize message 0xffff9c003600, new-clock from my_pipeline
0:00:00.762198250 8744 0x3d233770 DEBUG basesink gstbasesink.c:2603:gst_base_sink_do_sync:<my_sink> possibly waiting for clock to reach 0:00:00.000000000, adjusted 0:00:00.000000000
0:00:00.762294750 8744 0x3d233770 LOG basesink gstbasesink.c:2177:gst_base_sink_wait_clock:<my_sink> time 0:00:00.000000000, base_time 0:15:45.099030375
0:00:00.762386125 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:249:gst_clock_entry_new:<GstSystemClock> created entry 0xffffa4008580, time 0:15:45.099030375
0:00:00.762453000 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:537:gst_clock_id_wait:<GstSystemClock> waiting on clock entry 0xffffa4008580
0:00:00.762487500 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:1046:gst_clock_get_internal_time:<GstSystemClock> internal time 0:15:45.109439875
0:00:00.762524875 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:1091:gst_clock_get_time:<GstSystemClock> adjusted time 0:15:45.109439875
0:00:00.762555750 8744 0x3d233770 DEBUG GST_CLOCK gstsystemclock.c:718:gst_system_clock_id_wait_jitter_unlocked: entry 0xffffa4008580 time 0:15:45.099030375 now 0:15:45.109439875 diff (time-now) -10409500
0:00:00.762642125 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:547:gst_clock_id_wait:<GstSystemClock> done waiting entry 0xffffa4008580, res: 1 (early)
0:00:00.762721375 8744 0x3d233770 DEBUG basesink gstbasesink.c:2610:gst_base_sink_do_sync:<my_sink> clock returned 1, jitter 0:00:00.010409500
0:00:00.775023250 8744 0x3d233770 DEBUG basesink gstbasesink.c:2603:gst_base_sink_do_sync:<my_sink> possibly waiting for clock to reach 0:00:00.500000000, adjusted 0:00:00.500000000
0:00:00.775066250 8744 0x3d233770 LOG basesink gstbasesink.c:2177:gst_base_sink_wait_clock:<my_sink> time 0:00:00.500000000, base_time 0:15:45.099030375
0:00:00.775204125 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:537:gst_clock_id_wait:<GstSystemClock> waiting on clock entry 0xffffa4008580
0:00:00.775258375 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:1046:gst_clock_get_internal_time:<GstSystemClock> internal time 0:15:45.122210125
0:00:00.775362750 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:1091:gst_clock_get_time:<GstSystemClock> adjusted time 0:15:45.122210125
0:00:00.775421250 8744 0x3d233770 DEBUG GST_CLOCK gstsystemclock.c:718:gst_system_clock_id_wait_jitter_unlocked: entry 0xffffa4008580 time 0:15:45.599030375 now 0:15:45.122210125 diff (time-now) 476820250
0:00:01.252879125 8744 0x3d233770 DEBUG GST_CLOCK gstsystemclock.c:746:gst_system_clock_id_wait_jitter_unlocked: entry 0xffffa4008580 unlocked, status 3, ret 0
0:00:01.252991250 8744 0x3d233770 DEBUG GST_CLOCK gstsystemclock.c:770:gst_system_clock_id_wait_jitter_unlocked: entry 0xffffa4008580 unlocked after timeout
0:00:01.253131000 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:1046:gst_clock_get_internal_time:<GstSystemClock> internal time 0:15:45.600056750
0:00:01.253205000 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:1091:gst_clock_get_time:<GstSystemClock> adjusted time 0:15:45.600056750
0:00:01.253260500 8744 0x3d233770 DEBUG GST_CLOCK gstsystemclock.c:792:gst_system_clock_id_wait_jitter_unlocked: entry 0xffffa4008580 finished, diff -1026375
0:00:01.253319625 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:547:gst_clock_id_wait:<GstSystemClock> done waiting entry 0xffffa4008580, res: 0 (ok)
0:00:01.253388375 8744 0x3d233770 DEBUG basesink gstbasesink.c:2610:gst_base_sink_do_sync:<my_sink> clock returned 0, jitter -0:00:00.476820250
0:00:01.262417500 8744 0x3d233770 DEBUG basesink gstbasesink.c:2603:gst_base_sink_do_sync:<my_sink> possibly waiting for clock to reach 0:00:01.000000000, adjusted 0:00:01.000000000
0:00:01.262542000 8744 0x3d233770 LOG basesink gstbasesink.c:2177:gst_base_sink_wait_clock:<my_sink> time 0:00:01.000000000, base_time 0:15:45.099030375
0:00:01.262666500 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:537:gst_clock_id_wait:<GstSystemClock> waiting on clock entry 0xffffa4008580
0:00:01.262727375 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:1046:gst_clock_get_internal_time:<GstSystemClock> internal time 0:15:45.609674125
0:00:01.262809500 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:1091:gst_clock_get_time:<GstSystemClock> adjusted time 0:15:45.609674125
0:00:01.262866125 8744 0x3d233770 DEBUG GST_CLOCK gstsystemclock.c:718:gst_system_clock_id_wait_jitter_unlocked: entry 0xffffa4008580 time 0:15:46.099030375 now 0:15:45.609674125 diff (time-now) 489356250
0:00:01.752951000 8744 0x3d233770 DEBUG GST_CLOCK gstsystemclock.c:746:gst_system_clock_id_wait_jitter_unlocked: entry 0xffffa4008580 unlocked, status 3, ret 0
0:00:01.753170000 8744 0x3d233770 DEBUG GST_CLOCK gstsystemclock.c:770:gst_system_clock_id_wait_jitter_unlocked: entry 0xffffa4008580 unlocked after timeout
0:00:01.753269000 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:1046:gst_clock_get_internal_time:<GstSystemClock> internal time 0:15:46.100185750
0:00:01.753340000 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:1091:gst_clock_get_time:<GstSystemClock> adjusted time 0:15:46.100185750
0:00:01.753395375 8744 0x3d233770 DEBUG GST_CLOCK gstsystemclock.c:792:gst_system_clock_id_wait_jitter_unlocked: entry 0xffffa4008580 finished, diff -1155375
0:00:01.753455625 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:547:gst_clock_id_wait:<GstSystemClock> done waiting entry 0xffffa4008580, res: 0 (ok)
0:00:01.753527250 8744 0x3d233770 DEBUG basesink gstbasesink.c:2610:gst_base_sink_do_sync:<my_sink> clock returned 0, jitter -0:00:00.489356250
0:00:01.762902750 8744 0x3d233770 DEBUG basesink gstbasesink.c:2603:gst_base_sink_do_sync:<my_sink> possibly waiting for clock to reach 0:00:01.500000000, adjusted 0:00:01.500000000
0:00:01.762982875 8744 0x3d233770 LOG basesink gstbasesink.c:2177:gst_base_sink_wait_clock:<my_sink> time 0:00:01.500000000, base_time 0:15:45.099030375
0:00:01.763062875 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:537:gst_clock_id_wait:<GstSystemClock> waiting on clock entry 0xffffa4008580
0:00:01.763121625 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:1046:gst_clock_get_internal_time:<GstSystemClock> internal time 0:15:46.110069000
0:00:01.763203500 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:1091:gst_clock_get_time:<GstSystemClock> adjusted time 0:15:46.110069000
0:00:01.763260375 8744 0x3d233770 DEBUG GST_CLOCK gstsystemclock.c:718:gst_system_clock_id_wait_jitter_unlocked: entry 0xffffa4008580 time 0:15:46.599030375 now 0:15:46.110069000 diff (time-now) 488961375
0:00:02.253087625 8744 0x3d233770 DEBUG GST_CLOCK gstsystemclock.c:746:gst_system_clock_id_wait_jitter_unlocked: entry 0xffffa4008580 unlocked, status 3, ret 0
0:00:02.253249375 8744 0x3d233770 DEBUG GST_CLOCK gstsystemclock.c:770:gst_system_clock_id_wait_jitter_unlocked: entry 0xffffa4008580 unlocked after timeout
0:00:02.253337375 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:1046:gst_clock_get_internal_time:<GstSystemClock> internal time 0:15:46.600263750
0:00:02.253410000 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:1091:gst_clock_get_time:<GstSystemClock> adjusted time 0:15:46.600263750
0:00:02.253468875 8744 0x3d233770 DEBUG GST_CLOCK gstsystemclock.c:792:gst_system_clock_id_wait_jitter_unlocked: entry 0xffffa4008580 finished, diff -1233375
0:00:02.253587250 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:547:gst_clock_id_wait:<GstSystemClock> done waiting entry 0xffffa4008580, res: 0 (ok)
0:00:02.253658000 8744 0x3d233770 DEBUG basesink gstbasesink.c:2610:gst_base_sink_do_sync:<my_sink> clock returned 0, jitter -0:00:00.488961375
0:00:02.262819250 8744 0x3d233770 DEBUG basesink gstbasesink.c:2603:gst_base_sink_do_sync:<my_sink> possibly waiting for clock to reach 0:00:02.000000000, adjusted 0:00:02.000000000
0:00:02.262930125 8744 0x3d233770 LOG basesink gstbasesink.c:2177:gst_base_sink_wait_clock:<my_sink> time 0:00:02.000000000, base_time 0:15:45.099030375
0:00:02.263010375 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:537:gst_clock_id_wait:<GstSystemClock> waiting on clock entry 0xffffa4008580
0:00:02.263122625 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:1046:gst_clock_get_internal_time:<GstSystemClock> internal time 0:15:46.610068500
0:00:02.263190125 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:1091:gst_clock_get_time:<GstSystemClock> adjusted time 0:15:46.610068500
0:00:02.263257500 8744 0x3d233770 DEBUG GST_CLOCK gstsystemclock.c:718:gst_system_clock_id_wait_jitter_unlocked: entry 0xffffa4008580 time 0:15:47.099030375 now 0:15:46.610068500 diff (time-now) 488961875
0:00:02.752920875 8744 0x3d233770 DEBUG GST_CLOCK gstsystemclock.c:746:gst_system_clock_id_wait_jitter_unlocked: entry 0xffffa4008580 unlocked, status 3, ret 0
0:00:02.753178250 8744 0x3d233770 DEBUG GST_CLOCK gstsystemclock.c:770:gst_system_clock_id_wait_jitter_unlocked: entry 0xffffa4008580 unlocked after timeout
0:00:02.753286000 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:1046:gst_clock_get_internal_time:<GstSystemClock> internal time 0:15:47.100202250
0:00:02.753455125 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:1091:gst_clock_get_time:<GstSystemClock> adjusted time 0:15:47.100202250
0:00:02.753511625 8744 0x3d233770 DEBUG GST_CLOCK gstsystemclock.c:792:gst_system_clock_id_wait_jitter_unlocked: entry 0xffffa4008580 finished, diff -1171875
0:00:02.753571500 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:547:gst_clock_id_wait:<GstSystemClock> done waiting entry 0xffffa4008580, res: 0 (ok)
0:00:02.753642000 8744 0x3d233770 DEBUG basesink gstbasesink.c:2610:gst_base_sink_do_sync:<my_sink> clock returned 0, jitter -0:00:00.488961875
0:00:02.763377750 8744 0x3d233770 DEBUG basesink gstbasesink.c:2603:gst_base_sink_do_sync:<my_sink> possibly waiting for clock to reach 0:00:02.500000000, adjusted 0:00:02.500000000
0:00:02.763456125 8744 0x3d233770 LOG basesink gstbasesink.c:2177:gst_base_sink_wait_clock:<my_sink> time 0:00:02.500000000, base_time 0:15:45.099030375
0:00:02.763534625 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:537:gst_clock_id_wait:<GstSystemClock> waiting on clock entry 0xffffa4008580
0:00:02.763609000 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:1046:gst_clock_get_internal_time:<GstSystemClock> internal time 0:15:47.110555625
0:00:02.763813250 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:1091:gst_clock_get_time:<GstSystemClock> adjusted time 0:15:47.110555625
0:00:02.763886000 8744 0x3d233770 DEBUG GST_CLOCK gstsystemclock.c:718:gst_system_clock_id_wait_jitter_unlocked: entry 0xffffa4008580 time 0:15:47.599030375 now 0:15:47.110555625 diff (time-now) 488474750
0:00:03.253098500 8744 0x3d233770 DEBUG GST_CLOCK gstsystemclock.c:746:gst_system_clock_id_wait_jitter_unlocked: entry 0xffffa4008580 unlocked, status 3, ret 0
0:00:03.253247250 8744 0x3d233770 DEBUG GST_CLOCK gstsystemclock.c:770:gst_system_clock_id_wait_jitter_unlocked: entry 0xffffa4008580 unlocked after timeout
0:00:03.253332000 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:1046:gst_clock_get_internal_time:<GstSystemClock> internal time 0:15:47.600257375
0:00:03.253401625 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:1091:gst_clock_get_time:<GstSystemClock> adjusted time 0:15:47.600257375
0:00:03.253456875 8744 0x3d233770 DEBUG GST_CLOCK gstsystemclock.c:792:gst_system_clock_id_wait_jitter_unlocked: entry 0xffffa4008580 finished, diff -1227000
0:00:03.253516625 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:547:gst_clock_id_wait:<GstSystemClock> done waiting entry 0xffffa4008580, res: 0 (ok)
0:00:03.253586000 8744 0x3d233770 DEBUG basesink gstbasesink.c:2610:gst_base_sink_do_sync:<my_sink> clock returned 0, jitter -0:00:00.488474750
0:00:03.271244625 8744 0x3d233770 DEBUG basesink gstbasesink.c:2603:gst_base_sink_do_sync:<my_sink> possibly waiting for clock to reach 0:00:03.000000000, adjusted 0:00:03.000000000
0:00:03.271367125 8744 0x3d233770 LOG basesink gstbasesink.c:2177:gst_base_sink_wait_clock:<my_sink> time 0:00:03.000000000, base_time 0:15:45.099030375
0:00:03.271461250 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:537:gst_clock_id_wait:<GstSystemClock> waiting on clock entry 0xffffa4008580
0:00:03.271522000 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:1046:gst_clock_get_internal_time:<GstSystemClock> internal time 0:15:47.618469125
0:00:03.271604375 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:1091:gst_clock_get_time:<GstSystemClock> adjusted time 0:15:47.618469125
0:00:03.271663625 8744 0x3d233770 DEBUG GST_CLOCK gstsystemclock.c:718:gst_system_clock_id_wait_jitter_unlocked: entry 0xffffa4008580 time 0:15:48.099030375 now 0:15:47.618469125 diff (time-now) 480561250
0:00:03.752921125 8744 0x3d233770 DEBUG GST_CLOCK gstsystemclock.c:746:gst_system_clock_id_wait_jitter_unlocked: entry 0xffffa4008580 unlocked, status 3, ret 0
0:00:03.753105500 8744 0x3d233770 DEBUG GST_CLOCK gstsystemclock.c:770:gst_system_clock_id_wait_jitter_unlocked: entry 0xffffa4008580 unlocked after timeout
0:00:03.753209000 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:1046:gst_clock_get_internal_time:<GstSystemClock> internal time 0:15:48.100125125
0:00:03.753282250 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:1091:gst_clock_get_time:<GstSystemClock> adjusted time 0:15:48.100125125
0:00:03.753337875 8744 0x3d233770 DEBUG GST_CLOCK gstsystemclock.c:792:gst_system_clock_id_wait_jitter_unlocked: entry 0xffffa4008580 finished, diff -1094750
0:00:03.753398625 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:547:gst_clock_id_wait:<GstSystemClock> done waiting entry 0xffffa4008580, res: 0 (ok)
0:00:03.753472875 8744 0x3d233770 DEBUG basesink gstbasesink.c:2610:gst_base_sink_do_sync:<my_sink> clock returned 0, jitter -0:00:00.480561250
0:00:03.764120250 8744 0x3d233770 DEBUG basesink gstbasesink.c:2603:gst_base_sink_do_sync:<my_sink> possibly waiting for clock to reach 0:00:03.500000000, adjusted 0:00:03.500000000
0:00:03.764199250 8744 0x3d233770 LOG basesink gstbasesink.c:2177:gst_base_sink_wait_clock:<my_sink> time 0:00:03.500000000, base_time 0:15:45.099030375
0:00:03.764280750 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:537:gst_clock_id_wait:<GstSystemClock> waiting on clock entry 0xffffa4008580
0:00:03.764342750 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:1046:gst_clock_get_internal_time:<GstSystemClock> internal time 0:15:48.111289000
0:00:03.764410625 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:1091:gst_clock_get_time:<GstSystemClock> adjusted time 0:15:48.111289000
0:00:03.764467250 8744 0x3d233770 DEBUG GST_CLOCK gstsystemclock.c:718:gst_system_clock_id_wait_jitter_unlocked: entry 0xffffa4008580 time 0:15:48.599030375 now 0:15:48.111289000 diff (time-now) 487741375
0:00:04.252890000 8744 0x3d233770 DEBUG GST_CLOCK gstsystemclock.c:746:gst_system_clock_id_wait_jitter_unlocked: entry 0xffffa4008580 unlocked, status 3, ret 0
0:00:04.253000250 8744 0x3d233770 DEBUG GST_CLOCK gstsystemclock.c:770:gst_system_clock_id_wait_jitter_unlocked: entry 0xffffa4008580 unlocked after timeout
0:00:04.253138000 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:1046:gst_clock_get_internal_time:<GstSystemClock> internal time 0:15:48.600063125
0:00:04.253217625 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:1091:gst_clock_get_time:<GstSystemClock> adjusted time 0:15:48.600063125
0:00:04.253273375 8744 0x3d233770 DEBUG GST_CLOCK gstsystemclock.c:792:gst_system_clock_id_wait_jitter_unlocked: entry 0xffffa4008580 finished, diff -1032750
0:00:04.253333250 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:547:gst_clock_id_wait:<GstSystemClock> done waiting entry 0xffffa4008580, res: 0 (ok)
0:00:04.253403125 8744 0x3d233770 DEBUG basesink gstbasesink.c:2610:gst_base_sink_do_sync:<my_sink> clock returned 0, jitter -0:00:00.487741375
0:00:04.263324625 8744 0x3d233770 DEBUG basesink gstbasesink.c:2603:gst_base_sink_do_sync:<my_sink> possibly waiting for clock to reach 0:00:04.000000000, adjusted 0:00:04.000000000
0:00:04.263405375 8744 0x3d233770 LOG basesink gstbasesink.c:2177:gst_base_sink_wait_clock:<my_sink> time 0:00:04.000000000, base_time 0:15:45.099030375
0:00:04.263570500 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:537:gst_clock_id_wait:<GstSystemClock> waiting on clock entry 0xffffa4008580
0:00:04.263664125 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:1046:gst_clock_get_internal_time:<GstSystemClock> internal time 0:15:48.610610375
0:00:04.263735375 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:1091:gst_clock_get_time:<GstSystemClock> adjusted time 0:15:48.610610375
0:00:04.263794000 8744 0x3d233770 DEBUG GST_CLOCK gstsystemclock.c:718:gst_system_clock_id_wait_jitter_unlocked: entry 0xffffa4008580 time 0:15:49.099030375 now 0:15:48.610610375 diff (time-now) 488420000
0:00:04.752925250 8744 0x3d233770 DEBUG GST_CLOCK gstsystemclock.c:746:gst_system_clock_id_wait_jitter_unlocked: entry 0xffffa4008580 unlocked, status 3, ret 0
0:00:04.753182250 8744 0x3d233770 DEBUG GST_CLOCK gstsystemclock.c:770:gst_system_clock_id_wait_jitter_unlocked: entry 0xffffa4008580 unlocked after timeout
0:00:04.753275875 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:1046:gst_clock_get_internal_time:<GstSystemClock> internal time 0:15:49.100201250
0:00:04.753348375 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:1091:gst_clock_get_time:<GstSystemClock> adjusted time 0:15:49.100201250
0:00:04.753405125 8744 0x3d233770 DEBUG GST_CLOCK gstsystemclock.c:792:gst_system_clock_id_wait_jitter_unlocked: entry 0xffffa4008580 finished, diff -1170875
0:00:04.753467250 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:547:gst_clock_id_wait:<GstSystemClock> done waiting entry 0xffffa4008580, res: 0 (ok)
0:00:04.753542750 8744 0x3d233770 DEBUG basesink gstbasesink.c:2610:gst_base_sink_do_sync:<my_sink> clock returned 0, jitter -0:00:00.488420000
0:00:04.766212375 8744 0x3d233770 DEBUG basesink gstbasesink.c:2603:gst_base_sink_do_sync:<my_sink> possibly waiting for clock to reach 0:00:04.500000000, adjusted 0:00:04.500000000
0:00:04.766348875 8744 0x3d233770 LOG basesink gstbasesink.c:2177:gst_base_sink_wait_clock:<my_sink> time 0:00:04.500000000, base_time 0:15:45.099030375
0:00:04.766533625 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:537:gst_clock_id_wait:<GstSystemClock> waiting on clock entry 0xffffa4008580
0:00:04.766600875 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:1046:gst_clock_get_internal_time:<GstSystemClock> internal time 0:15:49.113547125
0:00:04.766686250 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:1091:gst_clock_get_time:<GstSystemClock> adjusted time 0:15:49.113547125
0:00:04.766760625 8744 0x3d233770 DEBUG GST_CLOCK gstsystemclock.c:718:gst_system_clock_id_wait_jitter_unlocked: entry 0xffffa4008580 time 0:15:49.599030375 now 0:15:49.113547125 diff (time-now) 485483250
0:00:05.252967875 8744 0x3d233770 DEBUG GST_CLOCK gstsystemclock.c:746:gst_system_clock_id_wait_jitter_unlocked: entry 0xffffa4008580 unlocked, status 3, ret 0
0:00:05.253158625 8744 0x3d233770 DEBUG GST_CLOCK gstsystemclock.c:770:gst_system_clock_id_wait_jitter_unlocked: entry 0xffffa4008580 unlocked after timeout
0:00:05.253243000 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:1046:gst_clock_get_internal_time:<GstSystemClock> internal time 0:15:49.600170250
0:00:05.253315375 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:1091:gst_clock_get_time:<GstSystemClock> adjusted time 0:15:49.600170250
0:00:05.253371625 8744 0x3d233770 DEBUG GST_CLOCK gstsystemclock.c:792:gst_system_clock_id_wait_jitter_unlocked: entry 0xffffa4008580 finished, diff -1139875
0:00:05.253431500 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:547:gst_clock_id_wait:<GstSystemClock> done waiting entry 0xffffa4008580, res: 0 (ok)
0:00:05.253501875 8744 0x3d233770 DEBUG basesink gstbasesink.c:2610:gst_base_sink_do_sync:<my_sink> clock returned 0, jitter -0:00:00.485483250
0:00:05.265454375 8744 0x3d233770 DEBUG basesink gstbasesink.c:2603:gst_base_sink_do_sync:<my_sink> possibly waiting for clock to reach 0:00:05.000000000, adjusted 0:00:05.000000000
0:00:05.265531125 8744 0x3d233770 LOG basesink gstbasesink.c:2177:gst_base_sink_wait_clock:<my_sink> time 0:00:05.000000000, base_time 0:15:45.099030375
0:00:05.265613625 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:537:gst_clock_id_wait:<GstSystemClock> waiting on clock entry 0xffffa4008580
0:00:05.265676000 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:1046:gst_clock_get_internal_time:<GstSystemClock> internal time 0:15:49.612622125
0:00:05.265744750 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:1091:gst_clock_get_time:<GstSystemClock> adjusted time 0:15:49.612622125
0:00:05.265803000 8744 0x3d233770 DEBUG GST_CLOCK gstsystemclock.c:718:gst_system_clock_id_wait_jitter_unlocked: entry 0xffffa4008580 time 0:15:50.099030375 now 0:15:49.612622125 diff (time-now) 486408250
0:00:05.497472375 8744 0x3d0a0600 DEBUG GST_CLOCK gstclock.c:1046:gst_clock_get_internal_time:<GstSystemClock> internal time 0:15:49.844417875
0:00:05.497543250 8744 0x3d0a0600 DEBUG GST_CLOCK gstclock.c:1091:gst_clock_get_time:<GstSystemClock> adjusted time 0:15:49.844417875
0:00:05.499786000 8744 0x3d0a0600 DEBUG basesink gstbasesink.c:5168:gst_base_sink_change_state:<my_sink> unschedule clock
0:00:05.499867250 8744 0x3d0a0600 DEBUG GST_CLOCK gstsystemclock.c:1005:gst_system_clock_id_unschedule: unscheduling entry 0xffffa4008580
0:00:05.499915500 8744 0x3d0a0600 DEBUG GST_CLOCK gstsystemclock.c:1019:gst_system_clock_id_unschedule: entry was BUSY, doing wakeup
0:00:05.499953750 8744 0x3d0a0600 DEBUG GST_CLOCK gstsystemclock.c:397:gst_system_clock_add_wakeup: writing control
0:00:05.500096375 8744 0x3d0a0600 DEBUG GST_CLOCK gstsystemclock.c:401:gst_system_clock_add_wakeup: wakeup count 1
0:00:05.500135875 8744 0x3d233770 DEBUG GST_CLOCK gstsystemclock.c:746:gst_system_clock_id_wait_jitter_unlocked: entry 0xffffa4008580 unlocked, status 2, ret 1
0:00:05.500616125 8744 0x3d233770 DEBUG GST_CLOCK gstsystemclock.c:378:gst_system_clock_remove_wakeup: reading control
0:00:05.500803250 8744 0x3d233770 DEBUG GST_CLOCK gstsystemclock.c:391:gst_system_clock_remove_wakeup: wakeup count 0
0:00:05.500865875 8744 0x3d233770 DEBUG GST_CLOCK gstclock.c:547:gst_clock_id_wait:<GstSystemClock> done waiting entry 0xffffa4008580, res: 2 (unscheduled)
0:00:05.502220625 8744 0x3d233770 DEBUG basesink gstbasesink.c:2610:gst_base_sink_do_sync:<my_sink> clock returned 2, jitter -0:00:00.486408250
0:00:05.510106375 8744 0x3d0a0600 DEBUG GST_CLOCK gstclock.c:1046:gst_clock_get_internal_time:<GstSystemClock> internal time 0:15:49.857053500
0:00:05.510173500 8744 0x3d0a0600 DEBUG GST_CLOCK gstclock.c:1091:gst_clock_get_time:<GstSystemClock> adjusted time 0:15:49.857053500
0:00:05.514795250 8744 0x3d0a0600 DEBUG GST_CLOCK gstclock.c:352:_gst_clock_id_free: freed entry 0xffffa4008580
0:00:05.594726375 8744 0x3d0a0600 DEBUG GST_CLOCK gstelement.c:429:gst_element_set_clock:<my_sink> setting clock (nil)
0:00:05.596297500 8744 0x3d0a0600 DEBUG GST_CLOCK gstelement.c:429:gst_element_set_clock:<my_vdec> setting clock (nil)
0:00:05.598276125 8744 0x3d0a0600 DEBUG GST_CLOCK gstelement.c:429:gst_element_set_clock:<my_h264parse> setting clock (nil)
0:00:05.600359000 8744 0x3d0a0600 DEBUG GST_CLOCK gstelement.c:429:gst_element_set_clock:<my_appsrc> setting clock (nil)
-------------- next part --------------
A non-text attachment was scrubbed...
Name: appsrc-codec.c
Type: text/x-c-code
Size: 8914 bytes
Desc: not available
URL: <https://lists.freedesktop.org/archives/gstreamer-devel/attachments/20190520/dd3ec18d/attachment-0001.bin>
More information about the gstreamer-devel
mailing list