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 /* TODO: log more items, cpuload is calculated as an aggregated value
  28  * - in many cases a windowed value would be more interesting to see local
  29  *   cpu-load spikes
  30  */
  31
  32 #ifdef HAVE_CONFIG_H
  33 #  include "config.h"
  34 #endif
  35
  36 #include "gstrusage.h"
  37
  38 #ifdef HAVE_SYS_RESOURCE_H
  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 #define _do_init \
  46     GST_DEBUG_CATEGORY_INIT (gst_rusage_debug, "rusage", 0, "rusage tracer");
  47 #define gst_rusage_tracer_parent_class parent_class
  48 G_DEFINE_TYPE_WITH_CODE (GstRUsageTracer, gst_rusage_tracer, GST_TYPE_TRACER,
  49     _do_init);
  50
  51 /* for ts calibration */
  52 static gpointer main_thread_id = NULL;
  53 static guint64 tproc_base = G_GINT64_CONSTANT (0);
  54
  55 typedef struct
  56 {
  57   /* time spend in this thread */
  58   GstClockTime tthread;
  59 } GstThreadStats;
  60
  61 static void gst_rusage_tracer_invoke (GstTracer * self, GstTracerHookId id,
  62     GstTracerMessageId mid, va_list var_args);
  63
  64 /* data helper */
  65
  66 static void
  67 free_thread_stats (gpointer data)
  68 {
  69   g_slice_free (GstThreadStats, data);
  70 }
  71
  72 static void
  73 gst_rusage_tracer_class_init (GstRUsageTracerClass * klass)
  74 {
  75   GstTracerClass *gst_tracer_class = GST_TRACER_CLASS (klass);
  76
  77   gst_tracer_class->invoke = gst_rusage_tracer_invoke;
  78 }
  79
  80 static void
  81 gst_rusage_tracer_init (GstRUsageTracer * self)
  82 {
  83   g_object_set (self, "mask", GST_TRACER_HOOK_ALL, NULL);
  84   self->threads = g_hash_table_new_full (NULL, NULL, NULL, free_thread_stats);
  85
  86   main_thread_id = g_thread_self ();
  87   GST_DEBUG ("rusage: main thread=%p", main_thread_id);
  88
  89   /* announce trace formats */
  90   /* *INDENT-OFF* */
  91   gst_tracer_log_trace (gst_structure_new ("thread-rusage.class",
  92       "thread-id", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
  93           "related-to", G_TYPE_STRING, "thread",  // use genum
  94           NULL),
  95       "cpuload", GST_TYPE_STRUCTURE, gst_structure_new ("value",
  96           "type", G_TYPE_GTYPE, G_TYPE_UINT,
  97           "description", G_TYPE_STRING, "cpu usage per thread",
  98           "flags", G_TYPE_STRING, "aggregated",  // use gflags
  99           "min", G_TYPE_UINT, 0, "max", G_TYPE_UINT, 100,
 100           NULL),
 101       "time", GST_TYPE_STRUCTURE, gst_structure_new ("value",
 102           "type", G_TYPE_GTYPE, G_TYPE_UINT64,
 103           "description", G_TYPE_STRING, "time spent in thread",
 104           "flags", G_TYPE_STRING, "aggregated",  // use gflags
 105           "min", G_TYPE_UINT64, G_GUINT64_CONSTANT (0),
 106           "max", G_TYPE_UINT64, G_MAXUINT64,
 107           NULL),
 108       NULL));
 109   gst_tracer_log_trace (gst_structure_new ("proc-rusage.class",
 110       "thread-id", GST_TYPE_STRUCTURE, gst_structure_new ("scope",
 111           "related-to", G_TYPE_STRING, "process",  // use genum
 112           NULL),
 113       "cpuload", GST_TYPE_STRUCTURE, gst_structure_new ("value",
 114           "type", G_TYPE_GTYPE, G_TYPE_UINT,
 115           "description", G_TYPE_STRING, "cpu usage per process",
 116           "flags", G_TYPE_STRING, "aggregated",  // use gflags
 117           "min", G_TYPE_UINT, 0, "max", G_TYPE_UINT, 100,
 118           NULL),
 119       "time", GST_TYPE_STRUCTURE, gst_structure_new ("value",
 120           "type", G_TYPE_GTYPE, G_TYPE_UINT64,
 121           "description", G_TYPE_STRING, "time spent in process",
 122           "flags", G_TYPE_STRING, "aggregated",  // use gflags
 123           "min", G_TYPE_UINT64, G_GUINT64_CONSTANT (0),
 124           "max", G_TYPE_UINT64, G_MAXUINT64,
 125           NULL),
 126       NULL));
 127   /* *INDENT-ON* */
 128 }
 129
 130 static void
 131 gst_rusage_tracer_invoke (GstTracer * obj, GstTracerHookId hid,
 132     GstTracerMessageId mid, va_list var_args)
 133 {
 134   GstRUsageTracer *self = GST_RUSAGE_TRACER_CAST (obj);
 135   guint64 ts = va_arg (var_args, guint64);
 136   GstThreadStats *stats;
 137   gpointer thread_id = g_thread_self ();
 138   guint cpuload = 0;
 139   struct rusage ru;
 140   GstClockTime tproc = G_GUINT64_CONSTANT (0);
 141
 142   // FIXME(ensonic): not threadsafe
 143   static GstClockTime last_ts = G_GUINT64_CONSTANT (0);
 144
 145   getrusage (RUSAGE_SELF, &ru);
 146
 147   /* get stats record for current thread */
 148   if (!(stats = g_hash_table_lookup (self->threads, thread_id))) {
 149     stats = g_slice_new0 (GstThreadStats);
 150     g_hash_table_insert (self->threads, thread_id, stats);
 151   }
 152 #ifdef HAVE_CLOCK_GETTIME
 153   {
 154     struct timespec now;
 155
 156     if (!clock_gettime (CLOCK_PROCESS_CPUTIME_ID, &now)) {
 157       tproc = GST_TIMESPEC_TO_TIME (now);
 158     } else {
 159       GST_WARNING ("clock_gettime (CLOCK_PROCESS_CPUTIME_ID,...) failed.");
 160       tproc =
 161           GST_TIMEVAL_TO_TIME (ru.ru_utime) + GST_TIMEVAL_TO_TIME (ru.ru_stime);
 162     }
 163
 164     /* cpu time per thread */
 165     if (!clock_gettime (CLOCK_THREAD_CPUTIME_ID, &now)) {
 166       stats->tthread = GST_TIMESPEC_TO_TIME (now);
 167     } else {
 168       GST_WARNING ("clock_gettime (CLOCK_THREAD_CPUTIME_ID,...) failed.");
 169       stats->tthread += GST_CLOCK_DIFF (last_ts, ts);
 170     }
 171   }
 172 #else
 173   tproc = GST_TIMEVAL_TO_TIME (ru.ru_utime) + GST_TIMEVAL_TO_TIME (ru.ru_stime);
 174   /* crude way to meassure time spend in which thread */
 175   stats->tthread += GST_CLOCK_DIFF (last_ts, ts);
 176 #endif
 177
 178   /* remember last timestamp for fallback calculations */
 179   last_ts = ts;
 180
 181   /* Calibrate ts for the process and main thread. For tthread[main] and tproc
 182    * the time is larger than ts, as our base-ts is taken after the process has
 183    * started.
 184    */
 185   if (G_UNLIKELY (thread_id == main_thread_id)) {
 186     main_thread_id = NULL;
 187     /* when the registry gets updated, the tproc is less than the debug time ? */
 188     /* TODO(ensonic): we still see cases where tproc overtakes ts, especially
 189      * when with sync=false, can this be due to multiple cores in use? */
 190     if (tproc > ts) {
 191       tproc_base = tproc - ts;
 192       GST_DEBUG ("rusage: calibrating by %" G_GUINT64_FORMAT ", thread: %"
 193           G_GUINT64_FORMAT ", proc: %" G_GUINT64_FORMAT,
 194           tproc_base, stats->tthread, tproc);
 195       stats->tthread -= tproc_base;
 196     }
 197   }
 198   /* we always need to corect proc time */
 199   tproc -= tproc_base;
 200
 201   /* FIXME: how can we take cpu-frequency scaling into account?
 202    * - looking at /sys/devices/system/cpu/cpu0/cpufreq/
 203    *   scale_factor=scaling_max_freq/scaling_cur_freq
 204    * - as a workaround we can switch it via /sys/devices/system/cpu/cpu0/cpufreq/scaling_governor
 205    *   cpufreq-selector -g performance
 206    *   cpufreq-selector -g ondemand
 207    */
 208   /* *INDENT-OFF* */
 209   cpuload = (guint) gst_util_uint64_scale (stats->tthread,
 210       G_GINT64_CONSTANT (100), ts);
 211   gst_tracer_log_trace (gst_structure_new ("thread-rusage",
 212       "ts", G_TYPE_UINT64, ts,
 213       "thread-id", G_TYPE_UINT, GPOINTER_TO_UINT (thread_id),
 214       "cpuload", G_TYPE_UINT, cpuload,
 215       "time", G_TYPE_UINT64, stats->tthread,
 216       NULL));
 217   cpuload = (guint) gst_util_uint64_scale (tproc, G_GINT64_CONSTANT (100), ts);
 218   gst_tracer_log_trace (gst_structure_new ("proc-rusage",
 219       "ts", G_TYPE_UINT64, ts,
 220       "cpuload", G_TYPE_UINT, cpuload,
 221       "time", G_TYPE_UINT64, tproc,
 222       NULL));
 223   /* *INDENT-ON* */
 224 }