dispatcher: log duration of dispatcher call

Yes, we anyway log the timestamps for every log message. So one could
always calculate the offset. However, when you read a logfile, it can be
cumbersome to stop looking at where you currently are to find the
start/end of a call. For convenience, log the duration explicitly.

https://gitlab.freedesktop.org/NetworkManager/NetworkManager/-/merge_requests/1251

src/core/nm-dispatcher.c

@@ -56,6 +56,7 @@ struct NMDispatcherCallId {
     gpointer           user_data;
     const char        *log_ifname;
     const char        *log_con_uuid;
+    gint64             start_at_msec;
     NMDispatcherAction action;
     guint              idle_id;
     guint32            request_id;
@@ -82,6 +83,7 @@ static struct {
 
 static NMDispatcherCallId *
 dispatcher_call_id_new(guint32            request_id,
+                       gint64             start_at_msec,
                        NMDispatcherAction action,
                        NMDispatcherFunc   callback,
                        gpointer           user_data,
@@ -99,6 +101,7 @@ dispatcher_call_id_new(guint32            request_id,
     call_id = g_malloc(sizeof(NMDispatcherCallId) + l_log_ifname + l_log_con_uuid);
 
     call_id->action        = action;
+    call_id->start_at_msec = start_at_msec;
     call_id->request_id    = request_id;
     call_id->callback      = callback;
     call_id->user_data     = user_data;
@@ -366,6 +369,8 @@ dispatch_result_to_string(DispatchResult result)
 
 static void
 dispatcher_results_process(guint32     request_id,
+                           gint64      start_at_msec,
+                           gint64      now_msec,
                            const char *log_ifname,
                            const char *log_con_uuid,
                            GVariant   *v_results)
@@ -373,13 +378,22 @@ dispatcher_results_process(guint32     request_id,
     nm_auto_free_variant_iter GVariantIter *results = NULL;
     const char                             *script, *err;
     guint32                                 result;
+    gsize                                   n_children;
 
     g_variant_get(v_results, "(a(sus))", &results);
 
-    if (g_variant_iter_n_children(results) == 0) {
+    n_children = g_variant_iter_n_children(results);
-        _LOG2D(request_id, log_ifname, log_con_uuid, "succeeded but no scripts invoked");
+
+    _LOG2D(request_id,
+           log_ifname,
+           log_con_uuid,
+           "succeeded (after %ld.%03d sec, %zu scripts invoked)",
+           (long int) ((now_msec - start_at_msec) / 1000),
+           (int) ((now_msec - start_at_msec) % 1000),
+           n_children);
+
+    if (n_children == 0)
         return;
-    }
 
     while (g_variant_iter_next(results, "(&su&s)", &script, &result, &err)) {
         if (result == DISPATCH_RESULT_SUCCESS) {
@@ -402,19 +416,30 @@ dispatcher_done_cb(GObject *source, GAsyncResult *result, gpointer user_data)
     gs_unref_variant GVariant *ret     = NULL;
     gs_free_error GError      *error   = NULL;
     NMDispatcherCallId        *call_id = user_data;
+    gint64                     now_msec;
 
     nm_assert((gpointer) source == gl.dbus_connection);
 
+    now_msec = nm_utils_get_monotonic_timestamp_msec();
+
     ret = g_dbus_connection_call_finish(G_DBUS_CONNECTION(source), result, &error);
     if (!ret) {
+        NMLogLevel log_level = LOGL_DEBUG;
+
         if (_nm_dbus_error_has_name(error, "org.freedesktop.systemd1.LoadFailed")) {
             g_dbus_error_strip_remote_error(error);
-            _LOG3W(call_id, "failed to call dispatcher scripts: %s", error->message);
+            log_level = LOGL_WARN;
-        } else {
-            _LOG3D(call_id, "failed to call dispatcher scripts: %s", error->message);
         }
+        _NMLOG3(log_level,
+                call_id,
+                "failed to call dispatcher scripts (after %ld.%03d sec): %s",
+                (long int) ((now_msec - call_id->start_at_msec) / 1000),
+                (int) ((now_msec - call_id->start_at_msec) % 1000),
+                error->message);
     } else {
         dispatcher_results_process(call_id->request_id,
+                                   call_id->start_at_msec,
+                                   now_msec,
                                    call_id->log_ifname,
                                    call_id->log_con_uuid,
                                    ret);
@@ -481,6 +506,8 @@ _dispatcher_call(NMDispatcherAction    action,
     const char                *connectivity_state_string = "UNKNOWN";
     const char                *log_ifname;
     const char                *log_con_uuid;
+    gint64                     start_at_msec;
+    gint64                     now_msec;
 
     g_return_val_if_fail(!blocking || (!callback && !user_data), FALSE);
 
@@ -596,6 +623,8 @@ _dispatcher_call(NMDispatcherAction    action,
                       &vpn_ip6_props,
                       nm_logging_enabled(LOGL_DEBUG, LOGD_DISPATCH));
 
+    start_at_msec = nm_utils_get_monotonic_timestamp_msec();
+
     /* Send the action to the dispatcher */
     if (blocking) {
         gs_unref_variant GVariant *ret   = NULL;
@@ -612,17 +641,36 @@ _dispatcher_call(NMDispatcherAction    action,
                                           CALL_TIMEOUT,
                                           NULL,
                                           &error);
+
+        now_msec = nm_utils_get_monotonic_timestamp_msec();
+
         if (!ret) {
             g_dbus_error_strip_remote_error(error);
-            _LOG2W(request_id, log_ifname, log_con_uuid, "failed: %s", error->message);
+            _LOG2W(request_id,
+                   log_ifname,
+                   log_con_uuid,
+                   "failed (after %ld.%03d sec): %s",
+                   (long int) ((now_msec - start_at_msec) / 1000),
+                   (int) ((now_msec - start_at_msec) % 1000),
+                   error->message);
             return FALSE;
         }
-        dispatcher_results_process(request_id, log_ifname, log_con_uuid, ret);
+        dispatcher_results_process(request_id,
+                                   start_at_msec,
+                                   now_msec,
+                                   log_ifname,
+                                   log_con_uuid,
+                                   ret);
         return TRUE;
     }
 
-    call_id =
+    call_id = dispatcher_call_id_new(request_id,
-        dispatcher_call_id_new(request_id, action, callback, user_data, log_ifname, log_con_uuid);
+                                     start_at_msec,
+                                     action,
+                                     callback,
+                                     user_data,
+                                     log_ifname,
+                                     log_con_uuid);
 
     g_dbus_connection_call(gl.dbus_connection,
                            NM_DISPATCHER_DBUS_SERVICE,