plugins/tracers/gstrusage.c

   1 /* GStreamer
   2  * Copyright (C) 2013 Stefan Sauer <ensonic@users.sf.net>
   3  *
   4  * gstrusage.c: tracing module that logs resource usage 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:gstrusage
  23  * @short_description: log resource usage stats
  24  *
  25  * A tracing module that take rusage() snapshots and logs them.
  26  */
  27
  28 #ifdef HAVE_CONFIG_H
  29 #  include "config.h"
  30 #endif
  31
  32 #include <unistd.h>
  33 #include "gstrusage.h"
  34
  35 #ifdef HAVE_SYS_RESOURCE_H
  36 #ifndef __USE_GNU
  37 # define __USE_GNU              /* RUSAGE_THREAD */
  38 #endif
  39 #include <sys/resource.h>
  40 #endif
  41
  42 GST_DEBUG_CATEGORY_STATIC (gst_rusage_debug);
  43 #define GST_CAT_DEFAULT gst_rusage_debug
  44
  45 G_LOCK_DEFINE (_proc);
  46
  47 #define _do_init \
  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,
  51     _do_init);
  52
  53 /* remember x measurements per self->window */
  54 #define WINDOW_SUBDIV 100
  55
  56 /* number of cpus to scale cpu-usage in threads */
  57 static glong num_cpus = 1;
  58
  59 static GstTracerRecord *tr_proc, *tr_thread;
  60
  61 typedef struct
  62 {
  63   /* time spend in this thread */
  64   GstClockTime tthread;
  65   GstTraceValues *tvs_thread;
  66 } GstThreadStats;
  67
  68 /* data helper */
  69
  70 static void
  71 free_trace_value (gpointer data)
  72 {
  73   g_slice_free (GstTraceValue, data);
  74 }
  75
  76 static GstTraceValues *
  77 make_trace_values (GstClockTime window)
  78 {
  79   GstTraceValues *self = g_slice_new0 (GstTraceValues);
  80   self->window = window;
  81   g_queue_init (&self->values);
  82   return self;
  83 }
  84
  85 static void
  86 free_trace_values (GstTraceValues * self)
  87 {
  88   g_queue_foreach (&self->values, (GFunc) free_trace_value, NULL);
  89   g_queue_clear (&self->values);
  90   g_slice_free (GstTraceValues, self);
  91 }
  92
  93 static gboolean
  94 update_trace_value (GstTraceValues * self, GstClockTime nts,
  95     GstClockTime nval, GstClockTime * dts, GstClockTime * dval)
  96 {
  97   GstTraceValue *lv;
  98   GstClockTimeDiff dt;
  99   GstClockTime window = self->window;
 100   GQueue *q = &self->values;
 101   GList *node = q->tail;
 102   gboolean ret = FALSE;
 103
 104
 105   /* search from the tail of the queue for a good GstTraceValue */
 106   while (node) {
 107     lv = node->data;
 108     dt = GST_CLOCK_DIFF (lv->ts, nts);
 109     if (dt < window) {
 110       break;
 111     } else {
 112       node = g_list_previous (node);
 113     }
 114   }
 115
 116   if (node) {
 117     /* calculate the windowed value */
 118     *dts = dt;
 119     *dval = GST_CLOCK_DIFF (lv->val, nval);
 120
 121     /* drop all older measurements */
 122     while (q->tail != node) {
 123       free_trace_value (g_queue_pop_tail (q));
 124     }
 125     ret = TRUE;
 126   } else {
 127     *dts = nts;
 128     *dval = nval;
 129   }
 130
 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);
 136     lv->ts = nts;
 137     lv->val = nval;
 138     g_queue_push_head (q, lv);
 139   }
 140   return ret;
 141 }
 142
 143
 144 static void
 145 free_thread_stats (gpointer data)
 146 {
 147   free_trace_values (((GstThreadStats *) data)->tvs_thread);
 148   g_slice_free (GstThreadStats, data);
 149 }
 150
 151 static void
 152 do_stats (GstTracer * obj, guint64 ts)
 153 {
 154   GstRUsageTracer *self = GST_RUSAGE_TRACER_CAST (obj);
 155   GstThreadStats *stats;
 156   gpointer thread_id = g_thread_self ();
 157   guint avg_cpuload, cur_cpuload;
 158   struct rusage ru;
 159   GstClockTime tproc = G_GUINT64_CONSTANT (0);
 160   GstClockTime tthread = G_GUINT64_CONSTANT (0);
 161   GstClockTime dts, dtproc;
 162
 163 #ifdef HAVE_CLOCK_GETTIME
 164   {
 165     struct timespec now;
 166
 167     if (!clock_gettime (CLOCK_PROCESS_CPUTIME_ID, &now)) {
 168       tproc = GST_TIMESPEC_TO_TIME (now);
 169     } else {
 170       GST_WARNING_OBJECT (obj,
 171           "clock_gettime (CLOCK_PROCESS_CPUTIME_ID,...) failed: %s",
 172           g_strerror (errno));
 173       getrusage (RUSAGE_SELF, &ru);
 174       tproc =
 175           GST_TIMEVAL_TO_TIME (ru.ru_utime) + GST_TIMEVAL_TO_TIME (ru.ru_stime);
 176     }
 177
 178     /* cpu time per thread */
 179     if (!clock_gettime (CLOCK_THREAD_CPUTIME_ID, &now)) {
 180       tthread = GST_TIMESPEC_TO_TIME (now);
 181     } else {
 182       GST_WARNING_OBJECT (obj,
 183           "clock_gettime (CLOCK_THREAD_CPUTIME_ID,...) failed: %s",
 184           g_strerror (errno));
 185 #ifdef RUSAGE_THREAD
 186       getrusage (RUSAGE_THREAD, &ru);
 187       tthread =
 188           GST_TIMEVAL_TO_TIME (ru.ru_utime) + GST_TIMEVAL_TO_TIME (ru.ru_stime);
 189 #endif
 190     }
 191   }
 192 #else
 193   getrusage (RUSAGE_SELF, &ru);
 194   tproc = GST_TIMEVAL_TO_TIME (ru.ru_utime) + GST_TIMEVAL_TO_TIME (ru.ru_stime);
 195 #ifdef RUSAGE_THREAD
 196   getrusage (RUSAGE_THREAD, &ru);
 197   tthread =
 198       GST_TIMEVAL_TO_TIME (ru.ru_utime) + GST_TIMEVAL_TO_TIME (ru.ru_stime);
 199 #endif
 200 #endif
 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);
 206   }
 207   stats->tthread = tthread;
 208
 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
 211    * started.
 212    */
 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? */
 218     if (tproc > ts) {
 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;
 224     }
 225   }
 226   /* we always need to correct proc time */
 227   tproc -= self->tproc_base;
 228
 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
 235    */
 236   /* *INDENT-OFF* */
 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);
 244
 245   avg_cpuload = (guint) gst_util_uint64_scale (tproc / num_cpus,
 246       G_GINT64_CONSTANT (1000), ts);
 247   G_LOCK (_proc);
 248   update_trace_value (self->tvs_proc, ts, tproc, &dts, &dtproc);
 249   G_UNLOCK (_proc);
 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);
 254   /* *INDENT-ON* */
 255 }
 256
 257 /* tracer class */
 258
 259 static void
 260 gst_rusage_tracer_finalize (GObject * obj)
 261 {
 262   GstRUsageTracer *self = GST_RUSAGE_TRACER (obj);
 263
 264   g_hash_table_destroy (self->threads);
 265   free_trace_values (self->tvs_proc);
 266
 267   G_OBJECT_CLASS (parent_class)->finalize (obj);
 268 }
 269
 270 static void
 271 gst_rusage_tracer_class_init (GstRUsageTracerClass * klass)
 272 {
 273   GObjectClass *gobject_class = G_OBJECT_CLASS (klass);
 274
 275   gobject_class->finalize = gst_rusage_tracer_finalize;
 276
 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");
 281       num_cpus = 1;
 282     }
 283   }
 284   GST_DEBUG ("rusage: num_cpus=%ld", num_cpus);
 285
 286   /* announce trace formats */
 287   /* *INDENT-OFF* */
 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,
 292           NULL),
 293       "ts", GST_TYPE_STRUCTURE, gst_structure_new ("value",
 294           "type", G_TYPE_GTYPE, G_TYPE_UINT64,
 295           "description", G_TYPE_STRING, "event ts",
 296           NULL),
 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,
 303           NULL),
 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,
 309           NULL),
 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,
 316           NULL),
 317       NULL);
 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,
 322           NULL),
 323       "ts", GST_TYPE_STRUCTURE, gst_structure_new ("value",
 324           "type", G_TYPE_GTYPE, G_TYPE_UINT64,
 325           "description", G_TYPE_STRING, "event ts",
 326           NULL),
 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,
 333           NULL),
 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,
 339           NULL),
 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,
 346           NULL),
 347       NULL);
 348   /* *INDENT-ON* */
 349 }
 350
 351 static void
 352 gst_rusage_tracer_init (GstRUsageTracer * self)
 353 {
 354   GstTracer *tracer = GST_TRACER (self);
 355
 356   gst_tracing_register_hook (tracer, NULL, G_CALLBACK (do_stats));
 357
 358   self->threads = g_hash_table_new_full (NULL, NULL, NULL, free_thread_stats);
 359   self->tvs_proc = make_trace_values (GST_SECOND);
 360   self->main_thread_id = g_thread_self ();
 361
 362   GST_DEBUG ("rusage: main thread=%p", self->main_thread_id);
 363 }