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:element-latencytracer
  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. This elements supports tracing
  27  * the entire pipeline latency and per element latency. By default, only
  28  * pipeline latency is traced. The 'flags' parameter can be used to enabled
  29  * element tracing.
  30  *
  31  * ```
  32  * GST_TRACERS="latency(flags=pipeline+element)" GST_DEBUG=GST_TRACER:7 ./...
  33  * ```
  34  */
  35 /* TODO(ensonic): if there are two sources feeding into a mixer/muxer and later
  36  * we fan-out with tee and have two sinks, each sink would get all two events,
  37  * the later event would overwrite the former. Unfortunately when the buffer
  38  * arrives on the sink we don't know to which event it correlates. Better would
  39  * be to use the buffer meta in 1.0 instead of the event. Or we track a min/max
  40  * latency.
  41  */
  42
  43 #ifdef HAVE_CONFIG_H
  44 #  include "config.h"
  45 #endif
  46
  47 #include "gstlatency.h"
  48
  49 GST_DEBUG_CATEGORY_STATIC (gst_latency_debug);
  50 #define GST_CAT_DEFAULT gst_latency_debug
  51
  52 #define _do_init \
  53     GST_DEBUG_CATEGORY_INIT (gst_latency_debug, "latency", 0, "latency tracer");
  54 #define gst_latency_tracer_parent_class parent_class
  55 G_DEFINE_TYPE_WITH_CODE (GstLatencyTracer, gst_latency_tracer, GST_TYPE_TRACER,
  56     _do_init);
  57
  58 static GQuark latency_probe_id;
  59 static GQuark sub_latency_probe_id;
  60 static GQuark latency_probe_pad;
  61 static GQuark latency_probe_ts;
  62 static GQuark drop_sub_latency_quark;
  63
  64 static GstTracerRecord *tr_latency;
  65 static GstTracerRecord *tr_element_latency;
  66
  67 /* data helpers */
  68
  69 /*
  70  * Get the element/bin owning the pad.
  71  *
  72  * in: a normal pad
  73  * out: the element
  74  *
  75  * in: a proxy pad
  76  * out: the element that contains the peer of the proxy
  77  *
  78  * in: a ghost pad
  79  * out: the bin owning the ghostpad
  80  */
  81 /* TODO(ensonic): gst_pad_get_parent_element() would not work here, should we
  82  * add this as new api, e.g. gst_pad_find_parent_element();
  83  */
  84 static GstElement *
  85 get_real_pad_parent (GstPad * pad)
  86 {
  87   GstObject *parent;
  88
  89   if (!pad)
  90     return NULL;
  91
  92   parent = GST_OBJECT_PARENT (pad);
  93
  94   /* if parent of pad is a ghost-pad, then pad is a proxy_pad */
  95   if (parent && GST_IS_GHOST_PAD (parent)) {
  96     pad = GST_PAD_CAST (parent);
  97     parent = GST_OBJECT_PARENT (pad);
  98   }
  99   return GST_ELEMENT_CAST (parent);
 100 }
 101
 102 /* hooks */
 103
 104 static void
 105 log_latency (const GstStructure * data, GstPad * sink_pad, guint64 sink_ts)
 106 {
 107   guint64 src_ts;
 108   const char *src;
 109   const GValue *value;
 110   gchar *sink;
 111
 112   value = gst_structure_id_get_value (data, latency_probe_ts);
 113   src_ts = g_value_get_uint64 (value);
 114
 115   value = gst_structure_id_get_value (data, latency_probe_pad);
 116   src = g_value_get_string (value);
 117
 118   sink = g_strdup_printf ("%s_%s",
 119       GST_DEBUG_PAD_NAME (GST_PAD_PEER (sink_pad)));
 120   gst_tracer_record_log (tr_latency, src, sink,
 121       GST_CLOCK_DIFF (src_ts, sink_ts), sink_ts);
 122   g_free (sink);
 123 }
 124
 125 static void
 126 log_element_latency (const GstStructure * data, GstPad * pad, guint64 sink_ts)
 127 {
 128   guint64 src_ts;
 129   gchar *pad_name;
 130   const GValue *value;
 131
 132   pad_name = g_strdup_printf ("%s_%s", GST_DEBUG_PAD_NAME (pad));
 133
 134   /* TODO filtering */
 135
 136   value = gst_structure_id_get_value (data, latency_probe_ts);
 137   src_ts = g_value_get_uint64 (value);
 138
 139   gst_tracer_record_log (tr_element_latency, pad_name,
 140       GST_CLOCK_DIFF (src_ts, sink_ts), sink_ts);
 141
 142   g_free (pad_name);
 143 }
 144
 145 static void
 146 send_latency_probe (GstLatencyTracer * self, GstElement * parent, GstPad * pad,
 147     guint64 ts)
 148 {
 149   GstPad *peer_pad = GST_PAD_PEER (pad);
 150
 151   /* allow for non-parented pads to send latency probes as used in e.g.
 152    * rtspsrc for TCP connections */
 153   if (peer_pad && (!parent || (!GST_IS_BIN (parent)))) {
 154     gchar *pad_name;
 155     GstEvent *latency_probe;
 156
 157     if (self->flags & GST_LATENCY_TRACER_FLAG_PIPELINE &&
 158         GST_OBJECT_FLAG_IS_SET (parent, GST_ELEMENT_FLAG_SOURCE)) {
 159       pad_name = g_strdup_printf ("%s_%s", GST_DEBUG_PAD_NAME (pad));
 160
 161       GST_DEBUG ("%s: Sending latency event", pad_name);
 162
 163       latency_probe = gst_event_new_custom (GST_EVENT_CUSTOM_DOWNSTREAM,
 164           gst_structure_new_id (latency_probe_id,
 165               latency_probe_pad, G_TYPE_STRING, pad_name,
 166               latency_probe_ts, G_TYPE_UINT64, ts, NULL));
 167       g_free (pad_name);
 168       gst_pad_push_event (pad, latency_probe);
 169     }
 170
 171     if (self->flags & GST_LATENCY_TRACER_FLAG_ELEMENT) {
 172       GST_DEBUG ("%s_%s: Sending sub-latency event", GST_DEBUG_PAD_NAME (pad));
 173
 174       pad_name = g_strdup_printf ("%s_%s", GST_DEBUG_PAD_NAME (peer_pad));
 175       latency_probe = gst_event_new_custom (GST_EVENT_CUSTOM_DOWNSTREAM,
 176           gst_structure_new_id (sub_latency_probe_id,
 177               latency_probe_pad, G_TYPE_STRING, pad_name,
 178               latency_probe_ts, G_TYPE_UINT64, ts, NULL));
 179       gst_pad_push_event (pad, latency_probe);
 180       g_free (pad_name);
 181     }
 182   }
 183 }
 184
 185 static void
 186 calculate_latency (GstElement * parent, GstPad * pad, guint64 ts)
 187 {
 188   GstElement *peer_parent = get_real_pad_parent (GST_PAD_PEER (pad));
 189
 190   if (parent && (!GST_IS_BIN (parent)) &&
 191       (!GST_OBJECT_FLAG_IS_SET (parent, GST_ELEMENT_FLAG_SOURCE))) {
 192     GstEvent *ev;
 193
 194     /* FIXME unsafe use of peer */
 195     if (GST_OBJECT_FLAG_IS_SET (peer_parent, GST_ELEMENT_FLAG_SINK)) {
 196       GST_DEBUG ("%s_%s: Should log full lantency now",
 197           GST_DEBUG_PAD_NAME (pad));
 198       ev = g_object_get_qdata ((GObject *) pad, latency_probe_id);
 199       if (ev) {
 200         g_object_set_qdata ((GObject *) pad, latency_probe_id, NULL);
 201         log_latency (gst_event_get_structure (ev), pad, ts);
 202         gst_event_unref (ev);
 203       }
 204     }
 205
 206     GST_DEBUG ("%s_%s: Should log sub lantency now", GST_DEBUG_PAD_NAME (pad));
 207     ev = g_object_get_qdata ((GObject *) pad, sub_latency_probe_id);
 208     if (ev) {
 209       g_object_set_qdata ((GObject *) pad, sub_latency_probe_id, NULL);
 210       log_element_latency (gst_event_get_structure (ev), pad, ts);
 211       gst_event_unref (ev);
 212     }
 213   }
 214 }
 215
 216 static void
 217 do_push_buffer_pre (GstTracer * tracer, guint64 ts, GstPad * pad)
 218 {
 219   GstLatencyTracer *self = (GstLatencyTracer *) tracer;
 220   GstElement *parent = get_real_pad_parent (pad);
 221
 222   send_latency_probe (self, parent, pad, ts);
 223   calculate_latency (parent, pad, ts);
 224 }
 225
 226 static void
 227 do_pull_range_pre (GstTracer * tracer, guint64 ts, GstPad * pad)
 228 {
 229   GstLatencyTracer *self = (GstLatencyTracer *) tracer;
 230   GstPad *peer_pad = GST_PAD_PEER (pad);
 231   GstElement *parent = get_real_pad_parent (peer_pad);
 232
 233   send_latency_probe (self, parent, peer_pad, ts);
 234 }
 235
 236 static void
 237 do_pull_range_post (GstTracer * self, guint64 ts, GstPad * pad)
 238 {
 239   GstElement *parent = get_real_pad_parent (pad);
 240
 241   calculate_latency (parent, pad, ts);
 242 }
 243
 244 static GstPadProbeReturn
 245 do_drop_sub_latency_event (GstPad * pad, GstPadProbeInfo * info,
 246     gpointer user_data)
 247 {
 248   GstEvent *ev = info->data;
 249   GstPadProbeReturn ret = GST_PAD_PROBE_OK;
 250
 251   if (GST_EVENT_TYPE (ev) == GST_EVENT_CUSTOM_DOWNSTREAM) {
 252     const GstStructure *data = gst_event_get_structure (ev);
 253
 254     if (gst_structure_get_name_id (data) == sub_latency_probe_id) {
 255       const GValue *value;
 256       /* FIXME unsafe peer pad usage */
 257       gchar *pad_name = g_strdup_printf ("%s_%s",
 258           GST_DEBUG_PAD_NAME (GST_PAD_PEER (pad)));
 259
 260       value = gst_structure_id_get_value (data, latency_probe_pad);
 261       if (!g_str_equal (g_value_get_string (value), pad_name)) {
 262         GST_DEBUG ("%s: Dropping sub-latency event", pad_name);
 263         ret = GST_PAD_PROBE_DROP;
 264       }
 265
 266       g_free (pad_name);
 267     }
 268   }
 269
 270   return ret;
 271 }
 272
 273 static void
 274 do_push_event_pre (GstTracer * self, guint64 ts, GstPad * pad, GstEvent * ev)
 275 {
 276   GstElement *parent = get_real_pad_parent (pad);
 277   GstPad *peer_pad = GST_PAD_PEER (pad);
 278   GstElement *peer_parent = get_real_pad_parent (peer_pad);
 279
 280   if (parent && (!GST_IS_BIN (parent)) &&
 281       (!GST_OBJECT_FLAG_IS_SET (parent, GST_ELEMENT_FLAG_SOURCE)) &&
 282       GST_EVENT_TYPE (ev) == GST_EVENT_CUSTOM_DOWNSTREAM) {
 283     const GstStructure *data = gst_event_get_structure (ev);
 284
 285     /* if not set yet, add a pad probe that prevents sub-latency event from
 286      * flowing further */
 287     if (gst_structure_get_name_id (data) == latency_probe_id) {
 288
 289       if (!g_object_get_qdata ((GObject *) pad, drop_sub_latency_quark)) {
 290         GST_DEBUG ("%s_%s: Adding pad probe to drop sub-latency event",
 291             GST_DEBUG_PAD_NAME (pad));
 292         gst_pad_add_probe (pad, GST_PAD_PROBE_TYPE_EVENT_DOWNSTREAM,
 293             do_drop_sub_latency_event, NULL, NULL);
 294         g_object_set_qdata ((GObject *) pad, drop_sub_latency_quark,
 295             (gpointer) 1);
 296       }
 297
 298       /* FIXME unsafe peer access */
 299       if (GST_OBJECT_FLAG_IS_SET (peer_parent, GST_ELEMENT_FLAG_SINK)) {
 300         GST_DEBUG ("%s_%s: Storing latency event", GST_DEBUG_PAD_NAME (pad));
 301
 302         /* store event so that we can calculate latency when the buffer that
 303          * follows has been processed */
 304         if (!g_object_get_qdata ((GObject *) pad, latency_probe_id))
 305           g_object_set_qdata ((GObject *) pad, latency_probe_id,
 306               gst_event_ref (ev));
 307       }
 308     }
 309
 310     if (gst_structure_get_name_id (data) == sub_latency_probe_id) {
 311       const GValue *value;
 312       gchar *pad_name = g_strdup_printf ("%s_%s",
 313           GST_DEBUG_PAD_NAME (peer_pad));
 314
 315       value = gst_structure_id_get_value (data, latency_probe_pad);
 316
 317       if (!g_str_equal (g_value_get_string (value), pad_name)) {
 318         GST_DEBUG ("%s: Storing sub-latency event", pad_name);
 319         if (!g_object_get_qdata ((GObject *) pad, sub_latency_probe_id))
 320           g_object_set_qdata ((GObject *) pad, sub_latency_probe_id,
 321               gst_event_ref (ev));
 322       }
 323
 324       g_free (pad_name);
 325     }
 326   }
 327 }
 328
 329 /* tracer class */
 330
 331 static void
 332 gst_latency_tracer_constructed (GObject * object)
 333 {
 334   GstLatencyTracer *self = GST_LATENCY_TRACER (object);
 335   gchar *params, *tmp;
 336   GstStructure *params_struct = NULL;
 337
 338   g_object_get (self, "params", &params, NULL);
 339
 340   if (!params)
 341     return;
 342
 343   tmp = g_strdup_printf ("latency,%s", params);
 344   params_struct = gst_structure_from_string (tmp, NULL);
 345   g_free (tmp);
 346
 347   /* Read the flags if available */
 348   if (params_struct) {
 349     const gchar *flags = gst_structure_get_string (params_struct, "flags");
 350
 351     self->flags = 0;
 352
 353     if (flags) {
 354       GStrv split = g_strsplit (flags, "+", -1);
 355       gint i;
 356
 357       for (i = 0; split[i]; i++) {
 358         if (g_str_equal (split[i], "pipeline"))
 359           self->flags |= GST_LATENCY_TRACER_FLAG_PIPELINE;
 360         else if (g_str_equal (split[i], "element"))
 361           self->flags |= GST_LATENCY_TRACER_FLAG_ELEMENT;
 362         else
 363           GST_WARNING ("Invalid latency tracer flags %s", split[i]);
 364       }
 365
 366       g_strfreev (split);
 367     }
 368   }
 369
 370   g_free (params);
 371 }
 372
 373 static void
 374 gst_latency_tracer_class_init (GstLatencyTracerClass * klass)
 375 {
 376   GObjectClass *gobject_class = G_OBJECT_CLASS (klass);
 377
 378   gobject_class->constructed = gst_latency_tracer_constructed;
 379
 380   latency_probe_id = g_quark_from_static_string ("latency_probe.id");
 381   sub_latency_probe_id = g_quark_from_static_string ("sub_latency_probe.id");
 382   latency_probe_pad = g_quark_from_static_string ("latency_probe.pad");
 383   latency_probe_ts = g_quark_from_static_string ("latency_probe.ts");
 384   drop_sub_latency_quark =
 385       g_quark_from_static_string ("drop_sub_latency.quark");
 386
 387   /* announce trace formats */
 388   /* *INDENT-OFF* */
 389   tr_latency = gst_tracer_record_new ("latency.class",
 390       "src", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
 391           "type", G_TYPE_GTYPE, G_TYPE_STRING,
 392           "related-to", GST_TYPE_TRACER_VALUE_SCOPE, GST_TRACER_VALUE_SCOPE_PAD,
 393           NULL),
 394       "sink", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
 395           "type", G_TYPE_GTYPE, G_TYPE_STRING,
 396           "related-to", GST_TYPE_TRACER_VALUE_SCOPE, GST_TRACER_VALUE_SCOPE_PAD,
 397           NULL),
 398       "time", GST_TYPE_STRUCTURE, gst_structure_new ("value",
 399           "type", G_TYPE_GTYPE, G_TYPE_UINT64,
 400           "description", G_TYPE_STRING,
 401               "time it took for the buffer to go from src to sink ns",
 402           "min", G_TYPE_UINT64, G_GUINT64_CONSTANT (0),
 403           "max", G_TYPE_UINT64, G_MAXUINT64,
 404           NULL),
 405       "ts", GST_TYPE_STRUCTURE, gst_structure_new ("value",
 406           "type", G_TYPE_GTYPE, G_TYPE_UINT64,
 407           "description", G_TYPE_STRING, "ts when the latency has been logged",
 408           "min", G_TYPE_UINT64, G_GUINT64_CONSTANT (0),
 409           "max", G_TYPE_UINT64, G_MAXUINT64,
 410           NULL),
 411       NULL);
 412
 413   tr_element_latency = gst_tracer_record_new ("element-latency.class",
 414       "src", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
 415           "type", G_TYPE_GTYPE, G_TYPE_STRING,
 416           "related-to", GST_TYPE_TRACER_VALUE_SCOPE, GST_TRACER_VALUE_SCOPE_PAD,
 417           NULL),
 418       "time", GST_TYPE_STRUCTURE, gst_structure_new ("value",
 419           "type", G_TYPE_GTYPE, G_TYPE_UINT64,
 420           "description", G_TYPE_STRING,
 421               "time it took for the buffer to go from src to sink ns",
 422           "min", G_TYPE_UINT64, G_GUINT64_CONSTANT (0),
 423           "max", G_TYPE_UINT64, G_MAXUINT64,
 424           NULL),
 425       "ts", GST_TYPE_STRUCTURE, gst_structure_new ("value",
 426           "type", G_TYPE_GTYPE, G_TYPE_UINT64,
 427           "description", G_TYPE_STRING, "ts when the latency has been logged",
 428           "min", G_TYPE_UINT64, G_GUINT64_CONSTANT (0),
 429           "max", G_TYPE_UINT64, G_MAXUINT64,
 430           NULL),
 431       NULL);
 432   /* *INDENT-ON* */
 433 }
 434
 435 static void
 436 gst_latency_tracer_init (GstLatencyTracer * self)
 437 {
 438   GstTracer *tracer = GST_TRACER (self);
 439
 440   /* only trace pipeline latency by default */
 441   self->flags = GST_LATENCY_TRACER_FLAG_PIPELINE;
 442
 443   /* in push mode, pre/post will be called before/after the peer chain
 444    * function has been called. For this reaosn, we only use -pre to avoid
 445    * accounting for the processing time of the peer element (the sink) */
 446   gst_tracing_register_hook (tracer, "pad-push-pre",
 447       G_CALLBACK (do_push_buffer_pre));
 448   gst_tracing_register_hook (tracer, "pad-push-list-pre",
 449       G_CALLBACK (do_push_buffer_pre));
 450
 451   /* while in pull mode, pre/post will happen before and after the upstream
 452    * pull_range call is made, so it already only account for the upstream
 453    * processing time. As a side effect, in pull mode, we can measure the
 454    * source processing latency, while in push mode, we can't */
 455   gst_tracing_register_hook (tracer, "pad-pull-range-pre",
 456       G_CALLBACK (do_pull_range_pre));
 457   gst_tracing_register_hook (tracer, "pad-pull-range-post",
 458       G_CALLBACK (do_pull_range_post));
 459
 460   gst_tracing_register_hook (tracer, "pad-push-event-pre",
 461       G_CALLBACK (do_push_event_pre));
 462 }