diff --git a/ChangeLog b/ChangeLog index 955db0d2e7..54af6bff1b 100644 --- a/ChangeLog +++ b/ChangeLog @@ -1,3 +1,26 @@ +2006-04-07 Wim Taymans + + * gst/gstbus.c: + Small documentation clarification about the signal watch. + + * libs/gst/base/gstbasesink.c: (gst_base_sink_get_sync_times), + (gst_base_sink_wait_clock), (gst_base_sink_do_sync), + (gst_base_sink_perform_qos), (gst_base_sink_reset_qos), + (gst_base_sink_do_render_stats), (gst_base_sink_render_object), + (gst_base_sink_get_position_last), + (gst_base_sink_get_position_paused), (gst_base_sink_change_state): + Convert and store timestamps in stream time and running time, the + raw timestamps are not usefull, also document this better. + Use different window sizes for good and bad QoS observations so + we react to badness a little quicker. + Keep track of the amount of rendered and dropped buffers. + Send QoS timestamps in running time. + + * libs/gst/base/gstbasetransform.c: + (gst_base_transform_sink_eventfunc), + (gst_base_transform_handle_buffer): + Compare QoS timestamps against running time. + 2006-04-06 Tim-Philipp Müller * gst/gstpad.c: diff --git a/gst/gstbus.c b/gst/gstbus.c index 0e7f7a08e2..aa41144a3a 100644 --- a/gst/gstbus.c +++ b/gst/gstbus.c @@ -688,6 +688,7 @@ gst_bus_create_watch (GstBus * bus) * @notify: the function to call when the source is removed. * * Adds a bus watch to the default main context with the given @priority. + * This function is used to receive asynchronous messages in the main loop. * * When @func is called, the message belongs to the caller; if you want to * keep a copy of it, call gst_message_ref() before leaving @func. @@ -729,6 +730,7 @@ gst_bus_add_watch_full (GstBus * bus, gint priority, * @user_data: user data passed to @func. * * Adds a bus watch to the default main context with the default priority. + * This function is used to receive asynchronous messages in the main loop. * * The watch can be removed using g_source_remove() or by returning FALSE * from @func. diff --git a/libs/gst/base/gstbasesink.c b/libs/gst/base/gstbasesink.c index f507216c57..83184aba9e 100644 --- a/libs/gst/base/gstbasesink.c +++ b/libs/gst/base/gstbasesink.c @@ -152,21 +152,21 @@ struct _GstBaseSinkPrivate { gint qos_enabled; /* ATOMIC */ - /* last position */ - GstClockTime last_cstart; - GstClockTime last_cstop; + /* start, stop of current buffer, stream time, used to report position */ + GstClockTime current_sstart; + GstClockTime current_sstop; - /* start, stop and jitter of current buffer, stream time */ - GstClockTime current_start; - GstClockTime current_stop; + /* start, stop and jitter of current buffer, running time */ + GstClockTime current_rstart; + GstClockTime current_rstop; GstClockTimeDiff current_jitter; - /* last buffer that arrived in time, stream time */ + /* last buffer that arrived in time, running time */ GstClockTime last_in_time; - /* when the last buffer left the sink, stream time */ + /* when the last buffer left the sink, running time */ GstClockTime last_left; - /* running averages go here these are done on stream time */ + /* running averages go here these are done on running time */ GstClockTime avg_pt; GstClockTime avg_duration; gdouble avg_rate; @@ -177,11 +177,20 @@ struct _GstBaseSinkPrivate * buffers. */ GstClockTime last_left_systime; GstClockTime avg_jitter; + GTimeVal start, stop; GstClockTime avg_render; + + /* number of rendered and dropped frames */ + guint64 rendered; + guint64 dropped; }; -#define RUNNING_AVG_WINDOW 8 -#define UPDATE_RUNNING_AVG(avg,val) ((val) + (RUNNING_AVG_WINDOW-1) * (avg)) / RUNNING_AVG_WINDOW +#define DO_RUNNING_AVG(avg,val,size) (((val) + ((size)-1) * (avg)) / (size)) + +#define UPDATE_RUNNING_AVG(avg,val) DO_RUNNING_AVG(avg,val,8) + +#define UPDATE_RUNNING_AVG_P(avg,val) DO_RUNNING_AVG(avg,val,16) +#define UPDATE_RUNNING_AVG_N(avg,val) DO_RUNNING_AVG(avg,val,4) /* BaseSink signals and properties */ enum @@ -273,10 +282,6 @@ static gboolean gst_base_sink_is_too_late (GstBaseSink * basesink, GstMiniObject * obj, GstClockTime start, GstClockTime stop, GstClockReturn status, GstClockTimeDiff jitter); -/* QoS */ -static void gst_base_sink_record_qos_observation (GstBaseSink * sink, - GstClockTime start, GstClockTime stop, GstClockTimeDiff jitter); - static void gst_base_sink_base_init (gpointer g_class) { @@ -726,7 +731,6 @@ gst_base_sink_configure_segment (GstBaseSink * basesink, GstPad * pad, } /* with PREROLL_LOCK, STREAM_LOCK */ -/* FIXME, call change_state function, see #326311 */ static gboolean gst_base_sink_commit_state (GstBaseSink * basesink) { @@ -837,20 +841,23 @@ async_failed: * Returns TRUE if the object needs synchronisation and takes therefore * part in prerolling. * - * rstart/rstop contain the raw timestamp start/stop times of the object. - * rcstart/rcstop contain the times usefull for synchronising to the clock. + * rsstart/rsstop contain the start/stop in stream time. + * rrstart/rrstop contain the start/stop in running time. */ static gboolean gst_base_sink_get_sync_times (GstBaseSink * basesink, GstMiniObject * obj, - GstClockTime * rstart, GstClockTime * rstop, - GstClockTime * rcstart, GstClockTime * rcstop, gboolean * do_sync) + GstClockTime * rsstart, GstClockTime * rsstop, + GstClockTime * rrstart, GstClockTime * rrstop, gboolean * do_sync) { GstBaseSinkClass *bclass; GstBuffer *buffer; - gint64 cstart, cstop; - GstClockTime start, stop; + GstClockTime start, stop; /* raw start/stop timestamps */ + gint64 cstart, cstop; /* clipped raw timestamps */ + gint64 rstart, rstop; /* clipped timestamps converted to running time */ + GstClockTime sstart, sstop; /* clipped timestamps converted to stream time */ - start = stop = cstart = cstop = -1; + /* start with nothing */ + sstart = sstop = rstart = rstop = -1; if (G_UNLIKELY (GST_IS_EVENT (obj))) { GstEvent *event = GST_EVENT_CAST (obj); @@ -858,7 +865,8 @@ gst_base_sink_get_sync_times (GstBaseSink * basesink, GstMiniObject * obj, switch (GST_EVENT_TYPE (event)) { /* EOS event needs syncing */ case GST_EVENT_EOS: - start = stop = cstart = cstop = basesink->priv->last_cstop; + sstart = sstop = basesink->priv->current_sstop; + rstart = rstop = basesink->priv->current_rstop; goto done; /* other events do not need syncing */ /* FIXME, maybe NEWSEGMENT might need synchronisation @@ -871,6 +879,10 @@ gst_base_sink_get_sync_times (GstBaseSink * basesink, GstMiniObject * obj, } } + /* no sync if we did not get a TIME segment format */ + if (G_UNLIKELY (basesink->segment.format != GST_FORMAT_TIME)) + goto done; + /* else do buffer sync code */ buffer = GST_BUFFER_CAST (obj); @@ -890,13 +902,6 @@ gst_base_sink_get_sync_times (GstBaseSink * basesink, GstMiniObject * obj, GST_DEBUG_OBJECT (basesink, "got times start: %" GST_TIME_FORMAT ", stop: %" GST_TIME_FORMAT, GST_TIME_ARGS (start), GST_TIME_ARGS (stop)); - /* only clip for TIME format */ - if (G_UNLIKELY (basesink->segment.format != GST_FORMAT_TIME)) { - cstart = start; - cstop = stop; - goto done; - } - /* clip */ if (G_UNLIKELY (!gst_segment_clip (&basesink->segment, GST_FORMAT_TIME, (gint64) start, (gint64) stop, &cstart, &cstop))) @@ -908,12 +913,21 @@ gst_base_sink_get_sync_times (GstBaseSink * basesink, GstMiniObject * obj, GST_TIME_ARGS (cstop)); } + sstart = + gst_segment_to_stream_time (&basesink->segment, GST_FORMAT_TIME, cstart); + sstop = + gst_segment_to_stream_time (&basesink->segment, GST_FORMAT_TIME, cstop); + rstart = + gst_segment_to_running_time (&basesink->segment, GST_FORMAT_TIME, cstart); + rstop = + gst_segment_to_running_time (&basesink->segment, GST_FORMAT_TIME, cstop); + done: /* save times */ - *rstart = start; - *rstop = stop; - *rcstart = cstart; - *rcstop = cstop; + *rsstart = sstart; + *rsstop = sstop; + *rrstart = rstart; + *rrstop = rstop; /* buffers and EOS always need syncing and preroll */ return TRUE; @@ -940,6 +954,8 @@ out_of_segment: * Else a blocking wait is performed on the clock. We save the ClockID * so we can unlock the entry at any time. While we are blocking, we * release the PREROLL_LOCK so that other threads can interrupt the entry. + * + * @time is expressed in running time. */ static GstClockReturn gst_base_sink_wait_clock (GstBaseSink * basesink, GstClockTime time, @@ -960,12 +976,6 @@ gst_base_sink_wait_clock (GstBaseSink * basesink, GstClockTime time, if (G_UNLIKELY ((clock = GST_ELEMENT_CLOCK (basesink)) == NULL)) goto no_clock; - time = gst_segment_to_running_time (&basesink->segment, - basesink->segment.format, time); - - if (G_UNLIKELY (!GST_CLOCK_TIME_IS_VALID (time))) - goto invalid_running_time; - base_time = GST_ELEMENT_CAST (basesink)->base_time; id = gst_clock_new_single_shot_id (clock, base_time + time); GST_OBJECT_UNLOCK (basesink); @@ -988,12 +998,6 @@ invalid_time: GST_DEBUG_OBJECT (basesink, "time not valid, no sync needed"); return GST_CLOCK_BADTIME; } -invalid_running_time: - { - GST_DEBUG_OBJECT (basesink, "sync time not valid, can't sync"); - GST_OBJECT_UNLOCK (basesink); - return GST_CLOCK_BADTIME; - } no_sync: { GST_DEBUG_OBJECT (basesink, "sync disabled"); @@ -1037,31 +1041,31 @@ gst_base_sink_do_sync (GstBaseSink * basesink, GstPad * pad, GstClockTimeDiff jitter; gboolean syncable; GstClockReturn status = GST_CLOCK_OK; - GstClockTime start, stop, cstart, cstop; - gboolean do_sync = TRUE; + GstClockTime sstart, sstop, rstart, rstop; + gboolean do_sync; - start = stop = cstart = cstop = -1; + sstart = sstop = rstart = rstop = -1; + do_sync = TRUE; - basesink->priv->current_start = -1; + basesink->priv->current_rstart = -1; /* update timing information for this object */ syncable = gst_base_sink_get_sync_times (basesink, obj, - &start, &stop, &cstart, &cstop, &do_sync); + &sstart, &sstop, &rstart, &rstop, &do_sync); /* a syncable object needs to participate in preroll and * clocking. All buffers and EOS are syncable. */ if (G_UNLIKELY (!syncable)) goto not_syncable; + /* store timing info for current object */ + basesink->priv->current_rstart = rstart; + basesink->priv->current_rstop = (rstop != -1 ? rstop : rstart); /* lock because we read this when answering the POSITION * query. */ GST_OBJECT_LOCK (basesink); - if (stop != -1) - basesink->priv->last_cstop = cstop; - else - basesink->priv->last_cstop = cstart; - - basesink->priv->last_cstart = cstart; + basesink->priv->current_sstart = sstart; + basesink->priv->current_sstop = (sstop != -1 ? sstop : sstart); GST_OBJECT_UNLOCK (basesink); again: @@ -1098,11 +1102,11 @@ again: /* preroll done, we can sync since we are in PLAYING now. */ GST_DEBUG_OBJECT (basesink, "waiting for clock to reach %" GST_TIME_FORMAT, - GST_TIME_ARGS (cstart)); + GST_TIME_ARGS (rstart)); /* this function will return immediatly if start == -1, no clock * or sync is disabled with GST_CLOCK_BADTIME. */ - status = gst_base_sink_wait_clock (basesink, cstart, &jitter); + status = gst_base_sink_wait_clock (basesink, rstart, &jitter); GST_DEBUG_OBJECT (basesink, "clock returned %d", status); @@ -1122,10 +1126,10 @@ again: } /* successful syncing done, record observation */ - gst_base_sink_record_qos_observation (basesink, cstart, cstop, jitter); + basesink->priv->current_jitter = jitter; /* check if the object should be dropped */ - *late = gst_base_sink_is_too_late (basesink, obj, start, stop, + *late = gst_base_sink_is_too_late (basesink, obj, rstart, rstop, status, jitter); done: @@ -1149,28 +1153,6 @@ stopping: } } -/* record a qos observation for later processing */ -static void -gst_base_sink_record_qos_observation (GstBaseSink * sink, GstClockTime start, - GstClockTime stop, GstClockTimeDiff jitter) -{ - GstBaseSinkPrivate *priv; - - priv = sink->priv; - - if (!g_atomic_int_get (&priv->qos_enabled)) - return; - - GST_CAT_DEBUG_OBJECT (GST_CAT_QOS, sink, - "recording QoS observation start: %" GST_TIME_FORMAT ", stop %" - GST_TIME_FORMAT ", jitter %" G_GINT64_FORMAT, - GST_TIME_ARGS (start), GST_TIME_ARGS (stop), jitter); - - priv->current_start = start; - priv->current_stop = stop; - priv->current_jitter = jitter; -} - static gboolean gst_base_sink_send_qos (GstBaseSink * basesink, gdouble proportion, GstClockTime time, GstClockTimeDiff diff) @@ -1203,13 +1185,13 @@ gst_base_sink_perform_qos (GstBaseSink * sink, gboolean dropped) priv = sink->priv; - start = priv->current_start; + start = priv->current_rstart; /* if QoS disabled, do nothing */ if (!g_atomic_int_get (&priv->qos_enabled) || start == -1) return; - stop = priv->current_stop; + stop = priv->current_rstop; jitter = priv->current_jitter; /* this is the time the buffer entered the sink */ @@ -1263,7 +1245,10 @@ gst_base_sink_perform_qos (GstBaseSink * sink, gboolean dropped) else rate = 1.0; - priv->avg_rate = UPDATE_RUNNING_AVG (priv->avg_rate, rate); + if (rate > 1.0) + priv->avg_rate = UPDATE_RUNNING_AVG_N (priv->avg_rate, rate); + else + priv->avg_rate = UPDATE_RUNNING_AVG_P (priv->avg_rate, rate); GST_CAT_DEBUG_OBJECT (GST_CAT_QOS, sink, "updated: avg_duration: %" GST_TIME_FORMAT ", avg_pt: %" GST_TIME_FORMAT @@ -1271,12 +1256,12 @@ gst_base_sink_perform_qos (GstBaseSink * sink, gboolean dropped) GST_TIME_ARGS (priv->avg_pt), priv->avg_rate); - /* last observation did not cause a drop, no need to send - * a QoS event */ - if (G_LIKELY (!dropped)) - return; + if (dropped) { + priv->avg_rate = 2.0; + } - gst_base_sink_send_qos (sink, priv->avg_rate, priv->current_start, + /* always send QoS events */ + gst_base_sink_send_qos (sink, priv->avg_rate, priv->current_rstart, priv->current_jitter); } @@ -1294,6 +1279,8 @@ gst_base_sink_reset_qos (GstBaseSink * sink) priv->avg_pt = -1; priv->avg_rate = 1.0; priv->avg_render = -1; + priv->rendered = 0; + priv->dropped = 0; } /* Checks if the object was scheduled too late. @@ -1374,6 +1361,35 @@ no_timestamp: } } +static void +gst_base_sink_do_render_stats (GstBaseSink * basesink, gboolean start) +{ + GstBaseSinkPrivate *priv; + + priv = basesink->priv; + + if (start) { + g_get_current_time (&priv->start); + } else { + GstClockTime elapsed; + + g_get_current_time (&priv->stop); + + elapsed = + GST_TIMEVAL_TO_TIME (priv->stop) - GST_TIMEVAL_TO_TIME (priv->start); + + if (priv->avg_render == -1) + priv->avg_render = elapsed; + else + priv->avg_render = UPDATE_RUNNING_AVG (priv->avg_render, elapsed); + + priv->rendered++; + + GST_CAT_DEBUG_OBJECT (GST_CAT_QOS, basesink, + "avg_render: %" GST_TIME_FORMAT, GST_TIME_ARGS (priv->avg_render)); + } +} + /* with STREAM_LOCK, PREROLL_LOCK, * * Synchronize the object on the clock and then render it. @@ -1387,6 +1403,9 @@ gst_base_sink_render_object (GstBaseSink * basesink, GstPad * pad, GstFlowReturn ret = GST_FLOW_OK; GstBaseSinkClass *bclass; gboolean late = FALSE; + GstBaseSinkPrivate *priv; + + priv = basesink->priv; /* synchronize this object, non syncable objects return OK * immediatly. */ @@ -1396,8 +1415,6 @@ gst_base_sink_render_object (GstBaseSink * basesink, GstPad * pad, /* and now render, event or buffer. */ if (G_LIKELY (GST_IS_BUFFER (obj))) { - GTimeVal start, stop; - /* drop late buffers unconditionally, let's hope it's unlikely */ if (G_UNLIKELY (late)) goto dropped; @@ -1406,9 +1423,6 @@ gst_base_sink_render_object (GstBaseSink * basesink, GstPad * pad, if (G_LIKELY (bclass->render)) { gint do_qos; - GstBaseSinkPrivate *priv; - - priv = basesink->priv; /* read once, to get same value before and after */ do_qos = g_atomic_int_get (&priv->qos_enabled); @@ -1417,27 +1431,13 @@ gst_base_sink_render_object (GstBaseSink * basesink, GstPad * pad, /* record rendering time for QoS and stats */ if (do_qos) - g_get_current_time (&start); + gst_base_sink_do_render_stats (basesink, TRUE); ret = bclass->render (basesink, GST_BUFFER_CAST (obj)); - if (do_qos) { - GstClockTime elapsed; - - g_get_current_time (&stop); - - elapsed = GST_TIMEVAL_TO_TIME (stop) - GST_TIMEVAL_TO_TIME (start); - - if (priv->avg_render == -1) - priv->avg_render = elapsed; - else - priv->avg_render = UPDATE_RUNNING_AVG (priv->avg_render, elapsed); - - GST_CAT_DEBUG_OBJECT (GST_CAT_QOS, basesink, - "avg_render: %" GST_TIME_FORMAT, GST_TIME_ARGS (priv->avg_render)); - } + if (do_qos) + gst_base_sink_do_render_stats (basesink, FALSE); } - } else { GstEvent *event = GST_EVENT_CAST (obj); gboolean event_res = TRUE; @@ -1494,6 +1494,7 @@ sync_failed: } dropped: { + priv->dropped++; GST_DEBUG_OBJECT (basesink, "buffer late, dropping"); goto done; } @@ -2177,15 +2178,12 @@ gst_base_sink_peer_query (GstBaseSink * sink, GstQuery * query) return res; } -/* get the position of the last seen object against the last seen - * segment. */ +/* get the position of the last seen object */ static gboolean gst_base_sink_get_position_last (GstBaseSink * basesink, gint64 * cur) { - /* convert last observed stop to stream time */ - *cur = - gst_segment_to_stream_time (&basesink->segment, basesink->segment.format, - basesink->priv->last_cstop); + /* return last observed stream time */ + *cur = basesink->priv->current_sstop; return TRUE; } @@ -2196,9 +2194,7 @@ gst_base_sink_get_position_last (GstBaseSink * basesink, gint64 * cur) static gboolean gst_base_sink_get_position_paused (GstBaseSink * basesink, gint64 * cur) { - *cur = - gst_segment_to_stream_time (&basesink->segment, basesink->segment.format, - basesink->priv->last_cstart); + *cur = basesink->priv->current_sstart; if (*cur != -1) *cur = MAX (*cur, basesink->abidata.ABI.clip_segment->time); @@ -2395,8 +2391,8 @@ gst_base_sink_change_state (GstElement * element, GstStateChange transition) basesink->have_preroll = FALSE; basesink->need_preroll = TRUE; basesink->playing_async = TRUE; - basesink->priv->last_cstart = 0; - basesink->priv->last_cstop = 0; + basesink->priv->current_sstart = 0; + basesink->priv->current_sstop = 0; basesink->eos = FALSE; gst_base_sink_reset_qos (basesink); ret = GST_STATE_CHANGE_ASYNC; @@ -2462,8 +2458,8 @@ gst_base_sink_change_state (GstElement * element, GstStateChange transition) GST_PAD_PREROLL_UNLOCK (basesink->sinkpad); break; case GST_STATE_CHANGE_PAUSED_TO_READY: - basesink->priv->last_cstart = 0; - basesink->priv->last_cstop = 0; + basesink->priv->current_sstart = 0; + basesink->priv->current_sstop = 0; break; case GST_STATE_CHANGE_READY_TO_NULL: if (bclass->stop) diff --git a/libs/gst/base/gstbasetransform.c b/libs/gst/base/gstbasetransform.c index 3c6951c67b..a7fd7ad106 100644 --- a/libs/gst/base/gstbasetransform.c +++ b/libs/gst/base/gstbasetransform.c @@ -1176,7 +1176,7 @@ gst_base_transform_sink_eventfunc (GstBaseTransform * trans, GstEvent * event) trans->have_newsegment = TRUE; if (format == GST_FORMAT_TIME) { - GST_DEBUG_OBJECT (trans, "received NEW_SEGMENT %" GST_TIME_FORMAT + GST_DEBUG_OBJECT (trans, "received TIME NEW_SEGMENT %" GST_TIME_FORMAT " -- %" GST_TIME_FORMAT ", time %" GST_TIME_FORMAT ", accum %" GST_TIME_FORMAT, GST_TIME_ARGS (trans->segment.start), @@ -1254,7 +1254,7 @@ gst_base_transform_handle_buffer (GstBaseTransform * trans, GstBuffer * inbuf, GstFlowReturn ret = GST_FLOW_OK; guint out_size; gboolean want_in_place; - GstClockTime outtime; + GstClockTime qostime; bclass = GST_BASE_TRANSFORM_GET_CLASS (trans); @@ -1273,7 +1273,14 @@ gst_base_transform_handle_buffer (GstBaseTransform * trans, GstBuffer * inbuf, if (!trans->negotiated && !trans->passthrough && (bclass->set_caps != NULL)) goto not_negotiated; - if ((outtime = GST_BUFFER_TIMESTAMP (inbuf)) != -1) { + /* can only do QoS if the segment is in TIME */ + if (trans->segment.format != GST_FORMAT_TIME) + goto no_qos; + + qostime = gst_segment_to_running_time (&trans->segment, GST_FORMAT_TIME, + GST_BUFFER_TIMESTAMP (inbuf)); + + if (qostime != -1) { gboolean need_skip; GstClockTime earliest_time; @@ -1282,17 +1289,18 @@ gst_base_transform_handle_buffer (GstBaseTransform * trans, GstBuffer * inbuf, /* check for QoS, don't perform conversion for buffers * that are known to be late. */ need_skip = trans->priv->qos_enabled && - earliest_time != -1 && outtime <= earliest_time; + earliest_time != -1 && qostime != -1 && qostime <= earliest_time; GST_OBJECT_UNLOCK (trans); if (need_skip) { - GST_CAT_DEBUG_OBJECT (GST_CAT_QOS, trans, "skipping transform: outtime %" + GST_CAT_DEBUG_OBJECT (GST_CAT_QOS, trans, "skipping transform: qostime %" GST_TIME_FORMAT " <= %" GST_TIME_FORMAT, - GST_TIME_ARGS (outtime), GST_TIME_ARGS (earliest_time)); + GST_TIME_ARGS (qostime), GST_TIME_ARGS (earliest_time)); goto skip; } } +no_qos: if (trans->passthrough) { /* In passthrough mode, give transform_ip a look at the * buffer, without making it writable, or just push the