2014-02-18 10:06:10 +00:00
|
|
|
/* GStreamer
|
|
|
|
* Copyright (C) 2013 Stefan Sauer <ensonic@users.sf.net>
|
|
|
|
*
|
|
|
|
* gstlatency.c: tracing module that logs processing latency stats
|
|
|
|
*
|
|
|
|
* This library is free software; you can redistribute it and/or
|
|
|
|
* modify it under the terms of the GNU Library General Public
|
|
|
|
* License as published by the Free Software Foundation; either
|
|
|
|
* version 2 of the License, or (at your option) any later version.
|
|
|
|
*
|
|
|
|
* This library is distributed in the hope that it will be useful,
|
|
|
|
* but WITHOUT ANY WARRANTY; without even the implied warranty of
|
|
|
|
* MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU
|
|
|
|
* Library General Public License for more details.
|
|
|
|
*
|
|
|
|
* You should have received a copy of the GNU Library General Public
|
|
|
|
* License along with this library; if not, write to the
|
|
|
|
* Free Software Foundation, Inc., 51 Franklin St, Fifth Floor,
|
|
|
|
* Boston, MA 02110-1301, USA.
|
|
|
|
*/
|
2014-07-16 16:48:52 +00:00
|
|
|
/**
|
2017-12-05 10:36:34 +00:00
|
|
|
* SECTION:element-latencytracer
|
2014-07-16 16:48:52 +00:00
|
|
|
* @short_description: log processing latency stats
|
|
|
|
*
|
|
|
|
* A tracing module that determines src-to-sink latencies by injecting custom
|
2018-10-31 20:50:48 +00:00
|
|
|
* events at sources and process them at sinks. This elements supports tracing
|
|
|
|
* the entire pipeline latency and per element latency. By default, only
|
|
|
|
* pipeline latency is traced. The 'flags' parameter can be used to enabled
|
|
|
|
* element tracing.
|
|
|
|
*
|
|
|
|
* ```
|
|
|
|
* GST_TRACERS="latency(flags=pipeline+element)" GST_DEBUG=GST_TRACER:7 ./...
|
|
|
|
* ```
|
2014-07-16 16:48:52 +00:00
|
|
|
*/
|
2014-02-20 10:15:20 +00:00
|
|
|
/* TODO(ensonic): if there are two sources feeding into a mixer/muxer and later
|
|
|
|
* we fan-out with tee and have two sinks, each sink would get all two events,
|
|
|
|
* the later event would overwrite the former. Unfortunately when the buffer
|
|
|
|
* arrives on the sink we don't know to which event it correlates. Better would
|
|
|
|
* be to use the buffer meta in 1.0 instead of the event. Or we track a min/max
|
|
|
|
* latency.
|
|
|
|
*/
|
2014-02-18 10:06:10 +00:00
|
|
|
|
|
|
|
#ifdef HAVE_CONFIG_H
|
|
|
|
# include "config.h"
|
|
|
|
#endif
|
|
|
|
|
|
|
|
#include "gstlatency.h"
|
|
|
|
|
|
|
|
GST_DEBUG_CATEGORY_STATIC (gst_latency_debug);
|
|
|
|
#define GST_CAT_DEFAULT gst_latency_debug
|
|
|
|
|
|
|
|
#define _do_init \
|
|
|
|
GST_DEBUG_CATEGORY_INIT (gst_latency_debug, "latency", 0, "latency tracer");
|
|
|
|
#define gst_latency_tracer_parent_class parent_class
|
|
|
|
G_DEFINE_TYPE_WITH_CODE (GstLatencyTracer, gst_latency_tracer, GST_TYPE_TRACER,
|
|
|
|
_do_init);
|
|
|
|
|
2019-03-21 09:37:34 +00:00
|
|
|
static void latency_query_stack_destroy (gpointer data);
|
|
|
|
|
2014-02-18 10:06:10 +00:00
|
|
|
static GQuark latency_probe_id;
|
2018-07-06 21:08:24 +00:00
|
|
|
static GQuark sub_latency_probe_id;
|
2014-02-18 10:06:10 +00:00
|
|
|
static GQuark latency_probe_pad;
|
2019-04-09 12:05:09 +00:00
|
|
|
static GQuark latency_probe_element;
|
|
|
|
static GQuark latency_probe_element_id;
|
2014-02-18 10:06:10 +00:00
|
|
|
static GQuark latency_probe_ts;
|
2018-07-06 21:08:24 +00:00
|
|
|
static GQuark drop_sub_latency_quark;
|
2014-02-18 10:06:10 +00:00
|
|
|
|
2016-01-12 13:59:04 +00:00
|
|
|
static GstTracerRecord *tr_latency;
|
2018-07-06 21:08:24 +00:00
|
|
|
static GstTracerRecord *tr_element_latency;
|
2019-03-21 09:37:34 +00:00
|
|
|
static GstTracerRecord *tr_element_reported_latency;
|
|
|
|
|
|
|
|
/* The private stack for each thread */
|
|
|
|
static GPrivate latency_query_stack =
|
|
|
|
G_PRIVATE_INIT (latency_query_stack_destroy);
|
|
|
|
|
|
|
|
struct LatencyQueryTableValue
|
|
|
|
{
|
|
|
|
GstElement *peer_element;
|
|
|
|
guint64 min;
|
|
|
|
guint64 max;
|
|
|
|
};
|
2016-01-12 13:59:04 +00:00
|
|
|
|
2014-02-18 10:06:10 +00:00
|
|
|
/* data helpers */
|
|
|
|
|
|
|
|
/*
|
2016-01-10 13:30:05 +00:00
|
|
|
* Get the element/bin owning the pad.
|
2014-02-18 10:06:10 +00:00
|
|
|
*
|
|
|
|
* in: a normal pad
|
|
|
|
* out: the element
|
|
|
|
*
|
|
|
|
* in: a proxy pad
|
|
|
|
* out: the element that contains the peer of the proxy
|
|
|
|
*
|
|
|
|
* in: a ghost pad
|
|
|
|
* out: the bin owning the ghostpad
|
|
|
|
*/
|
|
|
|
/* TODO(ensonic): gst_pad_get_parent_element() would not work here, should we
|
|
|
|
* add this as new api, e.g. gst_pad_find_parent_element();
|
|
|
|
*/
|
|
|
|
static GstElement *
|
|
|
|
get_real_pad_parent (GstPad * pad)
|
|
|
|
{
|
|
|
|
GstObject *parent;
|
|
|
|
|
|
|
|
if (!pad)
|
|
|
|
return NULL;
|
|
|
|
|
|
|
|
parent = GST_OBJECT_PARENT (pad);
|
|
|
|
|
|
|
|
/* if parent of pad is a ghost-pad, then pad is a proxy_pad */
|
|
|
|
if (parent && GST_IS_GHOST_PAD (parent)) {
|
|
|
|
pad = GST_PAD_CAST (parent);
|
|
|
|
parent = GST_OBJECT_PARENT (pad);
|
|
|
|
}
|
|
|
|
return GST_ELEMENT_CAST (parent);
|
|
|
|
}
|
|
|
|
|
2019-03-21 09:37:34 +00:00
|
|
|
static void
|
|
|
|
latency_query_table_value_destroy (gpointer data)
|
|
|
|
{
|
|
|
|
struct LatencyQueryTableValue *v = data;
|
|
|
|
|
|
|
|
/* Unref the element */
|
|
|
|
if (v->peer_element) {
|
|
|
|
gst_object_unref (v->peer_element);
|
|
|
|
v->peer_element = NULL;
|
|
|
|
}
|
|
|
|
|
|
|
|
/* Destroy the structure */
|
|
|
|
g_free (v);
|
|
|
|
}
|
|
|
|
|
|
|
|
static void
|
|
|
|
latency_query_stack_destroy (gpointer data)
|
|
|
|
{
|
|
|
|
GQueue *queue = data;
|
|
|
|
g_queue_free_full (queue, latency_query_table_value_destroy);
|
|
|
|
}
|
|
|
|
|
|
|
|
static GQueue *
|
|
|
|
local_latency_query_stack_get (void)
|
|
|
|
{
|
|
|
|
/* Make sure the stack exists */
|
|
|
|
GQueue *stack = g_private_get (&latency_query_stack);
|
|
|
|
if (!stack) {
|
|
|
|
g_private_set (&latency_query_stack, g_queue_new ());
|
|
|
|
stack = g_private_get (&latency_query_stack);
|
|
|
|
}
|
|
|
|
|
|
|
|
g_assert (stack);
|
|
|
|
return stack;
|
|
|
|
}
|
|
|
|
|
|
|
|
static struct LatencyQueryTableValue *
|
|
|
|
local_latency_query_stack_pop (void)
|
|
|
|
{
|
|
|
|
GQueue *stack = local_latency_query_stack_get ();
|
|
|
|
return g_queue_pop_tail (stack);
|
|
|
|
}
|
|
|
|
|
|
|
|
static void
|
|
|
|
local_latency_query_stack_push (struct LatencyQueryTableValue *value)
|
|
|
|
{
|
|
|
|
GQueue *stack = local_latency_query_stack_get ();
|
|
|
|
g_queue_push_tail (stack, value);
|
|
|
|
}
|
|
|
|
|
2014-02-18 10:06:10 +00:00
|
|
|
/* hooks */
|
|
|
|
|
2014-02-20 10:15:20 +00:00
|
|
|
static void
|
2019-04-09 12:05:09 +00:00
|
|
|
log_latency (const GstStructure * data, GstElement * sink_parent,
|
|
|
|
GstPad * sink_pad, guint64 sink_ts)
|
2014-02-20 10:15:20 +00:00
|
|
|
{
|
|
|
|
guint64 src_ts;
|
2019-04-09 12:05:09 +00:00
|
|
|
const char *src, *element_src, *id_element_src;
|
2018-07-04 18:18:42 +00:00
|
|
|
const GValue *value;
|
2019-04-09 12:05:09 +00:00
|
|
|
gchar *sink, *element_sink, *id_element_sink;
|
2014-02-20 10:15:20 +00:00
|
|
|
|
2018-07-04 18:18:42 +00:00
|
|
|
value = gst_structure_id_get_value (data, latency_probe_ts);
|
|
|
|
src_ts = g_value_get_uint64 (value);
|
2014-02-20 10:15:20 +00:00
|
|
|
|
2018-07-04 18:18:42 +00:00
|
|
|
value = gst_structure_id_get_value (data, latency_probe_pad);
|
|
|
|
src = g_value_get_string (value);
|
2014-02-20 10:15:20 +00:00
|
|
|
|
2019-04-09 12:05:09 +00:00
|
|
|
value = gst_structure_id_get_value (data, latency_probe_element);
|
|
|
|
element_src = g_value_get_string (value);
|
|
|
|
|
|
|
|
value = gst_structure_id_get_value (data, latency_probe_element_id);
|
|
|
|
id_element_src = g_value_get_string (value);
|
|
|
|
|
|
|
|
id_element_sink = g_strdup_printf ("%p", sink_parent);
|
|
|
|
element_sink = gst_element_get_name (sink_parent);
|
|
|
|
sink = gst_pad_get_name (sink_pad);
|
|
|
|
gst_tracer_record_log (tr_latency, id_element_src, element_src, src,
|
|
|
|
id_element_sink, element_sink, sink, GST_CLOCK_DIFF (src_ts, sink_ts),
|
|
|
|
sink_ts);
|
2014-02-20 10:15:20 +00:00
|
|
|
g_free (sink);
|
2019-04-09 12:05:09 +00:00
|
|
|
g_free (element_sink);
|
|
|
|
g_free (id_element_sink);
|
2014-02-20 10:15:20 +00:00
|
|
|
}
|
|
|
|
|
2018-07-06 21:08:24 +00:00
|
|
|
static void
|
2019-04-09 12:05:09 +00:00
|
|
|
log_element_latency (const GstStructure * data, GstElement * parent,
|
|
|
|
GstPad * pad, guint64 sink_ts)
|
2018-07-06 21:08:24 +00:00
|
|
|
{
|
|
|
|
guint64 src_ts;
|
2019-04-09 12:05:09 +00:00
|
|
|
gchar *pad_name, *element_name, *element_id;
|
2018-07-06 21:08:24 +00:00
|
|
|
const GValue *value;
|
|
|
|
|
2019-04-09 12:05:09 +00:00
|
|
|
element_id = g_strdup_printf ("%p", parent);
|
|
|
|
element_name = gst_element_get_name (parent);
|
|
|
|
pad_name = gst_pad_get_name (pad);
|
2018-07-06 21:08:24 +00:00
|
|
|
|
|
|
|
/* TODO filtering */
|
|
|
|
|
|
|
|
value = gst_structure_id_get_value (data, latency_probe_ts);
|
|
|
|
src_ts = g_value_get_uint64 (value);
|
|
|
|
|
2019-04-09 12:05:09 +00:00
|
|
|
gst_tracer_record_log (tr_element_latency, element_id, element_name, pad_name,
|
2018-07-06 21:08:24 +00:00
|
|
|
GST_CLOCK_DIFF (src_ts, sink_ts), sink_ts);
|
2019-03-20 11:20:48 +00:00
|
|
|
|
|
|
|
g_free (pad_name);
|
2019-04-09 12:05:09 +00:00
|
|
|
g_free (element_name);
|
|
|
|
g_free (element_id);
|
2018-07-06 21:08:24 +00:00
|
|
|
}
|
|
|
|
|
2014-02-18 10:06:10 +00:00
|
|
|
static void
|
2018-10-31 20:50:48 +00:00
|
|
|
send_latency_probe (GstLatencyTracer * self, GstElement * parent, GstPad * pad,
|
|
|
|
guint64 ts)
|
2014-02-18 10:06:10 +00:00
|
|
|
{
|
2018-07-06 21:08:24 +00:00
|
|
|
GstPad *peer_pad = GST_PAD_PEER (pad);
|
2019-04-09 12:05:09 +00:00
|
|
|
GstElement *peer_parent = get_real_pad_parent (peer_pad);
|
2018-07-06 21:08:24 +00:00
|
|
|
|
2018-02-15 01:58:43 +00:00
|
|
|
/* allow for non-parented pads to send latency probes as used in e.g.
|
|
|
|
* rtspsrc for TCP connections */
|
2018-07-06 21:08:24 +00:00
|
|
|
if (peer_pad && (!parent || (!GST_IS_BIN (parent)))) {
|
2019-04-09 12:05:09 +00:00
|
|
|
gchar *pad_name, *element_name, *element_id;
|
2018-07-04 18:18:42 +00:00
|
|
|
GstEvent *latency_probe;
|
|
|
|
|
2018-10-31 20:50:48 +00:00
|
|
|
if (self->flags & GST_LATENCY_TRACER_FLAG_PIPELINE &&
|
|
|
|
GST_OBJECT_FLAG_IS_SET (parent, GST_ELEMENT_FLAG_SOURCE)) {
|
2019-04-09 12:05:09 +00:00
|
|
|
element_id = g_strdup_printf ("%p", parent);
|
|
|
|
element_name = gst_element_get_name (parent);
|
|
|
|
pad_name = gst_pad_get_name (pad);
|
2018-07-06 21:08:24 +00:00
|
|
|
|
|
|
|
GST_DEBUG ("%s: Sending latency event", pad_name);
|
|
|
|
|
|
|
|
latency_probe = gst_event_new_custom (GST_EVENT_CUSTOM_DOWNSTREAM,
|
|
|
|
gst_structure_new_id (latency_probe_id,
|
2019-04-09 12:05:09 +00:00
|
|
|
latency_probe_element_id, G_TYPE_STRING, element_id,
|
|
|
|
latency_probe_element, G_TYPE_STRING, element_name,
|
2018-07-06 21:08:24 +00:00
|
|
|
latency_probe_pad, G_TYPE_STRING, pad_name,
|
|
|
|
latency_probe_ts, G_TYPE_UINT64, ts, NULL));
|
|
|
|
g_free (pad_name);
|
2019-04-09 12:05:09 +00:00
|
|
|
g_free (element_name);
|
|
|
|
g_free (element_id);
|
2018-07-06 21:08:24 +00:00
|
|
|
gst_pad_push_event (pad, latency_probe);
|
|
|
|
}
|
|
|
|
|
2018-10-31 20:50:48 +00:00
|
|
|
if (self->flags & GST_LATENCY_TRACER_FLAG_ELEMENT) {
|
|
|
|
GST_DEBUG ("%s_%s: Sending sub-latency event", GST_DEBUG_PAD_NAME (pad));
|
2018-07-06 21:08:24 +00:00
|
|
|
|
2019-04-09 12:05:09 +00:00
|
|
|
element_id = g_strdup_printf ("%p", peer_parent);
|
|
|
|
element_name = gst_element_get_name (peer_parent);
|
|
|
|
pad_name = gst_pad_get_name (peer_pad);
|
2018-10-31 20:50:48 +00:00
|
|
|
latency_probe = gst_event_new_custom (GST_EVENT_CUSTOM_DOWNSTREAM,
|
|
|
|
gst_structure_new_id (sub_latency_probe_id,
|
2019-04-10 13:17:01 +00:00
|
|
|
latency_probe_element_id, G_TYPE_STRING, element_id,
|
2019-04-09 12:05:09 +00:00
|
|
|
latency_probe_element, G_TYPE_STRING, element_name,
|
2018-10-31 20:50:48 +00:00
|
|
|
latency_probe_pad, G_TYPE_STRING, pad_name,
|
|
|
|
latency_probe_ts, G_TYPE_UINT64, ts, NULL));
|
|
|
|
gst_pad_push_event (pad, latency_probe);
|
|
|
|
g_free (pad_name);
|
2019-04-09 12:05:09 +00:00
|
|
|
g_free (element_name);
|
|
|
|
g_free (element_id);
|
2018-10-31 20:50:48 +00:00
|
|
|
}
|
2014-02-18 10:06:10 +00:00
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
static void
|
2014-09-17 06:38:02 +00:00
|
|
|
calculate_latency (GstElement * parent, GstPad * pad, guint64 ts)
|
2014-02-20 10:15:20 +00:00
|
|
|
{
|
2018-07-06 21:08:24 +00:00
|
|
|
GstElement *peer_parent = get_real_pad_parent (GST_PAD_PEER (pad));
|
|
|
|
|
2014-02-20 10:15:20 +00:00
|
|
|
if (parent && (!GST_IS_BIN (parent)) &&
|
2018-07-06 21:08:24 +00:00
|
|
|
(!GST_OBJECT_FLAG_IS_SET (parent, GST_ELEMENT_FLAG_SOURCE))) {
|
|
|
|
GstEvent *ev;
|
|
|
|
|
|
|
|
/* FIXME unsafe use of peer */
|
|
|
|
if (GST_OBJECT_FLAG_IS_SET (peer_parent, GST_ELEMENT_FLAG_SINK)) {
|
|
|
|
GST_DEBUG ("%s_%s: Should log full lantency now",
|
|
|
|
GST_DEBUG_PAD_NAME (pad));
|
|
|
|
ev = g_object_get_qdata ((GObject *) pad, latency_probe_id);
|
|
|
|
if (ev) {
|
|
|
|
g_object_set_qdata ((GObject *) pad, latency_probe_id, NULL);
|
2019-04-09 12:05:09 +00:00
|
|
|
log_latency (gst_event_get_structure (ev), peer_parent,
|
|
|
|
GST_PAD_PEER (pad), ts);
|
2018-07-06 21:08:24 +00:00
|
|
|
gst_event_unref (ev);
|
|
|
|
}
|
|
|
|
}
|
2014-02-20 10:15:20 +00:00
|
|
|
|
2018-07-06 21:08:24 +00:00
|
|
|
GST_DEBUG ("%s_%s: Should log sub lantency now", GST_DEBUG_PAD_NAME (pad));
|
|
|
|
ev = g_object_get_qdata ((GObject *) pad, sub_latency_probe_id);
|
2016-12-07 20:53:49 +00:00
|
|
|
if (ev) {
|
2018-07-06 21:08:24 +00:00
|
|
|
g_object_set_qdata ((GObject *) pad, sub_latency_probe_id, NULL);
|
2019-04-09 12:05:09 +00:00
|
|
|
log_element_latency (gst_event_get_structure (ev), parent, pad, ts);
|
2016-12-07 20:53:49 +00:00
|
|
|
gst_event_unref (ev);
|
|
|
|
}
|
2014-02-20 10:15:20 +00:00
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
static void
|
2018-10-31 20:50:48 +00:00
|
|
|
do_push_buffer_pre (GstTracer * tracer, guint64 ts, GstPad * pad)
|
2017-10-11 15:08:12 +00:00
|
|
|
{
|
2018-10-31 20:50:48 +00:00
|
|
|
GstLatencyTracer *self = (GstLatencyTracer *) tracer;
|
2017-10-11 15:08:12 +00:00
|
|
|
GstElement *parent = get_real_pad_parent (pad);
|
|
|
|
|
2018-10-31 20:50:48 +00:00
|
|
|
send_latency_probe (self, parent, pad, ts);
|
2018-07-06 21:08:24 +00:00
|
|
|
calculate_latency (parent, pad, ts);
|
2017-10-11 15:08:12 +00:00
|
|
|
}
|
|
|
|
|
|
|
|
static void
|
2018-10-31 20:50:48 +00:00
|
|
|
do_pull_range_pre (GstTracer * tracer, guint64 ts, GstPad * pad)
|
2014-02-20 10:15:20 +00:00
|
|
|
{
|
2018-10-31 20:50:48 +00:00
|
|
|
GstLatencyTracer *self = (GstLatencyTracer *) tracer;
|
2014-02-20 10:15:20 +00:00
|
|
|
GstPad *peer_pad = GST_PAD_PEER (pad);
|
|
|
|
GstElement *parent = get_real_pad_parent (peer_pad);
|
|
|
|
|
2018-10-31 20:50:48 +00:00
|
|
|
send_latency_probe (self, parent, peer_pad, ts);
|
2014-02-20 10:15:20 +00:00
|
|
|
}
|
|
|
|
|
|
|
|
static void
|
2014-09-18 06:26:19 +00:00
|
|
|
do_pull_range_post (GstTracer * self, guint64 ts, GstPad * pad)
|
2014-02-18 10:06:10 +00:00
|
|
|
{
|
2014-02-20 10:15:20 +00:00
|
|
|
GstElement *parent = get_real_pad_parent (pad);
|
|
|
|
|
2014-09-17 06:38:02 +00:00
|
|
|
calculate_latency (parent, pad, ts);
|
2014-02-20 10:15:20 +00:00
|
|
|
}
|
|
|
|
|
2018-07-06 21:08:24 +00:00
|
|
|
static GstPadProbeReturn
|
|
|
|
do_drop_sub_latency_event (GstPad * pad, GstPadProbeInfo * info,
|
|
|
|
gpointer user_data)
|
|
|
|
{
|
|
|
|
GstEvent *ev = info->data;
|
|
|
|
GstPadProbeReturn ret = GST_PAD_PROBE_OK;
|
|
|
|
|
|
|
|
if (GST_EVENT_TYPE (ev) == GST_EVENT_CUSTOM_DOWNSTREAM) {
|
|
|
|
const GstStructure *data = gst_event_get_structure (ev);
|
|
|
|
|
|
|
|
if (gst_structure_get_name_id (data) == sub_latency_probe_id) {
|
|
|
|
const GValue *value;
|
|
|
|
/* FIXME unsafe peer pad usage */
|
|
|
|
gchar *pad_name = g_strdup_printf ("%s_%s",
|
|
|
|
GST_DEBUG_PAD_NAME (GST_PAD_PEER (pad)));
|
|
|
|
|
|
|
|
value = gst_structure_id_get_value (data, latency_probe_pad);
|
|
|
|
if (!g_str_equal (g_value_get_string (value), pad_name)) {
|
|
|
|
GST_DEBUG ("%s: Dropping sub-latency event", pad_name);
|
|
|
|
ret = GST_PAD_PROBE_DROP;
|
|
|
|
}
|
|
|
|
|
|
|
|
g_free (pad_name);
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
return ret;
|
|
|
|
}
|
|
|
|
|
2014-02-20 10:15:20 +00:00
|
|
|
static void
|
2014-09-18 06:26:19 +00:00
|
|
|
do_push_event_pre (GstTracer * self, guint64 ts, GstPad * pad, GstEvent * ev)
|
2014-02-20 10:15:20 +00:00
|
|
|
{
|
2018-07-06 21:08:24 +00:00
|
|
|
GstElement *parent = get_real_pad_parent (pad);
|
2014-02-18 10:06:10 +00:00
|
|
|
GstPad *peer_pad = GST_PAD_PEER (pad);
|
2018-07-06 21:08:24 +00:00
|
|
|
GstElement *peer_parent = get_real_pad_parent (peer_pad);
|
2014-02-18 10:06:10 +00:00
|
|
|
|
2014-02-18 15:15:44 +00:00
|
|
|
if (parent && (!GST_IS_BIN (parent)) &&
|
2018-07-06 21:08:24 +00:00
|
|
|
(!GST_OBJECT_FLAG_IS_SET (parent, GST_ELEMENT_FLAG_SOURCE)) &&
|
|
|
|
GST_EVENT_TYPE (ev) == GST_EVENT_CUSTOM_DOWNSTREAM) {
|
|
|
|
const GstStructure *data = gst_event_get_structure (ev);
|
|
|
|
|
|
|
|
/* if not set yet, add a pad probe that prevents sub-latency event from
|
|
|
|
* flowing further */
|
|
|
|
if (gst_structure_get_name_id (data) == latency_probe_id) {
|
|
|
|
|
|
|
|
if (!g_object_get_qdata ((GObject *) pad, drop_sub_latency_quark)) {
|
|
|
|
GST_DEBUG ("%s_%s: Adding pad probe to drop sub-latency event",
|
|
|
|
GST_DEBUG_PAD_NAME (pad));
|
|
|
|
gst_pad_add_probe (pad, GST_PAD_PROBE_TYPE_EVENT_DOWNSTREAM,
|
|
|
|
do_drop_sub_latency_event, NULL, NULL);
|
|
|
|
g_object_set_qdata ((GObject *) pad, drop_sub_latency_quark,
|
|
|
|
(gpointer) 1);
|
|
|
|
}
|
|
|
|
|
|
|
|
/* FIXME unsafe peer access */
|
|
|
|
if (GST_OBJECT_FLAG_IS_SET (peer_parent, GST_ELEMENT_FLAG_SINK)) {
|
|
|
|
GST_DEBUG ("%s_%s: Storing latency event", GST_DEBUG_PAD_NAME (pad));
|
|
|
|
|
|
|
|
/* store event so that we can calculate latency when the buffer that
|
|
|
|
* follows has been processed */
|
2019-03-19 01:55:50 +00:00
|
|
|
if (!g_object_get_qdata ((GObject *) pad, latency_probe_id))
|
|
|
|
g_object_set_qdata ((GObject *) pad, latency_probe_id,
|
|
|
|
gst_event_ref (ev));
|
2014-02-18 10:06:10 +00:00
|
|
|
}
|
|
|
|
}
|
2018-07-06 21:08:24 +00:00
|
|
|
|
|
|
|
if (gst_structure_get_name_id (data) == sub_latency_probe_id) {
|
|
|
|
const GValue *value;
|
2019-04-10 13:13:53 +00:00
|
|
|
gchar *element_id = g_strdup_printf ("%p", peer_parent);
|
|
|
|
gchar *element_name = gst_element_get_name (peer_parent);
|
|
|
|
gchar *pad_name = gst_pad_get_name (peer_pad);
|
|
|
|
const gchar *value_element_id, *value_element_name, *value_pad_name;
|
|
|
|
|
|
|
|
/* Get the element id, element name and pad name from data */
|
|
|
|
value = gst_structure_id_get_value (data, latency_probe_element_id);
|
|
|
|
value_element_id = g_value_get_string (value);
|
|
|
|
value = gst_structure_id_get_value (data, latency_probe_element);
|
|
|
|
value_element_name = g_value_get_string (value);
|
2018-07-06 21:08:24 +00:00
|
|
|
value = gst_structure_id_get_value (data, latency_probe_pad);
|
2019-04-10 13:13:53 +00:00
|
|
|
value_pad_name = g_value_get_string (value);
|
|
|
|
|
|
|
|
if (!g_str_equal (value_element_id, element_id) ||
|
|
|
|
!g_str_equal (value_element_name, element_name) ||
|
|
|
|
!g_str_equal (value_pad_name, pad_name)) {
|
|
|
|
GST_DEBUG ("%s_%s: Storing latency event", GST_DEBUG_PAD_NAME (pad));
|
2018-07-06 21:08:24 +00:00
|
|
|
|
2019-03-19 01:55:50 +00:00
|
|
|
if (!g_object_get_qdata ((GObject *) pad, sub_latency_probe_id))
|
|
|
|
g_object_set_qdata ((GObject *) pad, sub_latency_probe_id,
|
|
|
|
gst_event_ref (ev));
|
2018-07-06 21:08:24 +00:00
|
|
|
}
|
|
|
|
|
|
|
|
g_free (pad_name);
|
2019-04-10 13:13:53 +00:00
|
|
|
g_free (element_name);
|
|
|
|
g_free (element_id);
|
2018-07-06 21:08:24 +00:00
|
|
|
}
|
2014-02-18 10:06:10 +00:00
|
|
|
}
|
|
|
|
}
|
|
|
|
|
2019-03-21 09:37:34 +00:00
|
|
|
static void
|
|
|
|
do_query_post (GstLatencyTracer * tracer, GstClockTime ts, GstPad * pad,
|
|
|
|
GstQuery * query, gboolean res)
|
|
|
|
{
|
|
|
|
/* Only check for latency queries if flag is enabled */
|
|
|
|
if ((tracer->flags & GST_LATENCY_TRACER_FLAG_REPORTED_ELEMENT) &&
|
|
|
|
(GST_QUERY_TYPE (query) == GST_QUERY_LATENCY)) {
|
|
|
|
gboolean live;
|
|
|
|
guint64 min = 0, max = 0, min_prev = 0, max_prev = 0;
|
2019-04-09 12:05:09 +00:00
|
|
|
gchar *element_name, *element_id;
|
2019-03-21 09:37:34 +00:00
|
|
|
struct LatencyQueryTableValue *value;
|
|
|
|
GstElement *element = get_real_pad_parent (pad);
|
|
|
|
GstElement *peer_element = get_real_pad_parent (GST_PAD_PEER (pad));
|
|
|
|
|
|
|
|
/* Parse the query */
|
|
|
|
gst_query_parse_latency (query, &live, &min, &max);
|
|
|
|
|
|
|
|
/* Pop from stack */
|
|
|
|
value = local_latency_query_stack_pop ();
|
|
|
|
while (value && value->peer_element == element) {
|
|
|
|
min_prev = MAX (value->min, min_prev);
|
|
|
|
max_prev = MAX (value->max, max_prev);
|
|
|
|
value = local_latency_query_stack_pop ();
|
|
|
|
}
|
|
|
|
|
|
|
|
/* Push to stack */
|
|
|
|
value = g_new0 (struct LatencyQueryTableValue, 1);
|
|
|
|
value->peer_element = gst_object_ref (peer_element);
|
|
|
|
value->min = min;
|
|
|
|
value->max = max;
|
|
|
|
local_latency_query_stack_push (value);
|
|
|
|
|
|
|
|
/* Get the pad name */
|
2019-04-09 12:05:09 +00:00
|
|
|
element_id = g_strdup_printf ("%p", element);
|
2019-03-21 09:37:34 +00:00
|
|
|
element_name = gst_element_get_name (element);
|
|
|
|
|
|
|
|
/* Log reported latency */
|
2019-04-09 12:05:09 +00:00
|
|
|
gst_tracer_record_log (tr_element_reported_latency, element_id,
|
|
|
|
element_name, live, GST_CLOCK_DIFF (min_prev, min),
|
|
|
|
GST_CLOCK_DIFF (max_prev, max), ts);
|
2019-03-21 09:37:34 +00:00
|
|
|
|
|
|
|
/* Clean up */
|
|
|
|
g_free (element_name);
|
2019-04-09 12:05:09 +00:00
|
|
|
g_free (element_id);
|
2019-03-21 09:37:34 +00:00
|
|
|
}
|
|
|
|
}
|
|
|
|
|
2014-09-15 11:15:17 +00:00
|
|
|
/* tracer class */
|
|
|
|
|
2018-10-31 20:50:48 +00:00
|
|
|
static void
|
|
|
|
gst_latency_tracer_constructed (GObject * object)
|
|
|
|
{
|
|
|
|
GstLatencyTracer *self = GST_LATENCY_TRACER (object);
|
|
|
|
gchar *params, *tmp;
|
|
|
|
GstStructure *params_struct = NULL;
|
|
|
|
|
|
|
|
g_object_get (self, "params", ¶ms, NULL);
|
|
|
|
|
|
|
|
if (!params)
|
|
|
|
return;
|
|
|
|
|
|
|
|
tmp = g_strdup_printf ("latency,%s", params);
|
|
|
|
params_struct = gst_structure_from_string (tmp, NULL);
|
|
|
|
g_free (tmp);
|
|
|
|
|
|
|
|
/* Read the flags if available */
|
|
|
|
if (params_struct) {
|
|
|
|
const gchar *flags = gst_structure_get_string (params_struct, "flags");
|
|
|
|
|
|
|
|
self->flags = 0;
|
|
|
|
|
|
|
|
if (flags) {
|
|
|
|
GStrv split = g_strsplit (flags, "+", -1);
|
|
|
|
gint i;
|
|
|
|
|
|
|
|
for (i = 0; split[i]; i++) {
|
|
|
|
if (g_str_equal (split[i], "pipeline"))
|
|
|
|
self->flags |= GST_LATENCY_TRACER_FLAG_PIPELINE;
|
|
|
|
else if (g_str_equal (split[i], "element"))
|
|
|
|
self->flags |= GST_LATENCY_TRACER_FLAG_ELEMENT;
|
2019-03-21 09:37:34 +00:00
|
|
|
else if (g_str_equal (split[i], "reported"))
|
|
|
|
self->flags |= GST_LATENCY_TRACER_FLAG_REPORTED_ELEMENT;
|
2018-10-31 20:50:48 +00:00
|
|
|
else
|
|
|
|
GST_WARNING ("Invalid latency tracer flags %s", split[i]);
|
|
|
|
}
|
|
|
|
|
|
|
|
g_strfreev (split);
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
g_free (params);
|
|
|
|
}
|
|
|
|
|
2014-02-18 10:06:10 +00:00
|
|
|
static void
|
2014-09-15 11:15:17 +00:00
|
|
|
gst_latency_tracer_class_init (GstLatencyTracerClass * klass)
|
2014-02-18 10:06:10 +00:00
|
|
|
{
|
2018-10-31 20:50:48 +00:00
|
|
|
GObjectClass *gobject_class = G_OBJECT_CLASS (klass);
|
|
|
|
|
|
|
|
gobject_class->constructed = gst_latency_tracer_constructed;
|
|
|
|
|
2014-09-15 11:15:17 +00:00
|
|
|
latency_probe_id = g_quark_from_static_string ("latency_probe.id");
|
2018-07-06 21:08:24 +00:00
|
|
|
sub_latency_probe_id = g_quark_from_static_string ("sub_latency_probe.id");
|
2014-09-15 11:15:17 +00:00
|
|
|
latency_probe_pad = g_quark_from_static_string ("latency_probe.pad");
|
2019-04-09 12:05:09 +00:00
|
|
|
latency_probe_element = g_quark_from_static_string ("latency_probe.element");
|
|
|
|
latency_probe_element_id =
|
|
|
|
g_quark_from_static_string ("latency_probe.element_id");
|
2014-09-15 11:15:17 +00:00
|
|
|
latency_probe_ts = g_quark_from_static_string ("latency_probe.ts");
|
2018-07-06 21:08:24 +00:00
|
|
|
drop_sub_latency_quark =
|
|
|
|
g_quark_from_static_string ("drop_sub_latency.quark");
|
2014-09-15 11:15:17 +00:00
|
|
|
|
|
|
|
/* announce trace formats */
|
|
|
|
/* *INDENT-OFF* */
|
2016-01-21 07:12:01 +00:00
|
|
|
tr_latency = gst_tracer_record_new ("latency.class",
|
2019-04-09 12:05:09 +00:00
|
|
|
"src-element-id", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
|
|
|
|
"type", G_TYPE_GTYPE, G_TYPE_STRING,
|
|
|
|
"related-to", GST_TYPE_TRACER_VALUE_SCOPE,
|
|
|
|
GST_TRACER_VALUE_SCOPE_ELEMENT,
|
|
|
|
NULL),
|
|
|
|
"src-element", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
|
|
|
|
"type", G_TYPE_GTYPE, G_TYPE_STRING,
|
|
|
|
"related-to", GST_TYPE_TRACER_VALUE_SCOPE,
|
|
|
|
GST_TRACER_VALUE_SCOPE_ELEMENT,
|
|
|
|
NULL),
|
2014-09-15 11:15:17 +00:00
|
|
|
"src", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
|
2016-01-12 13:59:04 +00:00
|
|
|
"type", G_TYPE_GTYPE, G_TYPE_STRING,
|
2016-01-16 12:24:16 +00:00
|
|
|
"related-to", GST_TYPE_TRACER_VALUE_SCOPE, GST_TRACER_VALUE_SCOPE_PAD,
|
2014-09-15 11:15:17 +00:00
|
|
|
NULL),
|
2019-04-09 12:05:09 +00:00
|
|
|
"sink-element-id", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
|
|
|
|
"type", G_TYPE_GTYPE, G_TYPE_STRING,
|
|
|
|
"related-to", GST_TYPE_TRACER_VALUE_SCOPE,
|
|
|
|
GST_TRACER_VALUE_SCOPE_ELEMENT,
|
|
|
|
NULL),
|
|
|
|
"sink-element", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
|
|
|
|
"type", G_TYPE_GTYPE, G_TYPE_STRING,
|
|
|
|
"related-to", GST_TYPE_TRACER_VALUE_SCOPE,
|
|
|
|
GST_TRACER_VALUE_SCOPE_ELEMENT,
|
|
|
|
NULL),
|
2014-09-15 11:15:17 +00:00
|
|
|
"sink", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
|
2016-01-12 13:59:04 +00:00
|
|
|
"type", G_TYPE_GTYPE, G_TYPE_STRING,
|
2016-01-16 12:24:16 +00:00
|
|
|
"related-to", GST_TYPE_TRACER_VALUE_SCOPE, GST_TRACER_VALUE_SCOPE_PAD,
|
2014-09-15 11:15:17 +00:00
|
|
|
NULL),
|
|
|
|
"time", GST_TYPE_STRUCTURE, gst_structure_new ("value",
|
|
|
|
"type", G_TYPE_GTYPE, G_TYPE_UINT64,
|
|
|
|
"description", G_TYPE_STRING,
|
|
|
|
"time it took for the buffer to go from src to sink ns",
|
|
|
|
"min", G_TYPE_UINT64, G_GUINT64_CONSTANT (0),
|
|
|
|
"max", G_TYPE_UINT64, G_MAXUINT64,
|
|
|
|
NULL),
|
2017-04-13 14:28:54 +00:00
|
|
|
"ts", GST_TYPE_STRUCTURE, gst_structure_new ("value",
|
|
|
|
"type", G_TYPE_GTYPE, G_TYPE_UINT64,
|
|
|
|
"description", G_TYPE_STRING, "ts when the latency has been logged",
|
|
|
|
"min", G_TYPE_UINT64, G_GUINT64_CONSTANT (0),
|
|
|
|
"max", G_TYPE_UINT64, G_MAXUINT64,
|
|
|
|
NULL),
|
2016-01-21 07:12:01 +00:00
|
|
|
NULL);
|
2018-07-06 21:08:24 +00:00
|
|
|
|
|
|
|
tr_element_latency = gst_tracer_record_new ("element-latency.class",
|
2019-04-09 12:05:09 +00:00
|
|
|
"element-id", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
|
|
|
|
"type", G_TYPE_GTYPE, G_TYPE_STRING,
|
|
|
|
"related-to", GST_TYPE_TRACER_VALUE_SCOPE,
|
|
|
|
GST_TRACER_VALUE_SCOPE_ELEMENT,
|
|
|
|
NULL),
|
|
|
|
"element", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
|
|
|
|
"type", G_TYPE_GTYPE, G_TYPE_STRING,
|
|
|
|
"related-to", GST_TYPE_TRACER_VALUE_SCOPE,
|
|
|
|
GST_TRACER_VALUE_SCOPE_ELEMENT,
|
|
|
|
NULL),
|
2019-03-20 11:20:48 +00:00
|
|
|
"src", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
|
2018-07-06 21:08:24 +00:00
|
|
|
"type", G_TYPE_GTYPE, G_TYPE_STRING,
|
2019-03-20 11:20:48 +00:00
|
|
|
"related-to", GST_TYPE_TRACER_VALUE_SCOPE, GST_TRACER_VALUE_SCOPE_PAD,
|
2018-07-06 21:08:24 +00:00
|
|
|
NULL),
|
|
|
|
"time", GST_TYPE_STRUCTURE, gst_structure_new ("value",
|
|
|
|
"type", G_TYPE_GTYPE, G_TYPE_UINT64,
|
|
|
|
"description", G_TYPE_STRING,
|
|
|
|
"time it took for the buffer to go from src to sink ns",
|
|
|
|
"min", G_TYPE_UINT64, G_GUINT64_CONSTANT (0),
|
|
|
|
"max", G_TYPE_UINT64, G_MAXUINT64,
|
|
|
|
NULL),
|
|
|
|
"ts", GST_TYPE_STRUCTURE, gst_structure_new ("value",
|
|
|
|
"type", G_TYPE_GTYPE, G_TYPE_UINT64,
|
|
|
|
"description", G_TYPE_STRING, "ts when the latency has been logged",
|
|
|
|
"min", G_TYPE_UINT64, G_GUINT64_CONSTANT (0),
|
|
|
|
"max", G_TYPE_UINT64, G_MAXUINT64,
|
|
|
|
NULL),
|
|
|
|
NULL);
|
2019-03-21 09:37:34 +00:00
|
|
|
|
|
|
|
|
|
|
|
tr_element_reported_latency = gst_tracer_record_new (
|
|
|
|
"element-reported-latency.class",
|
2019-04-09 12:05:09 +00:00
|
|
|
"element-id", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
|
|
|
|
"type", G_TYPE_GTYPE, G_TYPE_STRING,
|
|
|
|
"related-to", GST_TYPE_TRACER_VALUE_SCOPE,
|
|
|
|
GST_TRACER_VALUE_SCOPE_ELEMENT,
|
|
|
|
NULL),
|
2019-03-21 09:37:34 +00:00
|
|
|
"element", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
|
|
|
|
"type", G_TYPE_GTYPE, G_TYPE_STRING,
|
|
|
|
"related-to", GST_TYPE_TRACER_VALUE_SCOPE,
|
|
|
|
GST_TRACER_VALUE_SCOPE_ELEMENT,
|
|
|
|
NULL),
|
|
|
|
"live", GST_TYPE_STRUCTURE, gst_structure_new ("value",
|
|
|
|
"type", G_TYPE_GTYPE, G_TYPE_BOOLEAN,
|
|
|
|
"description", G_TYPE_STRING,
|
|
|
|
"wether the it is a live stream or not",
|
|
|
|
NULL),
|
|
|
|
"min", GST_TYPE_STRUCTURE, gst_structure_new ("value",
|
|
|
|
"type", G_TYPE_GTYPE, G_TYPE_UINT64,
|
|
|
|
"description", G_TYPE_STRING,
|
|
|
|
"the minimum reported latency",
|
|
|
|
"min", G_TYPE_UINT64, G_GUINT64_CONSTANT (0),
|
|
|
|
"max", G_TYPE_UINT64, G_MAXUINT64,
|
|
|
|
NULL),
|
|
|
|
"max", GST_TYPE_STRUCTURE, gst_structure_new ("value",
|
|
|
|
"type", G_TYPE_GTYPE, G_TYPE_UINT64,
|
|
|
|
"description", G_TYPE_STRING, "the maximum reported latency",
|
|
|
|
"min", G_TYPE_UINT64, G_GUINT64_CONSTANT (0),
|
|
|
|
"max", G_TYPE_UINT64, G_MAXUINT64,
|
|
|
|
NULL),
|
|
|
|
"ts", GST_TYPE_STRUCTURE, gst_structure_new ("value",
|
|
|
|
"type", G_TYPE_GTYPE, G_TYPE_UINT64,
|
|
|
|
"description", G_TYPE_STRING, "ts when the latency has been reported",
|
|
|
|
"min", G_TYPE_UINT64, G_GUINT64_CONSTANT (0),
|
|
|
|
"max", G_TYPE_UINT64, G_MAXUINT64,
|
|
|
|
NULL),
|
|
|
|
NULL);
|
2014-09-15 11:15:17 +00:00
|
|
|
/* *INDENT-ON* */
|
|
|
|
}
|
|
|
|
|
|
|
|
static void
|
|
|
|
gst_latency_tracer_init (GstLatencyTracer * self)
|
|
|
|
{
|
|
|
|
GstTracer *tracer = GST_TRACER (self);
|
2017-10-11 15:08:12 +00:00
|
|
|
|
2018-10-31 20:50:48 +00:00
|
|
|
/* only trace pipeline latency by default */
|
|
|
|
self->flags = GST_LATENCY_TRACER_FLAG_PIPELINE;
|
|
|
|
|
2017-10-11 15:08:12 +00:00
|
|
|
/* in push mode, pre/post will be called before/after the peer chain
|
|
|
|
* function has been called. For this reaosn, we only use -pre to avoid
|
|
|
|
* accounting for the processing time of the peer element (the sink) */
|
2014-09-22 07:55:56 +00:00
|
|
|
gst_tracing_register_hook (tracer, "pad-push-pre",
|
2014-09-18 06:26:19 +00:00
|
|
|
G_CALLBACK (do_push_buffer_pre));
|
2014-09-22 07:55:56 +00:00
|
|
|
gst_tracing_register_hook (tracer, "pad-push-list-pre",
|
2014-09-18 06:26:19 +00:00
|
|
|
G_CALLBACK (do_push_buffer_pre));
|
2017-10-11 15:08:12 +00:00
|
|
|
|
2018-04-27 16:40:31 +00:00
|
|
|
/* while in pull mode, pre/post will happen before and after the upstream
|
2017-10-11 15:08:12 +00:00
|
|
|
* pull_range call is made, so it already only account for the upstream
|
|
|
|
* processing time. As a side effect, in pull mode, we can measure the
|
|
|
|
* source processing latency, while in push mode, we can't */
|
2014-09-22 07:55:56 +00:00
|
|
|
gst_tracing_register_hook (tracer, "pad-pull-range-pre",
|
2014-09-18 06:26:19 +00:00
|
|
|
G_CALLBACK (do_pull_range_pre));
|
2014-09-22 07:55:56 +00:00
|
|
|
gst_tracing_register_hook (tracer, "pad-pull-range-post",
|
2014-09-18 06:26:19 +00:00
|
|
|
G_CALLBACK (do_pull_range_post));
|
2017-10-11 15:08:12 +00:00
|
|
|
|
2014-09-22 07:55:56 +00:00
|
|
|
gst_tracing_register_hook (tracer, "pad-push-event-pre",
|
2014-09-18 06:26:19 +00:00
|
|
|
G_CALLBACK (do_push_event_pre));
|
2019-03-21 09:37:34 +00:00
|
|
|
|
|
|
|
/* Add pad query post hook to get the reported per-element latency */
|
|
|
|
gst_tracing_register_hook (tracer, "pad-query-post",
|
|
|
|
G_CALLBACK (do_query_post));
|
2014-02-18 10:06:10 +00:00
|
|
|
}
|