* Boston, MA 02110-1301, USA.
*/
/**
- * SECTION:gstlatency
+ * SECTION:element-latencytracer
* @short_description: log processing latency stats
*
* A tracing module that determines src-to-sink latencies by injecting custom
- * events at sources and process them at sinks.
+ * 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 ./...
+ * ```
*/
/* 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,
_do_init);
static GQuark latency_probe_id;
+static GQuark sub_latency_probe_id;
static GQuark latency_probe_pad;
static GQuark latency_probe_ts;
+static GQuark drop_sub_latency_quark;
+
+static GstTracerRecord *tr_latency;
+static GstTracerRecord *tr_element_latency;
/* data helpers */
/*
- * Get the element/bin owning the pad.
+ * Get the element/bin owning the pad.
*
* in: a normal pad
* out: the element
static void
log_latency (const GstStructure * data, GstPad * sink_pad, guint64 sink_ts)
{
- GstPad *src_pad;
guint64 src_ts;
- gchar *src, *sink;
+ const char *src;
+ const GValue *value;
+ gchar *sink;
- gst_structure_id_get (data,
- latency_probe_pad, GST_TYPE_PAD, &src_pad,
- latency_probe_ts, G_TYPE_UINT64, &src_ts, NULL);
+ value = gst_structure_id_get_value (data, latency_probe_ts);
+ src_ts = g_value_get_uint64 (value);
- src = g_strdup_printf ("%s_%s", GST_DEBUG_PAD_NAME (src_pad));
- sink = g_strdup_printf ("%s_%s", GST_DEBUG_PAD_NAME (sink_pad));
+ value = gst_structure_id_get_value (data, latency_probe_pad);
+ src = g_value_get_string (value);
- /* TODO(ensonic): report format is still unstable */
- gst_tracer_log_trace (gst_structure_new ("latency",
- "src", G_TYPE_STRING, src,
- "sink", G_TYPE_STRING, sink,
- "time", G_TYPE_UINT64, GST_CLOCK_DIFF (src_ts, sink_ts), NULL));
- g_free (src);
+ sink = g_strdup_printf ("%s_%s",
+ GST_DEBUG_PAD_NAME (GST_PAD_PEER (sink_pad)));
+ gst_tracer_record_log (tr_latency, src, sink,
+ GST_CLOCK_DIFF (src_ts, sink_ts), sink_ts);
g_free (sink);
}
static void
-send_latency_probe (GstLatencyTracer * self, GstElement * parent, GstPad * pad,
- guint64 ts)
+log_element_latency (const GstStructure * data, GstElement * element,
+ guint64 sink_ts)
{
- if (parent && (!GST_IS_BIN (parent)) &&
- GST_OBJECT_FLAG_IS_SET (parent, GST_ELEMENT_FLAG_SOURCE)) {
- GstEvent *latency_probe = gst_event_new_custom (GST_EVENT_CUSTOM_DOWNSTREAM,
- gst_structure_new_id (latency_probe_id,
- latency_probe_pad, GST_TYPE_PAD, pad,
- latency_probe_ts, G_TYPE_UINT64, ts,
- NULL));
- gst_pad_push_event (pad, latency_probe);
- }
-}
+ guint64 src_ts;
+ const gchar *element_name;
+ const GValue *value;
-static void
-do_push_buffer_pre (GstTracer * self, va_list var_args)
-{
- guint64 ts = va_arg (var_args, guint64);
- GstPad *pad = va_arg (var_args, GstPad *);
- GstElement *parent = get_real_pad_parent (pad);
+ element_name = GST_ELEMENT_NAME (element);
+
+ /* TODO filtering */
- send_latency_probe ((GstLatencyTracer *) self, parent, pad, ts);
+ value = gst_structure_id_get_value (data, latency_probe_ts);
+ src_ts = g_value_get_uint64 (value);
+
+ gst_tracer_record_log (tr_element_latency, element_name,
+ GST_CLOCK_DIFF (src_ts, sink_ts), sink_ts);
}
static void
-do_pull_range_pre (GstTracer * self, va_list var_args)
+send_latency_probe (GstLatencyTracer * self, GstElement * parent, GstPad * pad,
+ guint64 ts)
{
- guint64 ts = va_arg (var_args, guint64);
- GstPad *pad = va_arg (var_args, GstPad *);
GstPad *peer_pad = GST_PAD_PEER (pad);
- GstElement *parent = get_real_pad_parent (peer_pad);
- send_latency_probe ((GstLatencyTracer *) self, parent, peer_pad, ts);
+ /* allow for non-parented pads to send latency probes as used in e.g.
+ * rtspsrc for TCP connections */
+ if (peer_pad && (!parent || (!GST_IS_BIN (parent)))) {
+ gchar *pad_name;
+ GstEvent *latency_probe;
+
+ if (self->flags & GST_LATENCY_TRACER_FLAG_PIPELINE &&
+ GST_OBJECT_FLAG_IS_SET (parent, GST_ELEMENT_FLAG_SOURCE)) {
+ pad_name = g_strdup_printf ("%s_%s", GST_DEBUG_PAD_NAME (pad));
+
+ 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,
+ latency_probe_pad, G_TYPE_STRING, pad_name,
+ latency_probe_ts, G_TYPE_UINT64, ts, NULL));
+ g_free (pad_name);
+ gst_pad_push_event (pad, latency_probe);
+ }
+
+ if (self->flags & GST_LATENCY_TRACER_FLAG_ELEMENT) {
+ GST_DEBUG ("%s_%s: Sending sub-latency event", GST_DEBUG_PAD_NAME (pad));
+
+ pad_name = g_strdup_printf ("%s_%s", GST_DEBUG_PAD_NAME (peer_pad));
+ latency_probe = gst_event_new_custom (GST_EVENT_CUSTOM_DOWNSTREAM,
+ gst_structure_new_id (sub_latency_probe_id,
+ 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);
+ }
+ }
}
static void
-calculate_latency (GstLatencyTracer * self, GstElement * parent, GstPad * pad,
- guint64 ts)
+calculate_latency (GstElement * parent, GstPad * pad, guint64 ts)
{
+ GstElement *peer_parent = get_real_pad_parent (GST_PAD_PEER (pad));
+
if (parent && (!GST_IS_BIN (parent)) &&
- GST_OBJECT_FLAG_IS_SET (parent, GST_ELEMENT_FLAG_SINK)) {
- GstEvent *ev = g_object_get_qdata ((GObject *) pad, latency_probe_id);
+ (!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);
+ log_latency (gst_event_get_structure (ev), pad, ts);
+ gst_event_unref (ev);
+ }
+ }
- log_latency (gst_event_get_structure (ev), pad, ts);
- gst_event_unref (ev);
+ 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);
+ if (ev) {
+ g_object_set_qdata ((GObject *) pad, sub_latency_probe_id, NULL);
+ log_element_latency (gst_event_get_structure (ev), parent, ts);
+ gst_event_unref (ev);
+ }
}
}
static void
-do_push_buffer_post (GstTracer * self, va_list var_args)
+do_push_buffer_pre (GstTracer * tracer, guint64 ts, GstPad * pad)
+{
+ GstLatencyTracer *self = (GstLatencyTracer *) tracer;
+ GstElement *parent = get_real_pad_parent (pad);
+
+ send_latency_probe (self, parent, pad, ts);
+ calculate_latency (parent, pad, ts);
+}
+
+static void
+do_pull_range_pre (GstTracer * tracer, guint64 ts, GstPad * pad)
{
- guint64 ts = va_arg (var_args, guint64);
- GstPad *pad = va_arg (var_args, GstPad *);
+ GstLatencyTracer *self = (GstLatencyTracer *) tracer;
GstPad *peer_pad = GST_PAD_PEER (pad);
GstElement *parent = get_real_pad_parent (peer_pad);
- calculate_latency ((GstLatencyTracer *) self, parent, peer_pad, ts);
+ send_latency_probe (self, parent, peer_pad, ts);
}
static void
-do_pull_range_post (GstTracer * self, va_list var_args)
+do_pull_range_post (GstTracer * self, guint64 ts, GstPad * pad)
{
- guint64 ts = va_arg (var_args, guint64);
- GstPad *pad = va_arg (var_args, GstPad *);
GstElement *parent = get_real_pad_parent (pad);
- calculate_latency ((GstLatencyTracer *) self, parent, pad, ts);
+ calculate_latency (parent, pad, ts);
+}
+
+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;
}
static void
-do_push_event_pre (GstTracer * self, va_list var_args)
+do_push_event_pre (GstTracer * self, guint64 ts, GstPad * pad, GstEvent * ev)
{
- G_GNUC_UNUSED guint64 ts = va_arg (var_args, guint64);
- GstPad *pad = va_arg (var_args, GstPad *);
- GstEvent *ev = va_arg (var_args, GstEvent *);
+ GstElement *parent = get_real_pad_parent (pad);
GstPad *peer_pad = GST_PAD_PEER (pad);
- GstElement *parent = get_real_pad_parent (peer_pad);
+ GstElement *peer_parent = get_real_pad_parent (peer_pad);
if (parent && (!GST_IS_BIN (parent)) &&
- GST_OBJECT_FLAG_IS_SET (parent, GST_ELEMENT_FLAG_SINK)) {
- if (GST_EVENT_TYPE (ev) == GST_EVENT_CUSTOM_DOWNSTREAM) {
- const GstStructure *data = gst_event_get_structure (ev);
-
- if (gst_structure_get_name_id (data) == latency_probe_id) {
- /* store event and calculate latency when the buffer that follows
- * has been processed */
- g_object_set_qdata ((GObject *) peer_pad, latency_probe_id,
+ (!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 */
+ g_object_set_qdata ((GObject *) pad, latency_probe_id,
+ gst_event_ref (ev));
+ }
+ }
+
+ if (gst_structure_get_name_id (data) == sub_latency_probe_id) {
+ const GValue *value;
+ gchar *pad_name = g_strdup_printf ("%s_%s",
+ GST_DEBUG_PAD_NAME (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: Storing sub-latency event", pad_name);
+ g_object_set_qdata ((GObject *) pad, sub_latency_probe_id,
gst_event_ref (ev));
}
+
+ g_free (pad_name);
}
}
}
/* tracer class */
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;
+ else
+ GST_WARNING ("Invalid latency tracer flags %s", split[i]);
+ }
+
+ g_strfreev (split);
+ }
+ }
+
+ g_free (params);
+}
+
+static void
gst_latency_tracer_class_init (GstLatencyTracerClass * klass)
{
+ GObjectClass *gobject_class = G_OBJECT_CLASS (klass);
+
+ gobject_class->constructed = gst_latency_tracer_constructed;
+
latency_probe_id = g_quark_from_static_string ("latency_probe.id");
+ sub_latency_probe_id = g_quark_from_static_string ("sub_latency_probe.id");
latency_probe_pad = g_quark_from_static_string ("latency_probe.pad");
latency_probe_ts = g_quark_from_static_string ("latency_probe.ts");
+ drop_sub_latency_quark =
+ g_quark_from_static_string ("drop_sub_latency.quark");
/* announce trace formats */
/* *INDENT-OFF* */
- gst_tracer_log_trace (gst_structure_new ("latency.class",
+ tr_latency = gst_tracer_record_new ("latency.class",
"src", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
- "related-to", G_TYPE_STRING, "pad", /* TODO: use genum */
+ "type", G_TYPE_GTYPE, G_TYPE_STRING,
+ "related-to", GST_TYPE_TRACER_VALUE_SCOPE, GST_TRACER_VALUE_SCOPE_PAD,
NULL),
"sink", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
- "related-to", G_TYPE_STRING, "pad", /* TODO: use genum */
+ "type", G_TYPE_GTYPE, G_TYPE_STRING,
+ "related-to", GST_TYPE_TRACER_VALUE_SCOPE, GST_TRACER_VALUE_SCOPE_PAD,
+ 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);
+
+ tr_element_latency = gst_tracer_record_new ("element-latency.class",
+ "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),
"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",
- "flags", G_TYPE_STRING, "aggregated", /* TODO: use gflags */
"min", G_TYPE_UINT64, G_GUINT64_CONSTANT (0),
"max", G_TYPE_UINT64, G_MAXUINT64,
NULL),
- 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);
/* *INDENT-ON* */
}
gst_latency_tracer_init (GstLatencyTracer * self)
{
GstTracer *tracer = GST_TRACER (self);
- gst_tracer_register_hook (tracer, "pad-push-pre", do_push_buffer_pre);
- gst_tracer_register_hook (tracer, "pad-push-list-pre", do_push_buffer_pre);
- gst_tracer_register_hook (tracer, "pad-push-post", do_push_buffer_post);
- gst_tracer_register_hook (tracer, "pad-push-list-post", do_push_buffer_post);
- gst_tracer_register_hook (tracer, "pad-pull-range-pre", do_pull_range_pre);
- gst_tracer_register_hook (tracer, "pad-pull-range-post", do_pull_range_post);
- gst_tracer_register_hook (tracer, "pad-push-event-pre", do_push_event_pre);
+
+ /* only trace pipeline latency by default */
+ self->flags = GST_LATENCY_TRACER_FLAG_PIPELINE;
+
+ /* 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) */
+ gst_tracing_register_hook (tracer, "pad-push-pre",
+ G_CALLBACK (do_push_buffer_pre));
+ gst_tracing_register_hook (tracer, "pad-push-list-pre",
+ G_CALLBACK (do_push_buffer_pre));
+
+ /* while in pull mode, pre/post will happen before and after the upstream
+ * 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 */
+ gst_tracing_register_hook (tracer, "pad-pull-range-pre",
+ G_CALLBACK (do_pull_range_pre));
+ gst_tracing_register_hook (tracer, "pad-pull-range-post",
+ G_CALLBACK (do_pull_range_post));
+
+ gst_tracing_register_hook (tracer, "pad-push-event-pre",
+ G_CALLBACK (do_push_event_pre));
}
projects / platform / upstream / gstreamer.git / blobdiff