[MM] [PATCH] iface-modem, iface-modem-simple: log time taken for succeeded operations

[Ben Chan <benchan chromium org>]

This patch logs the time taken for succeeded initialization, enabling,
disabling, connection, and disconnection operations, which helps
evaluate how to optimize modem plugins.
---
 libmm-glib/mm-common-helpers.c |    7 +++++++
 libmm-glib/mm-common-helpers.h |    2 ++
 src/mm-iface-modem-simple.c    |   18 +++++++++++++++++-
 src/mm-iface-modem.c           |   24 ++++++++++++++++++++++++
 4 files changed, 50 insertions(+), 1 deletions(-)

diff --git a/libmm-glib/mm-common-helpers.c b/libmm-glib/mm-common-helpers.c
index 3f100b6..406a99a 100644
--- a/libmm-glib/mm-common-helpers.c
+++ b/libmm-glib/mm-common-helpers.c
@@ -960,3 +960,10 @@ mm_utils_check_for_single_value (guint32 value)
 
     return TRUE;
 }
+
+gdouble
+mm_utils_subtract_time (const GTimeVal *end_time, const GTimeVal *start_time)
+{
+    return (end_time->tv_sec - start_time->tv_sec) +
+           (end_time->tv_usec - start_time->tv_usec) / 1.0e6;
+}
diff --git a/libmm-glib/mm-common-helpers.h b/libmm-glib/mm-common-helpers.h
index 6155b58..42bbe20 100644
--- a/libmm-glib/mm-common-helpers.h
+++ b/libmm-glib/mm-common-helpers.h
@@ -102,4 +102,6 @@ gchar    *mm_utils_bin2hexstr (const guint8 *bin, gsize len);
 
 gboolean  mm_utils_check_for_single_value (guint32 value);
 
+gdouble mm_utils_subtract_time (const GTimeVal *end_time, const GTimeVal *start_time);
+
 #endif /* MM_COMMON_HELPERS_H */
diff --git a/src/mm-iface-modem-simple.c b/src/mm-iface-modem-simple.c
index 12aa152..b0bcf46 100644
--- a/src/mm-iface-modem-simple.c
+++ b/src/mm-iface-modem-simple.c
@@ -196,6 +196,8 @@ typedef struct {
 
     /* Results to set */
     MMBearer *bearer;
+
+    GTimeVal start_time;
 } ConnectionContext;
 
 static void
@@ -203,7 +205,6 @@ connection_context_free (ConnectionContext *ctx)
 {
     g_assert (ctx->state_changed_id == 0);
     g_assert (ctx->state_changed_wait_id == 0);
-
     g_variant_unref (ctx->dictionary);
     if (ctx->properties)
         g_object_unref (ctx->properties);
@@ -516,6 +517,8 @@ bearer_list_find_disconnected (MMBearer *bearer,
 static void
 connection_step (ConnectionContext *ctx)
 {
+    GTimeVal end_time;
+
     switch (ctx->step) {
     case CONNECTION_STEP_FIRST:
         /* Fall down to next step */
@@ -738,6 +741,9 @@ connection_step (ConnectionContext *ctx)
     case CONNECTION_STEP_LAST:
         mm_info ("Simple connect state (%d/%d): All done",
                  ctx->step, CONNECTION_STEP_LAST);
+        g_get_current_time (&end_time);
+        mm_info ("Connection steps took %.3f second(s).",
+                 mm_utils_subtract_time (&end_time, &ctx->start_time));
         /* All done, yey! */
         mm_gdbus_modem_simple_complete_connect (
             ctx->skeleton,
@@ -828,6 +834,7 @@ handle_connect (MmGdbusModemSimple *skeleton,
     ctx->invocation = g_object_ref (invocation);
     ctx->self = g_object_ref (self);
     ctx->dictionary = g_variant_ref (dictionary);
+    g_get_current_time (&ctx->start_time);
 
     mm_base_modem_authorize (MM_BASE_MODEM (self),
                              invocation,
@@ -846,6 +853,7 @@ typedef struct {
     gchar *bearer_path;
     GList *bearers;
     MMBearer *current;
+    GTimeVal start_time;
 } DisconnectionContext;
 
 static void
@@ -887,6 +895,12 @@ disconnect_next_bearer (DisconnectionContext *ctx)
 
     /* No more bearers? all done! */
     if (!ctx->bearers) {
+        GTimeVal end_time;
+
+        g_get_current_time (&end_time);
+        mm_info ("Disconnection steps took %.3f second(s).",
+                 mm_utils_subtract_time (&end_time, &ctx->start_time));
+
         mm_gdbus_modem_simple_complete_disconnect (ctx->skeleton,
                                                    ctx->invocation);
         disconnection_context_free (ctx);
@@ -977,6 +991,8 @@ handle_disconnect (MmGdbusModemSimple *skeleton,
         ctx->bearer_path = g_strdup (ctx->bearer_path);
     }
 
+    g_get_current_time (&ctx->start_time);
+
     mm_base_modem_authorize (MM_BASE_MODEM (self),
                              invocation,
                              MM_AUTHORIZATION_DEVICE_CONTROL,
diff --git a/src/mm-iface-modem.c b/src/mm-iface-modem.c
index 6b812e2..2edbcf4 100644
--- a/src/mm-iface-modem.c
+++ b/src/mm-iface-modem.c
@@ -2911,6 +2911,7 @@ struct _DisablingContext {
     MMModemState previous_state;
     GSimpleAsyncResult *result;
     MmGdbusModem *skeleton;
+    GTimeVal start_time;
 };
 
 static void
@@ -2935,6 +2936,8 @@ mm_iface_modem_disable_finish (MMIfaceModem *self,
 static void
 interface_disabling_step (DisablingContext *ctx)
 {
+    GTimeVal end_time;
+
     switch (ctx->step) {
     case DISABLING_STEP_FIRST:
         /* Fall down to next step */
@@ -2954,6 +2957,10 @@ interface_disabling_step (DisablingContext *ctx)
         ctx->step++;
 
     case DISABLING_STEP_LAST:
+        g_get_current_time (&end_time);
+        mm_info ("Disabling steps took %.3f second(s).",
+                 mm_utils_subtract_time (&end_time, &ctx->start_time));
+
         /* We are done without errors! */
         g_simple_async_result_set_op_res_gboolean (ctx->result, TRUE);
         disabling_context_complete_and_free (ctx);
@@ -2977,6 +2984,7 @@ mm_iface_modem_disable (MMIfaceModem *self,
                                              user_data,
                                              mm_iface_modem_disable);
     ctx->step = DISABLING_STEP_FIRST;
+    g_get_current_time (&ctx->start_time);
     g_object_get (ctx->self,
                   MM_IFACE_MODEM_DBUS_SKELETON, &ctx->skeleton,
                   MM_IFACE_MODEM_STATE, &ctx->previous_state,
@@ -3019,6 +3027,7 @@ struct _EnablingContext {
     GSimpleAsyncResult *result;
     GCancellable *cancellable;
     MmGdbusModem *skeleton;
+    GTimeVal start_time;
 };
 
 static void
@@ -3220,6 +3229,8 @@ static const MMModemCharset best_charsets[] = {
 static void
 interface_enabling_step (EnablingContext *ctx)
 {
+    GTimeVal end_time;
+
     /* Don't run new steps if we're cancelled */
     if (enabling_context_complete_and_free_if_cancelled (ctx))
         return;
@@ -3345,6 +3356,10 @@ interface_enabling_step (EnablingContext *ctx)
         ctx->step++;
 
     case ENABLING_STEP_LAST:
+        g_get_current_time (&end_time);
+        mm_info ("Enabling steps took %.3f second(s).",
+                 mm_utils_subtract_time (&end_time, &ctx->start_time));
+
         /* We are done without errors! */
         g_simple_async_result_set_op_res_gboolean (ctx->result, TRUE);
         enabling_context_complete_and_free (ctx);
@@ -3370,6 +3385,7 @@ mm_iface_modem_enable (MMIfaceModem *self,
                                              user_data,
                                              mm_iface_modem_enable);
     ctx->step = ENABLING_STEP_FIRST;
+    g_get_current_time (&ctx->start_time);
     g_object_get (ctx->self,
                   MM_IFACE_MODEM_DBUS_SKELETON, &ctx->skeleton,
                   NULL);
@@ -3417,6 +3433,7 @@ struct _InitializationContext {
     GCancellable *cancellable;
     MmGdbusModem *skeleton;
     GError *fatal_error;
+    GTimeVal start_time;
 };
 
 static void
@@ -4000,6 +4017,12 @@ interface_initialization_step (InitializationContext *ctx)
             g_simple_async_result_take_error (ctx->result, ctx->fatal_error);
             ctx->fatal_error = NULL;
         } else {
+            GTimeVal end_time;
+
+            g_get_current_time (&end_time);
+            mm_info ("Initialization steps took %.3f second(s).",
+                     mm_utils_subtract_time (&end_time, &ctx->start_time));
+
             /* We are done without errors!
              * Handle method invocations */
             g_signal_connect (ctx->skeleton,
@@ -4127,6 +4150,7 @@ mm_iface_modem_initialize (MMIfaceModem *self,
                                              mm_iface_modem_initialize);
     ctx->step = INITIALIZATION_STEP_FIRST;
     ctx->skeleton = skeleton;
+    g_get_current_time (&ctx->start_time);
 
     interface_initialization_step (ctx);
 }
-- 
1.7.7.3