There may be better ways to collect this kind of performance data than outputting them to ModemManager log. Is there a commonly used method for ModemManager to report performance metrics in a way that other tools can collect and analyze them?- BenOn Mon, Jan 21, 2013 at 8:30 PM, Ben Chan <benchan chromium org> wrote:
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