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 _______________________________________________ networkmanager-list mailing list networkmanager-list@gnome.org https://mail.gnome.org/mailman/listinfo/networkmanager-list