manager: extend performance measurement interface to include firmware/loader times

This only adds the fields to the D-Bus interfaces but doesn't fill them
in with anything useful yet. Gummiboot exposes the necessary bits of
information to use however and as soon as I get my fingers on a proper
UEFI laptop I'll hook up the remaining bits.

Since we want to stabilize the D-Bus interface soon and include it in
the stability promise we should get the last fixes in, hence this change
now.

7 files changed, 65 insertions, 27 deletions

diff --git a/src/analyze/systemd-analyze b/src/analyze/systemd-analyze
index 76eceee9f0..636fd7422b 100755
--- a/src/analyze/systemd-analyze
+++ b/src/analyze/systemd-analyze
@@ -32,17 +32,17 @@ def acquire_start_time():
         properties = dbus.Interface(bus.get_object('org.freedesktop.systemd1', '/org/freedesktop/systemd1'), 'org.freedesktop.DBus.Properties')
 
         initrd_time = int(properties.Get('org.freedesktop.systemd1.Manager', 'InitRDTimestampMonotonic'))
-        startup_time = int(properties.Get('org.freedesktop.systemd1.Manager', 'StartupTimestampMonotonic'))
+        userspace_time = int(properties.Get('org.freedesktop.systemd1.Manager', 'UserspaceTimestampMonotonic'))
         finish_time = int(properties.Get('org.freedesktop.systemd1.Manager', 'FinishTimestampMonotonic'))
 
         if finish_time == 0:
                 sys.stderr.write("Bootup is not yet finished. Please try again later.\n")
                 sys.exit(1)
 
-        assert initrd_time <= startup_time
-        assert startup_time <= finish_time
+        assert initrd_time <= userspace_time
+        assert userspace_time <= finish_time
 
-        return initrd_time, startup_time, finish_time
+        return initrd_time, userspace_time, finish_time
 
 def draw_box(context, j, k, l, m, r = 0, g = 0, b = 0):
         context.save()
diff --git a/src/core/dbus-manager.c b/src/core/dbus-manager.c
index c341d36a6b..557b3e4763 100644
--- a/src/core/dbus-manager.c
+++ b/src/core/dbus-manager.c
@@ -214,6 +214,8 @@
         "   <arg name=\"result\" type=\"s\"/>\n"                        \
         "  </signal>"                                                   \
         "  <signal name=\"StartupFinished\">\n"                         \
+        "   <arg name=\"firmware\" type=\"t\"/>\n"                      \
+        "   <arg name=\"loader\" type=\"t\"/>\n"                        \
         "   <arg name=\"kernel\" type=\"t\"/>\n"                        \
         "   <arg name=\"initrd\" type=\"t\"/>\n"                        \
         "   <arg name=\"userspace\" type=\"t\"/>\n"                     \
@@ -226,10 +228,16 @@
         "  <property name=\"Distribution\" type=\"s\" access=\"read\"/>\n" \
         "  <property name=\"Features\" type=\"s\" access=\"read\"/>\n"  \
         "  <property name=\"Tainted\" type=\"s\" access=\"read\"/>\n"   \
+        "  <property name=\"FirmwareTimestamp\" type=\"t\" access=\"read\"/>\n" \
+        "  <property name=\"FirmwareTimestampMonotonic\" type=\"t\" access=\"read\"/>\n" \
+        "  <property name=\"LoaderTimestamp\" type=\"t\" access=\"read\"/>\n" \
+        "  <property name=\"LoaderTimestampMonotonic\" type=\"t\" access=\"read\"/>\n" \
+        "  <property name=\"KernelTimestamp\" type=\"t\" access=\"read\"/>\n" \
+        "  <property name=\"KernelTimestampMonotonic\" type=\"t\" access=\"read\"/>\n" \
         "  <property name=\"InitRDTimestamp\" type=\"t\" access=\"read\"/>\n" \
         "  <property name=\"InitRDTimestampMonotonic\" type=\"t\" access=\"read\"/>\n" \
-        "  <property name=\"StartupTimestamp\" type=\"t\" access=\"read\"/>\n" \
-        "  <property name=\"StartupTimestampMonotonic\" type=\"t\" access=\"read\"/>\n" \
+        "  <property name=\"UserspaceTimestamp\" type=\"t\" access=\"read\"/>\n" \
+        "  <property name=\"UserspaceTimestampMonotonic\" type=\"t\" access=\"read\"/>\n" \
         "  <property name=\"FinishTimestamp\" type=\"t\" access=\"read\"/>\n" \
         "  <property name=\"FinishTimestampMonotonic\" type=\"t\" access=\"read\"/>\n" \
         "  <property name=\"LogLevel\" type=\"s\" access=\"readwrite\"/>\n"  \
@@ -520,10 +528,16 @@ static const BusProperty bus_systemd_properties[] = {
 
 static const BusProperty bus_manager_properties[] = {
         { "Tainted",       bus_manager_append_tainted,             "s", 0                                              },
+        { "FirmwareTimestamp", bus_property_append_uint64,         "t", offsetof(Manager, firmware_timestamp.realtime) },
+        { "FirmwareTimestampMonotonic", bus_property_append_uint64,"t", offsetof(Manager, firmware_timestamp.monotonic)},
+        { "LoaderTimestamp", bus_property_append_uint64,           "t", offsetof(Manager, loader_timestamp.realtime)   },
+        { "LoaderTimestampMonotonic", bus_property_append_uint64,  "t", offsetof(Manager, loader_timestamp.monotonic)  },
+        { "KernelTimestamp", bus_property_append_uint64,           "t", offsetof(Manager, kernel_timestamp.realtime)   },
+        { "KernelTimestampMonotonic", bus_property_append_uint64,  "t", offsetof(Manager, kernel_timestamp.monotonic)  },
         { "InitRDTimestamp", bus_property_append_uint64,           "t", offsetof(Manager, initrd_timestamp.realtime)   },
         { "InitRDTimestampMonotonic", bus_property_append_uint64,  "t", offsetof(Manager, initrd_timestamp.monotonic)  },
-        { "StartupTimestamp", bus_property_append_uint64,          "t", offsetof(Manager, startup_timestamp.realtime)  },
-        { "StartupTimestampMonotonic", bus_property_append_uint64, "t", offsetof(Manager, startup_timestamp.monotonic) },
+        { "UserspaceTimestamp", bus_property_append_uint64,        "t", offsetof(Manager, userspace_timestamp.realtime)},
+        { "UserspaceTimestampMonotonic", bus_property_append_uint64,"t",offsetof(Manager, userspace_timestamp.monotonic)},
         { "FinishTimestamp", bus_property_append_uint64,           "t", offsetof(Manager, finish_timestamp.realtime)   },
         { "FinishTimestampMonotonic", bus_property_append_uint64,  "t", offsetof(Manager, finish_timestamp.monotonic)  },
         { "LogLevel",      bus_manager_append_log_level,           "s", 0,                                             false, bus_manager_set_log_level },
diff --git a/src/core/dbus.c b/src/core/dbus.c
index 1fc714823e..75773aaa49 100644
--- a/src/core/dbus.c
+++ b/src/core/dbus.c
@@ -1436,6 +1436,8 @@ int bus_fdset_add_all(Manager *m, FDSet *fds) {
 
 void bus_broadcast_finished(
                 Manager *m,
+                usec_t firmware_usec,
+                usec_t loader_usec,
                 usec_t kernel_usec,
                 usec_t initrd_usec,
                 usec_t userspace_usec,
@@ -1453,6 +1455,8 @@ void bus_broadcast_finished(
 
         assert_cc(sizeof(usec_t) == sizeof(uint64_t));
         if (!dbus_message_append_args(message,
+                                      DBUS_TYPE_UINT64, &firmware_usec,
+                                      DBUS_TYPE_UINT64, &loader_usec,
                                       DBUS_TYPE_UINT64, &kernel_usec,
                                       DBUS_TYPE_UINT64, &initrd_usec,
                                       DBUS_TYPE_UINT64, &userspace_usec,
diff --git a/src/core/dbus.h b/src/core/dbus.h
index 0502d7c251..c7a058e198 100644
--- a/src/core/dbus.h
+++ b/src/core/dbus.h
@@ -42,7 +42,7 @@ bool bus_connection_has_subscriber(Manager *m, DBusConnection *c);
 
 int bus_fdset_add_all(Manager *m, FDSet *fds);
 
-void bus_broadcast_finished(Manager *m, usec_t kernel_usec, usec_t initrd_usec, usec_t userspace_usec, usec_t total_usec);
+void bus_broadcast_finished(Manager *m, usec_t firmware_usec, usec_t loader_usec, usec_t kernel_usec, usec_t initrd_usec, usec_t userspace_usec, usec_t total_usec);
 
 #define BUS_CONNECTION_SUBSCRIBED(m, c) dbus_connection_get_data((c), (m)->subscribed_data_slot)
 #define BUS_PENDING_CALL_NAME(m, p) dbus_pending_call_get_data((p), (m)->name_data_slot)
diff --git a/src/core/manager.c b/src/core/manager.c
index 40b0c50851..23d8ca3d34 100644
--- a/src/core/manager.c
+++ b/src/core/manager.c
@@ -244,10 +244,11 @@ int manager_new(ManagerRunningAs running_as, Manager **_m) {
         assert(running_as >= 0);
         assert(running_as < _MANAGER_RUNNING_AS_MAX);
 
-        if (!(m = new0(Manager, 1)))
+        m = new0(Manager, 1);
+        if (!m)
                 return -ENOMEM;
 
-        dual_timestamp_get(&m->startup_timestamp);
+        dual_timestamp_get(&m->userspace_timestamp);
 
         m->running_as = running_as;
         m->name_data_slot = m->conn_data_slot = m->subscribed_data_slot = -1;
@@ -1741,10 +1742,13 @@ int manager_serialize(Manager *m, FILE *f, FDSet *fds, bool serialize_jobs) {
         fprintf(f, "n-installed-jobs=%u\n", m->n_installed_jobs);
         fprintf(f, "n-failed-jobs=%u\n", m->n_failed_jobs);
 
+        dual_timestamp_serialize(f, "firmware-timestamp", &m->firmware_timestamp);
+        dual_timestamp_serialize(f, "kernel-timestamp", &m->kernel_timestamp);
+        dual_timestamp_serialize(f, "loader-timestamp", &m->loader_timestamp);
         dual_timestamp_serialize(f, "initrd-timestamp", &m->initrd_timestamp);
 
         if (!in_initrd()) {
-                dual_timestamp_serialize(f, "startup-timestamp", &m->startup_timestamp);
+                dual_timestamp_serialize(f, "userspace-timestamp", &m->userspace_timestamp);
                 dual_timestamp_serialize(f, "finish-timestamp", &m->finish_timestamp);
         }
 
@@ -1836,10 +1840,16 @@ int manager_deserialize(Manager *m, FILE *f, FDSet *fds) {
                                 log_debug("Failed to parse taint /usr flag %s", l+10);
                         else
                                 m->taint_usr = m->taint_usr || b;
-                } else if (startswith(l, "initrd-timestamp="))
+                } else if (startswith(l, "firmware-timestamp="))
+                        dual_timestamp_deserialize(l+19, &m->firmware_timestamp);
+                else if (startswith(l, "loader-timestamp="))
+                        dual_timestamp_deserialize(l+17, &m->loader_timestamp);
+                else if (startswith(l, "kernel-timestamp="))
+                        dual_timestamp_deserialize(l+17, &m->kernel_timestamp);
+                else if (startswith(l, "initrd-timestamp="))
                         dual_timestamp_deserialize(l+17, &m->initrd_timestamp);
-                else if (startswith(l, "startup-timestamp="))
-                        dual_timestamp_deserialize(l+18, &m->startup_timestamp);
+                else if (startswith(l, "userspace-timestamp="))
+                        dual_timestamp_deserialize(l+20, &m->userspace_timestamp);
                 else if (startswith(l, "finish-timestamp="))
                         dual_timestamp_deserialize(l+17, &m->finish_timestamp);
                 else
@@ -2003,8 +2013,8 @@ bool manager_unit_pending_inactive(Manager *m, const char *name) {
 }
 
 void manager_check_finished(Manager *m) {
-        char userspace[FORMAT_TIMESPAN_MAX], initrd[FORMAT_TIMESPAN_MAX], kernel[FORMAT_TIMESPAN_MAX], sum[FORMAT_TIMESPAN_MAX];
-        usec_t kernel_usec, initrd_usec, userspace_usec, total_usec;
+        char firmware[FORMAT_TIMESPAN_MAX], loader[FORMAT_TIMESPAN_MAX], userspace[FORMAT_TIMESPAN_MAX], initrd[FORMAT_TIMESPAN_MAX], kernel[FORMAT_TIMESPAN_MAX], sum[FORMAT_TIMESPAN_MAX];
+        usec_t firmware_usec, loader_usec, kernel_usec, initrd_usec, userspace_usec, total_usec;
 
         assert(m);
 
@@ -2024,13 +2034,20 @@ void manager_check_finished(Manager *m) {
 
         if (m->running_as == MANAGER_SYSTEM && detect_container(NULL) <= 0) {
 
-                userspace_usec = m->finish_timestamp.monotonic - m->startup_timestamp.monotonic;
-                total_usec = m->finish_timestamp.monotonic;
+                /* Note that m->kernel_usec.monotonic is always at 0,
+                 * and m->firmware_usec.monotonic and
+                 * m->loader_usec.monotonic should be considered
+                 * negative values. */
+
+                firmware_usec = m->firmware_usec.monotonic - m->loader_timestamp.monotonic;
+                loader_usec = m->loader_usec.monotonic - m->kernel_usec.monotonic;
+                userspace_usec = m->finish_timestamp.monotonic - m->userspace_timestamp.monotonic;
+                total_usec = m->firmware_usec.monotonic + m->finish_timestamp.monotonic;
 
                 if (dual_timestamp_is_set(&m->initrd_timestamp)) {
 
-                        kernel_usec = m->initrd_timestamp.monotonic;
-                        initrd_usec = m->startup_timestamp.monotonic - m->initrd_timestamp.monotonic;
+                        kernel_usec = m->initrd_timestamp.monotonic - m->kernel_timestamp.monotonic;
+                        initrd_usec = m->userspace_timestamp.monotonic - m->initrd_timestamp.monotonic;
 
                         if (!log_on_console())
                                 log_struct(LOG_INFO,
@@ -2045,7 +2062,7 @@ void manager_check_finished(Manager *m) {
                                            format_timespan(sum, sizeof(sum), total_usec),
                                            NULL);
                 } else {
-                        kernel_usec = m->startup_timestamp.monotonic;
+                        kernel_usec = m->userspace_timestamp.monotonic - m->kernel_timestamp.monotonic;
                         initrd_usec = 0;
 
                         if (!log_on_console())
@@ -2060,8 +2077,8 @@ void manager_check_finished(Manager *m) {
                                            NULL);
                 }
         } else {
-                initrd_usec = kernel_usec = 0;
-                total_usec = userspace_usec = m->finish_timestamp.monotonic - m->startup_timestamp.monotonic;
+                firmware_usec = loader_usec = initrd_usec = kernel_usec = 0;
+                total_usec = userspace_usec = m->finish_timestamp.monotonic - m->userspace_timestamp.monotonic;
 
                 if (!log_on_console())
                         log_struct(LOG_INFO,
@@ -2072,7 +2089,7 @@ void manager_check_finished(Manager *m) {
                                    NULL);
         }
 
-        bus_broadcast_finished(m, kernel_usec, initrd_usec, userspace_usec, total_usec);
+        bus_broadcast_finished(m, firmware_usec, loader_usec, kernel_usec, initrd_usec, userspace_usec, total_usec);
 
         sd_notifyf(false,
                    "READY=1\nSTATUS=Startup finished in %s.",
diff --git a/src/core/manager.h b/src/core/manager.h
index 603c2dc318..653496ded0 100644
--- a/src/core/manager.h
+++ b/src/core/manager.h
@@ -146,8 +146,11 @@ struct Manager {
         usec_t runtime_watchdog;
         usec_t shutdown_watchdog;
 
+        dual_timestamp firmware_timestamp;
+        dual_timestamp loader_timestamp;
+        dual_timestamp kernel_timestamp;
         dual_timestamp initrd_timestamp;
-        dual_timestamp startup_timestamp;
+        dual_timestamp userspace_timestamp;
         dual_timestamp finish_timestamp;
 
         char *generator_unit_path;
diff --git a/src/core/timer.c b/src/core/timer.c
index 0b3c5ce077..03c9610eb6 100644
--- a/src/core/timer.c
+++ b/src/core/timer.c
@@ -222,7 +222,7 @@ static void timer_enter_waiting(Timer *t, bool initial) {
                         break;
 
                 case TIMER_STARTUP:
-                        base = UNIT(t)->manager->startup_timestamp.monotonic;
+                        base = UNIT(t)->manager->userspace_timestamp.monotonic;
                         break;
 
                 case TIMER_UNIT_ACTIVE: