2 * Copyright (C) 2013 Stefan Sauer <ensonic@users.sf.net>
4 * gstlatency.c: tracing module that logs processing latency stats
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.
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.
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.
23 * @short_description: log processing latency stats
25 * A tracing module that determines src-to-sink latencies by injecting custom
26 * events at sources and process them at sinks.
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
40 #include "gstlatency.h"
42 GST_DEBUG_CATEGORY_STATIC (gst_latency_debug);
43 #define GST_CAT_DEFAULT gst_latency_debug
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,
51 static GQuark latency_probe_id;
52 static GQuark latency_probe_pad;
53 static GQuark latency_probe_ts;
58 * Get the element/bin owning the pad.
64 * out: the element that contains the peer of the proxy
67 * out: the bin owning the ghostpad
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();
73 get_real_pad_parent (GstPad * pad)
80 parent = GST_OBJECT_PARENT (pad);
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);
87 return GST_ELEMENT_CAST (parent);
93 log_latency (const GstStructure * data, GstPad * sink_pad, guint64 sink_ts)
99 gst_structure_id_get (data,
100 latency_probe_pad, GST_TYPE_PAD, &src_pad,
101 latency_probe_ts, G_TYPE_UINT64, &src_ts, NULL);
103 src = g_strdup_printf ("%s_%s", GST_DEBUG_PAD_NAME (src_pad));
104 sink = g_strdup_printf ("%s_%s", GST_DEBUG_PAD_NAME (sink_pad));
106 /* TODO(ensonic): report format is still unstable */
107 gst_tracer_log_trace (gst_structure_new ("latency",
108 "src", G_TYPE_STRING, src,
109 "sink", G_TYPE_STRING, sink,
110 "time", G_TYPE_UINT64, GST_CLOCK_DIFF (src_ts, sink_ts), NULL));
116 send_latency_probe (GstLatencyTracer * self, GstElement * parent, GstPad * pad,
119 if (parent && (!GST_IS_BIN (parent)) &&
120 GST_OBJECT_FLAG_IS_SET (parent, GST_ELEMENT_FLAG_SOURCE)) {
121 GstEvent *latency_probe = gst_event_new_custom (GST_EVENT_CUSTOM_DOWNSTREAM,
122 gst_structure_new_id (latency_probe_id,
123 latency_probe_pad, GST_TYPE_PAD, pad,
124 latency_probe_ts, G_TYPE_UINT64, ts,
126 gst_pad_push_event (pad, latency_probe);
131 do_push_buffer_pre (GstTracer * self, va_list var_args)
133 guint64 ts = va_arg (var_args, guint64);
134 GstPad *pad = va_arg (var_args, GstPad *);
135 GstElement *parent = get_real_pad_parent (pad);
137 send_latency_probe ((GstLatencyTracer *) self, parent, pad, ts);
141 do_pull_range_pre (GstTracer * self, va_list var_args)
143 guint64 ts = va_arg (var_args, guint64);
144 GstPad *pad = va_arg (var_args, GstPad *);
145 GstPad *peer_pad = GST_PAD_PEER (pad);
146 GstElement *parent = get_real_pad_parent (peer_pad);
148 send_latency_probe ((GstLatencyTracer *) self, parent, peer_pad, ts);
152 calculate_latency (GstLatencyTracer * self, GstElement * parent, GstPad * pad,
155 if (parent && (!GST_IS_BIN (parent)) &&
156 GST_OBJECT_FLAG_IS_SET (parent, GST_ELEMENT_FLAG_SINK)) {
157 GstEvent *ev = g_object_get_qdata ((GObject *) pad, latency_probe_id);
159 log_latency (gst_event_get_structure (ev), pad, ts);
160 gst_event_unref (ev);
165 do_push_buffer_post (GstTracer * self, va_list var_args)
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);
172 calculate_latency ((GstLatencyTracer *) self, parent, peer_pad, ts);
176 do_pull_range_post (GstTracer * self, va_list var_args)
178 guint64 ts = va_arg (var_args, guint64);
179 GstPad *pad = va_arg (var_args, GstPad *);
180 GstElement *parent = get_real_pad_parent (pad);
182 calculate_latency ((GstLatencyTracer *) self, parent, pad, ts);
186 do_push_event_pre (GstTracer * self, va_list var_args)
188 G_GNUC_UNUSED guint64 ts = va_arg (var_args, guint64);
189 GstPad *pad = va_arg (var_args, GstPad *);
190 GstEvent *ev = va_arg (var_args, GstEvent *);
191 GstPad *peer_pad = GST_PAD_PEER (pad);
192 GstElement *parent = get_real_pad_parent (peer_pad);
194 if (parent && (!GST_IS_BIN (parent)) &&
195 GST_OBJECT_FLAG_IS_SET (parent, GST_ELEMENT_FLAG_SINK)) {
196 if (GST_EVENT_TYPE (ev) == GST_EVENT_CUSTOM_DOWNSTREAM) {
197 const GstStructure *data = gst_event_get_structure (ev);
199 if (gst_structure_get_name_id (data) == latency_probe_id) {
200 /* store event and calculate latency when the buffer that follows
201 * has been processed */
202 g_object_set_qdata ((GObject *) peer_pad, latency_probe_id,
212 gst_latency_tracer_class_init (GstLatencyTracerClass * klass)
214 latency_probe_id = g_quark_from_static_string ("latency_probe.id");
215 latency_probe_pad = g_quark_from_static_string ("latency_probe.pad");
216 latency_probe_ts = g_quark_from_static_string ("latency_probe.ts");
218 /* announce trace formats */
220 gst_tracer_log_trace (gst_structure_new ("latency.class",
221 "src", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
222 "related-to", G_TYPE_STRING, "pad", /* TODO: use genum */
224 "sink", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
225 "related-to", G_TYPE_STRING, "pad", /* TODO: use genum */
227 "time", GST_TYPE_STRUCTURE, gst_structure_new ("value",
228 "type", G_TYPE_GTYPE, G_TYPE_UINT64,
229 "description", G_TYPE_STRING,
230 "time it took for the buffer to go from src to sink ns",
231 "flags", G_TYPE_STRING, "aggregated", /* TODO: use gflags */
232 "min", G_TYPE_UINT64, G_GUINT64_CONSTANT (0),
233 "max", G_TYPE_UINT64, G_MAXUINT64,
240 gst_latency_tracer_init (GstLatencyTracer * self)
242 GstTracer *tracer = GST_TRACER (self);
243 gst_tracer_register_hook (tracer, GST_TRACER_HOOK_ID_PAD_PUSH_PRE,
245 gst_tracer_register_hook (tracer, GST_TRACER_HOOK_ID_PAD_PUSH_LIST_PRE,
247 gst_tracer_register_hook (tracer, GST_TRACER_HOOK_ID_PAD_PUSH_POST,
248 do_push_buffer_post);
249 gst_tracer_register_hook (tracer, GST_TRACER_HOOK_ID_PAD_PUSH_LIST_POST,
250 do_push_buffer_post);
251 gst_tracer_register_hook (tracer, GST_TRACER_HOOK_ID_PAD_PULL_RANGE_PRE,
253 gst_tracer_register_hook (tracer, GST_TRACER_HOOK_ID_PAD_PULL_RANGE_POST,
255 gst_tracer_register_hook (tracer, GST_TRACER_HOOK_ID_PAD_PUSH_EVENT_PRE,
258 - we should also replace GstTracerHookId with a 'detail' string like in
260 - then we can attach to *all* hooks with 'null' as detail
261 gst_tracer_register_hook (self, gchar *detail, func);
262 gst_tracer_register_hook_id (self, GQuark detail, func);