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 static GstTracerRecord *tr_latency;
  56
  57 /* data helpers */
  58
  59 /*
  60  * Get the element/bin owning the pad.
  61  *
  62  * in: a normal pad
  63  * out: the element
  64  *
  65  * in: a proxy pad
  66  * out: the element that contains the peer of the proxy
  67  *
  68  * in: a ghost pad
  69  * out: the bin owning the ghostpad
  70  */
  71 /* TODO(ensonic): gst_pad_get_parent_element() would not work here, should we
  72  * add this as new api, e.g. gst_pad_find_parent_element();
  73  */
  74 static GstElement *
  75 get_real_pad_parent (GstPad * pad)
  76 {
  77   GstObject *parent;
  78
  79   if (!pad)
  80     return NULL;
  81
  82   parent = GST_OBJECT_PARENT (pad);
  83
  84   /* if parent of pad is a ghost-pad, then pad is a proxy_pad */
  85   if (parent && GST_IS_GHOST_PAD (parent)) {
  86     pad = GST_PAD_CAST (parent);
  87     parent = GST_OBJECT_PARENT (pad);
  88   }
  89   return GST_ELEMENT_CAST (parent);
  90 }
  91
  92 /* hooks */
  93
  94 static void
  95 log_latency (const GstStructure * data, GstPad * sink_pad, guint64 sink_ts)
  96 {
  97   GstPad *src_pad;
  98   guint64 src_ts;
  99   gchar *src, *sink;
 100
 101   gst_structure_id_get (data,
 102       latency_probe_pad, GST_TYPE_PAD, &src_pad,
 103       latency_probe_ts, G_TYPE_UINT64, &src_ts, NULL);
 104
 105   src = g_strdup_printf ("%s_%s", GST_DEBUG_PAD_NAME (src_pad));
 106   sink = g_strdup_printf ("%s_%s", GST_DEBUG_PAD_NAME (sink_pad));
 107
 108   gst_tracer_record_log (tr_latency, src, sink,
 109       GST_CLOCK_DIFF (src_ts, sink_ts));
 110   g_free (src);
 111   g_free (sink);
 112 }
 113
 114 static void
 115 send_latency_probe (GstElement * parent, GstPad * pad, guint64 ts)
 116 {
 117   if (parent && (!GST_IS_BIN (parent)) &&
 118       GST_OBJECT_FLAG_IS_SET (parent, GST_ELEMENT_FLAG_SOURCE)) {
 119     GstEvent *latency_probe = gst_event_new_custom (GST_EVENT_CUSTOM_DOWNSTREAM,
 120         gst_structure_new_id (latency_probe_id,
 121             latency_probe_pad, GST_TYPE_PAD, pad,
 122             latency_probe_ts, G_TYPE_UINT64, ts,
 123             NULL));
 124     gst_pad_push_event (pad, latency_probe);
 125   }
 126 }
 127
 128 static void
 129 do_push_buffer_pre (GstTracer * self, guint64 ts, GstPad * pad)
 130 {
 131   GstElement *parent = get_real_pad_parent (pad);
 132
 133   send_latency_probe (parent, pad, ts);
 134 }
 135
 136 static void
 137 do_pull_range_pre (GstTracer * self, guint64 ts, GstPad * pad)
 138 {
 139   GstPad *peer_pad = GST_PAD_PEER (pad);
 140   GstElement *parent = get_real_pad_parent (peer_pad);
 141
 142   send_latency_probe (parent, peer_pad, ts);
 143 }
 144
 145 static void
 146 calculate_latency (GstElement * parent, GstPad * pad, guint64 ts)
 147 {
 148   if (parent && (!GST_IS_BIN (parent)) &&
 149       GST_OBJECT_FLAG_IS_SET (parent, GST_ELEMENT_FLAG_SINK)) {
 150     GstEvent *ev = g_object_get_qdata ((GObject *) pad, latency_probe_id);
 151
 152     if (ev) {
 153       g_object_set_qdata ((GObject *) pad, latency_probe_id, NULL);
 154       log_latency (gst_event_get_structure (ev), pad, ts);
 155       gst_event_unref (ev);
 156     }
 157   }
 158 }
 159
 160 static void
 161 do_push_buffer_post (GstTracer * self, guint64 ts, GstPad * pad)
 162 {
 163   GstPad *peer_pad = GST_PAD_PEER (pad);
 164   GstElement *parent = get_real_pad_parent (peer_pad);
 165
 166   calculate_latency (parent, peer_pad, ts);
 167 }
 168
 169 static void
 170 do_pull_range_post (GstTracer * self, guint64 ts, GstPad * pad)
 171 {
 172   GstElement *parent = get_real_pad_parent (pad);
 173
 174   calculate_latency (parent, pad, ts);
 175 }
 176
 177 static void
 178 do_push_event_pre (GstTracer * self, guint64 ts, GstPad * pad, GstEvent * ev)
 179 {
 180   GstPad *peer_pad = GST_PAD_PEER (pad);
 181   GstElement *parent = get_real_pad_parent (peer_pad);
 182
 183   if (parent && (!GST_IS_BIN (parent)) &&
 184       GST_OBJECT_FLAG_IS_SET (parent, GST_ELEMENT_FLAG_SINK)) {
 185     if (GST_EVENT_TYPE (ev) == GST_EVENT_CUSTOM_DOWNSTREAM) {
 186       const GstStructure *data = gst_event_get_structure (ev);
 187
 188       if (gst_structure_get_name_id (data) == latency_probe_id) {
 189         /* store event and calculate latency when the buffer that follows
 190          * has been processed */
 191         g_object_set_qdata ((GObject *) peer_pad, latency_probe_id,
 192             gst_event_ref (ev));
 193       }
 194     }
 195   }
 196 }
 197
 198 /* tracer class */
 199
 200 static void
 201 gst_latency_tracer_class_init (GstLatencyTracerClass * klass)
 202 {
 203   latency_probe_id = g_quark_from_static_string ("latency_probe.id");
 204   latency_probe_pad = g_quark_from_static_string ("latency_probe.pad");
 205   latency_probe_ts = g_quark_from_static_string ("latency_probe.ts");
 206
 207   /* announce trace formats */
 208   /* *INDENT-OFF* */
 209   tr_latency = gst_tracer_record_new ("latency.class",
 210       "src", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
 211           "type", G_TYPE_GTYPE, G_TYPE_STRING,
 212           "related-to", GST_TYPE_TRACER_VALUE_SCOPE, GST_TRACER_VALUE_SCOPE_PAD,
 213           NULL),
 214       "sink", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
 215           "type", G_TYPE_GTYPE, G_TYPE_STRING,
 216           "related-to", GST_TYPE_TRACER_VALUE_SCOPE, GST_TRACER_VALUE_SCOPE_PAD,
 217           NULL),
 218       "time", GST_TYPE_STRUCTURE, gst_structure_new ("value",
 219           "type", G_TYPE_GTYPE, G_TYPE_UINT64,
 220           "description", G_TYPE_STRING,
 221               "time it took for the buffer to go from src to sink ns",
 222           "flags", GST_TYPE_TRACER_VALUE_FLAGS, GST_TRACER_VALUE_FLAGS_AGGREGATED,
 223           "min", G_TYPE_UINT64, G_GUINT64_CONSTANT (0),
 224           "max", G_TYPE_UINT64, G_MAXUINT64,
 225           NULL),
 226       NULL);
 227   /* *INDENT-ON* */
 228 }
 229
 230 static void
 231 gst_latency_tracer_init (GstLatencyTracer * self)
 232 {
 233   GstTracer *tracer = GST_TRACER (self);
 234   gst_tracing_register_hook (tracer, "pad-push-pre",
 235       G_CALLBACK (do_push_buffer_pre));
 236   gst_tracing_register_hook (tracer, "pad-push-list-pre",
 237       G_CALLBACK (do_push_buffer_pre));
 238   gst_tracing_register_hook (tracer, "pad-push-post",
 239       G_CALLBACK (do_push_buffer_post));
 240   gst_tracing_register_hook (tracer, "pad-push-list-post",
 241       G_CALLBACK (do_push_buffer_post));
 242   gst_tracing_register_hook (tracer, "pad-pull-range-pre",
 243       G_CALLBACK (do_pull_range_pre));
 244   gst_tracing_register_hook (tracer, "pad-pull-range-post",
 245       G_CALLBACK (do_pull_range_post));
 246   gst_tracing_register_hook (tracer, "pad-push-event-pre",
 247       G_CALLBACK (do_push_event_pre));
 248 }