From: Lennart Poettering Date: Thu, 13 Sep 2012 16:54:32 +0000 (+0200) Subject: manager: extend performance measurement interface to include firmware/loader times X-Git-Tag: v190~107 X-Git-Url: https://www.chiark.greenend.org.uk/ucgi/~ianmdlvl/git?p=elogind.git;a=commitdiff_plain;h=915b375388231ed97cad2929ab948756bfc77c42;ds=sidebyside 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 76eceee9f..636fd7422 100755 --- 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')) - 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) - 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() diff --git a/src/core/dbus-manager.c b/src/core/dbus-manager.c index c341d36a6..557b3e476 100644 --- a/src/core/dbus-manager.c +++ b/src/core/dbus-manager.c @@ -214,6 +214,8 @@ " \n" \ " " \ " \n" \ + " \n" \ + " \n" \ " \n" \ " \n" \ " \n" \ @@ -226,10 +228,16 @@ " \n" \ " \n" \ " \n" \ + " \n" \ + " \n" \ + " \n" \ + " \n" \ + " \n" \ + " \n" \ " \n" \ " \n" \ - " \n" \ - " \n" \ + " \n" \ + " \n" \ " \n" \ " \n" \ " \n" \ @@ -520,10 +528,16 @@ static const BusProperty bus_systemd_properties[] = { 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) }, - { "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 }, diff --git a/src/core/dbus.c b/src/core/dbus.c index 1fc714823..75773aaa4 100644 --- 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, + usec_t firmware_usec, + usec_t loader_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, + 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, diff --git a/src/core/dbus.h b/src/core/dbus.h index 0502d7c25..c7a058e19 100644 --- 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); -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) diff --git a/src/core/manager.c b/src/core/manager.c index 40b0c5085..23d8ca3d3 100644 --- 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); - 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; @@ -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); + 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); } @@ -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; - } 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 @@ -2003,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); @@ -2024,13 +2034,20 @@ 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. */ + + 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)) { - 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, @@ -2045,7 +2062,7 @@ void manager_check_finished(Manager *m) { 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()) @@ -2060,8 +2077,8 @@ void manager_check_finished(Manager *m) { 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, @@ -2072,7 +2089,7 @@ void manager_check_finished(Manager *m) { 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.", diff --git a/src/core/manager.h b/src/core/manager.h index 603c2dc31..653496ded 100644 --- a/src/core/manager.h +++ b/src/core/manager.h @@ -146,8 +146,11 @@ struct Manager { 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 startup_timestamp; + dual_timestamp userspace_timestamp; dual_timestamp finish_timestamp; char *generator_unit_path; diff --git a/src/core/timer.c b/src/core/timer.c index 0b3c5ce07..03c9610eb 100644 --- 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: - base = UNIT(t)->manager->startup_timestamp.monotonic; + base = UNIT(t)->manager->userspace_timestamp.monotonic; break; case TIMER_UNIT_ACTIVE: