Add AsProfile for speed profiling

5 files changed, 449 insertions, 0 deletions

diff --git a/libappstream-glib/Makefile.am b/libappstream-glib/Makefile.am
index ca8a91e..43b6dab 100644
--- a/libappstream-glib/Makefile.am
+++ b/libappstream-glib/Makefile.am
@@ -76,6 +76,7 @@ libappstream_glib_include_HEADERS =				\
 	as-inf.h						\
 	as-node.h						\
 	as-problem.h						\
+	as-profile.h						\
 	as-provide.h						\
 	as-release.h						\
 	as-screenshot.h						\
@@ -107,6 +108,8 @@ libappstream_glib_la_SOURCES =					\
 	as-node-private.h					\
 	as-problem.c						\
 	as-problem.h						\
+	as-profile.c						\
+	as-profile.h						\
 	as-provide.c						\
 	as-provide-private.h					\
 	as-release.c						\
diff --git a/libappstream-glib/appstream-glib.h b/libappstream-glib/appstream-glib.h
index ed87f8c..4c5945c 100644
--- a/libappstream-glib/appstream-glib.h
+++ b/libappstream-glib/appstream-glib.h
@@ -33,6 +33,7 @@
 #include <as-inf.h>
 #include <as-node.h>
 #include <as-problem.h>
+#include <as-profile.h>
 #include <as-provide.h>
 #include <as-release.h>
 #include <as-screenshot.h>
diff --git a/libappstream-glib/as-profile.c b/libappstream-glib/as-profile.c
new file mode 100644
index 0000000..a872573
--- /dev/null
+++ b/libappstream-glib/as-profile.c
@@ -0,0 +1,365 @@
+/* -*- Mode: C; tab-width: 8; indent-tabs-mode: t; c-basic-offset: 8 -*-
+ *
+ * Copyright (C) 2013-2015 Richard Hughes <richard@hughsie.com>
+ *
+ * Licensed under the GNU General Public License Version 2
+ *
+ * This program is free software; you can redistribute it and/or modify
+ * it under the terms of the GNU General Public License as published by
+ * the Free Software Foundation; either version 2 of the License, or
+ * (at your option) any later version.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License
+ * along with this program; if not, write to the Free Software
+ * Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA.
+ */
+
+#include "config.h"
+
+#include <glib/gi18n.h>
+
+#include "as-profile.h"
+
+struct _AsProfile
+{
+	GObject		 parent_instance;
+	GPtrArray	*current;
+	GPtrArray	*archived;
+	GMutex		 mutex;
+	GThread		*unthreaded;
+};
+
+typedef struct {
+	gchar		*id;
+	gint64		 time_start;
+	gint64		 time_stop;
+} AsProfileItem;
+
+G_DEFINE_TYPE (AsProfile, as_profile, G_TYPE_OBJECT)
+
+struct _AsProfileTask
+{
+	AsProfile	*profile;
+	gchar		*id;
+};
+
+static gpointer as_profile_object = NULL;
+
+/**
+ * as_profile_item_free:
+ **/
+static void
+as_profile_item_free (AsProfileItem *item)
+{
+	g_free (item->id);
+	g_free (item);
+}
+
+/**
+ * as_profile_item_find:
+ **/
+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_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_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) {
+		as_profile_dump (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;
+}
+
+/**
+ * as_profile_task_free_internal:
+ **/
+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 = (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_sort_cb:
+ **/
+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;
+}
+
+/**
+ * as_profile_dump:
+ **/
+void
+as_profile_dump (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;
+
+	g_return_if_fail (AS_IS_PROFILE (profile));
+
+	/* 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++) {
+		item = g_ptr_array_index (profile->archived, i);
+		time_ms = (item->time_stop - item->time_start) / 1000;
+		if (time_ms < 5)
+			continue;
+
+		/* print a timechart of what we've done */
+		bar_offset = scale * (item->time_start - time_start) / 1000;
+		for (j = 0; j < bar_offset; j++)
+			g_print (" ");
+		bar_length = scale * time_ms;
+		if (bar_length == 0)
+			bar_length = 1;
+		for (j = 0; j < bar_length; j++)
+			g_print ("#");
+		for (j = bar_offset + bar_length; j < console_width + 1; j++)
+			g_print (" ");
+		g_print ("@%04" G_GINT64_FORMAT "ms ",
+			 (item->time_stop - time_start) / 1000);
+		g_print ("%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_print (" @????ms %s %" G_GINT64_FORMAT "ms\n",
+				 item->id, time_ms);
+		}
+	}
+}
+
+/**
+ * as_profile_finalize:
+ **/
+static void
+as_profile_finalize (GObject *object)
+{
+	AsProfile *profile = AS_PROFILE (object);
+
+	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_OBJECT_CLASS (as_profile_parent_class)->finalize (object);
+}
+
+/**
+ * as_profile_class_init:
+ **/
+static void
+as_profile_class_init (AsProfileClass *klass)
+{
+	GObjectClass *object_class = G_OBJECT_CLASS (klass);
+	object_class->finalize = as_profile_finalize;
+}
+
+/**
+ * as_profile_init:
+ **/
+static void
+as_profile_init (AsProfile *profile)
+{
+	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);
+}
diff --git a/libappstream-glib/as-profile.h b/libappstream-glib/as-profile.h
new file mode 100644
index 0000000..ea0d4e5
--- /dev/null
+++ b/libappstream-glib/as-profile.h
@@ -0,0 +1,51 @@
+/* -*- Mode: C; tab-width: 8; indent-tabs-mode: t; c-basic-offset: 8 -*-
+ *
+ * Copyright (C) 2013-2015 Richard Hughes <richard@hughsie.com>
+ *
+ * Licensed under the GNU General Public License Version 2
+ *
+ * This program is free software; you can redistribute it and/or modify
+ * it under the terms of the GNU General Public License as published by
+ * the Free Software Foundation; either version 2 of the License, or
+ * (at your option) any later version.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License
+ * along with this program; if not, write to the Free Software
+ * Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA.
+ */
+
+#ifndef __AS_PROFILE_H
+#define __AS_PROFILE_H
+
+#include <glib-object.h>
+
+G_BEGIN_DECLS
+
+#define AS_TYPE_PROFILE	(as_profile_get_type ())
+
+G_DECLARE_FINAL_TYPE (AsProfile, as_profile, AS, PROFILE, GObject)
+
+typedef struct _AsProfileTask AsProfileTask;
+
+AsProfile	*as_profile_new			(void);
+AsProfileTask	*as_profile_start_literal	(AsProfile	*profile,
+						 const gchar	*id)
+						 G_GNUC_WARN_UNUSED_RESULT;
+AsProfileTask	*as_profile_start		(AsProfile	*profile,
+						 const gchar	*fmt,
+						 ...)
+						 G_GNUC_PRINTF (2, 3)
+						 G_GNUC_WARN_UNUSED_RESULT;
+void		 as_profile_dump		(AsProfile	*profile);
+void		 as_profile_task_free		(AsProfileTask	*ptask);
+
+G_DEFINE_AUTOPTR_CLEANUP_FUNC(AsProfileTask, as_profile_task_free)
+
+G_END_DECLS
+
+#endif /* __AS_PROFILE_H */
diff --git a/libappstream-glib/as-store.c b/libappstream-glib/as-store.c
index 43160d5..943c0b5 100644
--- a/libappstream-glib/as-store.c
+++ b/libappstream-glib/as-store.c
@@ -39,6 +39,7 @@
 #include "as-app-private.h"
 #include "as-node-private.h"
 #include "as-problem.h"
+#include "as-profile.h"
 #include "as-monitor.h"
 #include "as-store.h"
 #include "as-utils-private.h"
@@ -69,6 +70,7 @@ typedef struct
 	guint32			 filter;
 	guint			 changed_block_refcnt;
 	gboolean		 is_pending_changed_signal;
+	AsProfile		*profile;
 } AsStorePrivate;
 
 G_DEFINE_TYPE_WITH_PRIVATE (AsStore, as_store, G_TYPE_OBJECT)
@@ -112,6 +114,7 @@ as_store_finalize (GObject *object)
 	g_free (priv->builder_id);
 	g_ptr_array_unref (priv->array);
 	g_object_unref (priv->monitor);
+	g_object_unref (priv->profile);
 	g_hash_table_unref (priv->hash_id);
 	g_hash_table_unref (priv->hash_pkgname);
 	g_hash_table_unref (priv->metadata_indexes);
@@ -825,6 +828,10 @@ as_store_match_addons (AsStore *store)
 	const gchar *tmp;
 	guint i;
 	guint j;
+	g_autoptr(AsProfileTask) ptask = NULL;
+
+	/* profile */
+	ptask = as_profile_start_literal (priv->profile, "AsStore:match-addons");
 
 	for (i = 0; i < priv->array->len; i++) {
 		app = g_ptr_array_index (priv->array, i);
@@ -863,9 +870,13 @@ as_store_from_root (AsStore *store,
 	g_autofree AsNodeContext *ctx = NULL;
 	g_autofree gchar *icon_path = NULL;
 	_cleanup_uninhibit_ guint32 *tok = NULL;
+	g_autoptr(AsProfileTask) ptask = NULL;
 
 	g_return_val_if_fail (AS_IS_STORE (store), FALSE);
 
+	/* profile */
+	ptask = as_profile_start_literal (priv->profile, "AsStore:store-from-root");
+
 	/* emit once when finished */
 	tok = as_store_changed_inhibit (store);
 
@@ -1153,9 +1164,13 @@ as_store_from_file (AsStore *store,
 	g_autofree gchar *filename = NULL;
 	g_autoptr(GError) error_local = NULL;
 	g_autoptr(AsNode) root = NULL;
+	g_autoptr(AsProfileTask) ptask = NULL;
 
 	g_return_val_if_fail (AS_IS_STORE (store), FALSE);
 
+	/* profile */
+	ptask = as_profile_start_literal (priv->profile, "AsStore:store-from-file");
+
 	/* a DEP-11 file */
 	filename = g_file_get_path (file);
 	if (g_strstr_len (filename, -1, ".yml") != NULL)
@@ -1673,7 +1688,12 @@ as_store_load_app_info_file (AsStore *store,
 			     GCancellable *cancellable,
 			     GError **error)
 {
+	AsStorePrivate *priv = GET_PRIVATE (store);
 	g_autoptr(GFile) file = NULL;
+	g_autoptr(AsProfileTask) ptask = NULL;
+
+	/* profile */
+	ptask = as_profile_start (priv->profile, "AsStore:app-info{%s}", path_xml);
 
 	/* guess this based on the name */
 	if (!as_store_guess_origin_fallback (store, path_xml, error))
@@ -1895,6 +1915,10 @@ as_store_load_installed (AsStore *store,
 	const gchar *tmp;
 	g_autoptr(GDir) dir = NULL;
 	_cleanup_uninhibit_ guint32 *tok = NULL;
+	g_autoptr(AsProfileTask) ptask = NULL;
+
+	/* profile */
+	ptask = as_profile_start_literal (priv->profile, "AsStore:load-installed");
 
 	dir = g_dir_open (path, 0, error);
 	if (dir == NULL)
@@ -2004,8 +2028,12 @@ as_store_load (AsStore *store,
 	guint i;
 	g_autoptr(GPtrArray) app_info = NULL;
 	g_autoptr(GPtrArray) installed = NULL;
+	g_autoptr(AsProfileTask) ptask = NULL;
 	_cleanup_uninhibit_ guint32 *tok = NULL;
 
+	/* profile */
+	ptask = as_profile_start_literal (priv->profile, "AsStore:load");
+
 	/* system locations */
 	app_info = g_ptr_array_new_with_free_func (g_free);
 	installed = g_ptr_array_new_with_free_func (g_free);
@@ -2342,6 +2370,7 @@ static void
 as_store_init (AsStore *store)
 {
 	AsStorePrivate *priv = GET_PRIVATE (store);
+	priv->profile = as_profile_new ();
 	priv->api_version = AS_API_VERSION_NEWEST;
 	priv->array = g_ptr_array_new_with_free_func ((GDestroyNotify) g_object_unref);
 	priv->watch_flags = AS_STORE_WATCH_FLAG_NONE;