2 * Copyright (C) 2013 Stefan Sauer <ensonic@users.sf.net>
4 * gstrusage.c: tracing module that logs resource usage 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.
22 * SECTION:element-rusagetracer
23 * @short_description: log resource usage stats
25 * A tracing module that take rusage() snapshots and logs them.
33 #include "gstrusage.h"
35 #ifdef HAVE_SYS_RESOURCE_H
37 # define __USE_GNU /* RUSAGE_THREAD */
39 #include <sys/resource.h>
42 GST_DEBUG_CATEGORY_STATIC (gst_rusage_debug);
43 #define GST_CAT_DEFAULT gst_rusage_debug
45 G_LOCK_DEFINE (_proc);
48 GST_DEBUG_CATEGORY_INIT (gst_rusage_debug, "rusage", 0, "rusage tracer");
49 #define gst_rusage_tracer_parent_class parent_class
50 G_DEFINE_TYPE_WITH_CODE (GstRUsageTracer, gst_rusage_tracer, GST_TYPE_TRACER,
53 /* remember x measurements per self->window */
54 #define WINDOW_SUBDIV 100
56 /* number of cpus to scale cpu-usage in threads */
57 static glong num_cpus = 1;
59 static GstTracerRecord *tr_proc, *tr_thread;
63 /* time spend in this thread */
65 GstTraceValues *tvs_thread;
71 free_trace_value (gpointer data)
73 g_slice_free (GstTraceValue, data);
76 static GstTraceValues *
77 make_trace_values (GstClockTime window)
79 GstTraceValues *self = g_slice_new0 (GstTraceValues);
80 self->window = window;
81 g_queue_init (&self->values);
86 free_trace_values (GstTraceValues * self)
88 g_queue_foreach (&self->values, (GFunc) free_trace_value, NULL);
89 g_queue_clear (&self->values);
90 g_slice_free (GstTraceValues, self);
94 update_trace_value (GstTraceValues * self, GstClockTime nts,
95 GstClockTime nval, GstClockTime * dts, GstClockTime * dval)
99 GstClockTime window = self->window;
100 GQueue *q = &self->values;
101 GList *node = q->tail;
102 gboolean ret = FALSE;
105 /* search from the tail of the queue for a good GstTraceValue */
108 dt = GST_CLOCK_DIFF (lv->ts, nts);
112 node = g_list_previous (node);
117 /* calculate the windowed value */
119 *dval = GST_CLOCK_DIFF (lv->val, nval);
121 /* drop all older measurements */
122 while (q->tail != node) {
123 free_trace_value (g_queue_pop_tail (q));
131 /* don't push too many data items */
132 lv = q->head ? q->head->data : NULL;
133 if (!lv || (GST_CLOCK_DIFF (lv->ts, nts) > (window / WINDOW_SUBDIV))) {
134 /* push the new measurement */
135 lv = g_slice_new0 (GstTraceValue);
138 g_queue_push_head (q, lv);
145 free_thread_stats (gpointer data)
147 free_trace_values (((GstThreadStats *) data)->tvs_thread);
148 g_slice_free (GstThreadStats, data);
152 do_stats (GstTracer * obj, guint64 ts)
154 GstRUsageTracer *self = GST_RUSAGE_TRACER_CAST (obj);
155 GstThreadStats *stats;
156 gpointer thread_id = g_thread_self ();
157 guint avg_cpuload, cur_cpuload;
159 GstClockTime tproc = G_GUINT64_CONSTANT (0);
160 GstClockTime tthread = G_GUINT64_CONSTANT (0);
161 GstClockTime dts, dtproc;
163 #ifdef HAVE_CLOCK_GETTIME
167 if (!clock_gettime (CLOCK_PROCESS_CPUTIME_ID, &now)) {
168 tproc = GST_TIMESPEC_TO_TIME (now);
170 GST_WARNING_OBJECT (obj,
171 "clock_gettime (CLOCK_PROCESS_CPUTIME_ID,...) failed: %s",
173 getrusage (RUSAGE_SELF, &ru);
175 GST_TIMEVAL_TO_TIME (ru.ru_utime) + GST_TIMEVAL_TO_TIME (ru.ru_stime);
178 /* cpu time per thread */
179 if (!clock_gettime (CLOCK_THREAD_CPUTIME_ID, &now)) {
180 tthread = GST_TIMESPEC_TO_TIME (now);
182 GST_WARNING_OBJECT (obj,
183 "clock_gettime (CLOCK_THREAD_CPUTIME_ID,...) failed: %s",
186 getrusage (RUSAGE_THREAD, &ru);
188 GST_TIMEVAL_TO_TIME (ru.ru_utime) + GST_TIMEVAL_TO_TIME (ru.ru_stime);
193 getrusage (RUSAGE_SELF, &ru);
194 tproc = GST_TIMEVAL_TO_TIME (ru.ru_utime) + GST_TIMEVAL_TO_TIME (ru.ru_stime);
196 getrusage (RUSAGE_THREAD, &ru);
198 GST_TIMEVAL_TO_TIME (ru.ru_utime) + GST_TIMEVAL_TO_TIME (ru.ru_stime);
201 /* get stats record for current thread */
202 if (!(stats = g_hash_table_lookup (self->threads, thread_id))) {
203 stats = g_slice_new0 (GstThreadStats);
204 stats->tvs_thread = make_trace_values (GST_SECOND);
205 g_hash_table_insert (self->threads, thread_id, stats);
207 stats->tthread = tthread;
209 /* Calibrate ts for the process and main thread. For tthread[main] and tproc
210 * the time is larger than ts, as our base-ts is taken after the process has
213 if (G_UNLIKELY (thread_id == self->main_thread_id)) {
214 self->main_thread_id = NULL;
215 /* when the registry gets updated, the tproc is less than the debug time ? */
216 /* TODO(ensonic): we still see cases where tproc overtakes ts, especially
217 * when with sync=false, can this be due to multiple cores in use? */
219 self->tproc_base = tproc - ts;
220 GST_DEBUG ("rusage: calibrating by %" G_GUINT64_FORMAT ", thread: %"
221 G_GUINT64_FORMAT ", proc: %" G_GUINT64_FORMAT,
222 self->tproc_base, stats->tthread, tproc);
223 stats->tthread -= self->tproc_base;
226 /* we always need to correct proc time */
227 tproc -= self->tproc_base;
229 /* FIXME: how can we take cpu-frequency scaling into account?
230 * - looking at /sys/devices/system/cpu/cpu0/cpufreq/
231 * scale_factor=scaling_max_freq/scaling_cur_freq
232 * - as a workaround we can switch it via /sys/devices/system/cpu/cpu0/cpufreq/scaling_governor
233 * cpufreq-selector -g performance
234 * cpufreq-selector -g ondemand
237 avg_cpuload = (guint) gst_util_uint64_scale (stats->tthread,
238 G_GINT64_CONSTANT (1000), ts);
239 update_trace_value (stats->tvs_thread, ts, stats->tthread, &dts, &dtproc);
240 cur_cpuload = (guint) gst_util_uint64_scale (dtproc,
241 G_GINT64_CONSTANT (1000), dts);
242 gst_tracer_record_log (tr_thread, (guint64) (guintptr) thread_id, ts,
243 MIN (avg_cpuload, 1000), MIN (cur_cpuload, 1000), stats->tthread);
245 avg_cpuload = (guint) gst_util_uint64_scale (tproc / num_cpus,
246 G_GINT64_CONSTANT (1000), ts);
248 update_trace_value (self->tvs_proc, ts, tproc, &dts, &dtproc);
250 cur_cpuload = (guint) gst_util_uint64_scale (dtproc / num_cpus,
251 G_GINT64_CONSTANT (1000), dts);
252 gst_tracer_record_log (tr_proc, (guint64) getpid (), ts,
253 MIN (avg_cpuload, 1000), MIN (cur_cpuload, 1000), tproc);
260 gst_rusage_tracer_finalize (GObject * obj)
262 GstRUsageTracer *self = GST_RUSAGE_TRACER (obj);
264 g_hash_table_destroy (self->threads);
265 free_trace_values (self->tvs_proc);
267 G_OBJECT_CLASS (parent_class)->finalize (obj);
271 gst_rusage_tracer_class_init (GstRUsageTracerClass * klass)
273 GObjectClass *gobject_class = G_OBJECT_CLASS (klass);
275 gobject_class->finalize = gst_rusage_tracer_finalize;
277 if ((num_cpus = sysconf (_SC_NPROCESSORS_ONLN)) == -1) {
278 GST_WARNING ("failed to get number of cpus online");
279 if ((num_cpus = sysconf (_SC_NPROCESSORS_CONF)) == -1) {
280 GST_WARNING ("failed to get number of cpus, assuming 1");
284 GST_DEBUG ("rusage: num_cpus=%ld", num_cpus);
286 /* announce trace formats */
288 tr_thread = gst_tracer_record_new ("thread-rusage.class",
289 "thread-id", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
290 "type", G_TYPE_GTYPE, G_TYPE_UINT64,
291 "related-to", GST_TYPE_TRACER_VALUE_SCOPE, GST_TRACER_VALUE_SCOPE_THREAD,
293 "ts", GST_TYPE_STRUCTURE, gst_structure_new ("value",
294 "type", G_TYPE_GTYPE, G_TYPE_UINT64,
295 "description", G_TYPE_STRING, "event ts",
297 "average-cpuload", GST_TYPE_STRUCTURE, gst_structure_new ("value",
298 "type", G_TYPE_GTYPE, G_TYPE_UINT,
299 "description", G_TYPE_STRING, "average cpu usage per thread in ‰",
300 "flags", GST_TYPE_TRACER_VALUE_FLAGS, GST_TRACER_VALUE_FLAGS_AGGREGATED,
301 "min", G_TYPE_UINT, 0,
302 "max", G_TYPE_UINT, 1000,
304 "current-cpuload", GST_TYPE_STRUCTURE, gst_structure_new ("value",
305 "type", G_TYPE_GTYPE, G_TYPE_UINT,
306 "description", G_TYPE_STRING, "current cpu usage per thread in ‰",
307 "min", G_TYPE_UINT, 0,
308 "max", G_TYPE_UINT, 1000,
310 "time", GST_TYPE_STRUCTURE, gst_structure_new ("value",
311 "type", G_TYPE_GTYPE, G_TYPE_UINT64,
312 "description", G_TYPE_STRING, "time spent in thread in ns",
313 "flags", GST_TYPE_TRACER_VALUE_FLAGS, GST_TRACER_VALUE_FLAGS_AGGREGATED,
314 "min", G_TYPE_UINT64, G_GUINT64_CONSTANT (0),
315 "max", G_TYPE_UINT64, G_MAXUINT64,
318 tr_proc = gst_tracer_record_new ("proc-rusage.class",
319 "process-id", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
320 "type", G_TYPE_GTYPE, G_TYPE_UINT64,
321 "related-to", GST_TYPE_TRACER_VALUE_SCOPE, GST_TRACER_VALUE_SCOPE_PROCESS,
323 "ts", GST_TYPE_STRUCTURE, gst_structure_new ("value",
324 "type", G_TYPE_GTYPE, G_TYPE_UINT64,
325 "description", G_TYPE_STRING, "event ts",
327 "average-cpuload", GST_TYPE_STRUCTURE, gst_structure_new ("value",
328 "type", G_TYPE_GTYPE, G_TYPE_UINT,
329 "description", G_TYPE_STRING, "average cpu usage per process in ‰",
330 "flags", GST_TYPE_TRACER_VALUE_FLAGS, GST_TRACER_VALUE_FLAGS_AGGREGATED,
331 "min", G_TYPE_UINT, 0,
332 "max", G_TYPE_UINT, 1000,
334 "current-cpuload", GST_TYPE_STRUCTURE, gst_structure_new ("value",
335 "type", G_TYPE_GTYPE, G_TYPE_UINT,
336 "description", G_TYPE_STRING, "current cpu usage per process in ‰",
337 "min", G_TYPE_UINT, 0,
338 "max", G_TYPE_UINT, 1000,
340 "time", GST_TYPE_STRUCTURE, gst_structure_new ("value",
341 "type", G_TYPE_GTYPE, G_TYPE_UINT64,
342 "description", G_TYPE_STRING, "time spent in process in ns",
343 "flags", GST_TYPE_TRACER_VALUE_FLAGS, GST_TRACER_VALUE_FLAGS_AGGREGATED,
344 "min", G_TYPE_UINT64, G_GUINT64_CONSTANT (0),
345 "max", G_TYPE_UINT64, G_MAXUINT64,
352 gst_rusage_tracer_init (GstRUsageTracer * self)
354 GstTracer *tracer = GST_TRACER (self);
356 const gchar *hooks[] = { "pad-push-pre", "pad-push-post", "pad-push-list-pre",
357 "pad-push-list-post", "pad-pull-range-pre", "pad-pull-range-post",
358 "pad-push-event-pre", "pad-push-event-post", "pad-query-pre",
359 "pad-query-post", "element-post-message-pre", "element-post-message-post",
360 "element-query-pre", "element-query-post", "element-new", "element-add-pad",
361 "element-remove-pad", "element-change-state-pre",
362 "element-change-state-post", "bin-add-pre", "bin-add-post",
363 "bin-remove-pre", "bin-remove-post", "pad-link-pre", "pad-link-post",
364 "pad-unlink-pre", "pad-unlink-post"
367 for (i = 0; i < G_N_ELEMENTS (hooks); i++) {
368 gst_tracing_register_hook (tracer, hooks[i], G_CALLBACK (do_stats));
371 self->threads = g_hash_table_new_full (NULL, NULL, NULL, free_thread_stats);
372 self->tvs_proc = make_trace_values (GST_SECOND);
373 self->main_thread_id = g_thread_self ();
375 GST_DEBUG ("rusage: main thread=%p", self->main_thread_id);