Submitted a revised patch.
On Mon, Jan 21, 2013 at 8:39 PM, Ben Chan <benc...@chromium.org> wrote:
> 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?
>
> - Ben
>
>
> On Mon, Jan 21, 2013 at 8:30 PM, Ben Chan <benc...@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
>>
>>
>
_______________________________________________
networkmanager-list mailing list
networkmanager-list@gnome.org
https://mail.gnome.org/mailman/listinfo/networkmanager-list
