/* -*- Mode: C; tab-width: 8; indent-tabs-mode: t; c-basic-offset: 8 -*- * * Copyright (C) 2013-2015 Richard Hughes * * SPDX-License-Identifier: LGPL-2.1+ */ #include "config.h" #include #include "as-profile.h" struct _AsProfile { GObject parent_instance; GPtrArray *current; GPtrArray *archived; GMutex mutex; GThread *unthreaded; guint autodump_id; guint autoprune_duration; guint duration_min; }; typedef struct { gchar *id; gint64 time_start; gint64 time_stop; gboolean threaded; } AsProfileItem; G_DEFINE_TYPE (AsProfile, as_profile, G_TYPE_OBJECT) struct _AsProfileTask { AsProfile *profile; gchar *id; }; static gpointer as_profile_object = NULL; static void as_profile_item_free (AsProfileItem *item) { g_free (item->id); g_free (item); } static AsProfileItem * as_profile_item_find (GPtrArray *array, const gchar *id) { AsProfileItem *tmp; guint i; g_return_val_if_fail (id != NULL, NULL); for (i = 0; i < array->len; i++) { tmp = g_ptr_array_index (array, i); if (g_strcmp0 (tmp->id, id) == 0) return tmp; } return NULL; } /** * as_profile_task_set_threaded: * @ptask: A #AsProfileTask * @threaded: boolean * * Sets if the profile task is threaded so it can be printed differently in * in the profile output. * * Since: 0.6.5 **/ void as_profile_task_set_threaded (AsProfileTask *ptask, gboolean threaded) { AsProfileItem *item; g_autoptr(GMutexLocker) locker = g_mutex_locker_new (&ptask->profile->mutex); item = as_profile_item_find (ptask->profile->current, ptask->id); if (item == NULL) return; item->threaded = threaded; } static void as_profile_prune_safe (AsProfile *profile, guint duration) { gint64 now; guint i; g_autoptr(GPtrArray) removal = g_ptr_array_new (); /* find all events older than duration */ now = g_get_real_time () / 1000; for (i = 0; i < profile->archived->len; i++) { AsProfileItem *item = g_ptr_array_index (profile->archived, i); if (now - item->time_start / 1000 > duration) g_ptr_array_add (removal, item); } /* remove each one */ for (i = 0; i < removal->len; i++) { AsProfileItem *item = g_ptr_array_index (removal, i); g_ptr_array_remove (profile->archived, item); } } static gint as_profile_sort_cb (gconstpointer a, gconstpointer b) { AsProfileItem *item_a = *((AsProfileItem **) a); AsProfileItem *item_b = *((AsProfileItem **) b); if (item_a->time_start < item_b->time_start) return -1; if (item_a->time_start > item_b->time_start) return 1; return 0; } static const gchar * as_profile_get_item_printable (AsProfileItem *item) { if (item->threaded) return "\033[1m#\033[0m"; return "#"; } static void as_profile_dump_safe (AsProfile *profile) { AsProfileItem *item; gint64 time_start = G_MAXINT64; gint64 time_stop = 0; gint64 time_ms; guint console_width = 86; guint i; guint j; gdouble scale; guint bar_offset; guint bar_length; /* nothing to show */ if (profile->archived->len == 0) return; /* get the start and end times */ for (i = 0; i < profile->archived->len; i++) { item = g_ptr_array_index (profile->archived, i); if (item->time_start < time_start) time_start = item->time_start; if (item->time_stop > time_stop) time_stop = item->time_stop; } scale = (gdouble) console_width / (gdouble) ((time_stop - time_start) / 1000); /* sort the list */ g_ptr_array_sort (profile->archived, as_profile_sort_cb); /* dump a list of what happened when */ for (i = 0; i < profile->archived->len; i++) { const gchar *printable; item = g_ptr_array_index (profile->archived, i); time_ms = (item->time_stop - item->time_start) / 1000; if (time_ms < profile->duration_min) continue; /* print a timechart of what we've done */ bar_offset = (guint) (scale * (gdouble) (item->time_start - time_start) / 1000); for (j = 0; j < bar_offset; j++) g_printerr (" "); bar_length = (guint) (scale * (gdouble) time_ms); if (bar_length == 0) bar_length = 1; printable = as_profile_get_item_printable (item); for (j = 0; j < bar_length; j++) g_printerr ("%s", printable); for (j = bar_offset + bar_length; j < console_width + 1; j++) g_printerr (" "); g_printerr ("@%04" G_GINT64_FORMAT "ms ", (item->time_stop - time_start) / 1000); g_printerr ("%s %" G_GINT64_FORMAT "ms\n", item->id, time_ms); } /* not all complete */ if (profile->current->len > 0) { for (i = 0; i < profile->current->len; i++) { item = g_ptr_array_index (profile->current, i); item->time_stop = g_get_real_time (); for (j = 0; j < console_width; j++) g_print ("$"); time_ms = (item->time_stop - item->time_start) / 1000; g_printerr (" @????ms %s %" G_GINT64_FORMAT "ms\n", item->id, time_ms); } } } /** * as_profile_start: * @profile: A #AsProfile * @fmt: Format string * @...: varargs * * Starts profiling a section of code. * * Since: 0.2.2 * * Returns: A #AsProfileTask, free with as_profile_task_free() **/ AsProfileTask * as_profile_start (AsProfile *profile, const gchar *fmt, ...) { va_list args; g_autofree gchar *tmp = NULL; va_start (args, fmt); tmp = g_strdup_vprintf (fmt, args); va_end (args); return as_profile_start_literal (profile, tmp); } /** * as_profile_start_literal: * @profile: A #AsProfile * @id: ID string * * Starts profiling a section of code. * * Since: 0.2.2 * * Returns: A #AsProfileTask, free with as_profile_task_free() **/ AsProfileTask * as_profile_start_literal (AsProfile *profile, const gchar *id) { GThread *self; AsProfileItem *item; AsProfileTask *ptask = NULL; g_autofree gchar *id_thr = NULL; g_autoptr(GMutexLocker) locker = g_mutex_locker_new (&profile->mutex); g_return_val_if_fail (AS_IS_PROFILE (profile), NULL); g_return_val_if_fail (id != NULL, NULL); /* autoprune old data */ if (profile->autoprune_duration != 0) as_profile_prune_safe (profile, profile->autoprune_duration); /* only use the thread ID when not using the main thread */ self = g_thread_self (); if (self != profile->unthreaded) { id_thr = g_strdup_printf ("%p~%s", self, id); } else { id_thr = g_strdup (id); } /* already started */ item = as_profile_item_find (profile->current, id_thr); if (item != NULL) { as_profile_dump_safe (profile); g_warning ("Already a started task for %s", id_thr); return NULL; } /* add new item */ item = g_new0 (AsProfileItem, 1); item->id = g_strdup (id_thr); item->time_start = g_get_real_time (); g_ptr_array_add (profile->current, item); g_debug ("run %s", id_thr); /* create token */ ptask = g_new0 (AsProfileTask, 1); ptask->profile = g_object_ref (profile); ptask->id = g_strdup (id); return ptask; } static void as_profile_task_free_internal (AsProfile *profile, const gchar *id) { GThread *self; AsProfileItem *item; gdouble elapsed_ms; g_autofree gchar *id_thr = NULL; g_autoptr(GMutexLocker) locker = g_mutex_locker_new (&profile->mutex); g_return_if_fail (AS_IS_PROFILE (profile)); g_return_if_fail (id != NULL); /* only use the thread ID when not using the main thread */ self = g_thread_self (); if (self != profile->unthreaded) { id_thr = g_strdup_printf ("%p~%s", self, id); } else { id_thr = g_strdup (id); } /* already started */ item = as_profile_item_find (profile->current, id_thr); if (item == NULL) { g_warning ("Not already a started task for %s", id_thr); return; } /* debug */ elapsed_ms = (gdouble) (item->time_stop - item->time_start) / 1000; if (elapsed_ms > 5) g_debug ("%s took %.0fms", id_thr, elapsed_ms); /* update */ item->time_stop = g_get_real_time (); /* move to archive */ g_ptr_array_remove (profile->current, item); g_ptr_array_add (profile->archived, item); } /** * as_profile_task_free: * @ptask: A #AsProfileTask * * Frees a profile token, and marks the portion of code complete. * * Since: 0.2.2 **/ void as_profile_task_free (AsProfileTask *ptask) { if (ptask == NULL) return; g_assert (ptask->id != NULL); as_profile_task_free_internal (ptask->profile, ptask->id); g_free (ptask->id); g_object_unref (ptask->profile); g_free (ptask); } /** * as_profile_clear: * @profile: A #AsProfile * * Clears the list of profiled events. * * Since: 0.2.2 **/ void as_profile_clear (AsProfile *profile) { g_autoptr(GMutexLocker) locker = g_mutex_locker_new (&profile->mutex); g_ptr_array_set_size (profile->archived, 0); } /** * as_profile_prune: * @profile: A #AsProfile * @duration: A time in ms * * Clears the list of profiled events older than @duration. * * Since: 0.6.4 **/ void as_profile_prune (AsProfile *profile, guint duration) { g_autoptr(GMutexLocker) locker = g_mutex_locker_new (&profile->mutex); g_return_if_fail (AS_IS_PROFILE (profile)); as_profile_prune_safe (profile, duration); } /** * as_profile_set_autoprune: * @profile: A #AsProfile * @duration: A time in ms * * Automatically prunes events older than @duration when new ones are added. * * Since: 0.6.4 **/ void as_profile_set_autoprune (AsProfile *profile, guint duration) { profile->autoprune_duration = duration; as_profile_prune (profile, duration); } /** * as_profile_set_duration_min: * @profile: A #AsProfile * @duration_min: A time in ms * * Sets the smallest recordable task duration. * * Since: 0.6.5 **/ void as_profile_set_duration_min (AsProfile *profile, guint duration_min) { profile->duration_min = duration_min; } /** * as_profile_dump: * @profile: A #AsProfile * * Dumps the current profiling table to stdout. * * Since: 0.2.2 **/ void as_profile_dump (AsProfile *profile) { g_autoptr(GMutexLocker) locker = g_mutex_locker_new (&profile->mutex); g_return_if_fail (AS_IS_PROFILE (profile)); as_profile_dump_safe (profile); } static gboolean as_profile_autodump_cb (gpointer user_data) { AsProfile *profile = AS_PROFILE (user_data); as_profile_dump (profile); profile->autodump_id = 0; return G_SOURCE_REMOVE; } /** * as_profile_set_autodump: * @profile: A #AsProfile * @delay: Duration in ms * * Dumps the current profiling table to stdout on a set interval. * * Since: 0.2.2 **/ void as_profile_set_autodump (AsProfile *profile, guint delay) { if (profile->autodump_id != 0) g_source_remove (profile->autodump_id); profile->autodump_id = g_timeout_add (delay, as_profile_autodump_cb, profile); } static void as_profile_finalize (GObject *object) { AsProfile *profile = AS_PROFILE (object); if (profile->autodump_id != 0) g_source_remove (profile->autodump_id); g_ptr_array_foreach (profile->current, (GFunc) as_profile_item_free, NULL); g_ptr_array_unref (profile->current); g_ptr_array_unref (profile->archived); g_mutex_clear (&profile->mutex); G_OBJECT_CLASS (as_profile_parent_class)->finalize (object); } static void as_profile_class_init (AsProfileClass *klass) { GObjectClass *object_class = G_OBJECT_CLASS (klass); object_class->finalize = as_profile_finalize; } static void as_profile_init (AsProfile *profile) { profile->duration_min = 5; profile->current = g_ptr_array_new (); profile->unthreaded = g_thread_self (); profile->archived = g_ptr_array_new_with_free_func ((GDestroyNotify) as_profile_item_free); g_mutex_init (&profile->mutex); } /** * as_profile_new: * * Creates a new #AsProfile. * * Returns: (transfer full): a #AsProfile * * Since: 0.2.2 **/ AsProfile * as_profile_new (void) { if (as_profile_object != NULL) { g_object_ref (as_profile_object); } else { as_profile_object = g_object_new (AS_TYPE_PROFILE, NULL); g_object_add_weak_pointer (as_profile_object, &as_profile_object); } return AS_PROFILE (as_profile_object); }