GNOME Bugzilla – Bug 763165
qtdemux: Seeking in push mode broken
Last modified: 2016-05-31 14:27:33 UTC
On Android 6.0.1 with gstreamer 1.7.90, a seek event such as: gst_element_seek_simple(data->pipeline, GST_FORMAT_TIME, GST_SEEK_FLAG_FLUSH | GST_SEEK_FLAG_KEY_UNIT, s * GST_MSECOND); works with the following pipeline: playbin uri=file://path while it's not working with the following pipeline: filesrc location=path ! queue ! decodebin ! queue ! glimagesink everything else not changed. With the playbin pipeline, it's working as expected and the jump is immediate. After the seek event occurs, the video continues playing immediately at the new position. Here is the *:4 log. At 23:45:50.073, a seek to 31s is requested and at 23:45:50.174, the video plays at the 31s mark. With the decodebin pipeline, after the seek event occurs at 23:30:17.396, there is an immediate jump for one frame, meaning that a frame of the 31s mark is displayed at 23:30:17.476. Nevertheless, the pipeline restarts from the beginning without displaying anything (the 31s frame is still visible) and once 31 seconds have elapsed at 23:30:49.176, the video resumes playing after the 31s mark.
*:4 log for the playbin pipeline: 03-05 23:30:17.266 9153 9343 I GStreamer+baseparse: 0:01:56.302248081 0xce9bdf50 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:30:17.287 9153 9343 I GStreamer+baseparse: 0:01:56.322558289 0xce9bdf50 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:30:17.308 9153 9343 I GStreamer+baseparse: 0:01:56.343660216 0xce9bdf50 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:30:17.325 9153 9343 I GStreamer+baseparse: 0:01:56.361348341 0xce9bdf50 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:30:17.346 9153 9343 I GStreamer+baseparse: 0:01:56.382461726 0xce9bdf50 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:30:17.364 9153 9343 I GStreamer+baseparse: 0:01:56.399867768 0xce9bdf50 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:30:17.375 9153 9338 W GStreamer+amcvideodec: 0:01:56.411472508 0xdcc1e750 gstamcvideodec.c:1165:_amc_gl_wait gl_sync 0xd1e19930 could not wait for frame, took too long 03-05 23:30:17.383 9153 9343 I GStreamer+baseparse: 0:01:56.418768862 0xce9bdf50 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:30:17.396 9153 9153 D GStreamer+aiTennis3D: 0:01:56.431550320 0xf0d3fc00 gstreamer/aigstreamer.c:862:gst_native_seek Doing seek at 31713 mseconds 03-05 23:30:17.396 9153 9153 I GStreamer+GST_EVENT: 0:01:56.431771778 0xf0d3fc00 gstevent.c:1139:gst_event_new_seek creating seek rate 1.000000, format TIME, flags 5, start_type 1, start 0:00:31.713000000, stop_type 0, stop 0:00:00.000000000 03-05 23:30:17.403 9153 9153 I GStreamer+qtdemux: 0:01:56.439059122 0xf0d3fc00 qtdemux.c:1679:gst_qtdemux_handle_src_event:<qtdemux1> Time taken to parse index 0:00:00.007018594 03-05 23:30:17.403 9153 9153 I GStreamer+default: 0:01:56.439247924 0xf0d3fc00 gstsegment.c:372:gst_segment_do_seek segment updated: bytes segment start=31713000000, offset=0, stop=-1, rate=1.000000, applied_rate=1.000000, flags=0x01, time=31713000000, base=0, position 31713000000, duration -1 03-05 23:30:17.403 9153 9153 I GStreamer+GST_EVENT: 0:01:56.439365528 0xf0d3fc00 gstevent.c:1146:gst_event_new_seek creating seek rate 1.000000, format bytes, flags 5, start_type 1, start 236561809, stop_type 0, stop -1 03-05 23:30:17.404 9153 9153 I GStreamer+GST_STATES: 0:01:56.439593705 0xf0d3fc00 gstelement.c:2277:_priv_gst_element_state_changed:<sink> notifying about state-changed PAUSED to PAUSED (PAUSED pending) 03-05 23:30:17.404 9153 9153 I GStreamer+GST_STATES: 0:01:56.439837820 0xf0d3fc00 gstelement.c:2277:_priv_gst_element_state_changed:<glimagesinkbin1> notifying about state-changed PAUSED to PAUSED (PAUSED pending) 03-05 23:30:17.404 9153 9153 I GStreamer+GST_STATES: 0:01:56.440046310 0xf0d3fc00 gstelement.c:2277:_priv_gst_element_state_changed:<pipeline1> notifying about state-changed PAUSED to PAUSED (PAUSED pending) 03-05 23:30:17.404 9153 9336 I System.out: Gst setMessage (0) State changed (0) to PAUSED 03-05 23:30:17.405 9153 9338 W GStreamer+amcvideodec: 0:01:56.440708185 0xdcc1e750 gstamcvideodec.c:1165:_amc_gl_wait gl_sync 0xd1e19a50 could not wait for frame, took too long 03-05 23:30:17.409 9153 9349 I GStreamer+task: 0:01:56.444843966 0xce839ac0 gsttask.c:316:gst_task_func:<amcvideodec-omxqcomvideodecoderavc1:src> Task going to paused 03-05 23:30:17.409 9153 9343 E GStreamer+amcvideodec: 0:01:56.444864383 0xce9bdf50 gstamcvideodec.c:2257:gst_amc_video_dec_handle_frame:<amcvideodec-omxqcomvideodecoderavc1> Downstream returned flushing 03-05 23:30:17.409 9153 9343 I GStreamer+task: 0:01:56.445465685 0xce9bdf50 gsttask.c:316:gst_task_func:<multiqueue1:src_0> Task going to paused 03-05 23:30:17.410 9153 9263 I GStreamer+task: 0:01:56.446283341 0xdd68ed80 gsttask.c:316:gst_task_func:<queue3:src> Task going to paused 03-05 23:30:17.410 9153 9341 I GStreamer+task: 0:01:56.446366414 0xdd68eef0 gsttask.c:316:gst_task_func:<queue2:src> Task going to paused 03-05 23:30:17.410 9153 9342 I GStreamer+basesrc: 0:01:56.446452195 0xdd68ef20 gstbasesrc.c:2856:gst_base_src_loop:<filesrc1> pausing after gst_pad_push() = flushing 03-05 23:30:17.411 9153 9153 I GStreamer+default: 0:01:56.446660424 0xf0d3fc00 gstsegment.c:372:gst_segment_do_seek segment updated: bytes segment start=236561809, offset=0, stop=-1, rate=1.000000, applied_rate=1.000000, flags=0x01, time=236561809, base=0, position 236561809, duration 314431955 03-05 23:30:17.411 9153 9153 I GStreamer+basesrc: 0:01:56.446806466 0xf0d3fc00 gstbasesrc.c:1344:gst_base_src_do_seek:<filesrc1> seeking: bytes segment start=236561809, offset=0, stop=-1, rate=1.000000, applied_rate=1.000000, flags=0x01, time=236561809, base=0, position 236561809, duration 314431955 03-05 23:30:17.411 9153 9153 I GStreamer+GST_EVENT: 0:01:56.446888341 0xf0d3fc00 gstevent.c:547:gst_event_new_flush_stop creating flush stop 1 03-05 23:30:17.411 9153 9153 I GStreamer+GST_EVENT: 0:01:56.447058393 0xf0d3fc00 gstevent.c:760: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 03-05 23:30:17.411 9153 9342 I GStreamer+task: 0:01:56.447103758 0xdd68ef20 gsttask.c:316:gst_task_func:<filesrc1:src> Task going to paused 03-05 23:30:17.414 9153 9341 I GStreamer+task: 0:01:56.450051258 0xdd68eef0 gsttask.c:318:gst_task_func:<queue2:src> Task resume from paused 03-05 23:30:17.414 9153 9349 I GStreamer+task: 0:01:56.450099278 0xce839ac0 gsttask.c:318:gst_task_func:<amcvideodec-omxqcomvideodecoderavc1:src> Task resume from paused 03-05 23:30:17.414 9153 9263 I GStreamer+task: 0:01:56.450172455 0xdd68ed80 gsttask.c:318:gst_task_func:<queue3:src> Task resume from paused 03-05 23:30:17.414 9153 9342 I GStreamer+task: 0:01:56.450124747 0xdd68ef20 gsttask.c:318:gst_task_func:<filesrc1:src> Task resume from paused 03-05 23:30:17.414 9153 9343 I GStreamer+task: 0:01:56.450280580 0xce9bdf50 gsttask.c:318:gst_task_func:<multiqueue1:src_0> Task resume from paused 03-05 23:30:17.416 9153 9342 I GStreamer+GST_EVENT: 0:01:56.451836830 0xdd68ef20 gstevent.c:760:gst_event_new_segment creating segment event bytes segment start=236561809, offset=0, stop=-1, rate=1.000000, applied_rate=1.000000, flags=0x01, time=236561809, base=0, position 236561809, duration 314431955 03-05 23:30:17.416 9153 9342 I GStreamer+basesrc: 0:01:56.452032403 0xdd68ef20 gstbasesrc.c:2843:gst_base_src_loop:<filesrc1> marking pending DISCONT 03-05 23:30:17.416 9153 9341 I GStreamer+GST_EVENT: 0:01:56.452191778 0xdd68eef0 gstevent.c:760:gst_event_new_segment creating segment event time segment start=0:00:31.713000000, offset=0:00:00.000000000, stop=99:99:99.999999999, rate=1.000000, applied_rate=1.000000, flags=0x01, time=0:00:31.713000000, base=0:00:00.000000000, position 0:00:31.713000000, duration 0:00:41.982000000 03-05 23:30:17.431 9153 9343 I GStreamer+h264parse: 0:01:56.467239018 0xce9bdf50 gsth264parse.c:743:gst_h264_parse_process_nal:<h264parse1> have SPS/PPS in stream 03-05 23:30:17.432 9153 9343 I GStreamer+baseparse: 0:01:56.467729122 0xce9bdf50 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:30:17.444 9153 9343 I GStreamer+baseparse: 0:01:56.480119018 0xce9bdf50 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:30:17.446 9153 9343 I GStreamer+baseparse: 0:01:56.482092091 0xce9bdf50 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:30:17.455 9153 9343 I GStreamer+baseparse: 0:01:56.491021622 0xce9bdf50 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:30:17.460 9153 9343 I GStreamer+baseparse: 0:01:56.496388185 0xce9bdf50 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:30:17.462 9153 9343 I GStreamer+baseparse: 0:01:56.498106205 0xce9bdf50 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:30:17.467 9153 9263 I GStreamer+GST_STATES: 0:01:56.502979278 0xdd68ed80 gstbin.c:3238:bin_handle_async_done:<glimagesinkbin1> committing state from PAUSED to PAUSED, old pending PLAYING 03-05 23:30:17.467 9153 9263 I GStreamer+GST_STATES: 0:01:56.503159539 0xdd68ed80 gstbin.c:3258:bin_handle_async_done:<glimagesinkbin1> completed state change, pending VOID 03-05 23:30:17.467 9153 9263 I GStreamer+GST_STATES: 0:01:56.503283080 0xdd68ed80 gstelement.c:2277:_priv_gst_element_state_changed:<glimagesinkbin1> notifying about state-changed PAUSED to PAUSED (VOID_PENDING pending) 03-05 23:30:17.467 9153 9343 I GStreamer+baseparse: 0:01:56.503355737 0xce9bdf50 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:30:17.467 9153 9263 I GStreamer+GST_STATES: 0:01:56.503423393 0xdd68ed80 gstbin.c:3238:bin_handle_async_done:<pipeline1> committing state from PAUSED to PAUSED, old pending PLAYING 03-05 23:30:17.468 9153 9263 I GStreamer+GST_STATES: 0:01:56.503506466 0xdd68ed80 gstbin.c:3267:bin_handle_async_done:<pipeline1> continue state change, pending PLAYING 03-05 23:30:17.468 9153 9263 I GStreamer+GST_STATES: 0:01:56.503595893 0xdd68ed80 gstelement.c:2277:_priv_gst_element_state_changed:<pipeline1> notifying about state-changed PAUSED to PAUSED (PLAYING pending) 03-05 23:30:17.468 9153 9350 I GStreamer+GST_STATES: 0:01:56.503794591 0xdcfa3630 gstbin.c:3061:gst_bin_continue_func:<pipeline1> continue state change PAUSED to PLAYING, final PLAYING 03-05 23:30:17.468 9153 9336 I System.out: Gst setMessage (0) State changed (0) to PAUSED 03-05 23:30:17.468 9153 9350 I GStreamer+GST_EVENT: 0:01:56.504190528 0xdcfa3630 gstevent.c:1253:gst_event_new_latency creating latency event 0:00:00.000000000 03-05 23:30:17.468 9153 9350 I GStreamer+bin: 0:01:56.504405737 0xdcfa3630 gstbin.c:2593:gst_bin_do_latency_func:<pipeline1> configured latency of 0:00:00.000000000 03-05 23:30:17.469 9153 9350 I GStreamer+GST_STATES: 0:01:56.504542612 0xdcfa3630 gstbin.c:2316:gst_bin_element_set_state:<glimagesinkbin1> current PAUSED pending VOID_PENDING, desired next PLAYING 03-05 23:30:17.469 9153 9350 I GStreamer+GST_STATES: 0:01:56.504664330 0xdcfa3630 gstbin.c:2316:gst_bin_element_set_state:<sink> current PAUSED pending VOID_PENDING, desired next PLAYING 03-05 23:30:17.469 9153 9350 I GStreamer+GST_STATES: 0:01:56.504771830 0xdcfa3630 gstelement.c:2372:gst_element_continue_state:<sink> completed state change to PLAYING 03-05 23:30:17.469 9153 9350 I GStreamer+GST_STATES: 0:01:56.504877716 0xdcfa3630 gstelement.c:2277:_priv_gst_element_state_changed:<sink> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending) 03-05 23:30:17.469 9153 9350 I GStreamer+GST_STATES: 0:01:56.505005685 0xdcfa3630 gstbin.c:2764:gst_bin_change_state_func:<glimagesinkbin1> child 'sink' changed state to 4(PLAYING) successfully 03-05 23:30:17.469 9153 9350 I GStreamer+GST_STATES: 0:01:56.505107143 0xdcfa3630 gstbin.c:2316:gst_bin_element_set_state:<glcolorbalance1> current PLAYING pending VOID_PENDING, desired next PLAYING 03-05 23:30:17.469 9153 9350 I GStreamer+GST_STATES: 0:01:56.505201518 0xdcfa3630 gstbin.c:2433:gst_bin_element_set_state:<glcolorbalance1> skipping transition from PLAYING to PLAYING 03-05 23:30:17.469 9153 9350 I GStreamer+GST_STATES: 0:01:56.505286310 0xdcfa3630 gstbin.c:2764:gst_bin_change_state_func:<glimagesinkbin1> child 'glcolorbalance1' changed state to 4(PLAYING) successfully 03-05 23:30:17.469 9153 9350 I GStreamer+GST_STATES: 0:01:56.505380945 0xdcfa3630 gstbin.c:2316:gst_bin_element_set_state:<glcolorconvertelement1> current PLAYING pending VOID_PENDING, desired next PLAYING 03-05 23:30:17.469 9153 9350 I GStreamer+GST_STATES: 0:01:56.505453185 0xdcfa3630 gstbin.c:2433:gst_bin_element_set_state:<glcolorconvertelement1> skipping transition from PLAYING to PLAYING 03-05 23:30:17.470 9153 9350 I GStreamer+GST_STATES: 0:01:56.505527508 0xdcfa3630 gstbin.c:2764:gst_bin_change_state_func:<glimagesinkbin1> child 'glcolorconvertelement1' changed state to 4(PLAYING) successfully 03-05 23:30:17.470 9153 9350 I GStreamer+GST_STATES: 0:01:56.505604174 0xdcfa3630 gstbin.c:2316:gst_bin_element_set_state:<gluploadelement1> current PLAYING pending VOID_PENDING, desired next PLAYING 03-05 23:30:17.470 9153 9350 I GStreamer+GST_STATES: 0:01:56.505680997 0xdcfa3630 gstbin.c:2433:gst_bin_element_set_state:<gluploadelement1> skipping transition from PLAYING to PLAYING 03-05 23:30:17.470 9153 9350 I GStreamer+GST_STATES: 0:01:56.505755424 0xdcfa3630 gstbin.c:2764:gst_bin_change_state_func:<glimagesinkbin1> child 'gluploadelement1' changed state to 4(PLAYING) successfully 03-05 23:30:17.470 9153 9350 I GStreamer+GST_STATES: 0:01:56.505839122 0xdcfa3630 gstelement.c:2372:gst_element_continue_state:<glimagesinkbin1> completed state change to PLAYING 03-05 23:30:17.470 9153 9350 I GStreamer+GST_STATES: 0:01:56.505981362 0xdcfa3630 gstelement.c:2277:_priv_gst_element_state_changed:<glimagesinkbin1> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending) 03-05 23:30:17.470 9153 9343 I GStreamer+baseparse: 0:01:56.506020737 0xce9bdf50 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:30:17.470 9153 9350 I GStreamer+GST_STATES: 0:01:56.506208445 0xdcfa3630 gstbin.c:2764:gst_bin_change_state_func:<pipeline1> child 'glimagesinkbin1' changed state to 4(PLAYING) successfully 03-05 23:30:17.470 9153 9350 I GStreamer+GST_STATES: 0:01:56.506308966 0xdcfa3630 gstbin.c:2316:gst_bin_element_set_state:<identity0> current PLAYING pending VOID_PENDING, desired next PLAYING 03-05 23:30:17.470 9153 9350 I GStreamer+GST_STATES: 0:01:56.506391622 0xdcfa3630 gstbin.c:2433:gst_bin_element_set_state:<identity0> skipping transition from PLAYING to PLAYING 03-05 23:30:17.470 9153 9350 I GStreamer+GST_STATES: 0:01:56.506465841 0xdcfa3630 gstbin.c:2764:gst_bin_change_state_func:<pipeline1> child 'identity0' changed state to 4(PLAYING) successfully 03-05 23:30:17.471 9153 9350 I GStreamer+GST_STATES: 0:01:56.506549278 0xdcfa3630 gstbin.c:2316:gst_bin_element_set_state:<queue3> current PLAYING pending VOID_PENDING, desired next PLAYING 03-05 23:30:17.471 9153 9350 I GStreamer+GST_STATES: 0:01:56.506625112 0xdcfa3630 gstbin.c:2433:gst_bin_element_set_state:<queue3> skipping transition from PLAYING to PLAYING 03-05 23:30:17.471 9153 9350 I GStreamer+GST_STATES: 0:01:56.506691674 0xdcfa3630 gstbin.c:2764:gst_bin_change_state_func:<pipeline1> child 'queue3' changed state to 4(PLAYING) successfully 03-05 23:30:17.471 9153 9350 I GStreamer+GST_STATES: 0:01:56.506772351 0xdcfa3630 gstbin.c:2316:gst_bin_element_set_state:<decodebin0> current PLAYING pending VOID_PENDING, desired next PLAYING 03-05 23:30:17.471 9153 9350 I GStreamer+GST_STATES: 0:01:56.506886310 0xdcfa3630 gstbin.c:2316:gst_bin_element_set_state:<amcvideodec-omxqcomvideodecoderavc1> current PLAYING pending VOID_PENDING, desired next PLAYING 03-05 23:30:17.471 9153 9350 I GStreamer+GST_STATES: 0:01:56.506962039 0xdcfa3630 gstbin.c:2433:gst_bin_element_set_state:<amcvideodec-omxqcomvideodecoderavc1> skipping transition from PLAYING to PLAYING 03-05 23:30:17.471 9153 9350 I GStreamer+GST_STATES: 0:01:56.507037872 0xdcfa3630 gstbin.c:2764:gst_bin_change_state_func:<decodebin0> child 'amcvideodec-omxqcomvideodecoderavc1' changed state to 4(PLAYING) successfully 03-05 23:30:17.471 9153 9350 I GStreamer+GST_STATES: 0:01:56.507139330 0xdcfa3630 gstbin.c:2316:gst_bin_element_set_state:<capsfilter1> current PLAYING pending VOID_PENDING, desired next PLAYING 03-05 23:30:17.471 9153 9350 I GStreamer+GST_STATES: 0:01:56.507221258 0xdcfa3630 gstbin.c:2433:gst_bin_element_set_state:<capsfilter1> skipping transition from PLAYING to PLAYING 03-05 23:30:17.471 9153 9350 I GStreamer+GST_STATES: 0:01:56.507314174 0xdcfa3630 gstbin.c:2764:gst_bin_change_state_func:<decodebin0> child 'capsfilter1' changed state to 4(PLAYING) successfully 03-05 23:30:17.471 9153 9350 I GStreamer+GST_STATES: 0:01:56.507410580 0xdcfa3630 gstbin.c:2316:gst_bin_element_set_state:<h264parse1> current PLAYING pending VOID_PENDING, desired next PLAYING 03-05 23:30:17.471 9153 9343 I GStreamer+baseparse: 0:01:56.507449747 0xce9bdf50 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:30:17.471 9153 9350 I GStreamer+GST_STATES: 0:01:56.507486883 0xdcfa3630 gstbin.c:2433:gst_bin_element_set_state:<h264parse1> skipping transition from PLAYING to PLAYING 03-05 23:30:17.472 9153 9350 I GStreamer+GST_STATES: 0:01:56.507563758 0xdcfa3630 gstbin.c:2764:gst_bin_change_state_func:<decodebin0> child 'h264parse1' changed state to 4(PLAYING) successfully 03-05 23:30:17.472 9153 9350 I GStreamer+GST_STATES: 0:01:56.507656830 0xdcfa3630 gstbin.c:2316:gst_bin_element_set_state:<multiqueue1> current PLAYING pending VOID_PENDING, desired next PLAYING 03-05 23:30:17.472 9153 9350 I GStreamer+GST_STATES: 0:01:56.507742872 0xdcfa3630 gstbin.c:2433:gst_bin_element_set_state:<multiqueue1> skipping transition from PLAYING to PLAYING 03-05 23:30:17.472 9153 9350 I GStreamer+GST_STATES: 0:01:56.507821674 0xdcfa3630 gstbin.c:2764:gst_bin_change_state_func:<decodebin0> child 'multiqueue1' changed state to 4(PLAYING) successfully 03-05 23:30:17.472 9153 9350 I GStreamer+GST_STATES: 0:01:56.507915112 0xdcfa3630 gstbin.c:2316:gst_bin_element_set_state:<qtdemux1> current PLAYING pending VOID_PENDING, desired next PLAYING 03-05 23:30:17.472 9153 9350 I GStreamer+GST_STATES: 0:01:56.507993185 0xdcfa3630 gstbin.c:2433:gst_bin_element_set_state:<qtdemux1> skipping transition from PLAYING to PLAYING 03-05 23:30:17.472 9153 9350 I GStreamer+GST_STATES: 0:01:56.508068914 0xdcfa3630 gstbin.c:2764:gst_bin_change_state_func:<decodebin0> child 'qtdemux1' changed state to 4(PLAYING) successfully 03-05 23:30:17.472 9153 9350 I GStreamer+GST_STATES: 0:01:56.508150112 0xdcfa3630 gstbin.c:2316:gst_bin_element_set_state:<typefind> current PLAYING pending VOID_PENDING, desired next PLAYING 03-05 23:30:17.472 9153 9350 I GStreamer+GST_STATES: 0:01:56.508221622 0xdcfa3630 gstbin.c:2433:gst_bin_element_set_state:<typefind> skipping transition from PLAYING to PLAYING 03-05 23:30:17.472 9153 9350 I GStreamer+GST_STATES: 0:01:56.508294851 0xdcfa3630 gstbin.c:2764:gst_bin_change_state_func:<decodebin0> child 'typefind' changed state to 4(PLAYING) successfully 03-05 23:30:17.472 9153 9350 I GStreamer+GST_STATES: 0:01:56.508373653 0xdcfa3630 gstelement.c:2372:gst_element_continue_state:<decodebin0> completed state change to PLAYING 03-05 23:30:17.472 9153 9350 I GStreamer+GST_STATES: 0:01:56.508450424 0xdcfa3630 gstbin.c:2764:gst_bin_change_state_func:<pipeline1> child 'decodebin0' changed state to 4(PLAYING) successfully 03-05 23:30:17.473 9153 9350 I GStreamer+GST_STATES: 0:01:56.508532299 0xdcfa3630 gstbin.c:2316:gst_bin_element_set_state:<queue2> current PLAYING pending VOID_PENDING, desired next PLAYING 03-05 23:30:17.473 9153 9350 I GStreamer+GST_STATES: 0:01:56.508602820 0xdcfa3630 gstbin.c:2433:gst_bin_element_set_state:<queue2> skipping transition from PLAYING to PLAYING 03-05 23:30:17.473 9153 9350 I GStreamer+GST_STATES: 0:01:56.508676101 0xdcfa3630 gstbin.c:2764:gst_bin_change_state_func:<pipeline1> child 'queue2' changed state to 4(PLAYING) successfully 03-05 23:30:17.473 9153 9350 I GStreamer+GST_STATES: 0:01:56.508752664 0xdcfa3630 gstbin.c:2316:gst_bin_element_set_state:<filesrc1> current PLAYING pending VOID_PENDING, desired next PLAYING 03-05 23:30:17.473 9153 9350 I GStreamer+GST_STATES: 0:01:56.508827820 0xdcfa3630 gstbin.c:2433:gst_bin_element_set_state:<filesrc1> skipping transition from PLAYING to PLAYING 03-05 23:30:17.473 9153 9350 I GStreamer+GST_STATES: 0:01:56.508898810 0xdcfa3630 gstbin.c:2764:gst_bin_change_state_func:<pipeline1> child 'filesrc1' changed state to 4(PLAYING) successfully 03-05 23:30:17.473 9153 9350 I GStreamer+GST_STATES: 0:01:56.508973810 0xdcfa3630 gstelement.c:2372:gst_element_continue_state:<pipeline1> completed state change to PLAYING 03-05 23:30:17.473 9153 9350 I GStreamer+GST_STATES: 0:01:56.509045268 0xdcfa3630 gstelement.c:2277:_priv_gst_element_state_changed:<pipeline1> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending) 03-05 23:30:17.473 9153 9336 I System.out: Gst setMessage (0) State changed (0) to PLAYING 03-05 23:30:17.476 9153 9343 I GStreamer+baseparse: 0:01:56.512364695 0xce9bdf50 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:30:49.176 9153 9343 I GStreamer+baseparse: 0:02:28.212247964 0xce9bdf50 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:30:49.207 9153 9343 I GStreamer+baseparse: 0:02:28.243114683 0xce9bdf50 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:30:49.230 9153 9343 I GStreamer+baseparse: 0:02:28.265742131 0xce9bdf50 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:30:49.245 9153 9343 I GStreamer+baseparse: 0:02:28.280961245 0xce9bdf50 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:30:49.265 9153 9343 I GStreamer+baseparse: 0:02:28.300784266 0xce9bdf50 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:30:49.288 9153 9343 I GStreamer+baseparse: 0:02:28.323874683 0xce9bdf50 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:30:49.307 9153 9343 I GStreamer+baseparse: 0:02:28.342964006 0xce9bdf50 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
*:4 log for the playbin pipeline: 03-05 23:45:50.053 10004 10183 I GStreamer+baseparse: 0:01:43.665038554 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:45:50.055 10004 10183 I GStreamer+baseparse: 0:01:43.667027929 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:45:50.061 10004 10183 I GStreamer+baseparse: 0:01:43.673179075 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:45:50.068 10004 10183 I GStreamer+videodecoder: 0:01:43.680391940 0xd24d29b0 gstvideodecoder.c:1432:gst_video_decoder_sink_event_default:<amcvideodec-omxqcomvideodecoderavc1> upstream tags: taglist, video-codec=(string)"H.264\ \(Baseline\ Profile\)", bitrate=(uint)59910406, language-code=(string)en, minimum-bitrate=(uint)58910134, maximum-bitrate=(uint)59523670; 03-05 23:45:50.073 10004 10004 D GStreamer+aiTennis3D: 0:01:43.685840638 0xf0d3fc00 gstreamer/aigstreamer.c:862:gst_native_seek Doing seek at 31713 mseconds 03-05 23:45:50.073 10004 10004 I GStreamer+GST_EVENT: 0:01:43.686014232 0xf0d3fc00 gstevent.c:1139:gst_event_new_seek creating seek rate 1.000000, format TIME, flags 5, start_type 1, start 0:00:31.713000000, stop_type 0, stop 0:00:00.000000000 03-05 23:45:50.083 10004 10004 I GStreamer+qtdemux: 0:01:43.695640117 0xf0d3fc00 qtdemux.c:1679:gst_qtdemux_handle_src_event:<qtdemux1> Time taken to parse index 0:00:00.009257083 03-05 23:45:50.086 10004 10004 I GStreamer+GST_STATES: 0:01:43.698018294 0xf0d3fc00 gstelement.c:2277:_priv_gst_element_state_changed:<sink> notifying about state-changed PAUSED to PAUSED (PAUSED pending) 03-05 23:45:50.086 10004 10004 I GStreamer+GST_STATES: 0:01:43.698366054 0xf0d3fc00 gstelement.c:2277:_priv_gst_element_state_changed:<glimagesinkbin1> notifying about state-changed PAUSED to PAUSED (PAUSED pending) 03-05 23:45:50.086 10004 10004 I GStreamer+GST_STATES: 0:01:43.698651159 0xf0d3fc00 gstelement.c:2277:_priv_gst_element_state_changed:<vbin> notifying about state-changed PAUSED to PAUSED (PAUSED pending) 03-05 23:45:50.086 10004 10182 I GStreamer+task: 0:01:43.698954127 0xcfc47d50 gsttask.c:316:gst_task_func:<qtdemux1:sink> Task going to paused 03-05 23:45:50.086 10004 10004 I GStreamer+GST_STATES: 0:01:43.699005429 0xf0d3fc00 gstelement.c:2277:_priv_gst_element_state_changed:<playsink> notifying about state-changed PAUSED to PAUSED (PAUSED pending) 03-05 23:45:50.087 10004 10004 I GStreamer+GST_STATES: 0:01:43.699304075 0xf0d3fc00 gstelement.c:2277:_priv_gst_element_state_changed:<playbin1> notifying about state-changed PAUSED to PAUSED (PAUSED pending) 03-05 23:45:50.087 10004 10183 I GStreamer+task: 0:01:43.699361992 0xd24d29b0 gsttask.c:316:gst_task_func:<multiqueue1:src_0> Task going to paused 03-05 23:45:50.087 10004 10177 I System.out: Gst setMessage (0) State changed (0) to PAUSED 03-05 23:45:50.088 10004 10189 I GStreamer+task: 0:01:43.700083294 0xd24d2460 gsttask.c:316:gst_task_func:<amcvideodec-omxqcomvideodecoderavc1:src> Task going to paused 03-05 23:45:50.088 10004 10190 I GStreamer+task: 0:01:43.700375638 0xdcf6dbb0 gsttask.c:316:gst_task_func:<vqueue:src> Task going to paused 03-05 23:45:50.088 10004 10004 I GStreamer+default: 0:01:43.700722721 0xf0d3fc00 gstsegment.c:372:gst_segment_do_seek segment updated: time segment start=0:00:31.713000000, offset=0:00:00.000000000, stop=0:00:41.982000000, rate=1.000000, applied_rate=1.000000, flags=0x01, time=0:00:31.713000000, base=0:00:00.000000000, position 0:00:31.713000000, duration 0:00:41.982000000 03-05 23:45:50.088 10004 10004 I GStreamer+GST_EVENT: 0:01:43.700878450 0xf0d3fc00 gstevent.c:547:gst_event_new_flush_stop creating flush stop 1 03-05 23:45:50.092 10004 10189 I GStreamer+task: 0:01:43.704026054 0xd24d2460 gsttask.c:318:gst_task_func:<amcvideodec-omxqcomvideodecoderavc1:src> Task resume from paused 03-05 23:45:50.092 10004 10190 I GStreamer+task: 0:01:43.704674857 0xdcf6dbb0 gsttask.c:318:gst_task_func:<vqueue:src> Task resume from paused 03-05 23:45:50.092 10004 10182 I GStreamer+task: 0:01:43.704727565 0xcfc47d50 gsttask.c:318:gst_task_func:<qtdemux1:sink> Task resume from paused 03-05 23:45:50.092 10004 10183 I GStreamer+task: 0:01:43.704789492 0xd24d29b0 gsttask.c:318:gst_task_func:<multiqueue1:src_0> Task resume from paused 03-05 23:45:50.092 10004 10182 I GStreamer+GST_EVENT: 0:01:43.704940221 0xcfc47d50 gstevent.c:760:gst_event_new_segment creating segment event time segment start=0:00:31.713000000, offset=0:00:00.000000000, stop=0:00:41.982000000, rate=1.000000, applied_rate=1.000000, flags=0x01, time=0:00:31.713000000, base=0:00:00.000000000, position 0:00:31.713000000, duration 99:99:99.999999999 03-05 23:45:50.102 10004 10183 I GStreamer+h264parse: 0:01:43.714807565 0xd24d29b0 gsth264parse.c:743:gst_h264_parse_process_nal:<h264parse1> have SPS/PPS in stream 03-05 23:45:50.103 10004 10183 I GStreamer+baseparse: 0:01:43.715352200 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:45:50.125 10004 10183 I GStreamer+baseparse: 0:01:43.737678190 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:45:50.126 10004 10183 I GStreamer+videodecoder: 0:01:43.738612565 0xd24d29b0 gstvideodecoder.c:1432:gst_video_decoder_sink_event_default:<amcvideodec-omxqcomvideodecoderavc1> upstream tags: taglist, video-codec=(string)"H.264\ \(Baseline\ Profile\)", bitrate=(uint)59910406, language-code=(string)en, minimum-bitrate=(uint)58910134, maximum-bitrate=(uint)60183201; 03-05 23:45:50.128 10004 10183 I GStreamer+baseparse: 0:01:43.740961211 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:45:50.130 10004 10183 I GStreamer+baseparse: 0:01:43.742697825 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:45:50.131 10004 10183 I GStreamer+videodecoder: 0:01:43.743435169 0xd24d29b0 gstvideodecoder.c:1432:gst_video_decoder_sink_event_default:<amcvideodec-omxqcomvideodecoderavc1> upstream tags: taglist, video-codec=(string)"H.264\ \(Baseline\ Profile\)", bitrate=(uint)59910406, language-code=(string)en, minimum-bitrate=(uint)58910134, maximum-bitrate=(uint)60234534; 03-05 23:45:50.142 10004 10189 I GStreamer+GST_EVENT: 0:01:43.754383607 0xd24d2460 gstevent.c:760:gst_event_new_segment creating segment event time segment start=0:00:31.713000000, offset=0:00:00.000000000, stop=0:00:41.982000000, rate=1.000000, applied_rate=1.000000, flags=0x01, time=0:00:31.713000000, base=0:00:00.000000000, position 0:00:31.713000000, duration 99:99:99.999999999 03-05 23:45:50.149 10004 10183 I GStreamer+baseparse: 0:01:43.761115377 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:45:50.150 10004 10183 I GStreamer+baseparse: 0:01:43.762864648 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:45:50.151 10004 10183 I GStreamer+videodecoder: 0:01:43.763510482 0xd24d29b0 gstvideodecoder.c:1432:gst_video_decoder_sink_event_default:<amcvideodec-omxqcomvideodecoderavc1> upstream tags: taglist, video-codec=(string)"H.264\ \(Baseline\ Profile\)", bitrate=(uint)59910406, language-code=(string)en, minimum-bitrate=(uint)58910134, maximum-bitrate=(uint)60265334; 03-05 23:45:50.152 10004 10183 I GStreamer+baseparse: 0:01:43.764953450 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:45:50.153 10004 10183 I GStreamer+videodecoder: 0:01:43.765533034 0xd24d29b0 gstvideodecoder.c:1432:gst_video_decoder_sink_event_default:<amcvideodec-omxqcomvideodecoderavc1> upstream tags: taglist, video-codec=(string)"H.264\ \(Baseline\ Profile\)", bitrate=(uint)59910406, language-code=(string)en, minimum-bitrate=(uint)58910134, maximum-bitrate=(uint)60323649; 03-05 23:45:50.154 10004 10183 I GStreamer+baseparse: 0:01:43.766562721 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:45:50.159 10004 10183 I GStreamer+baseparse: 0:01:43.771724232 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:45:50.159 10004 10190 I GStreamer+GST_STATES: 0:01:43.771971315 0xdcf6dbb0 gstbin.c:3238:bin_handle_async_done:<glimagesinkbin1> committing state from PAUSED to PAUSED, old pending PLAYING 03-05 23:45:50.160 10004 10190 I GStreamer+GST_STATES: 0:01:43.772073034 0xdcf6dbb0 gstbin.c:3258:bin_handle_async_done:<glimagesinkbin1> completed state change, pending VOID 03-05 23:45:50.160 10004 10190 I GStreamer+GST_STATES: 0:01:43.772178919 0xdcf6dbb0 gstelement.c:2277:_priv_gst_element_state_changed:<glimagesinkbin1> notifying about state-changed PAUSED to PAUSED (VOID_PENDING pending) 03-05 23:45:50.160 10004 10190 I GStreamer+GST_STATES: 0:01:43.772343554 0xdcf6dbb0 gstbin.c:3238:bin_handle_async_done:<vbin> committing state from PAUSED to PAUSED, old pending PLAYING 03-05 23:45:50.160 10004 10190 I GStreamer+GST_STATES: 0:01:43.772497200 0xdcf6dbb0 gstbin.c:3258:bin_handle_async_done:<vbin> completed state change, pending VOID 03-05 23:45:50.160 10004 10190 I GStreamer+GST_STATES: 0:01:43.772603346 0xdcf6dbb0 gstelement.c:2277:_priv_gst_element_state_changed:<vbin> notifying about state-changed PAUSED to PAUSED (VOID_PENDING pending) 03-05 23:45:50.160 10004 10190 I GStreamer+GST_STATES: 0:01:43.772751002 0xdcf6dbb0 gstbin.c:3238:bin_handle_async_done:<playsink> committing state from PAUSED to PAUSED, old pending PLAYING 03-05 23:45:50.160 10004 10190 I GStreamer+GST_STATES: 0:01:43.772869857 0xdcf6dbb0 gstbin.c:3258:bin_handle_async_done:<playsink> completed state change, pending VOID 03-05 23:45:50.160 10004 10190 I GStreamer+GST_STATES: 0:01:43.773009284 0xdcf6dbb0 gstelement.c:2277:_priv_gst_element_state_changed:<playsink> notifying about state-changed PAUSED to PAUSED (VOID_PENDING pending) 03-05 23:45:50.161 10004 10190 I GStreamer+GST_STATES: 0:01:43.773318450 0xdcf6dbb0 gstbin.c:3238:bin_handle_async_done:<playbin1> committing state from PAUSED to PAUSED, old pending PLAYING 03-05 23:45:50.161 10004 10190 I GStreamer+GST_STATES: 0:01:43.773436679 0xdcf6dbb0 gstbin.c:3267:bin_handle_async_done:<playbin1> continue state change, pending PLAYING 03-05 23:45:50.161 10004 10190 I GStreamer+GST_STATES: 0:01:43.773530325 0xdcf6dbb0 gstelement.c:2277:_priv_gst_element_state_changed:<playbin1> notifying about state-changed PAUSED to PAUSED (PLAYING pending) 03-05 23:45:50.161 10004 10177 I System.out: Gst setMessage (0) State changed (0) to PAUSED 03-05 23:45:50.162 10004 10191 I GStreamer+GST_STATES: 0:01:43.774054804 0xdc9faf20 gstbin.c:3061:gst_bin_continue_func:<playbin1> continue state change PAUSED to PLAYING, final PLAYING 03-05 23:45:50.162 10004 10191 I GStreamer+GST_EVENT: 0:01:43.774669075 0xdc9faf20 gstevent.c:1253:gst_event_new_latency creating latency event 0:00:00.000000000 03-05 23:45:50.163 10004 10191 I GStreamer+bin: 0:01:43.775059961 0xdc9faf20 gstbin.c:2593:gst_bin_do_latency_func:<playbin1> configured latency of 0:00:00.000000000 03-05 23:45:50.163 10004 10191 I GStreamer+GST_STATES: 0:01:43.775209909 0xdc9faf20 gstbin.c:2316:gst_bin_element_set_state:<playsink> current PAUSED pending VOID_PENDING, desired next PLAYING 03-05 23:45:50.163 10004 10191 I GStreamer+GST_STATES: 0:01:43.775337982 0xdc9faf20 gstbin.c:2316:gst_bin_element_set_state:<vbin> current PAUSED pending VOID_PENDING, desired next PLAYING 03-05 23:45:50.163 10004 10191 I GStreamer+GST_STATES: 0:01:43.775456002 0xdc9faf20 gstbin.c:2316:gst_bin_element_set_state:<glimagesinkbin1> current PAUSED pending VOID_PENDING, desired next PLAYING 03-05 23:45:50.163 10004 10183 I GStreamer+baseparse: 0:01:43.775486992 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:45:50.163 10004 10191 I GStreamer+GST_STATES: 0:01:43.775577461 0xdc9faf20 gstbin.c:2316:gst_bin_element_set_state:<sink> current PAUSED pending VOID_PENDING, desired next PLAYING 03-05 23:45:50.163 10004 10191 I GStreamer+GST_STATES: 0:01:43.775690377 0xdc9faf20 gstelement.c:2372:gst_element_continue_state:<sink> completed state change to PLAYING 03-05 23:45:50.163 10004 10191 I GStreamer+GST_STATES: 0:01:43.775788086 0xdc9faf20 gstelement.c:2277:_priv_gst_element_state_changed:<sink> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending) 03-05 23:45:50.163 10004 10191 I GStreamer+GST_STATES: 0:01:43.775993554 0xdc9faf20 gstbin.c:2764:gst_bin_change_state_func:<glimagesinkbin1> child 'sink' changed state to 4(PLAYING) successfully 03-05 23:45:50.164 10004 10191 I GStreamer+GST_STATES: 0:01:43.776097409 0xdc9faf20 gstbin.c:2316:gst_bin_element_set_state:<glcolorbalance1> current PLAYING pending VOID_PENDING, desired next PLAYING 03-05 23:45:50.164 10004 10191 I GStreamer+GST_STATES: 0:01:43.776185429 0xdc9faf20 gstbin.c:2433:gst_bin_element_set_state:<glcolorbalance1> skipping transition from PLAYING to PLAYING 03-05 23:45:50.164 10004 10191 I GStreamer+GST_STATES: 0:01:43.776276054 0xdc9faf20 gstbin.c:2764:gst_bin_change_state_func:<glimagesinkbin1> child 'glcolorbalance1' changed state to 4(PLAYING) successfully 03-05 23:45:50.164 10004 10191 I GStreamer+GST_STATES: 0:01:43.776376992 0xdc9faf20 gstbin.c:2316:gst_bin_element_set_state:<glcolorconvertelement1> current PLAYING pending VOID_PENDING, desired next PLAYING 03-05 23:45:50.164 10004 10191 I GStreamer+GST_STATES: 0:01:43.776463867 0xdc9faf20 gstbin.c:2433:gst_bin_element_set_state:<glcolorconvertelement1> skipping transition from PLAYING to PLAYING 03-05 23:45:50.164 10004 10191 I GStreamer+GST_STATES: 0:01:43.776556054 0xdc9faf20 gstbin.c:2764:gst_bin_change_state_func:<glimagesinkbin1> child 'glcolorconvertelement1' changed state to 4(PLAYING) successfully 03-05 23:45:50.164 10004 10191 I GStreamer+GST_STATES: 0:01:43.776658607 0xdc9faf20 gstbin.c:2316:gst_bin_element_set_state:<gluploadelement1> current PLAYING pending VOID_PENDING, desired next PLAYING 03-05 23:45:50.164 10004 10191 I GStreamer+GST_STATES: 0:01:43.776748659 0xdc9faf20 gstbin.c:2433:gst_bin_element_set_state:<gluploadelement1> skipping transition from PLAYING to PLAYING 03-05 23:45:50.164 10004 10191 I GStreamer+GST_STATES: 0:01:43.776839075 0xdc9faf20 gstbin.c:2764:gst_bin_change_state_func:<glimagesinkbin1> child 'gluploadelement1' changed state to 4(PLAYING) successfully 03-05 23:45:50.164 10004 10191 I GStreamer+GST_STATES: 0:01:43.776937200 0xdc9faf20 gstelement.c:2372:gst_element_continue_state:<glimagesinkbin1> completed state change to PLAYING 03-05 23:45:50.165 10004 10191 I GStreamer+GST_STATES: 0:01:43.777025429 0xdc9faf20 gstelement.c:2277:_priv_gst_element_state_changed:<glimagesinkbin1> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending) 03-05 23:45:50.165 10004 10191 I GStreamer+GST_STATES: 0:01:43.777971315 0xdc9faf20 gstbin.c:2764:gst_bin_change_state_func:<vbin> child 'glimagesinkbin1' changed state to 4(PLAYING) successfully 03-05 23:45:50.166 10004 10191 I GStreamer+GST_STATES: 0:01:43.778173086 0xdc9faf20 gstbin.c:2316:gst_bin_element_set_state:<vconv> current PLAYING pending VOID_PENDING, desired next PLAYING 03-05 23:45:50.166 10004 10191 I GStreamer+GST_STATES: 0:01:43.778331054 0xdc9faf20 gstbin.c:2316:gst_bin_element_set_state:<scale> current PLAYING pending VOID_PENDING, desired next PLAYING 03-05 23:45:50.166 10004 10191 I GStreamer+GST_STATES: 0:01:43.778422252 0xdc9faf20 gstbin.c:2433:gst_bin_element_set_state:<scale> skipping transition from PLAYING to PLAYING 03-05 23:45:50.166 10004 10191 I GStreamer+GST_STATES: 0:01:43.778524388 0xdc9faf20 gstbin.c:2764:gst_bin_change_state_func:<vconv> child 'scale' changed state to 4(PLAYING) successfully 03-05 23:45:50.166 10004 10191 I GStreamer+GST_STATES: 0:01:43.778619284 0xdc9faf20 gstbin.c:2316:gst_bin_element_set_state:<conv> current PLAYING pending VOID_PENDING, desired next PLAYING 03-05 23:45:50.166 10004 10191 I GStreamer+GST_STATES: 0:01:43.778795690 0xdc9faf20 gstbin.c:2433:gst_bin_element_set_state:<conv> skipping transition from PLAYING to PLAYING 03-05 23:45:50.166 10004 10191 I GStreamer+GST_STATES: 0:01:43.778890221 0xdc9faf20 gstbin.c:2764:gst_bin_change_state_func:<vconv> child 'conv' changed state to 4(PLAYING) successfully 03-05 23:45:50.166 10004 10191 I GStreamer+GST_STATES: 0:01:43.778990013 0xdc9faf20 gstbin.c:2316:gst_bin_element_set_state:<identity> current PLAYING pending VOID_PENDING, desired next PLAYING 03-05 23:45:50.167 10004 10191 I GStreamer+GST_STATES: 0:01:43.779132982 0xdc9faf20 gstbin.c:2433:gst_bin_element_set_state:<identity> skipping transition from PLAYING to PLAYING 03-05 23:45:50.167 10004 10191 I GStreamer+GST_STATES: 0:01:43.779227200 0xdc9faf20 gstbin.c:2764:gst_bin_change_state_func:<vconv> child 'identity' changed state to 4(PLAYING) successfully 03-05 23:45:50.167 10004 10191 I GStreamer+GST_STATES: 0:01:43.779326002 0xdc9faf20 gstelement.c:2372:gst_element_continue_state:<vconv> completed state change to PLAYING 03-05 23:45:50.167 10004 10191 I GStreamer+GST_STATES: 0:01:43.779417825 0xdc9faf20 gstbin.c:2764:gst_bin_change_state_func:<vbin> child 'vconv' changed state to 4(PLAYING) successfully 03-05 23:45:50.167 10004 10191 I GStreamer+GST_STATES: 0:01:43.779519596 0xdc9faf20 gstbin.c:2316:gst_bin_element_set_state:<vqueue> current PLAYING pending VOID_PENDING, desired next PLAYING 03-05 23:45:50.167 10004 10191 I GStreamer+GST_STATES: 0:01:43.779618815 0xdc9faf20 gstbin.c:2433:gst_bin_element_set_state:<vqueue> skipping transition from PLAYING to PLAYING 03-05 23:45:50.167 10004 10191 I GStreamer+GST_STATES: 0:01:43.779708398 0xdc9faf20 gstbin.c:2764:gst_bin_change_state_func:<vbin> child 'vqueue' changed state to 4(PLAYING) successfully 03-05 23:45:50.167 10004 10191 I GStreamer+GST_STATES: 0:01:43.779811211 0xdc9faf20 gstelement.c:2372:gst_element_continue_state:<vbin> completed state change to PLAYING 03-05 23:45:50.167 10004 10191 I GStreamer+GST_STATES: 0:01:43.779909075 0xdc9faf20 gstelement.c:2277:_priv_gst_element_state_changed:<vbin> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending) 03-05 23:45:50.168 10004 10191 I GStreamer+GST_STATES: 0:01:43.780519179 0xdc9faf20 gstbin.c:2764:gst_bin_change_state_func:<playsink> child 'vbin' changed state to 4(PLAYING) successfully 03-05 23:45:50.168 10004 10183 I GStreamer+baseparse: 0:01:43.780613659 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:45:50.168 10004 10191 I GStreamer+GST_STATES: 0:01:43.780725638 0xdc9faf20 gstbin.c:2316:gst_bin_element_set_state:<vdbin> current PLAYING pending VOID_PENDING, desired next PLAYING 03-05 23:45:50.168 10004 10191 I GStreamer+GST_STATES: 0:01:43.780875482 0xdc9faf20 gstbin.c:2316:gst_bin_element_set_state:<vdconv> current PLAYING pending VOID_PENDING, desired next PLAYING 03-05 23:45:50.168 10004 10191 I GStreamer+GST_STATES: 0:01:43.780963919 0xdc9faf20 gstbin.c:2433:gst_bin_element_set_state:<vdconv> skipping transition from PLAYING to PLAYING 03-05 23:45:50.169 10004 10191 I GStreamer+GST_STATES: 0:01:43.781058242 0xdc9faf20 gstbin.c:2764:gst_bin_change_state_func:<vdbin> child 'vdconv' changed state to 4(PLAYING) successfully 03-05 23:45:50.169 10004 10191 I GStreamer+GST_STATES: 0:01:43.781157721 0xdc9faf20 gstelement.c:2372:gst_element_continue_state:<vdbin> completed state change to PLAYING 03-05 23:45:50.169 10004 10191 I GStreamer+GST_STATES: 0:01:43.781251159 0xdc9faf20 gstbin.c:2764:gst_bin_change_state_func:<playsink> child 'vdbin' changed state to 4(PLAYING) successfully 03-05 23:45:50.169 10004 10191 I GStreamer+GST_STATES: 0:01:43.781357825 0xdc9faf20 gstbin.c:2316:gst_bin_element_set_state:<streamsynchronizer1> current PLAYING pending VOID_PENDING, desired next PLAYING 03-05 23:45:50.169 10004 10191 I GStreamer+GST_STATES: 0:01:43.781444857 0xdc9faf20 gstbin.c:2433:gst_bin_element_set_state:<streamsynchronizer1> skipping transition from PLAYING to PLAYING 03-05 23:45:50.169 10004 10191 I GStreamer+GST_STATES: 0:01:43.781536575 0xdc9faf20 gstbin.c:2764:gst_bin_change_state_func:<playsink> child 'streamsynchronizer1' changed state to 4(PLAYING) successfully 03-05 23:45:50.169 10004 10191 I GStreamer+GST_STATES: 0:01:43.781643346 0xdc9faf20 gstelement.c:2372:gst_element_continue_state:<playsink> completed state change to PLAYING 03-05 23:45:50.169 10004 10191 I GStreamer+GST_STATES: 0:01:43.781748138 0xdc9faf20 gstelement.c:2277:_priv_gst_element_state_changed:<playsink> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending) 03-05 23:45:50.170 10004 10191 I GStreamer+GST_STATES: 0:01:43.782088607 0xdc9faf20 gstbin.c:2764:gst_bin_change_state_func:<playbin1> child 'playsink' changed state to 4(PLAYING) successfully 03-05 23:45:50.170 10004 10191 I GStreamer+GST_STATES: 0:01:43.782207252 0xdc9faf20 gstbin.c:2316:gst_bin_element_set_state:<inputselector1> current PLAYING pending VOID_PENDING, desired next PLAYING 03-05 23:45:50.170 10004 10191 I GStreamer+GST_STATES: 0:01:43.782295742 0xdc9faf20 gstbin.c:2433:gst_bin_element_set_state:<inputselector1> skipping transition from PLAYING to PLAYING 03-05 23:45:50.170 10004 10191 I GStreamer+GST_STATES: 0:01:43.782546627 0xdc9faf20 gstbin.c:2764:gst_bin_change_state_func:<playbin1> child 'inputselector1' changed state to 4(PLAYING) successfully 03-05 23:45:50.170 10004 10191 I GStreamer+GST_STATES: 0:01:43.782671940 0xdc9faf20 gstbin.c:2316:gst_bin_element_set_state:<uridecodebin1> current PLAYING pending VOID_PENDING, desired next PLAYING 03-05 23:45:50.170 10004 10191 I GStreamer+GST_STATES: 0:01:43.782804700 0xdc9faf20 gstbin.c:2316:gst_bin_element_set_state:<decodebin1> current PLAYING pending VOID_PENDING, desired next PLAYING 03-05 23:45:50.170 10004 10191 I GStreamer+GST_STATES: 0:01:43.782957304 0xdc9faf20 gstbin.c:2316:gst_bin_element_set_state:<amcvideodec-omxqcomvideodecoderavc1> current PLAYING pending VOID_PENDING, desired next PLAYING 03-05 23:45:50.171 10004 10191 I GStreamer+GST_STATES: 0:01:43.783051784 0xdc9faf20 gstbin.c:2433:gst_bin_element_set_state:<amcvideodec-omxqcomvideodecoderavc1> skipping transition from PLAYING to PLAYING 03-05 23:45:50.171 10004 10191 I GStreamer+GST_STATES: 0:01:43.783140117 0xdc9faf20 gstbin.c:2764:gst_bin_change_state_func:<decodebin1> child 'amcvideodec-omxqcomvideodecoderavc1' changed state to 4(PLAYING) successfully 03-05 23:45:50.171 10004 10191 I GStreamer+GST_STATES: 0:01:43.783243763 0xdc9faf20 gstbin.c:2316:gst_bin_element_set_state:<capsfilter1> current PLAYING pending VOID_PENDING, desired next PLAYING 03-05 23:45:50.171 10004 10191 I GStreamer+GST_STATES: 0:01:43.783331263 0xdc9faf20 gstbin.c:2433:gst_bin_element_set_state:<capsfilter1> skipping transition from PLAYING to PLAYING 03-05 23:45:50.171 10004 10191 I GStreamer+GST_STATES: 0:01:43.783422044 0xdc9faf20 gstbin.c:2764:gst_bin_change_state_func:<decodebin1> child 'capsfilter1' changed state to 4(PLAYING) successfully 03-05 23:45:50.171 10004 10191 I GStreamer+GST_STATES: 0:01:43.783527304 0xdc9faf20 gstbin.c:2316:gst_bin_element_set_state:<h264parse1> current PLAYING pending VOID_PENDING, desired next PLAYING 03-05 23:45:50.171 10004 10191 I GStreamer+GST_STATES: 0:01:43.783618971 0xdc9faf20 gstbin.c:2433:gst_bin_element_set_state:<h264parse1> skipping transition from PLAYING to PLAYING 03-05 23:45:50.171 10004 10191 I GStreamer+GST_STATES: 0:01:43.783707929 0xdc9faf20 gstbin.c:2764:gst_bin_change_state_func:<decodebin1> child 'h264parse1' changed state to 4(PLAYING) successfully 03-05 23:45:50.171 10004 10191 I GStreamer+GST_STATES: 0:01:43.783810898 0xdc9faf20 gstbin.c:2316:gst_bin_element_set_state:<multiqueue1> current PLAYING pending VOID_PENDING, desired next PLAYING 03-05 23:45:50.171 10004 10191 I GStreamer+GST_STATES: 0:01:43.783903242 0xdc9faf20 gstbin.c:2433:gst_bin_element_set_state:<multiqueue1> skipping transition from PLAYING to PLAYING 03-05 23:45:50.171 10004 10191 I GStreamer+GST_STATES: 0:01:43.783991471 0xdc9faf20 gstbin.c:2764:gst_bin_change_state_func:<decodebin1> child 'multiqueue1' changed state to 4(PLAYING) successfully 03-05 23:45:50.172 10004 10191 I GStreamer+GST_STATES: 0:01:43.784093607 0xdc9faf20 gstbin.c:2316:gst_bin_element_set_state:<qtdemux1> current PLAYING pending VOID_PENDING, desired next PLAYING 03-05 23:45:50.172 10004 10191 I GStreamer+GST_STATES: 0:01:43.784178346 0xdc9faf20 gstbin.c:2433:gst_bin_element_set_state:<qtdemux1> skipping transition from PLAYING to PLAYING 03-05 23:45:50.172 10004 10191 I GStreamer+GST_STATES: 0:01:43.784266419 0xdc9faf20 gstbin.c:2764:gst_bin_change_state_func:<decodebin1> child 'qtdemux1' changed state to 4(PLAYING) successfully 03-05 23:45:50.172 10004 10191 I GStreamer+GST_STATES: 0:01:43.784362617 0xdc9faf20 gstbin.c:2316:gst_bin_element_set_state:<typefind> current PLAYING pending VOID_PENDING, desired next PLAYING 03-05 23:45:50.172 10004 10191 I GStreamer+GST_STATES: 0:01:43.784448294 0xdc9faf20 gstbin.c:2433:gst_bin_element_set_state:<typefind> skipping transition from PLAYING to PLAYING 03-05 23:45:50.172 10004 10191 I GStreamer+GST_STATES: 0:01:43.784540794 0xdc9faf20 gstbin.c:2764:gst_bin_change_state_func:<decodebin1> child 'typefind' changed state to 4(PLAYING) successfully 03-05 23:45:50.172 10004 10191 I GStreamer+GST_STATES: 0:01:43.784646732 0xdc9faf20 gstelement.c:2372:gst_element_continue_state:<decodebin1> completed state change to PLAYING 03-05 23:45:50.172 10004 10191 I GStreamer+GST_STATES: 0:01:43.784760742 0xdc9faf20 gstbin.c:2764:gst_bin_change_state_func:<uridecodebin1> child 'decodebin1' changed state to 4(PLAYING) successfully 03-05 23:45:50.172 10004 10191 I GStreamer+GST_STATES: 0:01:43.784860898 0xdc9faf20 gstbin.c:2316:gst_bin_element_set_state:<source> current PLAYING pending VOID_PENDING, desired next PLAYING 03-05 23:45:50.172 10004 10191 I GStreamer+GST_STATES: 0:01:43.784950846 0xdc9faf20 gstbin.c:2433:gst_bin_element_set_state:<source> skipping transition from PLAYING to PLAYING 03-05 23:45:50.173 10004 10191 I GStreamer+GST_STATES: 0:01:43.785049544 0xdc9faf20 gstbin.c:2764:gst_bin_change_state_func:<uridecodebin1> child 'source' changed state to 4(PLAYING) successfully 03-05 23:45:50.173 10004 10191 I GStreamer+GST_STATES: 0:01:43.785152461 0xdc9faf20 gstelement.c:2372:gst_element_continue_state:<uridecodebin1> completed state change to PLAYING 03-05 23:45:50.173 10004 10191 I GStreamer+GST_STATES: 0:01:43.785252096 0xdc9faf20 gstbin.c:2764:gst_bin_change_state_func:<playbin1> child 'uridecodebin1' changed state to 4(PLAYING) successfully 03-05 23:45:50.173 10004 10191 I GStreamer+GST_STATES: 0:01:43.785346263 0xdc9faf20 gstelement.c:2372:gst_element_continue_state:<playbin1> completed state change to PLAYING 03-05 23:45:50.173 10004 10191 I GStreamer+GST_STATES: 0:01:43.785442096 0xdc9faf20 gstelement.c:2277:_priv_gst_element_state_changed:<playbin1> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending) 03-05 23:45:50.173 10004 10177 I System.out: Gst setMessage (0) State changed (0) to PLAYING 03-05 23:45:50.174 10004 10183 I GStreamer+baseparse: 0:01:43.786688659 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:45:50.180 10004 10183 I GStreamer+baseparse: 0:01:43.792532148 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:45:50.187 10004 10183 I GStreamer+baseparse: 0:01:43.799091784 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:45:50.206 10004 10183 I GStreamer+baseparse: 0:01:43.818876159 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:45:50.245 10004 10183 I GStreamer+baseparse: 0:01:43.857767773 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:45:50.266 10004 10183 I GStreamer+baseparse: 0:01:43.878381940 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:45:50.286 10004 10183 I GStreamer+baseparse: 0:01:43.898369804 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:45:50.305 10004 10183 I GStreamer+baseparse: 0:01:43.917465013 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:45:50.323 10004 10183 I GStreamer+videodecoder: 0:01:43.935723659 0xd24d29b0 gstvideodecoder.c:1432:gst_video_decoder_sink_event_default:<amcvideodec-omxqcomvideodecoderavc1> upstream tags: taglist, video-codec=(string)"H.264\ \(Baseline\ Profile\)", bitrate=(uint)59910406, language-code=(string)en, minimum-bitrate=(uint)58910134, maximum-bitrate=(uint)60381142; 03-05 23:45:50.345 10004 10183 I GStreamer+baseparse: 0:01:43.957159752 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:45:50.365 10004 10183 I GStreamer+baseparse: 0:01:43.977548971 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:45:50.383 10004 10183 I GStreamer+baseparse: 0:01:43.995340638 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:45:50.396 10004 10181 W GStreamer+amcvideodec: 0:01:44.008156158 0xdd4f8e30 gstamcvideodec.c:1165:_amc_gl_wait gl_sync 0xdd059530 could not wait for frame, took too long 03-05 23:45:50.402 10004 10183 I GStreamer+baseparse: 0:01:44.014981211 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:45:50.421 10004 10183 I GStreamer+baseparse: 0:01:44.033639231 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:45:50.440 10004 10183 I GStreamer+baseparse: 0:01:44.052932044 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:45:50.460 10004 10183 I GStreamer+baseparse: 0:01:44.072131419 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:45:50.480 10004 10183 I GStreamer+baseparse: 0:01:44.092328190 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:45:50.499 10004 10183 I GStreamer+baseparse: 0:01:44.111938242 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:45:50.519 10004 10183 I GStreamer+baseparse: 0:01:44.131230586 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:45:50.537 10004 10183 I GStreamer+baseparse: 0:01:44.149844127 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:45:50.556 10004 10183 I GStreamer+videodecoder: 0:01:44.168187981 0xd24d29b0 gstvideodecoder.c:1432:gst_video_decoder_sink_event_default:<amcvideodec-omxqcomvideodecoderavc1> upstream tags: taglist, video-codec=(string)"H.264\ \(Baseline\ Profile\)", bitrate=(uint)59910406, language-code=(string)en, minimum-bitrate=(uint)58910134, maximum-bitrate=(uint)60439868; 03-05 23:45:50.577 10004 10183 I GStreamer+baseparse: 0:01:44.189096783 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:45:50.602 10004 10183 I GStreamer+baseparse: 0:01:44.214494804 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:45:50.617 10004 10183 I GStreamer+baseparse: 0:01:44.229538919 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:45:50.632 10004 10181 W GStreamer+amcvideodec: 0:01:44.244060065 0xdd4f8e30 gstamcvideodec.c:1165:_amc_gl_wait gl_sync 0xdd059530 could not wait for frame, took too long 03-05 23:45:50.650 10004 10183 I GStreamer+baseparse: 0:01:44.262792096 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:45:50.673 10004 10183 I GStreamer+baseparse: 0:01:44.285156835 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:45:50.674 10004 10183 I GStreamer+baseparse: 0:01:44.286759960 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:45:50.676 10004 10183 I GStreamer+baseparse: 0:01:44.288144231 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:45:50.677 10004 10183 I GStreamer+baseparse: 0:01:44.289375169 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:45:50.685 10004 10183 I GStreamer+baseparse: 0:01:44.297046992 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:45:50.694 10004 10183 I GStreamer+baseparse: 0:01:44.306973971 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:45:50.713 10004 10183 I GStreamer+baseparse: 0:01:44.325366471 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:45:50.731 10004 10183 I GStreamer+videodecoder: 0:01:44.343390846 0xd24d29b0 gstvideodecoder.c:1432:gst_video_decoder_sink_event_default:<amcvideodec-omxqcomvideodecoderavc1> upstream tags: taglist, video-codec=(string)"H.264\ \(Baseline\ Profile\)", bitrate=(uint)59910406, language-code=(string)en, minimum-bitrate=(uint)58910134, maximum-bitrate=(uint)60499825; 03-05 23:45:50.772 10004 10183 I GStreamer+baseparse: 0:01:44.384426367 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:45:50.791 10004 10183 I GStreamer+baseparse: 0:01:44.403337981 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:45:50.793 10004 10183 I GStreamer+baseparse: 0:01:44.405854283 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:45:50.811 10004 10183 I GStreamer+baseparse: 0:01:44.423278710 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:45:50.851 10004 10183 I GStreamer+baseparse: 0:01:44.463315742 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:45:50.869 10004 10183 I GStreamer+baseparse: 0:01:44.481726002 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:45:50.879 10004 10181 W GStreamer+amcvideodec: 0:01:44.491802617 0xdd4f8e30 gstamcvideodec.c:1165:_amc_gl_wait gl_sync 0xdd058ba0 could not wait for frame, took too long 03-05 23:45:50.888 10004 10183 I GStreamer+baseparse: 0:01:44.500531679 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519 03-05 23:45:50.908 10004 10183 I GStreamer+baseparse: 0:01:44.520872669 0xd24d29b0 gstbaseparse.c:3945:gst_base_parse_set_latency:<h264parse1> min/max latency 0:00:00.019480519, 0:00:00.019480519
Comment #1 is the log of the decodebin pipeline. Sorry for the confusion. Comment #2 is the log of the playbin pipeline (no error here).
Does this happen on all files, or only MP4 files? Does it only happen if amcvideodec is used? Can you provide a *:6 debug log for the failing case?
It's working fine with: https://download.blender.org/peach/bigbuckbunny_movies/big_buck_bunny_480p_stereo.ogg So I tend to believe that it's an mp4 only problem
Try with a Matroska/MKV file that also contains H264. The Ogg file contains Theora, for which amcvideodec is not going to be used.
I have "handbrake" the h264-mp4 file and I'm getting a h264 mkv file which is working fine. this mkv file reports h264-mpeg-4-avc in VLC so I guess that it's indeed a h264 video muxed in a mkv container. I have some trouble to create a *:6 log file. Too much log. The video doesn't start, Is there a relevant subset log to provide? What should I do now?
Just to make sure, does it fail on every MP4 file you try or a specific one? Also please try without linking in the androidmedia plugin (i.e. using the libav plugin instead). After that I can probably tell you what other categories to use.
short log seems to show that it's still amcvideodec that is used in case of this h264 mkv file. Definitely hardware decoder used in this case. Therefore, the problem seems to be related to the mp4 container only when decodebin is used.
It seems to do it for EVERY h264 mp4 file I have tried so far.
It also seems that it's failing without androidmedia.
Ok, *:4,qtdemux:6 might help then.
Created attachment 323200 [details] log with *:4,qtdemux:6 The seek command occurs at 09:27:50.526 (26384-msecond mark) and the video resumes 26 seconds later at 09:28:17.713.
Not sure why your pipeline runs in push mode, but that is the problem. Seeking in push mode in qtdemux seems completely broken: > gst-play-1.0 pushfile:///path/to/mp4/file Trying to seek with the arrow keys starts from 0 again
git bisect shows this as the problematic commit: 2dbc9f86fce28f7f06205b6668d568e754b89ba9 is the first bad commit commit 2dbc9f86fce28f7f06205b6668d568e754b89ba9 Author: Thiago Santos <thiagoss@osg.samsung.com> Date: Tue Nov 24 10:57:28 2015 -0300 qtdemux: restore the segment on case of soft reset When seeking back to restore the mdat position a flush is pushed through and it resets downstream segment information. Make sure that after the flush (that does a soft reset) a segment will be pushed again Fixes regressions spotted at https://ci.gstreamer.net/job/GStreamer-master-validate/2100/
Man, how do you do that??? :-) I know it's your project but how do you find a bisect in seconds? What is push mode? And why don't I get all the good memos about critical changes and new features? ;-) Anyway, reverting 2dbc9f86fce28f7f06205b6668d568e754b89ba9 fixes the problem on my Android system. I can now seek in both directions.
(In reply to Gregoire from comment #16) > Man, how do you do that??? :-) I know it's your project but how do you find > a bisect in seconds? git bisect master..1.6.0 -- gst/isomp4 and then running through that step by step until it tells me the offending commit. Only knowledge needed here is that the problem is in gst-plugins-good/gst/isomp4 and that it worked in 1.6.0 :) And you need a testcase > What is push mode? And why don't I get all the good memos about critical > changes and new features? ;-) This one is a bug, not really a critical change or new feature :) A bugfix for something else that caused a new bug. Push mode is when the source (or upstream in general) gives you buffers one after another at its own pace (and block size). Pull mode is when downstream (the demuxer usually) asks upstream (the source usually) for buffers from a specific offset with a specific size. > Anyway, reverting 2dbc9f86fce28f7f06205b6668d568e754b89ba9 fixes the problem > on my Android system. I can now seek in both directions. Thanks for confirming
Created attachment 323275 [details] [review] qtdemux: reset pending segment if we are already pushing one When upstream is running in bytes in push-mode, qtdemux will convert seeks from time to bytes and send it upstream. Upstream element will perform a byte seek and send a byte segment to qtdemux that will convert it to time and push it downstream. There is, however, the pending_segment variable that stores a new segment event to be pushed before the next data. When handling seeks as mentioned above this variable was being ignored and, if it contained some segment event, it would override the one resulting from the seek. This would restore a previous segment and would cause the seek segment to be discarded downstream. This patch fixes this issue by unrefing any pending segment as the seek from upstream should contain the latest one that should be used, as requested by the application.
I confirm that it's working with the new patch attachment 323275 [details] [review]. Thanks!!! It seems to work great now.
commit d8fb7a9c96b108814beeaa0e63f818d4648c7fe9 Author: Thiago Santos <thiagoss@osg.samsung.com> Date: Mon Mar 7 10:28:06 2016 -0300 qtdemux: reset pending segment if we are already pushing one When upstream is running in bytes in push-mode, qtdemux will convert seeks from time to bytes and send it upstream. Upstream element will perform a byte seek and send a byte segment to qtdemux that will convert it to time and push it downstream. There is, however, the pending_segment variable that stores a new segment event to be pushed before the next data. When handling seeks as mentioned above this variable was being ignored and, if it contained some segment event, it would override the one resulting from the seek. This would restore a previous segment and would cause the seek segment to be discarded downstream. This patch fixes this issue by unrefing any pending segment as the seek from upstream should contain the latest one that should be used, as requested by the application. https://bugzilla.gnome.org/show_bug.cgi?id=763165