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.

diff --git a/src/analyze/systemd-analyze b/src/analyze/systemd-analyze
index 76eceee9f0f236aa66abe4bc069ca5d3a82a51ff..636fd7422b4a682a6f1e760231ec3be5c65592dd 100755 (executable)
--- 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'))
         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)
 
         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()
 
 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 c341d36a6bb926cdccfcbd9aa319c07a032fe264..557b3e47630c83626115b8218d6b993a7136687f 100644 (file)
--- 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=\"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"                     \
         "   <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=\"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=\"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"  \
         "  <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                                              },
 
 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)  },
         { "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 },
         { "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 1fc714823e6b2538d93106053ae32b7a3414439d..75773aaa49cf2ad338aed62a2f87e6bafb0b4644 100644 (file)
--- 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,
 
 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 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,
 
         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,
                                       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 0502d7c251bcbc1a9ab15f50beacbb93b897a544..c7a058e198357d240f8f2e2b50e24e98fc90808e 100644 (file)
--- 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);
 
 
 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)
 
 #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 40b0c5085185e9fc6762b4d67eb1e425a38ec285..23d8ca3d34b80da1d0b4e7771d236a3048fc27a8 100644 (file)
--- 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);
 
         assert(running_as >= 0);
         assert(running_as < _MANAGER_RUNNING_AS_MAX);
 

-        if (!(m = new0(Manager, 1)))
+        m = new0(Manager, 1);
+        if (!m)

                 return -ENOMEM;
 
                 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;
 
         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);
 
         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, "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);
         }
 
                 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;
                                 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);
                         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
                 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) {
 }
 
 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);
 
 
         assert(m);
 


@@ -2024,13 +2034,20 @@ void manager_check_finished(Manager *m) {
 
         if (m->running_as == MANAGER_SYSTEM && detect_container(NULL) <= 0) {
 
 
         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)) {
 
 
                 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,
 
                         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 {
                                            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())
                         initrd_usec = 0;
 
                         if (!log_on_console())


@@ -2060,8 +2077,8 @@ void manager_check_finished(Manager *m) {
                                            NULL);
                 }
         } else {
                                            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,
 
                 if (!log_on_console())
                         log_struct(LOG_INFO,


@@ -2072,7 +2089,7 @@ void manager_check_finished(Manager *m) {
                                    NULL);
         }
 
                                    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.",
 
         sd_notifyf(false,
                    "READY=1\nSTATUS=Startup finished in %s.",

diff --git a/src/core/manager.h b/src/core/manager.h
index 603c2dc31824dfbb68371b369ab4e66f3e460aec..653496ded03039b91bafaae19fcf4c31126735b4 100644 (file)
--- a/src/core/manager.h
+++ b/src/core/manager.h
@@ -146,8 +146,11 @@ struct Manager {
         usec_t runtime_watchdog;
         usec_t shutdown_watchdog;
 
         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 initrd_timestamp;

-        dual_timestamp startup_timestamp;
+        dual_timestamp userspace_timestamp;

         dual_timestamp finish_timestamp;
 
         char *generator_unit_path;
         dual_timestamp finish_timestamp;
 
         char *generator_unit_path;

diff --git a/src/core/timer.c b/src/core/timer.c
index 0b3c5ce0770bbc37d0c775357619e72ef13b09c7..03c9610eb61d85fe92e674a3879d4c65e14dc2ea 100644 (file)
--- 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:
                         break;
 
                 case TIMER_STARTUP:

-                        base = UNIT(t)->manager->startup_timestamp.monotonic;
+                        base = UNIT(t)->manager->userspace_timestamp.monotonic;

                         break;
 
                 case TIMER_UNIT_ACTIVE:
                         break;
 
                 case TIMER_UNIT_ACTIVE: