manager: measure startup times

src/dbus-manager.c

@@ -242,6 +242,7 @@ static DBusHandlerResult bus_manager_message_handler(DBusConnection *connection,
                 { "org.freedesktop.systemd1.Manager", "Version",       bus_property_append_string,    "s",  PACKAGE_STRING     },
                 { "org.freedesktop.systemd1.Manager", "RunningAs",     bus_manager_append_running_as, "s",  &m->running_as     },
                 { "org.freedesktop.systemd1.Manager", "StartupTimestamp", bus_property_append_uint64, "t",  &m->startup_timestamp.realtime },
+                { "org.freedesktop.systemd1.Manager", "FinishTimestamp", bus_property_append_uint64,  "t",  &m->finish_timestamp.realtime },
                 { "org.freedesktop.systemd1.Manager", "LogLevel",      bus_manager_append_log_level,  "s",  NULL               },
                 { "org.freedesktop.systemd1.Manager", "LogTarget",     bus_manager_append_log_target, "s",  NULL               },
                 { "org.freedesktop.systemd1.Manager", "NNames",        bus_manager_append_n_names,    "u",  NULL               },

src/job.c

@@ -540,6 +540,8 @@ int job_finish_and_invalidate(Job *j, bool success) {
                 if (other->meta.job)
                         job_add_to_run_queue(other->meta.job);
 
+        manager_check_finished(u->meta.manager);
+
         return 0;
 }
 

src/manager.c

@@ -2173,6 +2173,8 @@ int manager_loop(Manager *m) {
         set_free_free(m->unit_path_cache);
         m->unit_path_cache = NULL;
 
+        manager_check_finished(m);
+
         /* There might still be some zombies hanging around from
          * before we were exec()'ed. Leat's reap them */
         if ((r = manager_dispatch_sigchld(m)) < 0)
@@ -2598,6 +2600,34 @@ bool manager_unit_pending_inactive(Manager *m, const char *name) {
         return unit_pending_inactive(u);
 }
 
+void manager_check_finished(Manager *m) {
+        char userspace[FORMAT_TIMESPAN_MAX], kernel[FORMAT_TIMESPAN_MAX], sum[FORMAT_TIMESPAN_MAX];
+
+        assert(m);
+
+        if (dual_timestamp_is_set(&m->finish_timestamp))
+                return;
+
+        if (hashmap_size(m->jobs) > 0)
+                return;
+
+        dual_timestamp_get(&m->finish_timestamp);
+
+        if (m->running_as == MANAGER_SYSTEM)
+                log_info("Startup finished in %s (kernel) + %s (userspace) = %s.",
+                         format_timespan(kernel, sizeof(kernel),
+                                         m->startup_timestamp.monotonic),
+                         format_timespan(userspace, sizeof(userspace),
+                                         m->finish_timestamp.monotonic - m->startup_timestamp.monotonic),
+                         format_timespan(sum, sizeof(sum),
+                                         m->finish_timestamp.monotonic));
+        else
+                log_debug("Startup finished in %s.",
+                          format_timespan(userspace, sizeof(userspace),
+                                          m->finish_timestamp.monotonic - m->startup_timestamp.monotonic));
+
+}
+
 static const char* const manager_running_as_table[_MANAGER_RUNNING_AS_MAX] = {
         [MANAGER_SYSTEM] = "system",
         [MANAGER_SESSION] = "session"

src/manager.h

@@ -139,6 +139,7 @@ struct Manager {
         char **environment;
 
         dual_timestamp startup_timestamp;
+        dual_timestamp finish_timestamp;
 
         char *console;
 
@@ -263,6 +264,8 @@ void manager_send_unit_audit(Manager *m, Unit *u, int type, bool success);
 
 bool manager_unit_pending_inactive(Manager *m, const char *name);
 
+void manager_check_finished(Manager *m);
+
 const char *manager_running_as_to_string(ManagerRunningAs i);
 ManagerRunningAs manager_running_as_from_string(const char *s);
 

src/util.h

@@ -73,6 +73,8 @@ usec_t now(clockid_t clock);
 
 dual_timestamp* dual_timestamp_get(dual_timestamp *ts);
 
+#define dual_timestamp_is_set(ts) ((ts)->realtime > 0)
+
 usec_t timespec_load(const struct timespec *ts);
 struct timespec *timespec_store(struct timespec *ts, usec_t u);