[MM] [PATCH v2] modem: 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-broadband-modem.c       |   22 ++++++++++++++++++++++
 src/mm-iface-modem-simple.c    |   17 +++++++++++++++++
 src/mm-iface-modem.c           |   24 ++++++++++++++++++++++++
 5 files changed, 72 insertions(+), 0 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-broadband-modem.c b/src/mm-broadband-modem.c
index 0a7af2c..135e725 100644
--- a/src/mm-broadband-modem.c
+++ b/src/mm-broadband-modem.c
@@ -7460,6 +7460,7 @@ typedef struct {
     DisablingStep step;
     MMModemState previous_state;
     gboolean disabled;
+    GTimeVal start_time;
 } DisablingContext;
 
 static void disabling_step (DisablingContext *ctx);
@@ -7618,6 +7619,8 @@ disabling_wait_for_final_state_ready (MMIfaceModem *self,
 static void
 disabling_step (DisablingContext *ctx)
 {
+    GTimeVal end_time;
+
     /* Don't run new steps if we're cancelled */
     if (disabling_context_complete_and_free_if_cancelled (ctx))
         return;
@@ -7746,6 +7749,9 @@ disabling_step (DisablingContext *ctx)
     case DISABLING_STEP_LAST:
         mm_info ("Modem fully disabled...");
         ctx->disabled = TRUE;
+        g_get_current_time (&end_time);
+        mm_info ("Modem disabling steps took %.3f second(s).",
+                 mm_utils_subtract_time (&end_time, &ctx->start_time));
         /* All disabled without errors! */
         g_simple_async_result_set_op_res_gboolean (G_SIMPLE_ASYNC_RESULT (ctx->result), TRUE);
         disabling_context_complete_and_free (ctx);
@@ -7768,6 +7774,7 @@ disable (MMBaseModem *self,
     ctx->result = g_simple_async_result_new (G_OBJECT (self), callback, user_data, disable);
     ctx->cancellable = (cancellable ? g_object_ref (cancellable) : NULL);
     ctx->step = DISABLING_STEP_FIRST;
+    g_get_current_time (&ctx->start_time);
 
     disabling_step (ctx);
 }
@@ -7798,6 +7805,7 @@ typedef struct {
     EnablingStep step;
     MMModemState previous_state;
     gboolean enabled;
+    GTimeVal start_time;
 } EnablingContext;
 
 static void enabling_step (EnablingContext *ctx);
@@ -7940,6 +7948,8 @@ enabling_wait_for_final_state_ready (MMIfaceModem *self,
 static void
 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;
@@ -8068,6 +8078,9 @@ enabling_step (EnablingContext *ctx)
     case ENABLING_STEP_LAST:
         mm_info ("Modem fully enabled...");
         ctx->enabled = TRUE;
+        g_get_current_time (&end_time);
+        mm_info ("Modem enabling steps took %.3f second(s).",
+                 mm_utils_subtract_time (&end_time, &ctx->start_time));
         /* All enabled without errors! */
         g_simple_async_result_set_op_res_gboolean (G_SIMPLE_ASYNC_RESULT (ctx->result), TRUE);
         enabling_context_complete_and_free (ctx);
@@ -8118,6 +8131,7 @@ enable (MMBaseModem *self,
         ctx->result = result;
         ctx->cancellable = g_object_ref (cancellable);
         ctx->step = ENABLING_STEP_FIRST;
+        g_get_current_time (&ctx->start_time);
         enabling_step (ctx);
         return;
     }
@@ -8179,6 +8193,7 @@ typedef struct {
     GSimpleAsyncResult *result;
     InitializeStep step;
     gpointer ports_ctx;
+    GTimeVal start_time;
 } InitializeContext;
 
 static void initialize_step (InitializeContext *ctx);
@@ -8356,6 +8371,8 @@ INTERFACE_INIT_READY_FN (iface_modem_firmware,  MM_IFACE_MODEM_FIRMWARE,  FALSE)
 static void
 initialize_step (InitializeContext *ctx)
 {
+    GTimeVal end_time;
+
     /* Don't run new steps if we're cancelled */
     if (initialize_context_complete_and_free_if_cancelled (ctx))
         return;
@@ -8523,6 +8540,10 @@ initialize_step (InitializeContext *ctx)
 
         mm_info ("Modem fully initialized");
 
+        g_get_current_time (&end_time);
+        mm_info ("Modem initialization steps took %.3f second(s).",
+                 mm_utils_subtract_time (&end_time, &ctx->start_time));
+
         /* All initialized without errors!
          * Set as disabled (a.k.a. initialized) */
         mm_iface_modem_update_state (MM_IFACE_MODEM (ctx->self),
@@ -8567,6 +8588,7 @@ initialize (MMBaseModem *self,
         ctx->cancellable = g_object_ref (cancellable);
         ctx->result = result;
         ctx->step = INITIALIZE_STEP_FIRST;
+        g_get_current_time (&ctx->start_time);
 
         /* Set as being initialized, even if we were locked before */
         mm_iface_modem_update_state (MM_IFACE_MODEM (self),
diff --git a/src/mm-iface-modem-simple.c b/src/mm-iface-modem-simple.c
index 12aa152..abea0da 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
@@ -516,6 +518,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 +742,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 ("Simple interface 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 +835,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 +854,7 @@ typedef struct {
     gchar *bearer_path;
     GList *bearers;
     MMBearer *current;
+    GTimeVal start_time;
 } DisconnectionContext;
 
 static void
@@ -887,6 +896,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 ("Simple interface 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 +992,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..a730d1e 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 ("Modem interface 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 ("Modem interface 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 ("Modem interface 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