[gnome-software] plugins: Add a profiling function to see what's taking all the time

[Richard Hughes <rhughes src gnome org>]

commit 43f0790cc377dbedc1a6dd0e2777f08f0a3adabf
Author: Richard Hughes <richard hughsie com>
Date:   Thu Mar 7 11:12:33 2013 +0000

    plugins: Add a profiling function to see what's taking all the time

 src/gs-plugin-loader.c |   22 ++++++++++++++++++++++
 src/gs-plugin.h        |    1 +
 src/gs-self-test.c     |    7 +++++++
 3 files changed, 30 insertions(+), 0 deletions(-)
---
diff --git a/src/gs-plugin-loader.c b/src/gs-plugin-loader.c
index 1fe3bcd..4bf9a49 100644
--- a/src/gs-plugin-loader.c
+++ b/src/gs-plugin-loader.c
@@ -75,9 +75,14 @@ gs_plugin_loader_run_refine (GsPluginLoader *plugin_loader,
                        continue;
                g_debug ("run %s on %s", function_name,
                         g_module_name (plugin->module));
+               g_timer_start (plugin->timer);
                ret = plugin_func (plugin, list, error);
                if (!ret)
                        goto out;
+               g_debug ("%s(%s) took %.0fms",
+                        plugin->name,
+                        function_name,
+                        g_timer_elapsed (plugin->timer, NULL) * 1000);
        }
 out:
        return ret;
@@ -109,9 +114,14 @@ gs_plugin_loader_run_results (GsPluginLoader *plugin_loader,
                        continue;
                g_debug ("run %s on %s", function_name,
                         g_module_name (plugin->module));
+               g_timer_start (plugin->timer);
                ret = plugin_func (plugin, &list, error);
                if (!ret)
                        goto out;
+               g_debug ("%s(%s) took %.0fms",
+                        plugin->name,
+                        function_name,
+                        g_timer_elapsed (plugin->timer, NULL) * 1000);
        }
 
        /* run refine() on each one */
@@ -285,9 +295,14 @@ gs_plugin_loader_search (GsPluginLoader *plugin_loader, const gchar *value, GErr
                        continue;
                g_debug ("run %s on %s", function_name,
                         g_module_name (plugin->module));
+               g_timer_start (plugin->timer);
                ret = plugin_func (plugin, value, &list, error);
                if (!ret)
                        goto out;
+               g_debug ("%s(%s) took %.0fms",
+                        plugin->name,
+                        function_name,
+                        g_timer_elapsed (plugin->timer, NULL) * 1000);
        }
 
        /* run refine() on each one */
@@ -337,6 +352,7 @@ gs_plugin_loader_run_action (GsPluginLoader *plugin_loader,
                        continue;
                g_debug ("run %s on %s", function_name,
                         g_module_name (plugin->module));
+               g_timer_start (plugin->timer);
                ret = plugin_func (plugin, app, &error_local);
                if (!ret) {
                        if (g_error_matches (error_local,
@@ -350,6 +366,10 @@ gs_plugin_loader_run_action (GsPluginLoader *plugin_loader,
                                goto out;
                        }
                }
+               g_debug ("%s(%s) took %.0fms",
+                        plugin->name,
+                        function_name,
+                        g_timer_elapsed (plugin->timer, NULL) * 1000);
        }
 
        /* nothing ran */
@@ -495,6 +515,7 @@ gs_plugin_loader_open_plugin (GsPluginLoader *plugin_loader,
        plugin->pixbuf_size = 64;
        plugin->priority = plugin_prio (plugin);
        plugin->name = g_strdup (plugin_name ());
+       plugin->timer = g_timer_new ();
        g_debug ("opened plugin %s: %s", filename, plugin->name);
 
        /* add to array */
@@ -599,6 +620,7 @@ gs_plugin_loader_plugin_free (GsPlugin *plugin)
        g_free (plugin->priv);
        g_free (plugin->name);
        g_module_close (plugin->module);
+       g_timer_destroy (plugin->timer);
        g_free (plugin);
 }
 
diff --git a/src/gs-plugin.h b/src/gs-plugin.h
index d98f964..d2d1e5a 100644
--- a/src/gs-plugin.h
+++ b/src/gs-plugin.h
@@ -41,6 +41,7 @@ typedef struct {
        GsPluginPrivate         *priv;
        GCancellable            *cancellable;
        guint                    pixbuf_size;
+       GTimer                  *timer;
 } GsPlugin;
 
 typedef enum {
diff --git a/src/gs-self-test.c b/src/gs-self-test.c
index 9a34db7..af00f01 100644
--- a/src/gs-self-test.c
+++ b/src/gs-self-test.c
@@ -127,6 +127,13 @@ gs_plugin_loader_func (void)
        g_assert (gs_app_get_pixbuf (app) != NULL);
        g_list_free_full (list, (GDestroyNotify) g_object_unref);
 
+       /* do this again, which should be much faster */
+       list = gs_plugin_loader_get_installed (loader, &error);
+       g_assert_no_error (error);
+       g_assert (list != NULL);
+       g_assert_cmpint (g_list_length (list), >, 50);
+       g_list_free_full (list, (GDestroyNotify) g_object_unref);
+
        g_object_unref (loader);
 }