core/shutdown: add more shutdown timestamps

We already record when shutdown.target is initiated (ShutdownStart).
This adds a few more measuring points during shutdown: when
shutdown.target completes (i.e., all units stopped), when the shutdown
binary starts executing, and immediately before it hands off to the
kernel.

Obviously these are immediately lost upon reboot. But they will later
be wired in LUO so they get preserved on kexec, and can be inspected,
which is very useful for performance measurements.

diff --git a/src/core/main.c b/src/core/main.c
index 810da526d785520e6cdd1c63c5ebdd9897ee0397..30092626485b1df622f05b6a72d3344195338abe 100644 (file)
--- a/src/core/main.c
+++ b/src/core/main.c
@@ -2340,9 +2340,14 @@ static int invoke_main_loop(
                            MANAGER_REBOOT,
                            MANAGER_KEXEC,
                            MANAGER_HALT,
-                           MANAGER_POWEROFF) &&
-                    !dual_timestamp_is_set(m->timestamps + MANAGER_TIMESTAMP_SHUTDOWN_START))
-                        dual_timestamp_now(m->timestamps + MANAGER_TIMESTAMP_SHUTDOWN_START);
+                           MANAGER_POWEROFF)) {
+                        dual_timestamp ts;
+
+                        dual_timestamp_now(&ts);
+                        if (!dual_timestamp_is_set(m->timestamps + MANAGER_TIMESTAMP_SHUTDOWN_START))
+                                m->timestamps[MANAGER_TIMESTAMP_SHUTDOWN_START] = ts;
+                        m->timestamps[MANAGER_TIMESTAMP_SHUTDOWN_FINISH] = ts;
+                }
 
                 switch (objective) {
 

diff --git a/src/core/manager.c b/src/core/manager.c
index 015f575ac1b5ee755407afa838776efc449ac41b..f965e0a33a1d51d718c20f366ea27a82dfd3b10e 100644 (file)
--- a/src/core/manager.c
+++ b/src/core/manager.c
@@ -5577,26 +5577,31 @@ static const char* const manager_objective_table[_MANAGER_OBJECTIVE_MAX] = {
 DEFINE_STRING_TABLE_LOOKUP(manager_objective, ManagerObjective);
 
 static const char* const manager_timestamp_table[_MANAGER_TIMESTAMP_MAX] = {
-        [MANAGER_TIMESTAMP_FIRMWARE]                 = "firmware",
-        [MANAGER_TIMESTAMP_LOADER]                   = "loader",
-        [MANAGER_TIMESTAMP_KERNEL]                   = "kernel",
-        [MANAGER_TIMESTAMP_INITRD]                   = "initrd",
-        [MANAGER_TIMESTAMP_USERSPACE]                = "userspace",
-        [MANAGER_TIMESTAMP_FINISH]                   = "finish",
-        [MANAGER_TIMESTAMP_SECURITY_START]           = "security-start",
-        [MANAGER_TIMESTAMP_SECURITY_FINISH]          = "security-finish",
-        [MANAGER_TIMESTAMP_GENERATORS_START]         = "generators-start",
-        [MANAGER_TIMESTAMP_GENERATORS_FINISH]        = "generators-finish",
-        [MANAGER_TIMESTAMP_UNITS_LOAD_START]         = "units-load-start",
-        [MANAGER_TIMESTAMP_UNITS_LOAD_FINISH]        = "units-load-finish",
-        [MANAGER_TIMESTAMP_UNITS_LOAD]               = "units-load",
-        [MANAGER_TIMESTAMP_INITRD_SECURITY_START]    = "initrd-security-start",
-        [MANAGER_TIMESTAMP_INITRD_SECURITY_FINISH]   = "initrd-security-finish",
-        [MANAGER_TIMESTAMP_INITRD_GENERATORS_START]  = "initrd-generators-start",
-        [MANAGER_TIMESTAMP_INITRD_GENERATORS_FINISH] = "initrd-generators-finish",
-        [MANAGER_TIMESTAMP_INITRD_UNITS_LOAD_START]  = "initrd-units-load-start",
-        [MANAGER_TIMESTAMP_INITRD_UNITS_LOAD_FINISH] = "initrd-units-load-finish",
-        [MANAGER_TIMESTAMP_SHUTDOWN_START]           = "shutdown-start",
+        [MANAGER_TIMESTAMP_FIRMWARE]                      = "firmware",
+        [MANAGER_TIMESTAMP_LOADER]                        = "loader",
+        [MANAGER_TIMESTAMP_KERNEL]                        = "kernel",
+        [MANAGER_TIMESTAMP_INITRD]                        = "initrd",
+        [MANAGER_TIMESTAMP_USERSPACE]                     = "userspace",
+        [MANAGER_TIMESTAMP_FINISH]                        = "finish",
+        [MANAGER_TIMESTAMP_SECURITY_START]                = "security-start",
+        [MANAGER_TIMESTAMP_SECURITY_FINISH]               = "security-finish",
+        [MANAGER_TIMESTAMP_GENERATORS_START]              = "generators-start",
+        [MANAGER_TIMESTAMP_GENERATORS_FINISH]             = "generators-finish",
+        [MANAGER_TIMESTAMP_UNITS_LOAD_START]              = "units-load-start",
+        [MANAGER_TIMESTAMP_UNITS_LOAD_FINISH]             = "units-load-finish",
+        [MANAGER_TIMESTAMP_UNITS_LOAD]                    = "units-load",
+        [MANAGER_TIMESTAMP_INITRD_SECURITY_START]         = "initrd-security-start",
+        [MANAGER_TIMESTAMP_INITRD_SECURITY_FINISH]        = "initrd-security-finish",
+        [MANAGER_TIMESTAMP_INITRD_GENERATORS_START]       = "initrd-generators-start",
+        [MANAGER_TIMESTAMP_INITRD_GENERATORS_FINISH]      = "initrd-generators-finish",
+        [MANAGER_TIMESTAMP_INITRD_UNITS_LOAD_START]       = "initrd-units-load-start",
+        [MANAGER_TIMESTAMP_INITRD_UNITS_LOAD_FINISH]      = "initrd-units-load-finish",
+        [MANAGER_TIMESTAMP_SHUTDOWN_START]                = "shutdown-start",
+        [MANAGER_TIMESTAMP_SHUTDOWN_FINISH]               = "shutdown-finish",
+        [MANAGER_TIMESTAMP_PREVIOUS_SHUTDOWN_START]       = "previous-shutdown-start",
+        [MANAGER_TIMESTAMP_PREVIOUS_SHUTDOWN_FINISH]      = "previous-shutdown-finish",
+        [MANAGER_TIMESTAMP_PREVIOUS_SHUTDOWN_LATE_START]  = "previous-shutdown-late-start",
+        [MANAGER_TIMESTAMP_PREVIOUS_SHUTDOWN_LATE_FINISH] = "previous-shutdown-late-finish",
 };
 
 DEFINE_STRING_TABLE_LOOKUP(manager_timestamp, ManagerTimestamp);

diff --git a/src/core/manager.h b/src/core/manager.h
index a2f0644ef0f4ae685e0ac479b70a757fa905932a..91555e5ad0c93eebbcc7380d3e1a6e2eb7e587cf 100644 (file)
--- a/src/core/manager.h
+++ b/src/core/manager.h
@@ -78,6 +78,16 @@ typedef enum ManagerObjective {
  * 6. TIMESTAMP_USERSPACE is the timestamp of when the manager was started.
  *
  * 7. TIMESTAMP_INITRD_* are set only when the system is booted with an initrd.
+ *
+ * 8. TIMESTAMP_SHUTDOWN_START and TIMESTAMP_SHUTDOWN_FINISH bracket the unit-stopping phase during the
+ *    current shutdown (the latter is also propagated across soft-reboot).
+ *
+ * 9. TIMESTAMP_PREVIOUS_SHUTDOWN_START, TIMESTAMP_PREVIOUS_SHUTDOWN_FINISH,
+ *    TIMESTAMP_PREVIOUS_SHUTDOWN_LATE_START and TIMESTAMP_PREVIOUS_SHUTDOWN_LATE_FINISH describe the
+ *    shutdown of the *previous* boot, restored from the LUO payload after a kexec-based live update
+ *    (the LATE_* ones are taken by systemd-shutdown). Like TIMESTAMP_FIRMWARE/LOADER/KERNEL they refer
+ *    to events before the current systemd cycle took over, hence they are kept distinct from the
+ *    current cycle's SHUTDOWN_START/FINISH instead of overwriting them.
  */
 
 typedef enum ManagerTimestamp {
@@ -104,6 +114,12 @@ typedef enum ManagerTimestamp {
         MANAGER_TIMESTAMP_INITRD_UNITS_LOAD_FINISH,
 
         MANAGER_TIMESTAMP_SHUTDOWN_START,
+        MANAGER_TIMESTAMP_SHUTDOWN_FINISH,
+
+        MANAGER_TIMESTAMP_PREVIOUS_SHUTDOWN_START,
+        MANAGER_TIMESTAMP_PREVIOUS_SHUTDOWN_FINISH,
+        MANAGER_TIMESTAMP_PREVIOUS_SHUTDOWN_LATE_START,
+        MANAGER_TIMESTAMP_PREVIOUS_SHUTDOWN_LATE_FINISH,
 
         _MANAGER_TIMESTAMP_MAX,
         _MANAGER_TIMESTAMP_INVALID = -EINVAL,

diff --git a/src/shutdown/shutdown.c b/src/shutdown/shutdown.c
index bb68c1159235684e12f53902e7e28d5fea3591bc..bc1f41d990418bc574cbe82613961cdafde89cfd 100644 (file)
--- a/src/shutdown/shutdown.c
+++ b/src/shutdown/shutdown.c
@@ -374,9 +374,13 @@ int main(int argc, char *argv[]) {
         _cleanup_close_ int luo_session_fd = -EBADF;
         _cleanup_free_ int *luo_fds = NULL;
         _cleanup_free_ char *cgroup = NULL;
+        dual_timestamp shutdown_late_start;
         size_t n_luo_fds = 0;
         int cmd, r;
 
+        /* LUO will preserve these across kexec */
+        dual_timestamp_now(&shutdown_late_start);
+
         /* If PID 1 passed us an LUO serialization fd, parse it first so we know which fds to keep open. */
         (void) luo_parse_serialization(&luo_serialization, &luo_fds, &n_luo_fds);
 
@@ -642,6 +646,11 @@ int main(int argc, char *argv[]) {
 
         sleep_until_minimum_uptime();
 
+        /* This is conceptually where shutdown is complete and only the final syscall to bring the machine
+         * down is left, so record the late shutdown timestamp here. */
+        dual_timestamp shutdown_late_finish;
+        dual_timestamp_now(&shutdown_late_finish);
+
         if (streq(arg_verb, "exit")) {
                 if (in_container) {
                         log_info("Exiting container.");