chiark / gitweb /
manager: extend performance measurement interface to include firmware/loader times
[elogind.git] / src / core / manager.c
index 8f2635051e87a1a7bd0042e8382e664bbec0f103..23d8ca3d34b80da1d0b4e7771d236a3048fc27a8 100644 (file)
@@ -41,7 +41,9 @@
 #include <libaudit.h>
 #endif
 
-#include <systemd/sd-daemon.h>
+#include "systemd/sd-daemon.h"
+#include "systemd/sd-id128.h"
+#include "systemd/sd-messages.h"
 
 #include "manager.h"
 #include "transaction.h"
@@ -96,7 +98,7 @@ static int manager_setup_notify(Manager *m) {
         zero(sa);
         sa.sa.sa_family = AF_UNIX;
 
-        if (getpid() != 1)
+        if (getpid() != 1 || detect_container(NULL) > 0)
                 snprintf(sa.un.sun_path, sizeof(sa.un.sun_path), NOTIFY_SOCKET "/%llu", random_ull());
         else
                 strncpy(sa.un.sun_path, NOTIFY_SOCKET, sizeof(sa.un.sun_path));
@@ -242,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;
@@ -1625,7 +1628,7 @@ void manager_send_unit_plymouth(Manager *m, Unit *u) {
         }
 
         if (asprintf(&message, "U\002%c%s%n", (int) (strlen(u->id) + 1), u->id, &n) < 0) {
-                log_error("Out of memory");
+                log_oom();
                 goto finish;
         }
 
@@ -1722,7 +1725,7 @@ int manager_open_serialization(Manager *m, FILE **_f) {
         return 0;
 }
 
-int manager_serialize(Manager *m, FILE *f, FDSet *fds) {
+int manager_serialize(Manager *m, FILE *f, FDSet *fds, bool serialize_jobs) {
         Iterator i;
         Unit *u;
         const char *t;
@@ -1739,10 +1742,13 @@ int manager_serialize(Manager *m, FILE *f, FDSet *fds) {
         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);
         }
 
@@ -1759,7 +1765,7 @@ int manager_serialize(Manager *m, FILE *f, FDSet *fds) {
                 fputs(u->id, f);
                 fputc('\n', f);
 
-                if ((r = unit_serialize(u, f, fds)) < 0) {
+                if ((r = unit_serialize(u, f, fds, serialize_jobs)) < 0) {
                         m->n_reloading --;
                         return r;
                 }
@@ -1834,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
@@ -1899,7 +1911,7 @@ int manager_reload(Manager *m) {
                 goto finish;
         }
 
-        r = manager_serialize(m, f, fds);
+        r = manager_serialize(m, f, fds, true);
         if (r < 0) {
                 m->n_reloading --;
                 goto finish;
@@ -2001,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);
 
@@ -2022,37 +2034,62 @@ 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. */
 
-                if (dual_timestamp_is_set(&m->initrd_timestamp)) {
+                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;
 
-                        kernel_usec = m->initrd_timestamp.monotonic;
-                        initrd_usec = m->startup_timestamp.monotonic - m->initrd_timestamp.monotonic;
+                if (dual_timestamp_is_set(&m->initrd_timestamp)) {
 
-                        log_info("Startup finished in %s (kernel) + %s (initrd) + %s (userspace) = %s.",
-                                 format_timespan(kernel, sizeof(kernel), kernel_usec),
-                                 format_timespan(initrd, sizeof(initrd), initrd_usec),
-                                 format_timespan(userspace, sizeof(userspace), userspace_usec),
-                                 format_timespan(sum, sizeof(sum), total_usec));
+                        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,
+                                           "MESSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(SD_MESSAGE_STARTUP_FINISHED),
+                                           "KERNEL_USEC=%llu", (unsigned long long) kernel_usec,
+                                           "INITRD_USEC=%llu", (unsigned long long) initrd_usec,
+                                           "USERSPACE_USEC=%llu", (unsigned long long) userspace_usec,
+                                           "MESSAGE=Startup finished in %s (kernel) + %s (initrd) + %s (userspace) = %s.",
+                                           format_timespan(kernel, sizeof(kernel), kernel_usec),
+                                           format_timespan(initrd, sizeof(initrd), initrd_usec),
+                                           format_timespan(userspace, sizeof(userspace), userspace_usec),
+                                           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;
 
-                        log_info("Startup finished in %s (kernel) + %s (userspace) = %s.",
-                                 format_timespan(kernel, sizeof(kernel), kernel_usec),
-                                 format_timespan(userspace, sizeof(userspace), userspace_usec),
-                                 format_timespan(sum, sizeof(sum), total_usec));
+                        if (!log_on_console())
+                                log_struct(LOG_INFO,
+                                           "MESSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(SD_MESSAGE_STARTUP_FINISHED),
+                                           "KERNEL_USEC=%llu", (unsigned long long) kernel_usec,
+                                           "USERSPACE_USEC=%llu", (unsigned long long) userspace_usec,
+                                           "MESSAGE=Startup finished in %s (kernel) + %s (userspace) = %s.",
+                                           format_timespan(kernel, sizeof(kernel), kernel_usec),
+                                           format_timespan(userspace, sizeof(userspace), userspace_usec),
+                                           format_timespan(sum, sizeof(sum), total_usec),
+                                           NULL);
                 }
         } else {
-                userspace_usec = initrd_usec = kernel_usec = 0;
-                total_usec = m->finish_timestamp.monotonic - m->startup_timestamp.monotonic;
-
-                log_debug("Startup finished in %s.",
-                          format_timespan(sum, sizeof(sum), total_usec));
+                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,
+                                   "MESSAGE_ID=" SD_ID128_FORMAT_STR, SD_ID128_FORMAT_VAL(SD_MESSAGE_STARTUP_FINISHED),
+                                   "USERSPACE_USEC=%llu", (unsigned long long) userspace_usec,
+                                   "MESSAGE=Startup finished in %s.",
+                                   format_timespan(sum, sizeof(sum), total_usec),
+                                   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.",
@@ -2073,10 +2110,8 @@ static int create_generator_dir(Manager *m, char **generator, const char *name)
         if (m->running_as == MANAGER_SYSTEM && getpid() == 1) {
 
                 p = strappend("/run/systemd/", name);
-                if (!p) {
-                        log_error("Out of memory");
-                        return -ENOMEM;
-                }
+                if (!p)
+                        return log_oom();
 
                 r = mkdir_p_label(p, 0755);
                 if (r < 0) {
@@ -2086,10 +2121,8 @@ static int create_generator_dir(Manager *m, char **generator, const char *name)
                 }
         } else {
                 p = strjoin("/tmp/systemd-", name, ".XXXXXX", NULL);
-                if (!p) {
-                        log_error("Out of memory");
-                        return -ENOMEM;
-                }
+                if (!p)
+                        return log_oom();
 
                 if (!mkdtemp(p)) {
                         free(p);