tracer: latency: Show element id, element name and pad name

This commit is contained in:
Julian Bouzas 2019-04-09 08:05:09 -04:00
parent e615a3ddee
commit 1ec8114717
2 changed files with 114 additions and 25 deletions

View file

@ -60,6 +60,8 @@ static void latency_query_stack_destroy (gpointer data);
static GQuark latency_probe_id;
static GQuark sub_latency_probe_id;
static GQuark latency_probe_pad;
static GQuark latency_probe_element;
static GQuark latency_probe_element_id;
static GQuark latency_probe_ts;
static GQuark drop_sub_latency_quark;
@ -166,12 +168,13 @@ local_latency_query_stack_push (struct LatencyQueryTableValue *value)
/* hooks */
static void
log_latency (const GstStructure * data, GstPad * sink_pad, guint64 sink_ts)
log_latency (const GstStructure * data, GstElement * sink_parent,
GstPad * sink_pad, guint64 sink_ts)
{
guint64 src_ts;
const char *src;
const char *src, *element_src, *id_element_src;
const GValue *value;
gchar *sink;
gchar *sink, *element_sink, *id_element_sink;
value = gst_structure_id_get_value (data, latency_probe_ts);
src_ts = g_value_get_uint64 (value);
@ -179,31 +182,46 @@ log_latency (const GstStructure * data, GstPad * sink_pad, guint64 sink_ts)
value = gst_structure_id_get_value (data, latency_probe_pad);
src = g_value_get_string (value);
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);
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);
g_free (sink);
g_free (element_sink);
g_free (id_element_sink);
}
static void
log_element_latency (const GstStructure * data, GstPad * pad, guint64 sink_ts)
log_element_latency (const GstStructure * data, GstElement * parent,
GstPad * pad, guint64 sink_ts)
{
guint64 src_ts;
gchar *pad_name;
gchar *pad_name, *element_name, *element_id;
const GValue *value;
pad_name = g_strdup_printf ("%s_%s", GST_DEBUG_PAD_NAME (pad));
element_id = g_strdup_printf ("%p", parent);
element_name = gst_element_get_name (parent);
pad_name = gst_pad_get_name (pad);
/* TODO filtering */
value = gst_structure_id_get_value (data, latency_probe_ts);
src_ts = g_value_get_uint64 (value);
gst_tracer_record_log (tr_element_latency, pad_name,
gst_tracer_record_log (tr_element_latency, element_id, element_name, pad_name,
GST_CLOCK_DIFF (src_ts, sink_ts), sink_ts);
g_free (pad_name);
g_free (element_name);
g_free (element_id);
}
static void
@ -211,37 +229,50 @@ send_latency_probe (GstLatencyTracer * self, GstElement * parent, GstPad * pad,
guint64 ts)
{
GstPad *peer_pad = GST_PAD_PEER (pad);
GstElement *peer_parent = get_real_pad_parent (peer_pad);
/* 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;
gchar *pad_name, *element_name, *element_id;
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));
element_id = g_strdup_printf ("%p", parent);
element_name = gst_element_get_name (parent);
pad_name = gst_pad_get_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_element_id, G_TYPE_STRING, element_id,
latency_probe_element, G_TYPE_STRING, element_name,
latency_probe_pad, G_TYPE_STRING, pad_name,
latency_probe_ts, G_TYPE_UINT64, ts, NULL));
g_free (pad_name);
g_free (element_name);
g_free (element_id);
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));
element_id = g_strdup_printf ("%p", peer_parent);
element_name = gst_element_get_name (peer_parent);
pad_name = gst_pad_get_name (peer_pad);
latency_probe = gst_event_new_custom (GST_EVENT_CUSTOM_DOWNSTREAM,
gst_structure_new_id (sub_latency_probe_id,
latency_probe_element, G_TYPE_STRING, element_id,
latency_probe_element, G_TYPE_STRING, element_name,
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);
g_free (element_name);
g_free (element_id);
}
}
}
@ -262,7 +293,8 @@ calculate_latency (GstElement * parent, GstPad * pad, guint64 ts)
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);
log_latency (gst_event_get_structure (ev), peer_parent,
GST_PAD_PEER (pad), ts);
gst_event_unref (ev);
}
}
@ -271,7 +303,7 @@ calculate_latency (GstElement * parent, GstPad * pad, guint64 ts)
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), pad, ts);
log_element_latency (gst_event_get_structure (ev), parent, pad, ts);
gst_event_unref (ev);
}
}
@ -399,7 +431,7 @@ do_query_post (GstLatencyTracer * tracer, GstClockTime ts, GstPad * pad,
(GST_QUERY_TYPE (query) == GST_QUERY_LATENCY)) {
gboolean live;
guint64 min = 0, max = 0, min_prev = 0, max_prev = 0;
gchar *element_name;
gchar *element_name, *element_id;
struct LatencyQueryTableValue *value;
GstElement *element = get_real_pad_parent (pad);
GstElement *peer_element = get_real_pad_parent (GST_PAD_PEER (pad));
@ -423,14 +455,17 @@ do_query_post (GstLatencyTracer * tracer, GstClockTime ts, GstPad * pad,
local_latency_query_stack_push (value);
/* Get the pad name */
element_id = g_strdup_printf ("%p", element);
element_name = gst_element_get_name (element);
/* Log reported latency */
gst_tracer_record_log (tr_element_reported_latency, element_name, live,
GST_CLOCK_DIFF (min_prev, min), GST_CLOCK_DIFF (max_prev, max), ts);
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);
/* Clean up */
g_free (element_name);
g_free (element_id);
}
}
@ -490,6 +525,9 @@ gst_latency_tracer_class_init (GstLatencyTracerClass * klass)
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_element = g_quark_from_static_string ("latency_probe.element");
latency_probe_element_id =
g_quark_from_static_string ("latency_probe.element_id");
latency_probe_ts = g_quark_from_static_string ("latency_probe.ts");
drop_sub_latency_quark =
g_quark_from_static_string ("drop_sub_latency.quark");
@ -497,10 +535,30 @@ gst_latency_tracer_class_init (GstLatencyTracerClass * klass)
/* announce trace formats */
/* *INDENT-OFF* */
tr_latency = gst_tracer_record_new ("latency.class",
"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),
"src", 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_PAD,
NULL),
"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),
"sink", 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_PAD,
@ -521,6 +579,16 @@ gst_latency_tracer_class_init (GstLatencyTracerClass * klass)
NULL);
tr_element_latency = gst_tracer_record_new ("element-latency.class",
"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),
"src", 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_PAD,
@ -543,6 +611,11 @@ gst_latency_tracer_class_init (GstLatencyTracerClass * klass)
tr_element_reported_latency = gst_tracer_record_new (
"element-reported-latency.class",
"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,

View file

@ -501,12 +501,17 @@ static void
do_latency_stats (GstStructure * s)
{
gchar *key = NULL;
const gchar *src = NULL, *sink = NULL;
const gchar *src = NULL, *sink = NULL, *src_element = NULL,
*sink_element = NULL, *src_element_id = NULL, *sink_element_id = NULL;
guint64 ts = 0, time = 0;
/* Get the values from the structure */
src = gst_structure_get_string (s, "src");
sink = gst_structure_get_string (s, "sink");
src_element = gst_structure_get_string (s, "src-element");
sink_element = gst_structure_get_string (s, "sink-element");
src_element_id = gst_structure_get_string (s, "src-element-id");
sink_element_id = gst_structure_get_string (s, "sink-element-id");
gst_structure_get (s, "time", G_TYPE_UINT64, &time, NULL);
gst_structure_get (s, "ts", G_TYPE_UINT64, &ts, NULL);
@ -514,7 +519,8 @@ do_latency_stats (GstStructure * s)
last_ts = MAX (last_ts, ts);
/* Get the key */
key = g_strjoin ("|", src, sink, NULL);
key = g_strdup_printf ("%s.%s.%s|%s.%s.%s", src_element_id, src_element,
src, sink_element_id, sink_element, sink);
/* Update the latency in the table */
update_latency_table (latencies, key, time);
@ -528,19 +534,28 @@ do_latency_stats (GstStructure * s)
static void
do_element_latency_stats (GstStructure * s)
{
const gchar *src = NULL;
gchar *key = NULL;
const gchar *src = NULL, *element = NULL, *element_id = NULL;
guint64 ts = 0, time = 0;
/* Get the values from the structure */
src = gst_structure_get_string (s, "src");
element = gst_structure_get_string (s, "element");
element_id = gst_structure_get_string (s, "element-id");
gst_structure_get (s, "time", G_TYPE_UINT64, &time, NULL);
gst_structure_get (s, "ts", G_TYPE_UINT64, &ts, NULL);
/* Update last_ts */
last_ts = MAX (last_ts, ts);
/* Get the key */
key = g_strdup_printf ("%s.%s.%s", element_id, element, src);
/* Update the latency in the table */
update_latency_table (element_latencies, src, time);
update_latency_table (element_latencies, key, time);
/* Clean up */
g_free (key);
have_element_latency = TRUE;
}
@ -548,11 +563,12 @@ do_element_latency_stats (GstStructure * s)
static void
do_element_reported_latency (GstStructure * s)
{
const gchar *element = NULL;
const gchar *element = NULL, *element_id = NULL;
guint64 ts = 0, min = 0, max = 0;
GstReportedLatency *rl = NULL;
/* Get the values from the structure */
element_id = gst_structure_get_string (s, "element-id");
element = gst_structure_get_string (s, "element");
gst_structure_get (s, "min", G_TYPE_UINT64, &min, NULL);
gst_structure_get (s, "max", G_TYPE_UINT64, &max, NULL);
@ -563,7 +579,7 @@ do_element_reported_latency (GstStructure * s)
/* Insert/Update the key in the table */
rl = g_new0 (GstReportedLatency, 1);
rl->element = g_strdup (element);
rl->element = g_strdup_printf ("%s.%s", element_id, element);
rl->ts = ts;
rl->min = min;
rl->max = max;