compositor + buffering

[mariannasb]

Hi, I have a case where I want to use the compositor in order to be able to mix a live src with a buffered amount of video (which originates from the same src).
The basic idea is like a instant replay when there is fx a goal in a sports match.
So I want to have the live data playing all the time, and to keep fx the last 10 seconds saved in a queue. Then if a goal happens I want to show the content on the buffer on the same window.

The following pipeline should illustrate a bit the idea:

gst-launch-1.0 videotestsrc is-live=1 ! video/x-raw,width=500,height=500 ! timeoverlay ! tee name=t ! queue ! compositor name=mix sink_1::xpos=100 ! videoconvert ! ximagesink async=0 t. ! queue ! queue max-size-buffers=0 max-size-bytes=0 max-size-time=10000000000 min-threshold-time=10000000000 ! mix.

It almost works as expected.
The problem is that the is a 10 seconds delay before it all starts.

This is what I can see by setting the compositor and aggregators to debug level 5:

0:00:00.108142457  1404       0x6e0400 DEBUG        videoaggregator gstvideoaggregator.c:1919:gst_videoaggregator_sink_event:<mix:sink_0> Got segment event on pad mix:sink_0
0:00:00.108244765  1404       0x6e0400 DEBUG        videoaggregator gstvideoaggregator.c:952:gst_videoaggregator_update_qos:<mix> Updating QoS: proportion 0.500000, diff +0:00:00.000000000, timestamp 99:99:99.999999999
0:00:00.108449201  1404       0x6e0400 DEBUG             aggregator gstaggregator.c:1435:gst_aggregator_query_latency_unlocked:<mix> configured latency live:true min:10033333333 max:-1
0:00:00.108489586  1404       0x6e0400 DEBUG             aggregator gstaggregator.c:1202:gst_aggregator_default_sink_event:<mix:sink_0> Eating event: segment event: 0x6c8f10, time 99:99:99.999999999, seq-num 58, GstEventSegment, segment=(GstSegment)"GstSegment, flags=(GstSegmentFlags)GST_SEGMENT_FLAG_NONE, rate=(double)1, applied-rate=(double)1, format=(GstFormat)GST_FORMAT_TIME, base=(guint64)0, offset=(guint64)0, start=(guint64)0, stop=(guint64)18446744073709551615, time=(guint64)0, position=(guint64)0, duration=(guint64)18446744073709551615;";
0:00:00.108950463  1404       0x6e00f0 DEBUG             aggregator gstaggregator.c:672:gst_aggregator_wait_and_check:<mix> got subclass start time: 0:00:00.000000000
0:00:00.109017990  1404       0x6e00f0 DEBUG             aggregator gstaggregator.c:690:gst_aggregator_wait_and_check:<mix> possibly waiting for clock to reach 3:34:48.850798223 (base 3:34:38.817464890 start 0:00:00.000000000 latency 0:00:10.033333333 current 3:34:38.843425373)
0:00:00.109107989  1404       0x6e04a0 DEBUG        videoaggregator gstvideoaggregator.c:1919:gst_videoaggregator_sink_event:<mix:sink_1> Got segment event on pad mix:sink_1
0:00:00.109138507  1404       0x6e04a0 DEBUG        videoaggregator gstvideoaggregator.c:952:gst_videoaggregator_update_qos:<mix> Updating QoS: proportion 0.500000, diff +0:00:00.000000000, timestamp 99:99:99.999999999
0:00:00.109181071  1404       0x6e04a0 DEBUG             aggregator gstaggregator.c:1202:gst_aggregator_default_sink_event:<mix:sink_1> Eating event: segment event: 0x6c8f10, time 99:99:99.999999999, seq-num 58, GstEventSegment, segment=(GstSegment)"GstSegment, flags=(GstSegmentFlags)GST_SEGMENT_FLAG_NONE, rate=(double)1, applied-rate=(double)1, format=(GstFormat)GST_FORMAT_TIME, base=(guint64)0, offset=(guint64)0, start=(guint64)0, stop=(guint64)18446744073709551615, time=(guint64)0, position=(guint64)0, duration=(guint64)18446744073709551615;";
0:00:00.119823130  1404       0x6e0400 DEBUG             aggregator gstaggregator.c:2148:gst_aggregator_pad_chain_internal:<mix:sink_0> Start chaining a buffer buffer: 0x7f91d000e060, pts 0:00:00.024814444, dts 99:99:99.999999999, dur 0:00:00.033333333, size 376000, offset 0, offset_end 1, flags 0x40
0:00:00.119966388  1404       0x6e0400 DEBUG             aggregator gstaggregator.c:2251:gst_aggregator_pad_chain_internal:<mix> Selecting start time 0:00:00.000000000
0:00:00.119998132  1404       0x6e0400 DEBUG             aggregator gstaggregator.c:2263:gst_aggregator_pad_chain_internal:<mix:sink_0> Done chaining
0:00:00.120258146  1404       0x6e00f0 DEBUG             aggregator gstaggregator.c:707:gst_aggregator_wait_and_check:<mix> clock returned 2 (jitter: -0:00:10.007318606)
0:00:00.120338939  1404       0x6e00f0 DEBUG             aggregator gstaggregator.c:672:gst_aggregator_wait_and_check:<mix> got subclass start time: 0:00:00.000000000
0:00:00.120375223  1404       0x6e00f0 DEBUG             aggregator gstaggregator.c:690:gst_aggregator_wait_and_check:<mix> possibly waiting for clock to reach 3:34:48.850798223 (base 3:34:38.817464890 start 0:00:00.000000000 latency 0:00:10.033333333 current 3:34:38.854783033)
0:00:00.144040750  1404       0x6e0400 DEBUG             aggregator gstaggregator.c:2148:gst_aggregator_pad_chain_internal:<mix:sink_0> Start chaining a buffer buffer: 0x7f91d000e280, pts 0:00:00.058147777, dts 99:99:99.999999999, dur 0:00:00.033333333, size 376000, offset 1, offset_end 2, flags 0x0
0:00:00.144181270  1404       0x6e0400 DEBUG             aggregator gstaggregator.c:2263:gst_aggregator_pad_chain_internal:<mix:sink_0> Done chaining
0:00:00.144431414  1404       0x6e00f0 DEBUG             aggregator gstaggregator.c:707:gst_aggregator_wait_and_check:<mix> clock returned 2 (jitter: -0:00:09.995947446)
0:00:00.144515261  1404       0x6e00f0 DEBUG             aggregator gstaggregator.c:672:gst_aggregator_wait_and_check:<mix> got subclass start time: 0:00:00.000000000
0:00:00.144554123  1404       0x6e00f0 DEBUG             aggregator gstaggregator.c:690:gst_aggregator_wait_and_check:<mix> possibly waiting for clock to reach 3:34:48.850798223 (base 3:34:38.817464890 start 0:00:00.000000000 latency 0:00:10.033333333 current 3:34:38.878961476)
0:00:00.177125923  1404       0x6e0400 DEBUG             aggregator gstaggregator.c:2148:gst_aggregator_pad_chain_internal:<mix:sink_0> Start chaining a buffer buffer: 0x7f91d000e4a0, pts 0:00:00.091481110, dts 99:99:99.999999999, dur 0:00:00.033333334, size 376000, offset 2, offset_end 3, flags 0x0
0:00:00.177226496  1404       0x6e0400 DEBUG             aggregator gstaggregator.c:2202:gst_aggregator_pad_chain_internal:<mix:sink_0> Waiting for buffer to be consumed
0:00:10.126676612  1404       0x6e00f0 DEBUG             aggregator gstaggregator.c:707:gst_aggregator_wait_and_check:<mix> clock returned 0 (jitter: -0:00:09.971760916)
0:00:10.127926279  1404       0x6e00f0 DEBUG        videoaggregator gstvideoaggregator.c:718:gst_videoaggregator_update_src_caps:<mix> The output format will now be : 2 with chroma : jpeg
0:00:10.128376273  1404       0x6e00f0 DEBUG             compositor compositor.c:320:gst_compositor_pad_set_info:<mix:sink_0> This pad will be converted from 2 to 8
0:00:10.128494739  1404       0x6e00f0 DEBUG             compositor compositor.c:320:gst_compositor_pad_set_info:<mix:sink_1> This pad will be converted from 2 to 8
0:00:10.128547264  1404       0x6e00f0 INFO         videoaggregator gstvideoaggregator.c:550:gst_videoaggregator_src_setcaps:<mix:src> set src caps: video/x-raw, width=(int)600, height=(int)500, framerate=(fraction)30/1, format=(string)BGRx, pixel-aspect-ratio=(fraction)1/1
0:00:10.128614997  1404       0x6e00f0 INFO              aggregator gstaggregator.c:500:gst_aggregator_push_mandatory_events:<mix> pushing stream start
0:00:10.128662494  1404       0x6e00f0 FIXME               basesink gstbasesink.c:3125:gst_base_sink_default_event:<ximagesink0> stream-start event without group-id. Consider implementing group-id handling in the upstream elements

So from what I can understand the problem is that the compositor queries the pipeline for the latency and the buffer (queue) is reporting a latency of 10 seconds, which makes it wait 10 seconds to see if it will receive a frame on sink_1.

Is there any way to avoid this and just make it play without delays?

from gstaggregator.c

gst_aggregator_wait_and_check()
{
  ...
  latency = gst_aggregator_get_latency_unlocked (self);
  ...
  /* If we're not live, or if we use the running time
   * of the first buffer as start time, we wait until
   * all pads have buffers.
   * Otherwise (i.e. if we are live!), we wait on the clock
   * and if a pad does not have a buffer in time we ignore
   * that pad.
   */
  if (!GST_CLOCK_TIME_IS_VALID (latency) || ...){
    SRC_WAIT (self);
  } else {
    ...
    GST_DEBUG_OBJECT (self, "possibly waiting for clock to reach %" ...)
    ...
  }
  ...
}

[Sebastian Dröge-3]

On Mo, 2016-06-13 at 04:08 -0700, mariannasb wrote:

> Hi, I have a case where I want to use the compositor in order to be able to
> mix a live src with a buffered amount of video (which originates from the
> same src).
> The basic idea is like a instant replay when there is fx a goal in a sports
> match.
> So I want to have the live data playing all the time, and to keep fx the
> last 10 seconds saved in a queue. Then if a goal happens I want to show the
> content on the buffer on the same window.
>
> The following pipeline should illustrate a bit the idea:
>
> gst-launch-1.0 videotestsrc is-live=1 ! video/x-raw,width=500,height=500 !
> timeoverlay ! tee name=t ! queue ! compositor name=mix sink_1::xpos=100 !
> videoconvert ! ximagesink async=0 t. ! queue ! queue max-size-buffers=0
> max-size-bytes=0 max-size-time=10000000000 min-threshold-time=10000000000 !
> mix.
>
> It almost works as expected.
> The problem is that the is a 10 seconds delay before it all starts.
> [...]
> So from what I can understand the problem is that the compositor queries the
> pipeline for the latency and the buffer (queue) is reporting a latency of 10
> seconds, which makes it wait 10 seconds to see if it will receive a frame on
> sink_1.
>
> Is there any way to avoid this and just make it play without delays?

That's exactly the problem here and also expected, yes. Try to not use
min-threshold* on the queue but instead apply a pad offset of 10
seconds to the source pad that should be delayed (and make sure you
have a big enough queue there).

--
Sebastian Dröge, Centricular Ltd · http://www.centricular.com

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

[baumi]

I was also looking at this and I found something weird: running pipeline given as example here by mariannasb works differently when running from command line (this works as described) and when running from C app (the timeoverlays just freezes and being updated every 10 sec).

I'm using GStreamer ver. 1.8.1.
Any particular reason why the output is different?

[mariannasb]

> I was also looking at this and I found something weird: running pipeline given as example here by mariannasb works differently when running from command line (this works as described) and when running from C app (the timeoverlays just freezes and being updated every 10 sec).
>
> I'm using GStreamer ver. 1.8.1.
> Any particular reason why the output is different?

The difference I can see is because of the QOS time.

Running with gst-launch it behaves as expected (even tough it does drops some frames because it cant render fast enough).

Running with an app (which is basically just gst_parse_launch) the QOS starts at 10seconds and jumps 10 seconds at at time instead of running "smoothly".
That is why it seems to freeze and only updates every 10 seconds.

0:00:28.942918607  1348       0x96cd90 WARN         videoaggregator gstvideoaggregator.c:1473:gst_videoaggregator_do_qos:<mix> we are late, drop frame (qostime 0:00:00.066666667, earliest 0:00:10.301237307)
...
0:00:22.959818785  1357       0x9681e0 WARN         videoaggregator gstvideoaggregator.c:1473:gst_videoaggregator_do_qos:<mix> we are late, drop frame (qostime 0:00:10.300000000, earliest 0:00:10.331812708)
0:00:23.109781879  1357       0x9681e0 WARN         videoaggregator gstvideoaggregator.c:1473:gst_videoaggregator_do_qos:<mix> we are late, drop frame (qostime 0:00:10.366666667, earliest 0:00:20.408302756)

I can see the qos coming from ximagesink:

- from c app:
0:00:10.827026304  1458       0x944370 DEBUG                GST_QOS gstbasesink.c:3625:gst_base_sink_chain_unlocked:<ximagesink0> qos: dropped buffer rt 0:00:00.000000000, st 0:00:00.000000000, ts 0:00:00.000000000, dur 0:00:00.033333333
0:00:10.827145489  1458       0x944370 DEBUG                GST_QOS gstbasesink.c:3628:gst_base_sink_chain_unlocked:<ximagesink0> qos: rendered 0, dropped 1
0:00:10.827216006  1458       0x944370 DEBUG                GST_QOS gstbasesink.c:2695:gst_base_sink_perform_qos:<ximagesink0> start: 0:00:00.000000000, stop 0:00:00.033333333, entered 0:00:10.181082416, left 0:00:10.181082416, pt: 99:99:99.999999999, duration 0:00:00.033333333,jitter 10181082416
0:00:10.827257248  1458       0x944370 DEBUG                GST_QOS gstbasesink.c:2700:gst_base_sink_perform_qos:<ximagesink0> avg_duration: 99:99:99.999999999, avg_pt: 99:99:99.999999999, avg_rate: -1
0:00:10.827290848  1458       0x944370 DEBUG                GST_QOS gstbasesink.c:2735:gst_base_sink_perform_qos:<ximagesink0> updated: avg_duration: 0:00:00.033333333, avg_pt: 99:99:99.999999999, avg_rate: -1
0:00:10.944477809  1458       0x944370 DEBUG                GST_QOS gstbasesink.c:3625:gst_base_sink_chain_unlocked:<ximagesink0> qos: dropped buffer rt 0:00:00.033333333, st 0:00:00.033333333, ts 0:00:00.033333333, dur 0:00:00.033333334
0:00:10.944590226  1458       0x944370 DEBUG                GST_QOS gstbasesink.c:3628:gst_base_sink_chain_unlocked:<ximagesink0> qos: rendered 0, dropped 2
0:00:10.944695382  1458       0x944370 DEBUG                GST_QOS gstbasesink.c:2695:gst_base_sink_perform_qos:<ximagesink0> start: 0:00:00.033333333, stop 0:00:00.066666667, entered 0:00:10.298531099, left 0:00:10.298531099, pt: 0:00:00.117448683, duration 0:00:00.033333334,jitter 10265197766
0:00:10.944738746  1458       0x944370 DEBUG                GST_QOS gstbasesink.c:2700:gst_base_sink_perform_qos:<ximagesink0> avg_duration: 0:00:00.033333333, avg_pt: 99:99:99.999999999, avg_rate: -1
0:00:10.944774977  1458       0x944370 DEBUG                GST_QOS gstbasesink.c:2735:gst_base_sink_perform_qos:<ximagesink0> updated: avg_duration: 0:00:00.033333333, avg_pt: 0:00:00.117448683, avg_rate: 3.52346
0:00:10.944803322  1458       0x944370 DEBUG                GST_QOS gstbasesink.c:2623:gst_base_sink_send_qos:<ximagesink0> qos: type 1, proportion: 3.523461, diff 10265197766, timestamp 0:00:00.033333333

- from gst-launch
0:00:10.288794918  1469       0x6dd000 DEBUG                GST_QOS gstbasesink.c:3625:gst_base_sink_chain_unlocked:<ximagesink0> qos: dropped buffer rt 0:00:00.000000000, st 0:00:00.000000000, ts 0:00:00.000000000, dur 0:00:00.033333333
0:00:10.288913093  1469       0x6dd000 DEBUG                GST_QOS gstbasesink.c:3628:gst_base_sink_chain_unlocked:<ximagesink0> qos: rendered 0, dropped 1
0:00:10.288983782  1469       0x6dd000 DEBUG                GST_QOS gstbasesink.c:2695:gst_base_sink_perform_qos:<ximagesink0> start: 0:00:00.000000000, stop 0:00:00.033333333, entered 0:00:00.141323652, left 0:00:00.141323652, pt: 99:99:99.999999999, duration 0:00:00.033333333,jitter 141323652
0:00:10.289028931  1469       0x6dd000 DEBUG                GST_QOS gstbasesink.c:2700:gst_base_sink_perform_qos:<ximagesink0> avg_duration: 99:99:99.999999999, avg_pt: 99:99:99.999999999, avg_rate: -1
0:00:10.289066929  1469       0x6dd000 DEBUG                GST_QOS gstbasesink.c:2735:gst_base_sink_perform_qos:<ximagesink0> updated: avg_duration: 0:00:00.033333333, avg_pt: 99:99:99.999999999, avg_rate: -1
0:00:10.414462155  1469       0x6dd000 DEBUG                GST_QOS gstbasesink.c:3625:gst_base_sink_chain_unlocked:<ximagesink0> qos: dropped buffer rt 0:00:00.033333333, st 0:00:00.033333333, ts 0:00:00.033333333, dur 0:00:00.033333334
0:00:10.414570401  1469       0x6dd000 DEBUG                GST_QOS gstbasesink.c:3628:gst_base_sink_chain_unlocked:<ximagesink0> qos: rendered 0, dropped 2
0:00:10.414778921  1469       0x6dd000 DEBUG                GST_QOS gstbasesink.c:2695:gst_base_sink_perform_qos:<ximagesink0> start: 0:00:00.033333333, stop 0:00:00.066666667, entered 0:00:00.266991140, left 0:00:00.266991140, pt: 0:00:00.125667488, duration 0:00:00.033333334,jitter 233657807
0:00:10.414831646  1469       0x6dd000 DEBUG                GST_QOS gstbasesink.c:2700:gst_base_sink_perform_qos:<ximagesink0> avg_duration: 0:00:00.033333333, avg_pt: 99:99:99.999999999, avg_rate: -1
0:00:10.414875624  1469       0x6dd000 DEBUG                GST_QOS gstbasesink.c:2735:gst_base_sink_perform_qos:<ximagesink0> updated: avg_duration: 0:00:00.033333333, avg_pt: 0:00:00.125667488, avg_rate: 3.77002
0:00:10.414910373  1469       0x6dd000 DEBUG                GST_QOS gstbasesink.c:2623:gst_base_sink_send_qos:<ximagesink0> qos: type 1, proportion: 3.770025, diff 233657807, timestamp 0:00:00.033333333

But I don't really understand what is that gst-launch does differently to result in this QOS difference...