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 void latency_query_stack_destroy (gpointer data);
  59
  60 static GQuark latency_probe_id;
  61 static GQuark sub_latency_probe_id;
  62 static GQuark latency_probe_pad;
  63 static GQuark latency_probe_element;
  64 static GQuark latency_probe_element_id;
  65 static GQuark latency_probe_ts;
  66 static GQuark drop_sub_latency_quark;
  67
  68 static GstTracerRecord *tr_latency;
  69 static GstTracerRecord *tr_element_latency;
  70 static GstTracerRecord *tr_element_reported_latency;
  71
  72 /* The private stack for each thread */
  73 static GPrivate latency_query_stack =
  74 G_PRIVATE_INIT (latency_query_stack_destroy);
  75
  76 struct LatencyQueryTableValue
  77 {
  78   GstElement *peer_element;
  79   guint64 min;
  80   guint64 max;
  81 };
  82
  83 /* data helpers */
  84
  85 /*
  86  * Get the element/bin owning the pad.
  87  *
  88  * in: a normal pad
  89  * out: the element
  90  *
  91  * in: a proxy pad
  92  * out: the element that contains the peer of the proxy
  93  *
  94  * in: a ghost pad
  95  * out: the bin owning the ghostpad
  96  */
  97 /* TODO(ensonic): gst_pad_get_parent_element() would not work here, should we
  98  * add this as new api, e.g. gst_pad_find_parent_element();
  99  */
 100 static GstElement *
 101 get_real_pad_parent (GstPad * pad)
 102 {
 103   GstObject *parent;
 104
 105   if (!pad)
 106     return NULL;
 107
 108   parent = GST_OBJECT_PARENT (pad);
 109
 110   /* if parent of pad is a ghost-pad, then pad is a proxy_pad */
 111   if (parent && GST_IS_GHOST_PAD (parent)) {
 112     pad = GST_PAD_CAST (parent);
 113     parent = GST_OBJECT_PARENT (pad);
 114   }
 115   return GST_ELEMENT_CAST (parent);
 116 }
 117
 118 static void
 119 latency_query_table_value_destroy (gpointer data)
 120 {
 121   struct LatencyQueryTableValue *v = data;
 122
 123   /* Unref the element */
 124   if (v->peer_element) {
 125     gst_object_unref (v->peer_element);
 126     v->peer_element = NULL;
 127   }
 128
 129   /* Destroy the structure */
 130   g_free (v);
 131 }
 132
 133 static void
 134 latency_query_stack_destroy (gpointer data)
 135 {
 136   GQueue *queue = data;
 137   g_queue_free_full (queue, latency_query_table_value_destroy);
 138 }
 139
 140 static GQueue *
 141 local_latency_query_stack_get (void)
 142 {
 143   /* Make sure the stack exists */
 144   GQueue *stack = g_private_get (&latency_query_stack);
 145   if (!stack) {
 146     g_private_set (&latency_query_stack, g_queue_new ());
 147     stack = g_private_get (&latency_query_stack);
 148   }
 149
 150   g_assert (stack);
 151   return stack;
 152 }
 153
 154 static struct LatencyQueryTableValue *
 155 local_latency_query_stack_pop (void)
 156 {
 157   GQueue *stack = local_latency_query_stack_get ();
 158   return g_queue_pop_tail (stack);
 159 }
 160
 161 static void
 162 local_latency_query_stack_push (struct LatencyQueryTableValue *value)
 163 {
 164   GQueue *stack = local_latency_query_stack_get ();
 165   g_queue_push_tail (stack, value);
 166 }
 167
 168 /* hooks */
 169
 170 static void
 171 log_latency (const GstStructure * data, GstElement * sink_parent,
 172     GstPad * sink_pad, guint64 sink_ts)
 173 {
 174   guint64 src_ts;
 175   const char *src, *element_src, *id_element_src;
 176   const GValue *value;
 177   gchar *sink, *element_sink, *id_element_sink;
 178
 179   value = gst_structure_id_get_value (data, latency_probe_ts);
 180   src_ts = g_value_get_uint64 (value);
 181
 182   value = gst_structure_id_get_value (data, latency_probe_pad);
 183   src = g_value_get_string (value);
 184
 185   value = gst_structure_id_get_value (data, latency_probe_element);
 186   element_src = g_value_get_string (value);
 187
 188   value = gst_structure_id_get_value (data, latency_probe_element_id);
 189   id_element_src = g_value_get_string (value);
 190
 191   id_element_sink = g_strdup_printf ("%p", sink_parent);
 192   element_sink = gst_element_get_name (sink_parent);
 193   sink = gst_pad_get_name (sink_pad);
 194   gst_tracer_record_log (tr_latency, id_element_src, element_src, src,
 195       id_element_sink, element_sink, sink, GST_CLOCK_DIFF (src_ts, sink_ts),
 196       sink_ts);
 197   g_free (sink);
 198   g_free (element_sink);
 199   g_free (id_element_sink);
 200 }
 201
 202 static void
 203 log_element_latency (const GstStructure * data, GstElement * parent,
 204     GstPad * pad, guint64 sink_ts)
 205 {
 206   guint64 src_ts;
 207   gchar *pad_name, *element_name, *element_id;
 208   const GValue *value;
 209
 210   element_id = g_strdup_printf ("%p", parent);
 211   element_name = gst_element_get_name (parent);
 212   pad_name = gst_pad_get_name (pad);
 213
 214   /* TODO filtering */
 215
 216   value = gst_structure_id_get_value (data, latency_probe_ts);
 217   src_ts = g_value_get_uint64 (value);
 218
 219   gst_tracer_record_log (tr_element_latency, element_id, element_name, pad_name,
 220       GST_CLOCK_DIFF (src_ts, sink_ts), sink_ts);
 221
 222   g_free (pad_name);
 223   g_free (element_name);
 224   g_free (element_id);
 225 }
 226
 227 static void
 228 send_latency_probe (GstLatencyTracer * self, GstElement * parent, GstPad * pad,
 229     guint64 ts)
 230 {
 231   GstPad *peer_pad = GST_PAD_PEER (pad);
 232   GstElement *peer_parent = get_real_pad_parent (peer_pad);
 233
 234   /* allow for non-parented pads to send latency probes as used in e.g.
 235    * rtspsrc for TCP connections */
 236   if (peer_pad && (!parent || (!GST_IS_BIN (parent)))) {
 237     gchar *pad_name, *element_name, *element_id;
 238     GstEvent *latency_probe;
 239
 240     if (self->flags & GST_LATENCY_TRACER_FLAG_PIPELINE &&
 241         GST_OBJECT_FLAG_IS_SET (parent, GST_ELEMENT_FLAG_SOURCE)) {
 242       element_id = g_strdup_printf ("%p", parent);
 243       element_name = gst_element_get_name (parent);
 244       pad_name = gst_pad_get_name (pad);
 245
 246       GST_DEBUG ("%s: Sending latency event", pad_name);
 247
 248       latency_probe = gst_event_new_custom (GST_EVENT_CUSTOM_DOWNSTREAM,
 249           gst_structure_new_id (latency_probe_id,
 250               latency_probe_element_id, G_TYPE_STRING, element_id,
 251               latency_probe_element, G_TYPE_STRING, element_name,
 252               latency_probe_pad, G_TYPE_STRING, pad_name,
 253               latency_probe_ts, G_TYPE_UINT64, ts, NULL));
 254       g_free (pad_name);
 255       g_free (element_name);
 256       g_free (element_id);
 257       gst_pad_push_event (pad, latency_probe);
 258     }
 259
 260     if (self->flags & GST_LATENCY_TRACER_FLAG_ELEMENT) {
 261       GST_DEBUG ("%s_%s: Sending sub-latency event", GST_DEBUG_PAD_NAME (pad));
 262
 263       element_id = g_strdup_printf ("%p", peer_parent);
 264       element_name = gst_element_get_name (peer_parent);
 265       pad_name = gst_pad_get_name (peer_pad);
 266       latency_probe = gst_event_new_custom (GST_EVENT_CUSTOM_DOWNSTREAM,
 267           gst_structure_new_id (sub_latency_probe_id,
 268               latency_probe_element_id, G_TYPE_STRING, element_id,
 269               latency_probe_element, G_TYPE_STRING, element_name,
 270               latency_probe_pad, G_TYPE_STRING, pad_name,
 271               latency_probe_ts, G_TYPE_UINT64, ts, NULL));
 272       gst_pad_push_event (pad, latency_probe);
 273       g_free (pad_name);
 274       g_free (element_name);
 275       g_free (element_id);
 276     }
 277   }
 278 }
 279
 280 static void
 281 calculate_latency (GstElement * parent, GstPad * pad, guint64 ts)
 282 {
 283   GstElement *peer_parent = get_real_pad_parent (GST_PAD_PEER (pad));
 284
 285   if (parent && (!GST_IS_BIN (parent)) &&
 286       (!GST_OBJECT_FLAG_IS_SET (parent, GST_ELEMENT_FLAG_SOURCE))) {
 287     GstEvent *ev;
 288
 289     /* FIXME unsafe use of peer */
 290     if (GST_OBJECT_FLAG_IS_SET (peer_parent, GST_ELEMENT_FLAG_SINK)) {
 291       GST_DEBUG ("%s_%s: Should log full lantency now",
 292           GST_DEBUG_PAD_NAME (pad));
 293       ev = g_object_get_qdata ((GObject *) pad, latency_probe_id);
 294       if (ev) {
 295         g_object_set_qdata ((GObject *) pad, latency_probe_id, NULL);
 296         log_latency (gst_event_get_structure (ev), peer_parent,
 297             GST_PAD_PEER (pad), ts);
 298         gst_event_unref (ev);
 299       }
 300     }
 301
 302     GST_DEBUG ("%s_%s: Should log sub lantency now", GST_DEBUG_PAD_NAME (pad));
 303     ev = g_object_get_qdata ((GObject *) pad, sub_latency_probe_id);
 304     if (ev) {
 305       g_object_set_qdata ((GObject *) pad, sub_latency_probe_id, NULL);
 306       log_element_latency (gst_event_get_structure (ev), parent, pad, ts);
 307       gst_event_unref (ev);
 308     }
 309   }
 310 }
 311
 312 static void
 313 do_push_buffer_pre (GstTracer * tracer, guint64 ts, GstPad * pad)
 314 {
 315   GstLatencyTracer *self = (GstLatencyTracer *) tracer;
 316   GstElement *parent = get_real_pad_parent (pad);
 317
 318   send_latency_probe (self, parent, pad, ts);
 319   calculate_latency (parent, pad, ts);
 320 }
 321
 322 static void
 323 do_pull_range_pre (GstTracer * tracer, guint64 ts, GstPad * pad)
 324 {
 325   GstLatencyTracer *self = (GstLatencyTracer *) tracer;
 326   GstPad *peer_pad = GST_PAD_PEER (pad);
 327   GstElement *parent = get_real_pad_parent (peer_pad);
 328
 329   send_latency_probe (self, parent, peer_pad, ts);
 330 }
 331
 332 static void
 333 do_pull_range_post (GstTracer * self, guint64 ts, GstPad * pad)
 334 {
 335   GstElement *parent = get_real_pad_parent (pad);
 336
 337   calculate_latency (parent, pad, ts);
 338 }
 339
 340 static GstPadProbeReturn
 341 do_drop_sub_latency_event (GstPad * pad, GstPadProbeInfo * info,
 342     gpointer user_data)
 343 {
 344   GstEvent *ev = info->data;
 345   GstPadProbeReturn ret = GST_PAD_PROBE_OK;
 346
 347   if (GST_EVENT_TYPE (ev) == GST_EVENT_CUSTOM_DOWNSTREAM) {
 348     const GstStructure *data = gst_event_get_structure (ev);
 349
 350     if (gst_structure_get_name_id (data) == sub_latency_probe_id) {
 351       /* FIXME unsafe peer pad usage */
 352       GstPad *peer_pad = GST_PAD_PEER (pad);
 353       GstElement *peer_parent = get_real_pad_parent (peer_pad);
 354       const GValue *value;
 355       gchar *element_id = g_strdup_printf ("%p", peer_parent);
 356       gchar *element_name = gst_element_get_name (peer_parent);
 357       gchar *pad_name = gst_pad_get_name (peer_pad);
 358       const gchar *value_element_id, *value_element_name, *value_pad_name;
 359
 360       /* Get the element id, element name and pad name from data */
 361       value = gst_structure_id_get_value (data, latency_probe_element_id);
 362       value_element_id = g_value_get_string (value);
 363       value = gst_structure_id_get_value (data, latency_probe_element);
 364       value_element_name = g_value_get_string (value);
 365       value = gst_structure_id_get_value (data, latency_probe_pad);
 366       value_pad_name = g_value_get_string (value);
 367
 368       if (!g_str_equal (value_element_id, element_id) ||
 369           !g_str_equal (value_element_name, element_name) ||
 370           !g_str_equal (value_pad_name, pad_name)) {
 371         GST_DEBUG ("%s_%s: Dropping sub-latency event",
 372             GST_DEBUG_PAD_NAME (pad));
 373         ret = GST_PAD_PROBE_DROP;
 374       }
 375
 376       g_free (pad_name);
 377       g_free (element_name);
 378       g_free (element_id);
 379     }
 380   }
 381
 382   return ret;
 383 }
 384
 385 static void
 386 do_push_event_pre (GstTracer * self, guint64 ts, GstPad * pad, GstEvent * ev)
 387 {
 388   GstElement *parent = get_real_pad_parent (pad);
 389   GstPad *peer_pad = GST_PAD_PEER (pad);
 390   GstElement *peer_parent = get_real_pad_parent (peer_pad);
 391
 392   if (parent && (!GST_IS_BIN (parent)) &&
 393       (!GST_OBJECT_FLAG_IS_SET (parent, GST_ELEMENT_FLAG_SOURCE)) &&
 394       GST_EVENT_TYPE (ev) == GST_EVENT_CUSTOM_DOWNSTREAM) {
 395     const GstStructure *data = gst_event_get_structure (ev);
 396
 397     /* if not set yet, add a pad probe that prevents sub-latency event from
 398      * flowing further */
 399     if (gst_structure_get_name_id (data) == latency_probe_id) {
 400
 401       if (!g_object_get_qdata ((GObject *) pad, drop_sub_latency_quark)) {
 402         GST_DEBUG ("%s_%s: Adding pad probe to drop sub-latency event",
 403             GST_DEBUG_PAD_NAME (pad));
 404         gst_pad_add_probe (pad, GST_PAD_PROBE_TYPE_EVENT_DOWNSTREAM,
 405             do_drop_sub_latency_event, NULL, NULL);
 406         g_object_set_qdata ((GObject *) pad, drop_sub_latency_quark,
 407             (gpointer) 1);
 408       }
 409
 410       /* FIXME unsafe peer access */
 411       if (GST_OBJECT_FLAG_IS_SET (peer_parent, GST_ELEMENT_FLAG_SINK)) {
 412         GST_DEBUG ("%s_%s: Storing latency event", GST_DEBUG_PAD_NAME (pad));
 413
 414         /* store event so that we can calculate latency when the buffer that
 415          * follows has been processed */
 416         if (!g_object_get_qdata ((GObject *) pad, latency_probe_id))
 417           g_object_set_qdata ((GObject *) pad, latency_probe_id,
 418               gst_event_ref (ev));
 419       }
 420     }
 421
 422     if (gst_structure_get_name_id (data) == sub_latency_probe_id) {
 423       const GValue *value;
 424       gchar *element_id = g_strdup_printf ("%p", peer_parent);
 425       gchar *element_name = gst_element_get_name (peer_parent);
 426       gchar *pad_name = gst_pad_get_name (peer_pad);
 427       const gchar *value_element_id, *value_element_name, *value_pad_name;
 428
 429       /* Get the element id, element name and pad name from data */
 430       value = gst_structure_id_get_value (data, latency_probe_element_id);
 431       value_element_id = g_value_get_string (value);
 432       value = gst_structure_id_get_value (data, latency_probe_element);
 433       value_element_name = g_value_get_string (value);
 434       value = gst_structure_id_get_value (data, latency_probe_pad);
 435       value_pad_name = g_value_get_string (value);
 436
 437       if (!g_str_equal (value_element_id, element_id) ||
 438           !g_str_equal (value_element_name, element_name) ||
 439           !g_str_equal (value_pad_name, pad_name)) {
 440         GST_DEBUG ("%s_%s: Storing latency event", GST_DEBUG_PAD_NAME (pad));
 441
 442         if (!g_object_get_qdata ((GObject *) pad, sub_latency_probe_id))
 443           g_object_set_qdata ((GObject *) pad, sub_latency_probe_id,
 444               gst_event_ref (ev));
 445       }
 446
 447       g_free (pad_name);
 448       g_free (element_name);
 449       g_free (element_id);
 450     }
 451   }
 452 }
 453
 454 static void
 455 do_query_post (GstLatencyTracer * tracer, GstClockTime ts, GstPad * pad,
 456     GstQuery * query, gboolean res)
 457 {
 458   /* Only check for latency queries if flag is enabled */
 459   if ((tracer->flags & GST_LATENCY_TRACER_FLAG_REPORTED_ELEMENT) &&
 460       (GST_QUERY_TYPE (query) == GST_QUERY_LATENCY)) {
 461     gboolean live;
 462     guint64 min = 0, max = 0, min_prev = 0, max_prev = 0;
 463     gchar *element_name, *element_id;
 464     struct LatencyQueryTableValue *value;
 465     GstElement *element = get_real_pad_parent (pad);
 466     GstElement *peer_element = get_real_pad_parent (GST_PAD_PEER (pad));
 467
 468     /* Parse the query */
 469     gst_query_parse_latency (query, &live, &min, &max);
 470
 471     /* Pop from stack */
 472     value = local_latency_query_stack_pop ();
 473     while (value && value->peer_element == element) {
 474       min_prev = MAX (value->min, min_prev);
 475       max_prev = MAX (value->max, max_prev);
 476       value = local_latency_query_stack_pop ();
 477     }
 478
 479     /* Push to stack */
 480     value = g_new0 (struct LatencyQueryTableValue, 1);
 481     value->peer_element = gst_object_ref (peer_element);
 482     value->min = min;
 483     value->max = max;
 484     local_latency_query_stack_push (value);
 485
 486     /* Get the pad name */
 487     element_id = g_strdup_printf ("%p", element);
 488     element_name = gst_element_get_name (element);
 489
 490     /* Log reported latency */
 491     gst_tracer_record_log (tr_element_reported_latency, element_id,
 492         element_name, live, GST_CLOCK_DIFF (min_prev, min),
 493         GST_CLOCK_DIFF (max_prev, max), ts);
 494
 495     /* Clean up */
 496     g_free (element_name);
 497     g_free (element_id);
 498   }
 499 }
 500
 501 /* tracer class */
 502
 503 static void
 504 gst_latency_tracer_constructed (GObject * object)
 505 {
 506   GstLatencyTracer *self = GST_LATENCY_TRACER (object);
 507   gchar *params, *tmp;
 508   GstStructure *params_struct = NULL;
 509
 510   g_object_get (self, "params", &params, NULL);
 511
 512   if (!params)
 513     return;
 514
 515   tmp = g_strdup_printf ("latency,%s", params);
 516   params_struct = gst_structure_from_string (tmp, NULL);
 517   g_free (tmp);
 518
 519   /* Read the flags if available */
 520   if (params_struct) {
 521     const gchar *flags = gst_structure_get_string (params_struct, "flags");
 522
 523     self->flags = 0;
 524
 525     if (flags) {
 526       GStrv split = g_strsplit (flags, "+", -1);
 527       gint i;
 528
 529       for (i = 0; split[i]; i++) {
 530         if (g_str_equal (split[i], "pipeline"))
 531           self->flags |= GST_LATENCY_TRACER_FLAG_PIPELINE;
 532         else if (g_str_equal (split[i], "element"))
 533           self->flags |= GST_LATENCY_TRACER_FLAG_ELEMENT;
 534         else if (g_str_equal (split[i], "reported"))
 535           self->flags |= GST_LATENCY_TRACER_FLAG_REPORTED_ELEMENT;
 536         else
 537           GST_WARNING ("Invalid latency tracer flags %s", split[i]);
 538       }
 539
 540       g_strfreev (split);
 541     }
 542   }
 543
 544   g_free (params);
 545 }
 546
 547 static void
 548 gst_latency_tracer_class_init (GstLatencyTracerClass * klass)
 549 {
 550   GObjectClass *gobject_class = G_OBJECT_CLASS (klass);
 551
 552   gobject_class->constructed = gst_latency_tracer_constructed;
 553
 554   latency_probe_id = g_quark_from_static_string ("latency_probe.id");
 555   sub_latency_probe_id = g_quark_from_static_string ("sub_latency_probe.id");
 556   latency_probe_pad = g_quark_from_static_string ("latency_probe.pad");
 557   latency_probe_element = g_quark_from_static_string ("latency_probe.element");
 558   latency_probe_element_id =
 559       g_quark_from_static_string ("latency_probe.element_id");
 560   latency_probe_ts = g_quark_from_static_string ("latency_probe.ts");
 561   drop_sub_latency_quark =
 562       g_quark_from_static_string ("drop_sub_latency.quark");
 563
 564   /* announce trace formats */
 565   /* *INDENT-OFF* */
 566   tr_latency = gst_tracer_record_new ("latency.class",
 567       "src-element-id", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
 568           "type", G_TYPE_GTYPE, G_TYPE_STRING,
 569           "related-to", GST_TYPE_TRACER_VALUE_SCOPE,
 570           GST_TRACER_VALUE_SCOPE_ELEMENT,
 571           NULL),
 572       "src-element", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
 573           "type", G_TYPE_GTYPE, G_TYPE_STRING,
 574           "related-to", GST_TYPE_TRACER_VALUE_SCOPE,
 575           GST_TRACER_VALUE_SCOPE_ELEMENT,
 576           NULL),
 577       "src", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
 578           "type", G_TYPE_GTYPE, G_TYPE_STRING,
 579           "related-to", GST_TYPE_TRACER_VALUE_SCOPE, GST_TRACER_VALUE_SCOPE_PAD,
 580           NULL),
 581       "sink-element-id", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
 582           "type", G_TYPE_GTYPE, G_TYPE_STRING,
 583           "related-to", GST_TYPE_TRACER_VALUE_SCOPE,
 584           GST_TRACER_VALUE_SCOPE_ELEMENT,
 585           NULL),
 586       "sink-element", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
 587           "type", G_TYPE_GTYPE, G_TYPE_STRING,
 588           "related-to", GST_TYPE_TRACER_VALUE_SCOPE,
 589           GST_TRACER_VALUE_SCOPE_ELEMENT,
 590           NULL),
 591       "sink", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
 592           "type", G_TYPE_GTYPE, G_TYPE_STRING,
 593           "related-to", GST_TYPE_TRACER_VALUE_SCOPE, GST_TRACER_VALUE_SCOPE_PAD,
 594           NULL),
 595       "time", GST_TYPE_STRUCTURE, gst_structure_new ("value",
 596           "type", G_TYPE_GTYPE, G_TYPE_UINT64,
 597           "description", G_TYPE_STRING,
 598               "time it took for the buffer to go from src to sink ns",
 599           "min", G_TYPE_UINT64, G_GUINT64_CONSTANT (0),
 600           "max", G_TYPE_UINT64, G_MAXUINT64,
 601           NULL),
 602       "ts", GST_TYPE_STRUCTURE, gst_structure_new ("value",
 603           "type", G_TYPE_GTYPE, G_TYPE_UINT64,
 604           "description", G_TYPE_STRING, "ts when the latency has been logged",
 605           "min", G_TYPE_UINT64, G_GUINT64_CONSTANT (0),
 606           "max", G_TYPE_UINT64, G_MAXUINT64,
 607           NULL),
 608       NULL);
 609
 610   tr_element_latency = gst_tracer_record_new ("element-latency.class",
 611       "element-id", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
 612           "type", G_TYPE_GTYPE, G_TYPE_STRING,
 613           "related-to", GST_TYPE_TRACER_VALUE_SCOPE,
 614           GST_TRACER_VALUE_SCOPE_ELEMENT,
 615           NULL),
 616       "element", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
 617           "type", G_TYPE_GTYPE, G_TYPE_STRING,
 618           "related-to", GST_TYPE_TRACER_VALUE_SCOPE,
 619           GST_TRACER_VALUE_SCOPE_ELEMENT,
 620           NULL),
 621       "src", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
 622           "type", G_TYPE_GTYPE, G_TYPE_STRING,
 623           "related-to", GST_TYPE_TRACER_VALUE_SCOPE, GST_TRACER_VALUE_SCOPE_PAD,
 624           NULL),
 625       "time", GST_TYPE_STRUCTURE, gst_structure_new ("value",
 626           "type", G_TYPE_GTYPE, G_TYPE_UINT64,
 627           "description", G_TYPE_STRING,
 628               "time it took for the buffer to go from src to sink ns",
 629           "min", G_TYPE_UINT64, G_GUINT64_CONSTANT (0),
 630           "max", G_TYPE_UINT64, G_MAXUINT64,
 631           NULL),
 632       "ts", GST_TYPE_STRUCTURE, gst_structure_new ("value",
 633           "type", G_TYPE_GTYPE, G_TYPE_UINT64,
 634           "description", G_TYPE_STRING, "ts when the latency has been logged",
 635           "min", G_TYPE_UINT64, G_GUINT64_CONSTANT (0),
 636           "max", G_TYPE_UINT64, G_MAXUINT64,
 637           NULL),
 638       NULL);
 639
 640
 641   tr_element_reported_latency = gst_tracer_record_new (
 642       "element-reported-latency.class",
 643       "element-id", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
 644           "type", G_TYPE_GTYPE, G_TYPE_STRING,
 645           "related-to", GST_TYPE_TRACER_VALUE_SCOPE,
 646           GST_TRACER_VALUE_SCOPE_ELEMENT,
 647           NULL),
 648       "element", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
 649           "type", G_TYPE_GTYPE, G_TYPE_STRING,
 650           "related-to", GST_TYPE_TRACER_VALUE_SCOPE,
 651           GST_TRACER_VALUE_SCOPE_ELEMENT,
 652           NULL),
 653       "live", GST_TYPE_STRUCTURE, gst_structure_new ("value",
 654           "type", G_TYPE_GTYPE, G_TYPE_BOOLEAN,
 655           "description", G_TYPE_STRING,
 656               "wether the it is a live stream or not",
 657           NULL),
 658       "min", GST_TYPE_STRUCTURE, gst_structure_new ("value",
 659           "type", G_TYPE_GTYPE, G_TYPE_UINT64,
 660           "description", G_TYPE_STRING,
 661               "the minimum reported latency",
 662           "min", G_TYPE_UINT64, G_GUINT64_CONSTANT (0),
 663           "max", G_TYPE_UINT64, G_MAXUINT64,
 664           NULL),
 665       "max", GST_TYPE_STRUCTURE, gst_structure_new ("value",
 666           "type", G_TYPE_GTYPE, G_TYPE_UINT64,
 667           "description", G_TYPE_STRING, "the maximum reported latency",
 668           "min", G_TYPE_UINT64, G_GUINT64_CONSTANT (0),
 669           "max", G_TYPE_UINT64, G_MAXUINT64,
 670           NULL),
 671       "ts", GST_TYPE_STRUCTURE, gst_structure_new ("value",
 672           "type", G_TYPE_GTYPE, G_TYPE_UINT64,
 673           "description", G_TYPE_STRING, "ts when the latency has been reported",
 674           "min", G_TYPE_UINT64, G_GUINT64_CONSTANT (0),
 675           "max", G_TYPE_UINT64, G_MAXUINT64,
 676           NULL),
 677       NULL);
 678   /* *INDENT-ON* */
 679 }
 680
 681 static void
 682 gst_latency_tracer_init (GstLatencyTracer * self)
 683 {
 684   GstTracer *tracer = GST_TRACER (self);
 685
 686   /* only trace pipeline latency by default */
 687   self->flags = GST_LATENCY_TRACER_FLAG_PIPELINE;
 688
 689   /* in push mode, pre/post will be called before/after the peer chain
 690    * function has been called. For this reaosn, we only use -pre to avoid
 691    * accounting for the processing time of the peer element (the sink) */
 692   gst_tracing_register_hook (tracer, "pad-push-pre",
 693       G_CALLBACK (do_push_buffer_pre));
 694   gst_tracing_register_hook (tracer, "pad-push-list-pre",
 695       G_CALLBACK (do_push_buffer_pre));
 696
 697   /* while in pull mode, pre/post will happen before and after the upstream
 698    * pull_range call is made, so it already only account for the upstream
 699    * processing time. As a side effect, in pull mode, we can measure the
 700    * source processing latency, while in push mode, we can't */
 701   gst_tracing_register_hook (tracer, "pad-pull-range-pre",
 702       G_CALLBACK (do_pull_range_pre));
 703   gst_tracing_register_hook (tracer, "pad-pull-range-post",
 704       G_CALLBACK (do_pull_range_post));
 705
 706   gst_tracing_register_hook (tracer, "pad-push-event-pre",
 707       G_CALLBACK (do_push_event_pre));
 708
 709   /* Add pad query post hook to get the reported per-element latency */
 710   gst_tracing_register_hook (tracer, "pad-query-post",
 711       G_CALLBACK (do_query_post));
 712 }