core: add all manager timestamps to metrics report

These are all very useful for establishing the health of a fleet,
so export them too

Follow-up for 0b0db27050595251b40b4e7cf56593a275eaf3c2

diff --git a/src/core/varlink-metrics.c b/src/core/varlink-metrics.c
index 0e6bfa961890da40e42b1eb3ad694146265c25e3..5232da633c0cd72653920759ce0e0559b9c573f1 100644 (file)
--- a/src/core/varlink-metrics.c
+++ b/src/core/varlink-metrics.c
@@ -98,57 +98,231 @@ static int version_build_json(const MetricFamily *mf, sd_varlink *vl, void *user
                         /* fields= */ NULL);
 }
 
-static int boot_timestamp_build_json(
-                const MetricFamily *mf,
-                sd_varlink *vl,
-                const dual_timestamp *t,
-                bool with_monotonic) {
+/* Single source of truth for all manager timestamp metrics, driving both List (the values) and Describe
+ * (the schema advertised below). The .description is prefixed with "CLOCK_REALTIME "/"CLOCK_MONOTONIC " on
+ * emission; firmware, loader and kernel have no meaningful monotonic value (a pre-kernel offset or zero),
+ * hence they only expose the .Realtime metric (with_monotonic=false). */
+static const struct {
+        const char *name;
+        bool with_monotonic;
+        const char *description;
+} manager_timestamp_metrics[_MANAGER_TIMESTAMP_MAX] = {
+        [MANAGER_TIMESTAMP_FIRMWARE] = {
+                .name = "FirmwareTimestamp",
+                .with_monotonic = false,
+                .description = "microseconds at which the firmware began execution (CLOCK_MONOTONIC is a pre-kernel offset, not reported)",
+        },
+        [MANAGER_TIMESTAMP_LOADER] = {
+                .name = "LoaderTimestamp",
+                .with_monotonic = false,
+                .description = "microseconds at which the boot loader began execution (CLOCK_MONOTONIC is a pre-kernel offset, not reported)",
+        },
+        [MANAGER_TIMESTAMP_KERNEL] = {
+                .name = "KernelTimestamp",
+                .with_monotonic = false,
+                .description = "microseconds at which the kernel started (CLOCK_MONOTONIC == 0)",
+        },
+        [MANAGER_TIMESTAMP_INITRD] = {
+                .name = "InitRDTimestamp",
+                .with_monotonic = true,
+                .description = "microseconds at which the initrd began execution",
+        },
+        [MANAGER_TIMESTAMP_USERSPACE] = {
+                .name = "UserspaceTimestamp",
+                .with_monotonic = true,
+                .description = "microseconds at which userspace was reached",
+        },
+        [MANAGER_TIMESTAMP_FINISH] = {
+                .name = "FinishTimestamp",
+                .with_monotonic = true,
+                .description = "microseconds at which userspace finished booting",
+        },
+        [MANAGER_TIMESTAMP_SECURITY_START] = {
+                .name = "SecurityStartTimestamp",
+                .with_monotonic = true,
+                .description = "microseconds at which the manager started uploading security policies to the kernel",
+        },
+        [MANAGER_TIMESTAMP_SECURITY_FINISH] = {
+                .name = "SecurityFinishTimestamp",
+                .with_monotonic = true,
+                .description = "microseconds at which the manager finished uploading security policies to the kernel",
+        },
+        [MANAGER_TIMESTAMP_GENERATORS_START] = {
+                .name = "GeneratorsStartTimestamp",
+                .with_monotonic = true,
+                .description = "microseconds at which the manager started executing generators",
+        },
+        [MANAGER_TIMESTAMP_GENERATORS_FINISH] = {
+                .name = "GeneratorsFinishTimestamp",
+                .with_monotonic = true,
+                .description = "microseconds at which the manager finished executing generators",
+        },
+        [MANAGER_TIMESTAMP_UNITS_LOAD_START] = {
+                .name = "UnitsLoadStartTimestamp",
+                .with_monotonic = true,
+                .description = "microseconds at which the manager first started loading units",
+        },
+        [MANAGER_TIMESTAMP_UNITS_LOAD_FINISH] = {
+                .name = "UnitsLoadFinishTimestamp",
+                .with_monotonic = true,
+                .description = "microseconds at which the manager first finished loading units",
+        },
+        [MANAGER_TIMESTAMP_UNITS_LOAD] = {
+                .name = "UnitsLoadTimestamp",
+                .with_monotonic = true,
+                .description = "microseconds at which the manager last started loading units",
+        },
+        [MANAGER_TIMESTAMP_INITRD_SECURITY_START] = {
+                .name = "InitRDSecurityStartTimestamp",
+                .with_monotonic = true,
+                .description = "microseconds at which the manager started uploading security policies to the kernel in the initrd",
+        },
+        [MANAGER_TIMESTAMP_INITRD_SECURITY_FINISH] = {
+                .name = "InitRDSecurityFinishTimestamp",
+                .with_monotonic = true,
+                .description = "microseconds at which the manager finished uploading security policies to the kernel in the initrd",
+        },
+        [MANAGER_TIMESTAMP_INITRD_GENERATORS_START] = {
+                .name = "InitRDGeneratorsStartTimestamp",
+                .with_monotonic = true,
+                .description = "microseconds at which the manager started executing generators in the initrd",
+        },
+        [MANAGER_TIMESTAMP_INITRD_GENERATORS_FINISH] = {
+                .name = "InitRDGeneratorsFinishTimestamp",
+                .with_monotonic = true,
+                .description = "microseconds at which the manager finished executing generators in the initrd",
+        },
+        [MANAGER_TIMESTAMP_INITRD_UNITS_LOAD_START] = {
+                .name = "InitRDUnitsLoadStartTimestamp",
+                .with_monotonic = true,
+                .description = "microseconds at which the manager first started loading units in the initrd",
+        },
+        [MANAGER_TIMESTAMP_INITRD_UNITS_LOAD_FINISH] = {
+                .name = "InitRDUnitsLoadFinishTimestamp",
+                .with_monotonic = true,
+                .description = "microseconds at which the manager first finished loading units in the initrd",
+        },
+        [MANAGER_TIMESTAMP_SHUTDOWN_START] = {
+                .name = "ShutdownStartTimestamp",
+                .with_monotonic = true,
+                .description = "microseconds at which shutdown began, i.e. units started to be stopped",
+        },
+        [MANAGER_TIMESTAMP_SHUTDOWN_FINISH] = {
+                .name = "ShutdownFinishTimestamp",
+                .with_monotonic = true,
+                .description = "microseconds at which all units finished stopping during shutdown",
+        },
+        [MANAGER_TIMESTAMP_PREVIOUS_SHUTDOWN_START] = {
+                .name = "PreviousShutdownStartTimestamp",
+                .with_monotonic = true,
+                .description = "microseconds at which shutdown began during the previous boot, i.e. units started to be stopped, if available (e.g.: kexec or soft-reboot)",
+        },
+        [MANAGER_TIMESTAMP_PREVIOUS_SHUTDOWN_FINISH] = {
+                .name = "PreviousShutdownFinishTimestamp",
+                .with_monotonic = true,
+                .description = "microseconds at which all units finished stopping during the shutdown of the previous boot, if available (e.g.: kexec or soft-reboot)",
+        },
+        [MANAGER_TIMESTAMP_PREVIOUS_SHUTDOWN_LATE_START] = {
+                .name = "PreviousShutdownLateStartTimestamp",
+                .with_monotonic = true,
+                .description = "microseconds at which systemd-shutdown began execution during the previous boot, restored from the LUO payload after a kexec-based live update",
+        },
+        [MANAGER_TIMESTAMP_PREVIOUS_SHUTDOWN_LATE_FINISH] = {
+                .name = "PreviousShutdownLateFinishTimestamp",
+                .with_monotonic = true,
+                .description = "microseconds at which systemd-shutdown was about to kexec into the current kernel during the previous boot, restored from the LUO payload after a kexec-based live update",
+        },
+};
 
+static int manager_timestamps_build_json(sd_varlink *vl, void *userdata) {
+        Manager *manager = ASSERT_PTR(userdata);
         int r;
 
-        assert(mf && mf->name);
         assert(vl);
-        assert(t);
 
-        if (timestamp_is_set(t->realtime)) {
-                r = metric_build_send_unsigned(
-                                mf,  /* the .Realtime metric family entry */
-                                vl,
-                                /* object= */ NULL,
-                                t->realtime,
-                                /* fields= */ NULL);
-                if (r < 0)
-                        return r;
-        }
+        FOREACH_ELEMENT(i, manager_timestamp_metrics) {
+                if (!i->name)
+                        continue;
 
-        if (with_monotonic && timestamp_is_set(t->monotonic)) {
-                assert(endswith(mf[1].name, ".Monotonic"));
-                r = metric_build_send_unsigned(
-                                mf + 1,  /* the .Monotonic sibling is the next entry */
-                                vl,
-                                /* object= */ NULL,
-                                t->monotonic,
-                                /* fields= */ NULL);
-                if (r < 0)
-                        return r;
+                const dual_timestamp *t = manager->timestamps + (i - manager_timestamp_metrics);
+
+                if (timestamp_is_set(t->realtime)) {
+                        _cleanup_free_ char *name = strjoin(METRIC_IO_SYSTEMD_MANAGER_PREFIX, i->name, ".Realtime");
+                        if (!name)
+                                return -ENOMEM;
+
+                        r = metric_build_send_unsigned(
+                                        &(const MetricFamily) { .name = name },
+                                        vl,
+                                        /* object= */ NULL,
+                                        t->realtime,
+                                        /* fields= */ NULL);
+                        if (r < 0)
+                                return r;
+                }
+
+                if (i->with_monotonic && timestamp_is_set(t->monotonic)) {
+                        _cleanup_free_ char *name = strjoin(METRIC_IO_SYSTEMD_MANAGER_PREFIX, i->name, ".Monotonic");
+                        if (!name)
+                                return -ENOMEM;
+
+                        r = metric_build_send_unsigned(
+                                        &(const MetricFamily) { .name = name },
+                                        vl,
+                                        /* object= */ NULL,
+                                        t->monotonic,
+                                        /* fields= */ NULL);
+                        if (r < 0)
+                                return r;
+                }
         }
 
         return 0;
 }
 
-static int kernel_timestamp_build_json(const MetricFamily *mf, sd_varlink *vl, void *userdata) {
-        Manager *manager = ASSERT_PTR(userdata);
-        return boot_timestamp_build_json(mf, vl, &manager->timestamps[MANAGER_TIMESTAMP_KERNEL], /* with_monotonic= */ false);
-}
+static int manager_timestamps_describe(sd_varlink *link) {
+        int r;
 
-static int userspace_timestamp_build_json(const MetricFamily *mf, sd_varlink *vl, void *userdata) {
-        Manager *manager = ASSERT_PTR(userdata);
-        return boot_timestamp_build_json(mf, vl, &manager->timestamps[MANAGER_TIMESTAMP_USERSPACE], /* with_monotonic= */ true);
-}
+        assert(link);
 
-static int finish_timestamp_build_json(const MetricFamily *mf, sd_varlink *vl, void *userdata) {
-        Manager *manager = ASSERT_PTR(userdata);
-        return boot_timestamp_build_json(mf, vl, &manager->timestamps[MANAGER_TIMESTAMP_FINISH], /* with_monotonic= */ true);
+        FOREACH_ELEMENT(i, manager_timestamp_metrics) {
+                if (!i->name)
+                        continue;
+
+                _cleanup_free_ char *rt_name = strjoin(METRIC_IO_SYSTEMD_MANAGER_PREFIX, i->name, ".Realtime");
+                _cleanup_free_ char *rt_description = strjoin("CLOCK_REALTIME ", i->description);
+                if (!rt_name || !rt_description)
+                        return -ENOMEM;
+
+                r = metric_family_describe(
+                                &(const MetricFamily) {
+                                        .name = rt_name,
+                                        .description = rt_description,
+                                        .type = METRIC_FAMILY_TYPE_GAUGE,
+                                },
+                                link);
+                if (r < 0)
+                        return r;
+
+                if (i->with_monotonic) {
+                        _cleanup_free_ char *mt_name = strjoin(METRIC_IO_SYSTEMD_MANAGER_PREFIX, i->name, ".Monotonic");
+                        _cleanup_free_ char *mt_description = strjoin("CLOCK_MONOTONIC ", i->description);
+                        if (!mt_name || !mt_description)
+                                return -ENOMEM;
+
+                        r = metric_family_describe(
+                                        &(const MetricFamily) {
+                                                .name = mt_name,
+                                                .description = mt_description,
+                                                .type = METRIC_FAMILY_TYPE_GAUGE,
+                                        },
+                                        link);
+                        if (r < 0)
+                                return r;
+                }
+        }
+
+        return 0;
 }
 
 static int state_change_timestamp_build_json(const MetricFamily *mf, sd_varlink *vl, void *userdata) {
@@ -457,19 +631,6 @@ static const MetricFamily metric_family_table[] = {
                 .type = METRIC_FAMILY_TYPE_GAUGE,
                 .generate = active_timestamp_build_json,
         },
-        {
-                .name = METRIC_IO_SYSTEMD_MANAGER_PREFIX "FinishTimestamp.Realtime",
-                .description = "CLOCK_REALTIME microseconds at which userspace finished booting",
-                .type = METRIC_FAMILY_TYPE_GAUGE,
-                .generate = finish_timestamp_build_json,
-        },
-        {
-                .name = METRIC_IO_SYSTEMD_MANAGER_PREFIX "FinishTimestamp.Monotonic",
-                .description = "CLOCK_MONOTONIC microseconds at which userspace finished booting",
-                .type = METRIC_FAMILY_TYPE_GAUGE,
-                .generate = NULL,
-        },
-        /* Keep those ↑ in sync with finish_timestamp_build_json(). */
         {
                 .name = METRIC_IO_SYSTEMD_MANAGER_PREFIX "InactiveExitTimestamp",
                 .description = "Per unit metric: timestamp when the unit last exited the inactive state in microseconds; 0 indicates the transition has not occurred",
@@ -482,12 +643,6 @@ static const MetricFamily metric_family_table[] = {
                 .type = METRIC_FAMILY_TYPE_GAUGE,
                 .generate = jobs_queued_build_json,
         },
-        {
-                .name = METRIC_IO_SYSTEMD_MANAGER_PREFIX "KernelTimestamp.Realtime",
-                .description = "CLOCK_REALTIME microseconds at which the kernel started (CLOCK_MONOTONIC == 0)",
-                .type = METRIC_FAMILY_TYPE_GAUGE,
-                .generate = kernel_timestamp_build_json,
-        },
         {
                 .name = METRIC_IO_SYSTEMD_MANAGER_PREFIX "NRestarts",
                 .description = "Per unit metric: number of restarts",
@@ -554,19 +709,6 @@ static const MetricFamily metric_family_table[] = {
                 .type = METRIC_FAMILY_TYPE_GAUGE,
                 .generate = units_total_build_json,
         },
-        {
-                .name = METRIC_IO_SYSTEMD_MANAGER_PREFIX "UserspaceTimestamp.Realtime",
-                .description = "CLOCK_REALTIME microseconds at which userspace was reached",
-                .type = METRIC_FAMILY_TYPE_GAUGE,
-                .generate = userspace_timestamp_build_json,
-        },
-        {
-                .name = METRIC_IO_SYSTEMD_MANAGER_PREFIX "UserspaceTimestamp.Monotonic",
-                .description = "CLOCK_MONOTONIC microseconds at which userspace was reached",
-                .type = METRIC_FAMILY_TYPE_GAUGE,
-                .generate = NULL,
-        },
-        /* Keep those ↑ in sync with userspace_timestamp_build_json(). */
         {
                 .name = METRIC_IO_SYSTEMD_MANAGER_PREFIX "Version",
                 .description = "Version of systemd",
@@ -577,9 +719,21 @@ static const MetricFamily metric_family_table[] = {
 };
 
 int vl_method_describe_metrics(sd_varlink *link, sd_json_variant *parameters, sd_varlink_method_flags_t flags, void *userdata) {
-        return metrics_method_describe(metric_family_table, link, parameters, flags, userdata);
+        int r;
+
+        r = metrics_method_describe(metric_family_table, link, parameters, flags, userdata);
+        if (r < 0)
+                return r;
+
+        return manager_timestamps_describe(link);
 }
 
 int vl_method_list_metrics(sd_varlink *link, sd_json_variant *parameters, sd_varlink_method_flags_t flags, void *userdata) {
-        return metrics_method_list(metric_family_table, link, parameters, flags, userdata);
+        int r;
+
+        r = metrics_method_list(metric_family_table, link, parameters, flags, userdata);
+        if (r < 0)
+                return r;
+
+        return manager_timestamps_build_json(link, userdata);
 }

diff --git a/src/shared/metrics.c b/src/shared/metrics.c
index cb00977b539c829effb692f0bb5be8bfbc6faa74..68b18895b4288bf82ae1dad6c3652dede54ae2af 100644 (file)
--- a/src/shared/metrics.c
+++ b/src/shared/metrics.c
@@ -73,6 +73,20 @@ static int metric_family_build_json(const MetricFamily *mf, sd_json_variant **re
                         SD_JSON_BUILD_PAIR_STRING("type", metric_family_type_to_string(mf->type)));
 }
 
+int metric_family_describe(const MetricFamily *mf, sd_varlink *link) {
+        _cleanup_(sd_json_variant_unrefp) sd_json_variant *v = NULL;
+        int r;
+
+        assert(mf);
+        assert(link);
+
+        r = metric_family_build_json(mf, &v);
+        if (r < 0)
+                return r;
+
+        return sd_varlink_reply(link, v);
+}
+
 int metrics_method_describe(
                 const MetricFamily mfs[],
                 sd_varlink *link,
@@ -95,15 +109,9 @@ int metrics_method_describe(
                 return r;
 
         for (const MetricFamily *mf = mfs; mf->name; mf++) {
-                _cleanup_(sd_json_variant_unrefp) sd_json_variant *v = NULL;
-
-                r = metric_family_build_json(mf, &v);
+                r = metric_family_describe(mf, link);
                 if (r < 0)
                         return log_debug_errno(r, "Failed to describe metric family '%s': %m", mf->name);
-
-                r = sd_varlink_reply(link, v);
-                if (r < 0)
-                        return log_debug_errno(r, "Failed to send varlink reply: %m");
         }
 
         return 0;

diff --git a/src/shared/metrics.h b/src/shared/metrics.h
index 8d6dcec99945704b094ccb7c0b02c30fbd99fd2b..253e950fea7a6eae8c84d1df0b05231712b5abb7 100644 (file)
--- a/src/shared/metrics.h
+++ b/src/shared/metrics.h
@@ -34,6 +34,7 @@ int metrics_setup_varlink_server(
 
 DECLARE_STRING_TABLE_LOOKUP_TO_STRING(metric_family_type, MetricFamilyType);
 
+int metric_family_describe(const MetricFamily *mf, sd_varlink *link);
 int metrics_method_describe(const MetricFamily mfs[], sd_varlink *link, sd_json_variant *parameters, sd_varlink_method_flags_t flags, void *userdata);
 int metrics_method_list(const MetricFamily mfs[], sd_varlink *link, sd_json_variant *parameters, sd_varlink_method_flags_t flags, void *userdata);
 

diff --git a/test/units/TEST-74-AUX-UTILS.report.sh b/test/units/TEST-74-AUX-UTILS.report.sh
index 06914fdc50324f7a7d1b1b662f494f8e8a921f27..627e7fef6554e866822ed1f9e95822c200486faa 100755 (executable)
--- a/test/units/TEST-74-AUX-UTILS.report.sh
+++ b/test/units/TEST-74-AUX-UTILS.report.sh
@@ -109,6 +109,17 @@ fi
 [ "$(metric_value UserspaceTimestamp.Realtime)" -gt 0 ]
 [ "$(metric_value UserspaceTimestamp.Monotonic)" -gt 0 ]
 
+# These startup phases are captured unconditionally by manager_startup() on every boot (in containers
+# too, where they are not redirected to the InitRD* variants), so both clocks are always set on the
+# system manager by the time this service runs. We don't check UnitsLoadTimestamp (the last load, only
+# set on the reload/reexec triggered by switch-root) nor the Security/Firmware/Loader/InitRD timestamps,
+# which depend on the boot environment and may legitimately be unset (the metric is then suppressed).
+for phase in GeneratorsStartTimestamp GeneratorsFinishTimestamp \
+             UnitsLoadStartTimestamp UnitsLoadFinishTimestamp; do
+    [ "$(metric_value "$phase.Realtime")" -gt 0 ]
+    [ "$(metric_value "$phase.Monotonic")" -gt 0 ]
+done
+
 # test io.systemd.Basic.MachineInfo.* metrics, sourced from /etc/machine-info
 if [ -e /etc/machine-info ]; then
     MACHINE_INFO_BACKUP="$(mktemp)"