latency: display event pointer in logs

This is quite useful for debugging when tracer is reporting the wrong
latency because of an element breaking the events/buffers ordering.
This commit is contained in:
Guillaume Desmottes 2019-06-20 16:42:01 +05:30
parent f2d37d5132
commit f321f42359

View file

@ -243,14 +243,16 @@ send_latency_probe (GstLatencyTracer * self, GstElement * parent, GstPad * pad,
element_name = gst_element_get_name (parent); element_name = gst_element_get_name (parent);
pad_name = gst_pad_get_name (pad); pad_name = gst_pad_get_name (pad);
GST_DEBUG ("%s_%s: Sending latency event", GST_DEBUG_PAD_NAME (pad));
latency_probe = gst_event_new_custom (GST_EVENT_CUSTOM_DOWNSTREAM, latency_probe = gst_event_new_custom (GST_EVENT_CUSTOM_DOWNSTREAM,
gst_structure_new_id (latency_probe_id, gst_structure_new_id (latency_probe_id,
latency_probe_element_id, G_TYPE_STRING, element_id, latency_probe_element_id, G_TYPE_STRING, element_id,
latency_probe_element, G_TYPE_STRING, element_name, latency_probe_element, G_TYPE_STRING, element_name,
latency_probe_pad, G_TYPE_STRING, pad_name, latency_probe_pad, G_TYPE_STRING, pad_name,
latency_probe_ts, G_TYPE_UINT64, ts, NULL)); latency_probe_ts, G_TYPE_UINT64, ts, NULL));
GST_DEBUG ("%s_%s: Sending latency event %p", GST_DEBUG_PAD_NAME (pad),
latency_probe);
g_free (pad_name); g_free (pad_name);
g_free (element_name); g_free (element_name);
g_free (element_id); g_free (element_id);
@ -258,17 +260,20 @@ send_latency_probe (GstLatencyTracer * self, GstElement * parent, GstPad * pad,
} }
if (self->flags & GST_LATENCY_TRACER_FLAG_ELEMENT) { if (self->flags & GST_LATENCY_TRACER_FLAG_ELEMENT) {
GST_DEBUG ("%s_%s: Sending sub-latency event", GST_DEBUG_PAD_NAME (pad));
element_id = g_strdup_printf ("%p", peer_parent); element_id = g_strdup_printf ("%p", peer_parent);
element_name = gst_element_get_name (peer_parent); element_name = gst_element_get_name (peer_parent);
pad_name = gst_pad_get_name (peer_pad); pad_name = gst_pad_get_name (peer_pad);
latency_probe = gst_event_new_custom (GST_EVENT_CUSTOM_DOWNSTREAM, latency_probe = gst_event_new_custom (GST_EVENT_CUSTOM_DOWNSTREAM,
gst_structure_new_id (sub_latency_probe_id, gst_structure_new_id (sub_latency_probe_id,
latency_probe_element_id, G_TYPE_STRING, element_id, latency_probe_element_id, G_TYPE_STRING, element_id,
latency_probe_element, G_TYPE_STRING, element_name, latency_probe_element, G_TYPE_STRING, element_name,
latency_probe_pad, G_TYPE_STRING, pad_name, latency_probe_pad, G_TYPE_STRING, pad_name,
latency_probe_ts, G_TYPE_UINT64, ts, NULL)); latency_probe_ts, G_TYPE_UINT64, ts, NULL));
GST_DEBUG ("%s_%s: Sending sub-latency event %p",
GST_DEBUG_PAD_NAME (pad), latency_probe);
gst_pad_push_event (pad, latency_probe); gst_pad_push_event (pad, latency_probe);
g_free (pad_name); g_free (pad_name);
g_free (element_name); g_free (element_name);
@ -288,9 +293,9 @@ calculate_latency (GstElement * parent, GstPad * pad, guint64 ts)
/* FIXME unsafe use of peer */ /* FIXME unsafe use of peer */
if (GST_OBJECT_FLAG_IS_SET (peer_parent, GST_ELEMENT_FLAG_SINK)) { 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); ev = g_object_get_qdata ((GObject *) pad, latency_probe_id);
GST_DEBUG ("%s_%s: Should log full lantency now (event %p)",
GST_DEBUG_PAD_NAME (pad), ev);
if (ev) { if (ev) {
g_object_set_qdata ((GObject *) pad, latency_probe_id, NULL); g_object_set_qdata ((GObject *) pad, latency_probe_id, NULL);
log_latency (gst_event_get_structure (ev), peer_parent, log_latency (gst_event_get_structure (ev), peer_parent,
@ -299,8 +304,9 @@ calculate_latency (GstElement * parent, GstPad * pad, guint64 ts)
} }
} }
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); ev = g_object_get_qdata ((GObject *) pad, sub_latency_probe_id);
GST_DEBUG ("%s_%s: Should log sub lantency now (event %p)",
GST_DEBUG_PAD_NAME (pad), ev);
if (ev) { if (ev) {
g_object_set_qdata ((GObject *) pad, sub_latency_probe_id, NULL); g_object_set_qdata ((GObject *) pad, sub_latency_probe_id, NULL);
log_element_latency (gst_event_get_structure (ev), parent, pad, ts); log_element_latency (gst_event_get_structure (ev), parent, pad, ts);
@ -406,7 +412,6 @@ do_push_event_pre (GstTracer * self, guint64 ts, GstPad * pad, GstEvent * ev)
if (GST_OBJECT_FLAG_IS_SET (peer_parent, GST_ELEMENT_FLAG_SINK)) { if (GST_OBJECT_FLAG_IS_SET (peer_parent, GST_ELEMENT_FLAG_SINK)) {
/* store event so that we can calculate latency when the buffer that /* store event so that we can calculate latency when the buffer that
* follows has been processed */ * follows has been processed */
GST_DEBUG ("%s_%s: Storing latency event", GST_DEBUG_PAD_NAME (pad));
g_object_set_qdata ((GObject *) pad, latency_probe_id, g_object_set_qdata ((GObject *) pad, latency_probe_id,
gst_event_ref (ev)); gst_event_ref (ev));
} }