Commit 6a35153e authored by Nicolas Dufresne's avatar Nicolas Dufresne Committed by Julian Bouzas

tracer: latency: Add per element latency tracer

This adds per element latency tracing.
parent 4585d22a
......@@ -49,10 +49,13 @@ G_DEFINE_TYPE_WITH_CODE (GstLatencyTracer, gst_latency_tracer, GST_TYPE_TRACER,
_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 */
......@@ -105,43 +108,94 @@ 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 (sink_pad));
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
log_element_latency (const GstStructure * data, GstElement * element,
guint64 sink_ts)
{
guint64 src_ts;
const gchar *element_name;
const GValue *value;
element_name = GST_ELEMENT_NAME (element);
/* 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, element_name,
GST_CLOCK_DIFF (src_ts, sink_ts), sink_ts);
}
static void
send_latency_probe (GstElement * parent, GstPad * pad, guint64 ts)
{
GstPad *peer_pad = GST_PAD_PEER (pad);
/* allow for non-parented pads to send latency probes as used in e.g.
* rtspsrc for TCP connections */
if (!parent || (!GST_IS_BIN (parent) &&
GST_OBJECT_FLAG_IS_SET (parent, GST_ELEMENT_FLAG_SOURCE))) {
if (peer_pad && (!parent || (!GST_IS_BIN (parent)))) {
gchar *pad_name;
GstEvent *latency_probe;
pad_name = g_strdup_printf ("%s_%s", GST_DEBUG_PAD_NAME (pad));
if (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);
}
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 (latency_probe_id,
gst_structure_new_id (sub_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);
g_free (pad_name);
}
}
static void
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);
}
}
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, latency_probe_id, NULL);
log_latency (gst_event_get_structure (ev), pad, ts);
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);
}
}
......@@ -150,12 +204,10 @@ calculate_latency (GstElement * parent, GstPad * pad, guint64 ts)
static void
do_push_buffer_pre (GstTracer * self, guint64 ts, GstPad * pad)
{
GstPad *peer_pad = GST_PAD_PEER (pad);
GstElement *parent = get_real_pad_parent (pad);
GstElement *peer_parent = get_real_pad_parent (peer_pad);
send_latency_probe (parent, pad, ts);
calculate_latency (peer_parent, peer_pad, ts);
calculate_latency (parent, pad, ts);
}
static void
......@@ -175,24 +227,86 @@ do_pull_range_post (GstTracer * self, guint64 ts, GstPad * pad)
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, guint64 ts, GstPad * pad, GstEvent * ev)
{
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);
}
}
}
......@@ -202,8 +316,11 @@ static void
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_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* */
......@@ -230,6 +347,26 @@ gst_latency_tracer_class_init (GstLatencyTracerClass * klass)
"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",
"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);
/* *INDENT-ON* */
}
......
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment