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, 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       const GValue *value;
 352       /* FIXME unsafe peer pad usage */
 353       gchar *pad_name = g_strdup_printf ("%s_%s",
 354           GST_DEBUG_PAD_NAME (GST_PAD_PEER (pad)));
 355
 356       value = gst_structure_id_get_value (data, latency_probe_pad);
 357       if (!g_str_equal (g_value_get_string (value), pad_name)) {
 358         GST_DEBUG ("%s: Dropping sub-latency event", pad_name);
 359         ret = GST_PAD_PROBE_DROP;
 360       }
 361
 362       g_free (pad_name);
 363     }
 364   }
 365
 366   return ret;
 367 }
 368
 369 static void
 370 do_push_event_pre (GstTracer * self, guint64 ts, GstPad * pad, GstEvent * ev)
 371 {
 372   GstElement *parent = get_real_pad_parent (pad);
 373   GstPad *peer_pad = GST_PAD_PEER (pad);
 374   GstElement *peer_parent = get_real_pad_parent (peer_pad);
 375
 376   if (parent && (!GST_IS_BIN (parent)) &&
 377       (!GST_OBJECT_FLAG_IS_SET (parent, GST_ELEMENT_FLAG_SOURCE)) &&
 378       GST_EVENT_TYPE (ev) == GST_EVENT_CUSTOM_DOWNSTREAM) {
 379     const GstStructure *data = gst_event_get_structure (ev);
 380
 381     /* if not set yet, add a pad probe that prevents sub-latency event from
 382      * flowing further */
 383     if (gst_structure_get_name_id (data) == latency_probe_id) {
 384
 385       if (!g_object_get_qdata ((GObject *) pad, drop_sub_latency_quark)) {
 386         GST_DEBUG ("%s_%s: Adding pad probe to drop sub-latency event",
 387             GST_DEBUG_PAD_NAME (pad));
 388         gst_pad_add_probe (pad, GST_PAD_PROBE_TYPE_EVENT_DOWNSTREAM,
 389             do_drop_sub_latency_event, NULL, NULL);
 390         g_object_set_qdata ((GObject *) pad, drop_sub_latency_quark,
 391             (gpointer) 1);
 392       }
 393
 394       /* FIXME unsafe peer access */
 395       if (GST_OBJECT_FLAG_IS_SET (peer_parent, GST_ELEMENT_FLAG_SINK)) {
 396         GST_DEBUG ("%s_%s: Storing latency event", GST_DEBUG_PAD_NAME (pad));
 397
 398         /* store event so that we can calculate latency when the buffer that
 399          * follows has been processed */
 400         if (!g_object_get_qdata ((GObject *) pad, latency_probe_id))
 401           g_object_set_qdata ((GObject *) pad, latency_probe_id,
 402               gst_event_ref (ev));
 403       }
 404     }
 405
 406     if (gst_structure_get_name_id (data) == sub_latency_probe_id) {
 407       const GValue *value;
 408       gchar *pad_name = g_strdup_printf ("%s_%s",
 409           GST_DEBUG_PAD_NAME (peer_pad));
 410
 411       value = gst_structure_id_get_value (data, latency_probe_pad);
 412
 413       if (!g_str_equal (g_value_get_string (value), pad_name)) {
 414         GST_DEBUG ("%s: Storing sub-latency event", pad_name);
 415         if (!g_object_get_qdata ((GObject *) pad, sub_latency_probe_id))
 416           g_object_set_qdata ((GObject *) pad, sub_latency_probe_id,
 417               gst_event_ref (ev));
 418       }
 419
 420       g_free (pad_name);
 421     }
 422   }
 423 }
 424
 425 static void
 426 do_query_post (GstLatencyTracer * tracer, GstClockTime ts, GstPad * pad,
 427     GstQuery * query, gboolean res)
 428 {
 429   /* Only check for latency queries if flag is enabled */
 430   if ((tracer->flags & GST_LATENCY_TRACER_FLAG_REPORTED_ELEMENT) &&
 431       (GST_QUERY_TYPE (query) == GST_QUERY_LATENCY)) {
 432     gboolean live;
 433     guint64 min = 0, max = 0, min_prev = 0, max_prev = 0;
 434     gchar *element_name, *element_id;
 435     struct LatencyQueryTableValue *value;
 436     GstElement *element = get_real_pad_parent (pad);
 437     GstElement *peer_element = get_real_pad_parent (GST_PAD_PEER (pad));
 438
 439     /* Parse the query */
 440     gst_query_parse_latency (query, &live, &min, &max);
 441
 442     /* Pop from stack */
 443     value = local_latency_query_stack_pop ();
 444     while (value && value->peer_element == element) {
 445       min_prev = MAX (value->min, min_prev);
 446       max_prev = MAX (value->max, max_prev);
 447       value = local_latency_query_stack_pop ();
 448     }
 449
 450     /* Push to stack */
 451     value = g_new0 (struct LatencyQueryTableValue, 1);
 452     value->peer_element = gst_object_ref (peer_element);
 453     value->min = min;
 454     value->max = max;
 455     local_latency_query_stack_push (value);
 456
 457     /* Get the pad name */
 458     element_id = g_strdup_printf ("%p", element);
 459     element_name = gst_element_get_name (element);
 460
 461     /* Log reported latency */
 462     gst_tracer_record_log (tr_element_reported_latency, element_id,
 463         element_name, live, GST_CLOCK_DIFF (min_prev, min),
 464         GST_CLOCK_DIFF (max_prev, max), ts);
 465
 466     /* Clean up */
 467     g_free (element_name);
 468     g_free (element_id);
 469   }
 470 }
 471
 472 /* tracer class */
 473
 474 static void
 475 gst_latency_tracer_constructed (GObject * object)
 476 {
 477   GstLatencyTracer *self = GST_LATENCY_TRACER (object);
 478   gchar *params, *tmp;
 479   GstStructure *params_struct = NULL;
 480
 481   g_object_get (self, "params", &params, NULL);
 482
 483   if (!params)
 484     return;
 485
 486   tmp = g_strdup_printf ("latency,%s", params);
 487   params_struct = gst_structure_from_string (tmp, NULL);
 488   g_free (tmp);
 489
 490   /* Read the flags if available */
 491   if (params_struct) {
 492     const gchar *flags = gst_structure_get_string (params_struct, "flags");
 493
 494     self->flags = 0;
 495
 496     if (flags) {
 497       GStrv split = g_strsplit (flags, "+", -1);
 498       gint i;
 499
 500       for (i = 0; split[i]; i++) {
 501         if (g_str_equal (split[i], "pipeline"))
 502           self->flags |= GST_LATENCY_TRACER_FLAG_PIPELINE;
 503         else if (g_str_equal (split[i], "element"))
 504           self->flags |= GST_LATENCY_TRACER_FLAG_ELEMENT;
 505         else if (g_str_equal (split[i], "reported"))
 506           self->flags |= GST_LATENCY_TRACER_FLAG_REPORTED_ELEMENT;
 507         else
 508           GST_WARNING ("Invalid latency tracer flags %s", split[i]);
 509       }
 510
 511       g_strfreev (split);
 512     }
 513   }
 514
 515   g_free (params);
 516 }
 517
 518 static void
 519 gst_latency_tracer_class_init (GstLatencyTracerClass * klass)
 520 {
 521   GObjectClass *gobject_class = G_OBJECT_CLASS (klass);
 522
 523   gobject_class->constructed = gst_latency_tracer_constructed;
 524
 525   latency_probe_id = g_quark_from_static_string ("latency_probe.id");
 526   sub_latency_probe_id = g_quark_from_static_string ("sub_latency_probe.id");
 527   latency_probe_pad = g_quark_from_static_string ("latency_probe.pad");
 528   latency_probe_element = g_quark_from_static_string ("latency_probe.element");
 529   latency_probe_element_id =
 530       g_quark_from_static_string ("latency_probe.element_id");
 531   latency_probe_ts = g_quark_from_static_string ("latency_probe.ts");
 532   drop_sub_latency_quark =
 533       g_quark_from_static_string ("drop_sub_latency.quark");
 534
 535   /* announce trace formats */
 536   /* *INDENT-OFF* */
 537   tr_latency = gst_tracer_record_new ("latency.class",
 538       "src-element-id", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
 539           "type", G_TYPE_GTYPE, G_TYPE_STRING,
 540           "related-to", GST_TYPE_TRACER_VALUE_SCOPE,
 541           GST_TRACER_VALUE_SCOPE_ELEMENT,
 542           NULL),
 543       "src-element", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
 544           "type", G_TYPE_GTYPE, G_TYPE_STRING,
 545           "related-to", GST_TYPE_TRACER_VALUE_SCOPE,
 546           GST_TRACER_VALUE_SCOPE_ELEMENT,
 547           NULL),
 548       "src", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
 549           "type", G_TYPE_GTYPE, G_TYPE_STRING,
 550           "related-to", GST_TYPE_TRACER_VALUE_SCOPE, GST_TRACER_VALUE_SCOPE_PAD,
 551           NULL),
 552       "sink-element-id", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
 553           "type", G_TYPE_GTYPE, G_TYPE_STRING,
 554           "related-to", GST_TYPE_TRACER_VALUE_SCOPE,
 555           GST_TRACER_VALUE_SCOPE_ELEMENT,
 556           NULL),
 557       "sink-element", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
 558           "type", G_TYPE_GTYPE, G_TYPE_STRING,
 559           "related-to", GST_TYPE_TRACER_VALUE_SCOPE,
 560           GST_TRACER_VALUE_SCOPE_ELEMENT,
 561           NULL),
 562       "sink", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
 563           "type", G_TYPE_GTYPE, G_TYPE_STRING,
 564           "related-to", GST_TYPE_TRACER_VALUE_SCOPE, GST_TRACER_VALUE_SCOPE_PAD,
 565           NULL),
 566       "time", GST_TYPE_STRUCTURE, gst_structure_new ("value",
 567           "type", G_TYPE_GTYPE, G_TYPE_UINT64,
 568           "description", G_TYPE_STRING,
 569               "time it took for the buffer to go from src to sink ns",
 570           "min", G_TYPE_UINT64, G_GUINT64_CONSTANT (0),
 571           "max", G_TYPE_UINT64, G_MAXUINT64,
 572           NULL),
 573       "ts", GST_TYPE_STRUCTURE, gst_structure_new ("value",
 574           "type", G_TYPE_GTYPE, G_TYPE_UINT64,
 575           "description", G_TYPE_STRING, "ts when the latency has been logged",
 576           "min", G_TYPE_UINT64, G_GUINT64_CONSTANT (0),
 577           "max", G_TYPE_UINT64, G_MAXUINT64,
 578           NULL),
 579       NULL);
 580
 581   tr_element_latency = gst_tracer_record_new ("element-latency.class",
 582       "element-id", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
 583           "type", G_TYPE_GTYPE, G_TYPE_STRING,
 584           "related-to", GST_TYPE_TRACER_VALUE_SCOPE,
 585           GST_TRACER_VALUE_SCOPE_ELEMENT,
 586           NULL),
 587       "element", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
 588           "type", G_TYPE_GTYPE, G_TYPE_STRING,
 589           "related-to", GST_TYPE_TRACER_VALUE_SCOPE,
 590           GST_TRACER_VALUE_SCOPE_ELEMENT,
 591           NULL),
 592       "src", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
 593           "type", G_TYPE_GTYPE, G_TYPE_STRING,
 594           "related-to", GST_TYPE_TRACER_VALUE_SCOPE, GST_TRACER_VALUE_SCOPE_PAD,
 595           NULL),
 596       "time", GST_TYPE_STRUCTURE, gst_structure_new ("value",
 597           "type", G_TYPE_GTYPE, G_TYPE_UINT64,
 598           "description", G_TYPE_STRING,
 599               "time it took for the buffer to go from src to sink ns",
 600           "min", G_TYPE_UINT64, G_GUINT64_CONSTANT (0),
 601           "max", G_TYPE_UINT64, G_MAXUINT64,
 602           NULL),
 603       "ts", GST_TYPE_STRUCTURE, gst_structure_new ("value",
 604           "type", G_TYPE_GTYPE, G_TYPE_UINT64,
 605           "description", G_TYPE_STRING, "ts when the latency has been logged",
 606           "min", G_TYPE_UINT64, G_GUINT64_CONSTANT (0),
 607           "max", G_TYPE_UINT64, G_MAXUINT64,
 608           NULL),
 609       NULL);
 610
 611
 612   tr_element_reported_latency = gst_tracer_record_new (
 613       "element-reported-latency.class",
 614       "element-id", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
 615           "type", G_TYPE_GTYPE, G_TYPE_STRING,
 616           "related-to", GST_TYPE_TRACER_VALUE_SCOPE,
 617           GST_TRACER_VALUE_SCOPE_ELEMENT,
 618           NULL),
 619       "element", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
 620           "type", G_TYPE_GTYPE, G_TYPE_STRING,
 621           "related-to", GST_TYPE_TRACER_VALUE_SCOPE,
 622           GST_TRACER_VALUE_SCOPE_ELEMENT,
 623           NULL),
 624       "live", GST_TYPE_STRUCTURE, gst_structure_new ("value",
 625           "type", G_TYPE_GTYPE, G_TYPE_BOOLEAN,
 626           "description", G_TYPE_STRING,
 627               "wether the it is a live stream or not",
 628           NULL),
 629       "min", GST_TYPE_STRUCTURE, gst_structure_new ("value",
 630           "type", G_TYPE_GTYPE, G_TYPE_UINT64,
 631           "description", G_TYPE_STRING,
 632               "the minimum reported latency",
 633           "min", G_TYPE_UINT64, G_GUINT64_CONSTANT (0),
 634           "max", G_TYPE_UINT64, G_MAXUINT64,
 635           NULL),
 636       "max", GST_TYPE_STRUCTURE, gst_structure_new ("value",
 637           "type", G_TYPE_GTYPE, G_TYPE_UINT64,
 638           "description", G_TYPE_STRING, "the maximum reported latency",
 639           "min", G_TYPE_UINT64, G_GUINT64_CONSTANT (0),
 640           "max", G_TYPE_UINT64, G_MAXUINT64,
 641           NULL),
 642       "ts", GST_TYPE_STRUCTURE, gst_structure_new ("value",
 643           "type", G_TYPE_GTYPE, G_TYPE_UINT64,
 644           "description", G_TYPE_STRING, "ts when the latency has been reported",
 645           "min", G_TYPE_UINT64, G_GUINT64_CONSTANT (0),
 646           "max", G_TYPE_UINT64, G_MAXUINT64,
 647           NULL),
 648       NULL);
 649   /* *INDENT-ON* */
 650 }
 651
 652 static void
 653 gst_latency_tracer_init (GstLatencyTracer * self)
 654 {
 655   GstTracer *tracer = GST_TRACER (self);
 656
 657   /* only trace pipeline latency by default */
 658   self->flags = GST_LATENCY_TRACER_FLAG_PIPELINE;
 659
 660   /* in push mode, pre/post will be called before/after the peer chain
 661    * function has been called. For this reaosn, we only use -pre to avoid
 662    * accounting for the processing time of the peer element (the sink) */
 663   gst_tracing_register_hook (tracer, "pad-push-pre",
 664       G_CALLBACK (do_push_buffer_pre));
 665   gst_tracing_register_hook (tracer, "pad-push-list-pre",
 666       G_CALLBACK (do_push_buffer_pre));
 667
 668   /* while in pull mode, pre/post will happen before and after the upstream
 669    * pull_range call is made, so it already only account for the upstream
 670    * processing time. As a side effect, in pull mode, we can measure the
 671    * source processing latency, while in push mode, we can't */
 672   gst_tracing_register_hook (tracer, "pad-pull-range-pre",
 673       G_CALLBACK (do_pull_range_pre));
 674   gst_tracing_register_hook (tracer, "pad-pull-range-post",
 675       G_CALLBACK (do_pull_range_post));
 676
 677   gst_tracing_register_hook (tracer, "pad-push-event-pre",
 678       G_CALLBACK (do_push_event_pre));
 679
 680   /* Add pad query post hook to get the reported per-element latency */
 681   gst_tracing_register_hook (tracer, "pad-query-post",
 682       G_CALLBACK (do_query_post));
 683 }