From c972ff3ab40007578da27d5087b9591ac843257d Mon Sep 17 00:00:00 2001 From: "Owen W. Taylor" Date: Tue, 11 May 2010 15:48:47 -0400 Subject: [PATCH] Add "statistics" functionality to ShellPerfLog Add a facility for defining and recording numeric statistics as performance events shell_perf_log_define_statistic() Define a statistic and the corresponding event type shell_perf_log_update_statistic_[ix]() - Update the stored statistic value shell_perf_log_add_statistics_callback() Add a function called before collecting statistics shell_perf_collect_statistics() Update statistics and record events for them In addition to the explicit collection, statistics are recorded at a periodic interval (currently 5s) https://bugzilla.gnome.org/show_bug.cgi?id=618189 --- src/shell-perf-log.c | 299 ++++++++++++++++++++++++++++++++++++++++++- src/shell-perf-log.h | 22 ++++ 2 files changed, 319 insertions(+), 2 deletions(-) diff --git a/src/shell-perf-log.c b/src/shell-perf-log.c index f84aa232c..5c596825d 100644 --- a/src/shell-perf-log.c +++ b/src/shell-perf-log.c @@ -7,6 +7,9 @@ #include "shell-perf-log.h" typedef struct _ShellPerfEvent ShellPerfEvent; +typedef struct _ShellPerfStatistic ShellPerfStatistic; +typedef struct _ShellPerfStatisticsClosure ShellPerfStatisticsClosure; +typedef union _ShellPerfStatisticValue ShellPerfStatisticValue; typedef struct _ShellPerfBlock ShellPerfBlock; /** @@ -35,11 +38,18 @@ struct _ShellPerfLog GPtrArray *events; GHashTable *events_by_name; + GPtrArray *statistics; + GHashTable *statistics_by_name; + + GPtrArray *statistics_closures; + GQueue *blocks; gint64 start_time; gint64 last_time; + guint statistics_timeout_id; + guint enabled : 1; }; @@ -56,6 +66,30 @@ struct _ShellPerfEvent char *signature; }; +union _ShellPerfStatisticValue +{ + int i; + gint64 x; +}; + +struct _ShellPerfStatistic +{ + ShellPerfEvent *event; + + ShellPerfStatisticValue current_value; + ShellPerfStatisticValue last_value; + + guint initialized : 1; + guint recorded : 1; +}; + +struct _ShellPerfStatisticsClosure +{ + ShellPerfStatisticsCallback callback; + gpointer user_data; + GDestroyNotify notify; +}; + /* The events in the log are stored in a linked list of fixed size * blocks. * @@ -75,9 +109,16 @@ struct _ShellPerfBlock guchar buffer[BLOCK_SIZE]; }; +/* Number of milliseconds between periodic statistics collection when + * events are enabled. Statistics collection can also be explicitly + * triggered. + */ +#define STATISTIC_COLLECTION_INTERVAL_MS 5000 + /* Builtin events */ enum { - EVENT_SET_TIME + EVENT_SET_TIME, + EVENT_STATISTICS_COLLECTED }; G_DEFINE_TYPE(ShellPerfLog, shell_perf_log, G_TYPE_OBJECT); @@ -97,6 +138,9 @@ shell_perf_log_init (ShellPerfLog *perf_log) { perf_log->events = g_ptr_array_new (); perf_log->events_by_name = g_hash_table_new (g_str_hash, g_str_equal); + perf_log->statistics = g_ptr_array_new (); + perf_log->statistics_by_name = g_hash_table_new (g_str_hash, g_str_equal); + perf_log->statistics_closures = g_ptr_array_new (); perf_log->blocks = g_queue_new (); /* This event is used when timestamp deltas are greater than @@ -106,6 +150,20 @@ shell_perf_log_init (ShellPerfLog *perf_log) shell_perf_log_define_event (perf_log, "perf.setTime", "", "x"); g_assert (perf_log->events->len == EVENT_SET_TIME + 1); + /* The purpose of this event is to allow us to optimize out storing + * statistics that haven't changed. We want to mark every time we + * collect statistics even if we don't record any individual + * statistics so that we can distinguish sudden changes from gradual changes. + * + * The argument is the number of microseconds that statistics collection + * took; we record that since statistics collection could start taking + * significant time if we do things like grub around in /proc/ + */ + shell_perf_log_define_event (perf_log, "perf.statisticsCollected", + "Finished collecting statistics", + "x"); + g_assert (perf_log->events->len == EVENT_STATISTICS_COLLECTED + 1); + perf_log->start_time = perf_log->last_time = get_time(); } @@ -133,6 +191,16 @@ shell_perf_log_get_default (void) return perf_log; } +static gboolean +statistics_timeout (gpointer data) +{ + ShellPerfLog *perf_log = data; + + shell_perf_log_collect_statistics (perf_log); + + return TRUE; +} + /** * shell_perf_log_set_enabled: * @perf_log: a #ShellPerfLog @@ -146,7 +214,22 @@ shell_perf_log_set_enabled (ShellPerfLog *perf_log, { enabled = enabled != FALSE; - perf_log->enabled = enabled; + if (enabled != perf_log->enabled) + { + perf_log->enabled = enabled; + + if (enabled) + { + perf_log->statistics_timeout_id = g_timeout_add (STATISTIC_COLLECTION_INTERVAL_MS, + statistics_timeout, + perf_log); + } + else + { + g_source_remove (perf_log->statistics_timeout_id); + perf_log->statistics_timeout_id = 0; + } + } } static ShellPerfEvent * @@ -381,6 +464,218 @@ shell_perf_log_event_s (ShellPerfLog *perf_log, (const guchar *)arg, strlen (arg) + 1); } +/** + * shell_perf_log_define_statistic: + * @name: name of the statistic and of the corresponding event. + * This should follow the same guidelines as for shell_perf_log_define_event() + * @description: human readable description of the statistic. + * @signature: The type of the data stored for statistic. Must + * currently be 'i' or 'x'. + * + * Defines a statistic. A statistic is a numeric value that is stored + * by the performance log and recorded periodically or when + * shell_perf_log_collect_statistics() is called explicitly. + * + * Code that defines a statistic should update it by calling + * the update function for the particular data type of the statistic, + * such as shell_perf_log_update_statistic_i(). This can be done + * at any time, but would normally done inside a function registered + * with shell_perf_log_add_statistics_callback(). These functions + * are called immediately before statistics are recorded. + */ +void +shell_perf_log_define_statistic (ShellPerfLog *perf_log, + const char *name, + const char *description, + const char *signature) +{ + ShellPerfEvent *event; + ShellPerfStatistic *statistic; + + if (strcmp (signature, "i") != 0 && + strcmp (signature, "x") != 0) + { + g_warning ("Only supported statistic signatures are 'i' and 'x'\n"); + return; + } + + event = define_event (perf_log, name, description, signature); + if (event == NULL) + return; + + statistic = g_slice_new (ShellPerfStatistic); + statistic->event = event; + + statistic->initialized = FALSE; + statistic->recorded = FALSE; + + g_ptr_array_add (perf_log->statistics, statistic); + g_hash_table_insert (perf_log->statistics_by_name, event->name, statistic); +} + +static ShellPerfStatistic * +lookup_statistic (ShellPerfLog *perf_log, + const char *name, + const char *signature) +{ + ShellPerfStatistic *statistic = g_hash_table_lookup (perf_log->statistics_by_name, name); + + if (G_UNLIKELY (statistic == NULL)) + { + g_warning ("Unknown statistic '%s'\n", name); + return NULL; + } + + if (G_UNLIKELY (strcmp (statistic->event->signature, signature) != 0)) + { + g_warning ("Statistic '%s'; defined with signature '%s', used with '%s'\n", + name, statistic->event->signature, signature); + return NULL; + } + + return statistic; +} + +/** + * shell_perf_log_update_statistic_i: + * @perf_log: a #ShellPerfLog + * @name: name of the statistic + * @value: new value for the statistic + * + * Updates the current value of an 32-bit integer statistic. + */ +void +shell_perf_log_update_statistic_i (ShellPerfLog *perf_log, + const char *name, + gint32 value) +{ + ShellPerfStatistic *statistic; + + statistic = lookup_statistic (perf_log, name, "i"); + if (G_UNLIKELY (statistic == NULL)) + return; + + statistic->current_value.i = value; + statistic->initialized = TRUE; +} + +/** + * shell_perf_log_update_statistic_x: + * @perf_log: a #ShellPerfLog + * @name: name of the statistic + * @value: new value for the statistic + * + * Updates the current value of an 64-bit integer statistic. + */ +void +shell_perf_log_update_statistic_x (ShellPerfLog *perf_log, + const char *name, + gint64 value) +{ + ShellPerfStatistic *statistic; + + statistic = lookup_statistic (perf_log, name, "x"); + if (G_UNLIKELY (statistic == NULL)) + return; + + statistic->current_value.x = value; + statistic->initialized = TRUE; +} + +/** + * shell_perf_log_add statistics_callback: + * @perf_log: a #ShellPerfLog + * @callback: function to call before recording statistics + * @user_data: data to pass to @callback + * @notify: function to call when @user_data is no longer needed + * + * Adds a function that will be called before statistics are recorded. + * The function would typically compute one or more statistics values + * and call a function such as shell_perf_log_update_statistic_i() + * to update the value that will be recorded. + */ +void +shell_perf_log_add_statistics_callback (ShellPerfLog *perf_log, + ShellPerfStatisticsCallback callback, + gpointer user_data, + GDestroyNotify notify) +{ + ShellPerfStatisticsClosure *closure = g_slice_new (ShellPerfStatisticsClosure); + + closure->callback = callback; + closure->user_data = user_data; + closure->notify = notify; + + g_ptr_array_add (perf_log->statistics_closures, closure); +} + +/** + * shell_perf_log_collect_statistics: + * @perf_log: a #ShellPerfLog + * + * Calls all the update functions added with + * shell_perf_log_add_statistics_callback() and then records events + * for all statistics, followed by a perf.statisticsCollected event. + */ +void +shell_perf_log_collect_statistics (ShellPerfLog *perf_log) +{ + gint64 event_time = get_time (); + gint64 collection_time; + int i; + + if (!perf_log->enabled) + return; + + for (i = 0; i < perf_log->statistics_closures->len; i++) + { + ShellPerfStatisticsClosure *closure; + + closure = g_ptr_array_index (perf_log->statistics_closures, i); + closure->callback (perf_log, closure->user_data); + } + + collection_time = get_time() - event_time; + + for (i = 0; i < perf_log->statistics->len; i++) + { + ShellPerfStatistic *statistic = g_ptr_array_index (perf_log->statistics, i); + + if (!statistic->initialized) + continue; + + switch (statistic->event->signature[0]) + { + case 'i': + if (!statistic->recorded || + statistic->current_value.i != statistic->last_value.i) + { + record_event (perf_log, event_time, statistic->event, + (const guchar *)&statistic->current_value.i, + sizeof (gint32)); + statistic->last_value.i = statistic->current_value.i; + statistic->recorded = TRUE; + } + break; + case 'x': + if (!statistic->recorded || + statistic->current_value.x != statistic->last_value.x) + { + record_event (perf_log, event_time, statistic->event, + (const guchar *)&statistic->current_value.x, + sizeof (gint64)); + statistic->last_value.x = statistic->current_value.x; + statistic->recorded = TRUE; + } + break; + } + } + + record_event (perf_log, event_time, + g_ptr_array_index (perf_log->events, EVENT_STATISTICS_COLLECTED), + (const guchar *)&collection_time, sizeof (gint64)); +} + /** * shell_perf_log_replay: * @perf_log: a #ShellPerfLog diff --git a/src/shell-perf-log.h b/src/shell-perf-log.h index e1ccdf2bb..b566fad96 100644 --- a/src/shell-perf-log.h +++ b/src/shell-perf-log.h @@ -39,6 +39,28 @@ void shell_perf_log_event_s (ShellPerfLog *perf_log, const char *name, const char *arg); +void shell_perf_log_define_statistic (ShellPerfLog *perf_log, + const char *name, + const char *description, + const char *signature); + +void shell_perf_log_update_statistic_i (ShellPerfLog *perf_log, + const char *name, + int value); +void shell_perf_log_update_statistic_x (ShellPerfLog *perf_log, + const char *name, + gint64 value); + +typedef void (*ShellPerfStatisticsCallback) (ShellPerfLog *perf_log, + gpointer data); + +void shell_perf_log_add_statistics_callback (ShellPerfLog *perf_log, + ShellPerfStatisticsCallback callback, + gpointer user_data, + GDestroyNotify notify); + +void shell_perf_log_collect_statistics (ShellPerfLog *perf_log); + typedef void (*ShellPerfReplayFunction) (gint64 time, const char *name, const char *signature,