[gnome-software] trivial: Log the elapsed time for a plugin job

[Richard Hughes <rhughes src gnome org>]

commit 46534a8a922efcaa30dfd6f2bc7bc7b5b6407e64
Author: Richard Hughes <richard hughsie com>
Date:   Fri Jul 7 15:16:54 2017 +0100

    trivial: Log the elapsed time for a plugin job

 lib/gs-plugin-job.c    |    7 +++++++
 lib/gs-plugin-loader.c |    8 ++++++--
 2 files changed, 13 insertions(+), 2 deletions(-)
---
diff --git a/lib/gs-plugin-job.c b/lib/gs-plugin-job.c
index a3ca361..b862412 100644
--- a/lib/gs-plugin-job.c
+++ b/lib/gs-plugin-job.c
@@ -47,6 +47,7 @@ struct _GsPluginJob
        GsCategory              *category;
        AsReview                *review;
        GsPrice                 *price;
+       gint64                   time_created;
 };
 
 enum {
@@ -75,6 +76,7 @@ gchar *
 gs_plugin_job_to_string (GsPluginJob *self)
 {
        GString *str = g_string_new (NULL);
+       gint64 time_now = g_get_monotonic_time ();
        g_string_append_printf (str, "running %s",
                                gs_plugin_action_to_string (self->action));
        if (self->refine_flags > 0) {
@@ -141,6 +143,10 @@ gs_plugin_job_to_string (GsPluginJob *self)
                unique_ids_str = g_strjoinv (",", (gchar**) unique_ids);
                g_string_append_printf (str, " on apps %s", unique_ids_str);
        }
+       if (time_now - self->time_created > 1000) {
+               g_string_append_printf (str, " took %" G_GINT64_FORMAT "ms",
+                                       (time_now - self->time_created) / 1000);
+       }
        return g_string_free (str, FALSE);
 }
 
@@ -648,6 +654,7 @@ gs_plugin_job_init (GsPluginJob *self)
        self->refine_flags = GS_PLUGIN_REFINE_FLAGS_DEFAULT;
        self->refresh_flags = GS_PLUGIN_REFRESH_FLAGS_NONE;
        self->list = gs_app_list_new ();
+       self->time_created = g_get_monotonic_time ();
 }
 
 /* vim: set noexpandtab: */
diff --git a/lib/gs-plugin-loader.c b/lib/gs-plugin-loader.c
index 21fc059..49c6e41 100644
--- a/lib/gs-plugin-loader.c
+++ b/lib/gs-plugin-loader.c
@@ -1563,6 +1563,9 @@ gs_plugin_loader_job_get_categories_thread_cb (GTask *task,
                return;
        }
 
+       /* show elapsed time */
+       gs_plugin_loader_job_debug (helper);
+
        /* success */
        g_task_return_pointer (task, g_ptr_array_ref (helper->catlist), (GDestroyNotify) g_ptr_array_unref);
 }
@@ -1590,7 +1593,6 @@ gs_plugin_loader_job_get_categories_async (GsPluginLoader *plugin_loader,
        /* save helper */
        helper = gs_plugin_loader_helper_new (plugin_loader, plugin_job);
        helper->catlist = g_ptr_array_new_with_free_func ((GDestroyNotify) g_object_unref);
-       gs_plugin_loader_job_debug (helper);
 
        /* run in a thread */
        task = g_task_new (plugin_loader, cancellable, callback, user_data);
@@ -3295,6 +3297,9 @@ gs_plugin_loader_process_thread_cb (GTask *task,
        /* sort these again as the refine may have added useful metadata */
        gs_plugin_loader_job_sorted_truncation_again (helper);
 
+       /* show elapsed time */
+       gs_plugin_loader_job_debug (helper);
+
        /* success */
        g_task_return_pointer (task, g_object_ref (list), (GDestroyNotify) g_object_unref);
 }
@@ -3482,7 +3487,6 @@ gs_plugin_loader_job_process_async (GsPluginLoader *plugin_loader,
        /* save helper */
        helper = gs_plugin_loader_helper_new (plugin_loader, plugin_job);
        g_task_set_task_data (task, helper, (GDestroyNotify) gs_plugin_loader_helper_free);
-       gs_plugin_loader_job_debug (helper);
 
        /* let the task cancel itself */
        g_task_set_check_cancellable (task, FALSE);