From 8c15bf36e117054cf54b4f0cca59615b7531a545 Mon Sep 17 00:00:00 2001 From: Luca Boccassi Date: Fri, 20 Oct 2023 00:34:29 +0100 Subject: [PATCH 1/2] manager: serialize current objective So that we can tell what happened before the exec. It is overwritten shortly after deserialization. Use it to bump the soft reboots counter. --- src/core/main.c | 5 ----- src/core/manager-serialize.c | 11 +++++++++++ src/core/manager.c | 6 ++++++ src/core/manager.h | 2 ++ 4 files changed, 19 insertions(+), 5 deletions(-) diff --git a/src/core/main.c b/src/core/main.c index 8c8cf8b4a70..7ef66c86732 100644 --- a/src/core/main.c +++ b/src/core/main.c @@ -3192,11 +3192,6 @@ int main(int argc, char *argv[]) { goto finish; } - /* If we got a SoftRebootStart timestamp during deserialization, then we are in a new soft-reboot - * iteration, so bump the counter now before starting units, so that they can reliably read it. */ - if (dual_timestamp_is_set(&m->timestamps[MANAGER_TIMESTAMP_SOFTREBOOT_START])) - m->soft_reboots_count++; - /* This will close all file descriptors that were opened, but not claimed by any unit. */ fds = fdset_free(fds); arg_serialization = safe_fclose(arg_serialization); diff --git a/src/core/manager-serialize.c b/src/core/manager-serialize.c index 884332b3249..6008e5655e8 100644 --- a/src/core/manager-serialize.c +++ b/src/core/manager-serialize.c @@ -158,6 +158,9 @@ int manager_serialize( (void) serialize_ratelimit(f, "dump-ratelimit", &m->dump_ratelimit); (void) serialize_ratelimit(f, "reload-reexec-ratelimit", &m->reload_reexec_ratelimit); + if (m->objective >= 0 && m->objective < _MANAGER_OBJECTIVE_MAX) + (void) serialize_item_format(f, "previous-objective", "%u", (unsigned) m->objective); + bus_track_serialize(m->subscribed, f, "subscribed"); r = dynamic_user_serialize(m, f, fds); @@ -529,6 +532,14 @@ int manager_deserialize(Manager *m, FILE *f, FDSet *fds) { log_notice("Failed to parse soft reboots counter '%s', ignoring.", val); else m->soft_reboots_count = n; + } else if ((val = startswith(l, "previous-objective="))) { + unsigned n; + + if (safe_atou(val, &n) < 0 || n >= _MANAGER_OBJECTIVE_MAX) + log_notice("Failed to parse objective '%s', ignoring.", val); + else + m->previous_objective = n; + } else { ManagerTimestamp q; diff --git a/src/core/manager.c b/src/core/manager.c index 52f5e72e117..1fb0f7dd21c 100644 --- a/src/core/manager.c +++ b/src/core/manager.c @@ -882,6 +882,7 @@ int manager_new(RuntimeScope runtime_scope, ManagerTestRunFlags test_run_flags, *m = (Manager) { .runtime_scope = runtime_scope, .objective = _MANAGER_OBJECTIVE_INVALID, + .previous_objective = _MANAGER_OBJECTIVE_INVALID, .status_unit_format = STATUS_UNIT_FORMAT_DEFAULT, @@ -1973,6 +1974,11 @@ int manager_startup(Manager *m, FILE *serialization, FDSet *fds, const char *roo return log_error_errno(r, "Deserialization failed: %m"); } + /* If we are in a new soft-reboot iteration bump the counter now before starting units, so + * that they can reliably read it. We get the previous objective from serialized state. */ + if (m->previous_objective == MANAGER_SOFT_REBOOT) + m->soft_reboots_count++; + /* Any fds left? Find some unit which wants them. This is useful to allow container managers to pass * some file descriptors to us pre-initialized. This enables socket-based activation of entire * containers. */ diff --git a/src/core/manager.h b/src/core/manager.h index 9541a5e0b46..afc49a2f194 100644 --- a/src/core/manager.h +++ b/src/core/manager.h @@ -379,6 +379,8 @@ struct Manager { bool etc_localtime_accessible; ManagerObjective objective; + /* Objective as it was before serialization, mostly to detect soft-reboots */ + ManagerObjective previous_objective; /* Flags */ bool dispatching_load_queue; From b3f548615f529203c5efbc1ebdacbc6134d0da71 Mon Sep 17 00:00:00 2001 From: Luca Boccassi Date: Tue, 16 Apr 2024 15:33:09 +0100 Subject: [PATCH 2/2] core: rename SoftRebootStartTimestamp -> ShutdownStartTimestamp and generalize Follow-up for 54f86b86ba8168faccbfc2ad16ceeccefde98a51 --- man/org.freedesktop.systemd1.xml | 17 ++++++++--------- src/analyze/analyze-plot.c | 4 ++-- src/analyze/analyze-time-data.c | 16 ++++++++-------- src/analyze/analyze-time-data.h | 2 +- src/core/dbus-manager.c | 2 +- src/core/job.c | 7 +++++-- src/core/main.c | 12 ++++++++++-- src/core/manager.c | 6 +++--- src/core/manager.h | 2 +- 9 files changed, 39 insertions(+), 29 deletions(-) diff --git a/man/org.freedesktop.systemd1.xml b/man/org.freedesktop.systemd1.xml index 25b98c7ace4..6e90662fa9e 100644 --- a/man/org.freedesktop.systemd1.xml +++ b/man/org.freedesktop.systemd1.xml @@ -340,9 +340,9 @@ node /org/freedesktop/systemd1 { @org.freedesktop.DBus.Property.EmitsChangedSignal("const") readonly t FinishTimestampMonotonic = ...; @org.freedesktop.DBus.Property.EmitsChangedSignal("const") - readonly t SoftRebootStartTimestamp = ...; + readonly t ShutdownStartTimestamp = ...; @org.freedesktop.DBus.Property.EmitsChangedSignal("const") - readonly t SoftRebootStartTimestampMonotonic = ...; + readonly t ShutdownStartTimestampMonotonic = ...; @org.freedesktop.DBus.Property.EmitsChangedSignal("const") readonly t SecurityStartTimestamp = ...; @org.freedesktop.DBus.Property.EmitsChangedSignal("const") @@ -1039,9 +1039,9 @@ node /org/freedesktop/systemd1 { - + - + @@ -1746,12 +1746,11 @@ node /org/freedesktop/systemd1 { InitRDTimestamp, InitRDTimestampMonotonic, UserspaceTimestamp, UserspaceTimestampMonotonic, FinishTimestamp, FinishTimestampMonotonic, - SoftRebootStartTimestamp and SoftRebootStartTimestampMonotonic + ShutdownStartTimestamp and ShutdownStartTimestampMonotonic encode CLOCK_REALTIME and CLOCK_MONOTONIC microsecond timestamps taken when the firmware first began execution, when the boot loader first began execution, when the kernel first began execution, when the initrd first began execution, when the main systemd - instance began execution, when all queued startup jobs finished execution and finally, when a - systemd-soft-reboot.service8 + instance began execution, when all queued startup jobs finished execution and finally, when a shutdown operation first began execution. These values are useful for determining boot-time performance. Note that as monotonic time begins with the kernel startup, the KernelTimestampMonotonic timestamp will always be 0 and FirmwareTimestampMonotonic and @@ -12000,8 +11999,8 @@ $ gdbus introspect --system --dest org.freedesktop.systemd1 \ SoftReboot(), and DumpUnitFileDescriptorStore() were added in version 254. StartAuxiliaryScope(), - SoftRebootStartTimestamp, - SoftRebootStartTimestampMonotonic and + ShutdownStartTimestamp, + ShutdownStartTimestampMonotonic and SoftRebootsCount were added in version 256. diff --git a/src/analyze/analyze-plot.c b/src/analyze/analyze-plot.c index 797f23ae85a..e271296b687 100644 --- a/src/analyze/analyze-plot.c +++ b/src/analyze/analyze-plot.c @@ -316,7 +316,7 @@ static int produce_plot_as_svg( strempty(host->virtualization)); svg("\n", 20.0 + (SCALE_X * boot->firmware_time)); - if (timestamp_is_set(boot->softreboot_start_time)) + if (boot->soft_reboots_count > 0) svg_graph_box(m, 0, boot->finish_time); else svg_graph_box(m, -(double) boot->firmware_time, boot->finish_time); @@ -347,7 +347,7 @@ static int produce_plot_as_svg( svg_text(true, boot->initrd_time, y, "initrd"); y++; } - if (timestamp_is_set(boot->softreboot_start_time)) { + if (boot->soft_reboots_count > 0) { svg_bar("soft-reboot", 0, boot->userspace_time, y); svg_text(true, 0, y, "soft-reboot"); y++; diff --git a/src/analyze/analyze-time-data.c b/src/analyze/analyze-time-data.c index 94f6031893d..62e055dda4d 100644 --- a/src/analyze/analyze-time-data.c +++ b/src/analyze/analyze-time-data.c @@ -38,7 +38,7 @@ int acquire_boot_times(sd_bus *bus, bool require_finished, BootTimes **ret) { { "FinishTimestampMonotonic", "t", NULL, offsetof(BootTimes, finish_time) }, { "SecurityStartTimestampMonotonic", "t", NULL, offsetof(BootTimes, security_start_time) }, { "SecurityFinishTimestampMonotonic", "t", NULL, offsetof(BootTimes, security_finish_time) }, - { "SoftRebootStartTimestampMonotonic", "t", NULL, offsetof(BootTimes, softreboot_start_time) }, + { "ShutdownStartTimestampMonotonic", "t", NULL, offsetof(BootTimes, shutdown_start_time) }, { "GeneratorsStartTimestampMonotonic", "t", NULL, offsetof(BootTimes, generators_start_time) }, { "GeneratorsFinishTimestampMonotonic", "t", NULL, offsetof(BootTimes, generators_finish_time) }, { "UnitsLoadStartTimestampMonotonic", "t", NULL, offsetof(BootTimes, unitsload_start_time) }, @@ -83,13 +83,13 @@ int acquire_boot_times(sd_bus *bus, bool require_finished, BootTimes **ret) { if (require_finished && times.finish_time <= 0) return log_not_finished(times.finish_time); - if (arg_runtime_scope == RUNTIME_SCOPE_SYSTEM && timestamp_is_set(times.softreboot_start_time)) { + if (arg_runtime_scope == RUNTIME_SCOPE_SYSTEM && times.soft_reboots_count > 0) { /* On soft-reboot ignore kernel/firmware/initrd times as they are from the previous boot */ times.firmware_time = times.loader_time = times.kernel_time = times.initrd_time = times.initrd_security_start_time = times.initrd_security_finish_time = times.initrd_generators_start_time = times.initrd_generators_finish_time = times.initrd_unitsload_start_time = times.initrd_unitsload_finish_time = 0; - times.reverse_offset = times.softreboot_start_time; + times.reverse_offset = times.shutdown_start_time; /* Clamp all timestamps to avoid showing huge graphs */ if (timestamp_is_set(times.finish_time)) @@ -203,7 +203,7 @@ int pretty_boot_time(sd_bus *bus, char **ret) { return log_oom(); if (timestamp_is_set(t->initrd_time) && !strextend(&text, FORMAT_TIMESPAN(t->userspace_time - t->initrd_time, USEC_PER_MSEC), " (initrd) + ")) return log_oom(); - if (timestamp_is_set(t->softreboot_start_time) && strextendf(&text, "%s (soft reboot #%" PRIu64 ") + ", FORMAT_TIMESPAN(t->userspace_time, USEC_PER_MSEC), t->soft_reboots_count) < 0) + if (t->soft_reboots_count > 0 && strextendf(&text, "%s (soft reboot #%" PRIu64 ") + ", FORMAT_TIMESPAN(t->userspace_time, USEC_PER_MSEC), t->soft_reboots_count) < 0) return log_oom(); if (!strextend(&text, FORMAT_TIMESPAN(t->finish_time - t->userspace_time, USEC_PER_MSEC), " (userspace) ")) @@ -217,7 +217,7 @@ int pretty_boot_time(sd_bus *bus, char **ret) { usec_t base; /* On soft-reboot times are clamped to avoid showing huge graphs */ - if (timestamp_is_set(t->softreboot_start_time) && timestamp_is_set(t->userspace_time)) + if (t->soft_reboots_count > 0 && timestamp_is_set(t->userspace_time)) base = t->userspace_time + t->reverse_offset; else base = timestamp_is_set(t->userspace_time) ? t->userspace_time : t->reverse_offset; @@ -328,15 +328,15 @@ int acquire_time_data(sd_bus *bus, bool require_finished, UnitTimes **out) { u.id, bus_error_message(&error, r)); /* Activated in the previous soft-reboot iteration? Ignore it, we want new activations */ - if ((t->activated > 0 && t->activated < boot_times->softreboot_start_time) || - (t->activating > 0 && t->activating < boot_times->softreboot_start_time)) + if ((t->activated > 0 && t->activated < boot_times->shutdown_start_time) || + (t->activating > 0 && t->activating < boot_times->shutdown_start_time)) continue; subtract_timestamp(&t->activating, boot_times->reverse_offset); subtract_timestamp(&t->activated, boot_times->reverse_offset); /* If the last deactivation was in the previous soft-reboot, ignore it */ - if (timestamp_is_set(boot_times->softreboot_start_time)) { + if (boot_times->soft_reboots_count > 0) { if (t->deactivating < boot_times->reverse_offset) t->deactivating = 0; else diff --git a/src/analyze/analyze-time-data.h b/src/analyze/analyze-time-data.h index 1932d59c3d4..e7ffd8549d8 100644 --- a/src/analyze/analyze-time-data.h +++ b/src/analyze/analyze-time-data.h @@ -14,7 +14,7 @@ typedef struct BootTimes { usec_t initrd_time; usec_t userspace_time; usec_t finish_time; - usec_t softreboot_start_time; + usec_t shutdown_start_time; usec_t security_start_time; usec_t security_finish_time; usec_t generators_start_time; diff --git a/src/core/dbus-manager.c b/src/core/dbus-manager.c index 7077d44723b..397919dd300 100644 --- a/src/core/dbus-manager.c +++ b/src/core/dbus-manager.c @@ -3052,7 +3052,7 @@ const sd_bus_vtable bus_manager_vtable[] = { BUS_PROPERTY_DUAL_TIMESTAMP("InitRDTimestamp", offsetof(Manager, timestamps[MANAGER_TIMESTAMP_INITRD]), SD_BUS_VTABLE_PROPERTY_CONST), BUS_PROPERTY_DUAL_TIMESTAMP("UserspaceTimestamp", offsetof(Manager, timestamps[MANAGER_TIMESTAMP_USERSPACE]), SD_BUS_VTABLE_PROPERTY_CONST), BUS_PROPERTY_DUAL_TIMESTAMP("FinishTimestamp", offsetof(Manager, timestamps[MANAGER_TIMESTAMP_FINISH]), SD_BUS_VTABLE_PROPERTY_CONST), - BUS_PROPERTY_DUAL_TIMESTAMP("SoftRebootStartTimestamp", offsetof(Manager, timestamps[MANAGER_TIMESTAMP_SOFTREBOOT_START]), SD_BUS_VTABLE_PROPERTY_CONST), + BUS_PROPERTY_DUAL_TIMESTAMP("ShutdownStartTimestamp", offsetof(Manager, timestamps[MANAGER_TIMESTAMP_SHUTDOWN_START]), SD_BUS_VTABLE_PROPERTY_CONST), BUS_PROPERTY_DUAL_TIMESTAMP("SecurityStartTimestamp", offsetof(Manager, timestamps[MANAGER_TIMESTAMP_SECURITY_START]), SD_BUS_VTABLE_PROPERTY_CONST), BUS_PROPERTY_DUAL_TIMESTAMP("SecurityFinishTimestamp", offsetof(Manager, timestamps[MANAGER_TIMESTAMP_SECURITY_FINISH]), SD_BUS_VTABLE_PROPERTY_CONST), BUS_PROPERTY_DUAL_TIMESTAMP("GeneratorsStartTimestamp", offsetof(Manager, timestamps[MANAGER_TIMESTAMP_GENERATORS_START]), SD_BUS_VTABLE_PROPERTY_CONST), diff --git a/src/core/job.c b/src/core/job.c index 595fbce93ae..c6b48035a79 100644 --- a/src/core/job.c +++ b/src/core/job.c @@ -1387,10 +1387,13 @@ void job_shutdown_magic(Job *j) { if (j->type != JOB_START) return; - if (!MANAGER_IS_SYSTEM(j->unit->manager)) + if (!unit_has_name(j->unit, SPECIAL_SHUTDOWN_TARGET)) return; - if (!unit_has_name(j->unit, SPECIAL_SHUTDOWN_TARGET)) + /* This is the very beginning of the shutdown phase, so take the timestamp here */ + dual_timestamp_now(ASSERT_PTR(j->manager)->timestamps + MANAGER_TIMESTAMP_SHUTDOWN_START); + + if (!MANAGER_IS_SYSTEM(j->manager)) return; /* In case messages on console has been disabled on boot */ diff --git a/src/core/main.c b/src/core/main.c index 7ef66c86732..83a2b5b6614 100644 --- a/src/core/main.c +++ b/src/core/main.c @@ -2041,6 +2041,16 @@ static int invoke_main_loop( "MESSAGE_ID=" SD_MESSAGE_CORE_MAINLOOP_FAILED_STR); } + /* Ensure shutdown timestamp is taken even when bypassing the job engine */ + if (IN_SET(objective, + MANAGER_SOFT_REBOOT, + 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); + switch (objective) { case MANAGER_RELOAD: { @@ -2129,8 +2139,6 @@ static int invoke_main_loop( manager_send_reloading(m); manager_set_switching_root(m, true); - dual_timestamp_now(m->timestamps + MANAGER_TIMESTAMP_SOFTREBOOT_START); - r = prepare_reexecute(m, &arg_serialization, ret_fds, /* switching_root= */ true); if (r < 0) { *ret_error_message = "Failed to prepare for reexecution"; diff --git a/src/core/manager.c b/src/core/manager.c index 1fb0f7dd21c..3ffe0f87c0c 100644 --- a/src/core/manager.c +++ b/src/core/manager.c @@ -3695,10 +3695,10 @@ static void manager_notify_finished(Manager *m) { if (MANAGER_IS_TEST_RUN(m)) return; - if (MANAGER_IS_SYSTEM(m) && dual_timestamp_is_set(&m->timestamps[MANAGER_TIMESTAMP_SOFTREBOOT_START])) { + if (MANAGER_IS_SYSTEM(m) && m->soft_reboots_count > 0) { /* The soft-reboot case, where we only report data for the last reboot */ firmware_usec = loader_usec = initrd_usec = kernel_usec = 0; - total_usec = userspace_usec = usec_sub_unsigned(m->timestamps[MANAGER_TIMESTAMP_FINISH].monotonic, m->timestamps[MANAGER_TIMESTAMP_SOFTREBOOT_START].monotonic); + total_usec = userspace_usec = usec_sub_unsigned(m->timestamps[MANAGER_TIMESTAMP_FINISH].monotonic, m->timestamps[MANAGER_TIMESTAMP_SHUTDOWN_START].monotonic); log_struct(LOG_INFO, "MESSAGE_ID=" SD_MESSAGE_STARTUP_FINISHED_STR, @@ -5052,7 +5052,6 @@ static const char *const manager_timestamp_table[_MANAGER_TIMESTAMP_MAX] = { [MANAGER_TIMESTAMP_INITRD] = "initrd", [MANAGER_TIMESTAMP_USERSPACE] = "userspace", [MANAGER_TIMESTAMP_FINISH] = "finish", - [MANAGER_TIMESTAMP_SOFTREBOOT_START] = "softreboot-start", [MANAGER_TIMESTAMP_SECURITY_START] = "security-start", [MANAGER_TIMESTAMP_SECURITY_FINISH] = "security-finish", [MANAGER_TIMESTAMP_GENERATORS_START] = "generators-start", @@ -5066,6 +5065,7 @@ static const char *const manager_timestamp_table[_MANAGER_TIMESTAMP_MAX] = { [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", }; DEFINE_STRING_TABLE_LOOKUP(manager_timestamp, ManagerTimestamp); diff --git a/src/core/manager.h b/src/core/manager.h index afc49a2f194..70ae78aa849 100644 --- a/src/core/manager.h +++ b/src/core/manager.h @@ -121,7 +121,7 @@ typedef enum ManagerTimestamp { MANAGER_TIMESTAMP_INITRD_UNITS_LOAD_START, MANAGER_TIMESTAMP_INITRD_UNITS_LOAD_FINISH, - MANAGER_TIMESTAMP_SOFTREBOOT_START, + MANAGER_TIMESTAMP_SHUTDOWN_START, _MANAGER_TIMESTAMP_MAX, _MANAGER_TIMESTAMP_INVALID = -EINVAL,