From 018858980b4e0b40a689f10a7acedc7f4c7f1cc3 Mon Sep 17 00:00:00 2001 From: Stefan Sauer Date: Thu, 4 Sep 2014 10:11:52 +0200 Subject: [PATCH] rusage: announce the data format Rusage will now announce what is meassures and how it is logged. Use the new format in stats. Cleanup the the code and naming. --- plugins/tracers/gstrusage.c | 63 ++++++++++++++++++++++++++++++++++++++++++--- tools/gst-stats.c | 43 ++++++++++++++++--------------- 2 files changed, 81 insertions(+), 25 deletions(-) diff --git a/plugins/tracers/gstrusage.c b/plugins/tracers/gstrusage.c index f54f53a..71d6e4d 100644 --- a/plugins/tracers/gstrusage.c +++ b/plugins/tracers/gstrusage.c @@ -24,6 +24,10 @@ * * A tracing module that take rusage() snapshots and logs them. */ +/* TODO: log more items, cpuload is calculated as an aggregated value + * - in many cases a windowed value would be more interesting to see local + * cpu-load spikes + */ #ifdef HAVE_CONFIG_H # include "config.h" @@ -81,6 +85,46 @@ gst_rusage_tracer_init (GstRUsageTracer * self) main_thread_id = g_thread_self (); GST_DEBUG ("rusage: main thread=%p", main_thread_id); + + /* announce trace formats */ + /* *INDENT-OFF* */ + gst_tracer_log_trace (gst_structure_new ("thread-rusage.class", + "thread-id", GST_TYPE_STRUCTURE, gst_structure_new ("scope", + "related-to", G_TYPE_STRING, "thread", // use genum + NULL), + "cpuload", GST_TYPE_STRUCTURE, gst_structure_new ("value", + "type", G_TYPE_GTYPE, G_TYPE_UINT, + "description", G_TYPE_STRING, "cpu usage per thread", + "flags", G_TYPE_STRING, "aggregated", // use gflags + "min", G_TYPE_UINT, 0, "max", G_TYPE_UINT, 100, + NULL), + "time", GST_TYPE_STRUCTURE, gst_structure_new ("value", + "type", G_TYPE_GTYPE, G_TYPE_UINT64, + "description", G_TYPE_STRING, "time spent in thread", + "flags", G_TYPE_STRING, "aggregated", // use gflags + "min", G_TYPE_UINT64, G_GUINT64_CONSTANT (0), + "max", G_TYPE_UINT64, G_MAXUINT64, + NULL), + NULL)); + gst_tracer_log_trace (gst_structure_new ("proc-rusage.class", + "thread-id", GST_TYPE_STRUCTURE, gst_structure_new ("scope", + "related-to", G_TYPE_STRING, "process", // use genum + NULL), + "cpuload", GST_TYPE_STRUCTURE, gst_structure_new ("value", + "type", G_TYPE_GTYPE, G_TYPE_UINT, + "description", G_TYPE_STRING, "cpu usage per process", + "flags", G_TYPE_STRING, "aggregated", // use gflags + "min", G_TYPE_UINT, 0, "max", G_TYPE_UINT, 100, + NULL), + "time", GST_TYPE_STRUCTURE, gst_structure_new ("value", + "type", G_TYPE_GTYPE, G_TYPE_UINT64, + "description", G_TYPE_STRING, "time spent in process", + "flags", G_TYPE_STRING, "aggregated", // use gflags + "min", G_TYPE_UINT64, G_GUINT64_CONSTANT (0), + "max", G_TYPE_UINT64, G_MAXUINT64, + NULL), + NULL)); + /* *INDENT-ON* */ } static void @@ -161,9 +205,20 @@ gst_rusage_tracer_invoke (GstTracer * obj, GstTracerHookId hid, * cpufreq-selector -g performance * cpufreq-selector -g ondemand */ + /* *INDENT-OFF* */ + cpuload = (guint) gst_util_uint64_scale (stats->tthread, + G_GINT64_CONSTANT (100), ts); + gst_tracer_log_trace (gst_structure_new ("thread-rusage", + "ts", G_TYPE_UINT64, ts, + "thread-id", G_TYPE_UINT, GPOINTER_TO_UINT (thread_id), + "cpuload", G_TYPE_UINT, cpuload, + "time", G_TYPE_UINT64, stats->tthread, + NULL)); cpuload = (guint) gst_util_uint64_scale (tproc, G_GINT64_CONSTANT (100), ts); - gst_tracer_log_trace (gst_structure_new ("rusage", "ts", G_TYPE_UINT64, ts, "thread-id", G_TYPE_UINT, GPOINTER_TO_UINT (thread_id), "cpuload", G_TYPE_UINT, cpuload, /* cpu usage per thread - FIXME: not used in gst-stats */ - "thread-time", G_TYPE_UINT64, stats->tthread, /* time spent in thread */ - "proc-time", G_TYPE_UINT64, tproc, /* time spent in process */ - NULL)); + gst_tracer_log_trace (gst_structure_new ("proc-rusage", + "ts", G_TYPE_UINT64, ts, + "cpuload", G_TYPE_UINT, cpuload, + "time", G_TYPE_UINT64, tproc, + NULL)); + /* *INDENT-ON* */ } diff --git a/tools/gst-stats.c b/tools/gst-stats.c index b2a6f32..bc65cbd 100644 --- a/tools/gst-stats.c +++ b/tools/gst-stats.c @@ -41,7 +41,7 @@ static guint64 num_buffers = 0, num_events = 0, num_messages = 0, num_queries = 0; static guint num_elements = 0, num_bins = 0, num_pads = 0, num_ghostpads = 0; static GstClockTime last_ts = G_GUINT64_CONSTANT (0); -static GstClockTime tproc = G_GUINT64_CONSTANT (0); +static guint total_cpuload = 0; typedef struct { @@ -76,8 +76,6 @@ typedef struct guint num_events, num_messages, num_queries; /* first activity on the element */ GstClockTime first_ts, last_ts; - /* time spend in this element */ - GstClockTime tthread; /* hierarchy */ guint parent_ix; } GstElementStats; @@ -86,6 +84,7 @@ typedef struct { /* time spend in this thread */ GstClockTime tthread; + guint cpuload; } GstThreadStats; /* stats helper */ @@ -378,21 +377,31 @@ do_query_stats (GstStructure * s) } static void -do_rusage_stats (GstStructure * s) +do_thread_rusage_stats (GstStructure * s) { guint64 ts, tthread; - guint thread_id; + guint thread_id, cpuload; GstThreadStats *thread_stats; gst_structure_get (s, "ts", G_TYPE_UINT64, &ts, "thread-id", G_TYPE_UINT, &thread_id, - "thread-time", G_TYPE_UINT64, &tthread, - "proc-time", G_TYPE_UINT64, &tproc, NULL); + "cpuload", G_TYPE_UINT, &cpuload, "time", G_TYPE_UINT64, &tthread, NULL); thread_stats = get_thread_stats (thread_id); + thread_stats->cpuload = cpuload; thread_stats->tthread = tthread; last_ts = MAX (last_ts, ts); } +static void +do_proc_rusage_stats (GstStructure * s) +{ + guint64 ts; + + gst_structure_get (s, "ts", G_TYPE_UINT64, &ts, + "cpuload", G_TYPE_UINT, &total_cpuload, NULL); + last_ts = MAX (last_ts, ts); +} + /* reporting */ static gint @@ -451,19 +460,14 @@ print_thread_stats (gpointer key, gpointer value, gpointer user_data) GSList *list = user_data; GSList *node = g_slist_find_custom (list, key, find_pad_stats_for_thread); GstThreadStats *stats = (GstThreadStats *) value; - guint cpuload; /* skip stats if there are no pads for that thread (e.g. a pipeline) */ if (!node) return; - cpuload = - (guint) gst_util_uint64_scale (stats->tthread, G_GINT64_CONSTANT (100), - last_ts); - printf ("Thread %p Statistics:\n", key); printf (" Time: %" GST_TIME_FORMAT "\n", GST_TIME_ARGS (stats->tthread)); - printf (" Avg CPU load: %u %%\n", cpuload); + printf (" Avg CPU load: %u %%\n", stats->cpuload); puts (" Pad Statistics:"); g_slist_foreach (node, print_pad_stats, key); @@ -679,7 +683,6 @@ static void print_stats (void) { guint num_threads = g_hash_table_size (threads); - guint64 total_cpuload = 0; /* print overall stats */ puts ("\nOverall Statistics:"); @@ -693,11 +696,7 @@ print_stats (void) printf ("Number of Message sent: %" G_GUINT64_FORMAT "\n", num_messages); printf ("Number of Queries sent: %" G_GUINT64_FORMAT "\n", num_queries); printf ("Time: %" GST_TIME_FORMAT "\n", GST_TIME_ARGS (last_ts)); - if (tproc) { - total_cpuload = gst_util_uint64_scale (tproc, - G_GINT64_CONSTANT (100), last_ts); - printf ("Avg CPU load: %u %%\n", (guint) total_cpuload); - } + printf ("Avg CPU load: %u %%\n", (guint) total_cpuload); puts (""); /* thread stats */ @@ -800,8 +799,10 @@ collect_stats (const gchar * filename) do_message_stats (s); } else if (!strcmp (name, "query")) { do_query_stats (s); - } else if (!strcmp (name, "rusage")) { - do_rusage_stats (s); + } else if (!strcmp (name, "thread-rusage")) { + do_thread_rusage_stats (s); + } else if (!strcmp (name, "proc-rusage")) { + do_proc_rusage_stats (s); } else { GST_WARNING ("unknown log entry: '%s'", data); } -- 2.7.4