plugins/tracers/gstlatency.c

   1 /* GStreamer
   2  * Copyright (C) 2013 Stefan Sauer <ensonic@users.sf.net>
   3  *
   4  * gstlatency.c: tracing module that logs processing latency stats
   5  *
   6  * This library is free software; you can redistribute it and/or
   7  * modify it under the terms of the GNU Library General Public
   8  * License as published by the Free Software Foundation; either
   9  * version 2 of the License, or (at your option) any later version.
  10  *
  11  * This library is distributed in the hope that it will be useful,
  12  * but WITHOUT ANY WARRANTY; without even the implied warranty of
  13  * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
  14  * Library General Public License for more details.
  15  *
  16  * You should have received a copy of the GNU Library General Public
  17  * License along with this library; if not, write to the
  18  * Free Software Foundation, Inc., 51 Franklin St, Fifth Floor,
  19  * Boston, MA 02110-1301, USA.
  20  */
  21 /**
  22  * SECTION:gstlatency
  23  * @short_description: log processing latency stats
  24  *
  25  * A tracing module that determines src-to-sink latencies by injecting custom
  26  * events at sources and process them at sinks.
  27  */
  28 /* TODO(ensonic): if there are two sources feeding into a mixer/muxer and later
  29  * we fan-out with tee and have two sinks, each sink would get all two events,
  30  * the later event would overwrite the former. Unfortunately when the buffer
  31  * arrives on the sink we don't know to which event it correlates. Better would
  32  * be to use the buffer meta in 1.0 instead of the event. Or we track a min/max
  33  * latency.
  34  */
  35
  36 #ifdef HAVE_CONFIG_H
  37 #  include "config.h"
  38 #endif
  39
  40 #include "gstlatency.h"
  41
  42 GST_DEBUG_CATEGORY_STATIC (gst_latency_debug);
  43 #define GST_CAT_DEFAULT gst_latency_debug
  44
  45 #define _do_init \
  46     GST_DEBUG_CATEGORY_INIT (gst_latency_debug, "latency", 0, "latency tracer");
  47 #define gst_latency_tracer_parent_class parent_class
  48 G_DEFINE_TYPE_WITH_CODE (GstLatencyTracer, gst_latency_tracer, GST_TYPE_TRACER,
  49     _do_init);
  50
  51 static GQuark latency_probe_id;
  52 static GQuark latency_probe_pad;
  53 static GQuark latency_probe_ts;
  54
  55 /* data helpers */
  56
  57 /*
  58  * Get the element/bin owning the pad.
  59  *
  60  * in: a normal pad
  61  * out: the element
  62  *
  63  * in: a proxy pad
  64  * out: the element that contains the peer of the proxy
  65  *
  66  * in: a ghost pad
  67  * out: the bin owning the ghostpad
  68  */
  69 /* TODO(ensonic): gst_pad_get_parent_element() would not work here, should we
  70  * add this as new api, e.g. gst_pad_find_parent_element();
  71  */
  72 static GstElement *
  73 get_real_pad_parent (GstPad * pad)
  74 {
  75   GstObject *parent;
  76
  77   if (!pad)
  78     return NULL;
  79
  80   parent = GST_OBJECT_PARENT (pad);
  81
  82   /* if parent of pad is a ghost-pad, then pad is a proxy_pad */
  83   if (parent && GST_IS_GHOST_PAD (parent)) {
  84     pad = GST_PAD_CAST (parent);
  85     parent = GST_OBJECT_PARENT (pad);
  86   }
  87   return GST_ELEMENT_CAST (parent);
  88 }
  89
  90 /* tracer class */
  91
  92 static void gst_latency_tracer_invoke (GstTracer * obj, GstTracerHookId id,
  93     GstTracerMessageId mid, va_list var_args);
  94
  95 static void
  96 gst_latency_tracer_class_init (GstLatencyTracerClass * klass)
  97 {
  98   GstTracerClass *gst_tracer_class = GST_TRACER_CLASS (klass);
  99
 100   gst_tracer_class->invoke = gst_latency_tracer_invoke;
 101
 102   latency_probe_id = g_quark_from_static_string ("latency_probe.id");
 103   latency_probe_pad = g_quark_from_static_string ("latency_probe.pad");
 104   latency_probe_ts = g_quark_from_static_string ("latency_probe.ts");
 105 }
 106
 107 static void
 108 gst_latency_tracer_init (GstLatencyTracer * self)
 109 {
 110   g_object_set (self, "mask", GST_TRACER_HOOK_BUFFERS | GST_TRACER_HOOK_EVENTS,
 111       NULL);
 112 }
 113
 114 /* hooks */
 115
 116 static void
 117 log_latency (const GstStructure * data, GstPad * sink_pad, guint64 sink_ts)
 118 {
 119   GstPad *src_pad;
 120   guint64 src_ts;
 121   gchar *src, *sink;
 122
 123   gst_structure_id_get (data,
 124       latency_probe_pad, GST_TYPE_PAD, &src_pad,
 125       latency_probe_ts, G_TYPE_UINT64, &src_ts, NULL);
 126
 127   src = g_strdup_printf ("%s_%s", GST_DEBUG_PAD_NAME (src_pad));
 128   sink = g_strdup_printf ("%s_%s", GST_DEBUG_PAD_NAME (sink_pad));
 129
 130   /* TODO(ensonic): report format is still unstable */
 131   gst_tracer_log_trace (gst_structure_new ("latency",
 132           "src", G_TYPE_STRING, src,
 133           "sink", G_TYPE_STRING, sink,
 134           "time", G_TYPE_UINT64, GST_CLOCK_DIFF (src_ts, sink_ts), NULL));
 135   g_free (src);
 136   g_free (sink);
 137 }
 138
 139 static void
 140 send_latency_probe (GstLatencyTracer * self, GstElement * parent, GstPad * pad,
 141     guint64 ts)
 142 {
 143   if (parent && (!GST_IS_BIN (parent)) &&
 144       GST_OBJECT_FLAG_IS_SET (parent, GST_ELEMENT_FLAG_SOURCE)) {
 145     GstEvent *latency_probe = gst_event_new_custom (GST_EVENT_CUSTOM_DOWNSTREAM,
 146         gst_structure_new_id (latency_probe_id,
 147             latency_probe_pad, GST_TYPE_PAD, pad,
 148             latency_probe_ts, G_TYPE_UINT64, ts,
 149             NULL));
 150     gst_pad_push_event (pad, latency_probe);
 151   }
 152 }
 153
 154 static void
 155 do_push_buffer_pre (GstLatencyTracer * self, va_list var_args)
 156 {
 157   guint64 ts = va_arg (var_args, guint64);
 158   GstPad *pad = va_arg (var_args, GstPad *);
 159   GstElement *parent = get_real_pad_parent (pad);
 160
 161   send_latency_probe (self, parent, pad, ts);
 162 }
 163
 164 static void
 165 do_pull_buffer_pre (GstLatencyTracer * self, va_list var_args)
 166 {
 167   guint64 ts = va_arg (var_args, guint64);
 168   GstPad *pad = va_arg (var_args, GstPad *);
 169   GstPad *peer_pad = GST_PAD_PEER (pad);
 170   GstElement *parent = get_real_pad_parent (peer_pad);
 171
 172   send_latency_probe (self, parent, peer_pad, ts);
 173 }
 174
 175 static void
 176 calculate_latency (GstLatencyTracer * self, GstElement * parent, GstPad * pad,
 177     guint64 ts)
 178 {
 179   if (parent && (!GST_IS_BIN (parent)) &&
 180       GST_OBJECT_FLAG_IS_SET (parent, GST_ELEMENT_FLAG_SINK)) {
 181     GstEvent *ev = g_object_get_qdata ((GObject *) pad, latency_probe_id);
 182
 183     log_latency (gst_event_get_structure (ev), pad, ts);
 184     gst_event_unref (ev);
 185   }
 186 }
 187
 188 static void
 189 do_push_buffer_post (GstLatencyTracer * self, va_list var_args)
 190 {
 191   guint64 ts = va_arg (var_args, guint64);
 192   GstPad *pad = va_arg (var_args, GstPad *);
 193   GstPad *peer_pad = GST_PAD_PEER (pad);
 194   GstElement *parent = get_real_pad_parent (peer_pad);
 195
 196   calculate_latency (self, parent, peer_pad, ts);
 197 }
 198
 199 static void
 200 do_pull_range_post (GstLatencyTracer * self, va_list var_args)
 201 {
 202   guint64 ts = va_arg (var_args, guint64);
 203   GstPad *pad = va_arg (var_args, GstPad *);
 204   GstElement *parent = get_real_pad_parent (pad);
 205
 206   calculate_latency (self, parent, pad, ts);
 207 }
 208
 209 static void
 210 do_push_event_pre (GstLatencyTracer * self, va_list var_args)
 211 {
 212   G_GNUC_UNUSED guint64 ts = va_arg (var_args, guint64);
 213   GstPad *pad = va_arg (var_args, GstPad *);
 214   GstEvent *ev = va_arg (var_args, GstEvent *);
 215   GstPad *peer_pad = GST_PAD_PEER (pad);
 216   GstElement *parent = get_real_pad_parent (peer_pad);
 217
 218   if (parent && (!GST_IS_BIN (parent)) &&
 219       GST_OBJECT_FLAG_IS_SET (parent, GST_ELEMENT_FLAG_SINK)) {
 220     if (GST_EVENT_TYPE (ev) == GST_EVENT_CUSTOM_DOWNSTREAM) {
 221       const GstStructure *data = gst_event_get_structure (ev);
 222
 223       if (gst_structure_get_name_id (data) == latency_probe_id) {
 224         /* store event and calculate latency when the buffer that follows
 225          * has been processed */
 226         g_object_set_qdata ((GObject *) peer_pad, latency_probe_id,
 227             gst_event_ref (ev));
 228       }
 229     }
 230   }
 231 }
 232
 233 static void
 234 gst_latency_tracer_invoke (GstTracer * obj, GstTracerHookId hid,
 235     GstTracerMessageId mid, va_list var_args)
 236 {
 237   GstLatencyTracer *self = GST_LATENCY_TRACER_CAST (obj);
 238
 239   switch (mid) {
 240     case GST_TRACER_MESSAGE_ID_PAD_PUSH_PRE:
 241     case GST_TRACER_MESSAGE_ID_PAD_PUSH_LIST_PRE:
 242       do_push_buffer_pre (self, var_args);
 243       break;
 244     case GST_TRACER_MESSAGE_ID_PAD_PUSH_POST:
 245     case GST_TRACER_MESSAGE_ID_PAD_PUSH_LIST_POST:
 246       do_push_buffer_post (self, var_args);
 247       break;
 248     case GST_TRACER_MESSAGE_ID_PAD_PULL_RANGE_PRE:
 249       do_pull_buffer_pre (self, var_args);
 250       break;
 251     case GST_TRACER_MESSAGE_ID_PAD_PULL_RANGE_POST:
 252       do_pull_range_post (self, var_args);
 253       break;
 254     case GST_TRACER_MESSAGE_ID_PAD_PUSH_EVENT_PRE:
 255       do_push_event_pre (self, var_args);
 256       break;
 257     default:
 258       break;
 259   }
 260 }