From: Lennart Poettering Date: Thu, 7 Apr 2011 19:35:37 +0000 (+0200) Subject: dbus: expose monotonic timestamps on the bus X-Git-Tag: v25~77 X-Git-Url: https://www.chiark.greenend.org.uk/ucgi/~ianmdlvl/git?p=elogind.git;a=commitdiff_plain;h=b21a0ef8fc3d78ca3cc9d08e8ec8e41705d9902e dbus: expose monotonic timestamps on the bus --- diff --git a/TODO b/TODO index 5a3944fe0..e16fdeef7 100644 --- a/TODO +++ b/TODO @@ -32,8 +32,6 @@ Features: * show enablement status in systemctl status -* expose monotonic timestamps on the bus and make systemd-analyze use it - * write blog stories about: - chroot, nspawn and friends - the blame game: systemd-analyze diff --git a/src/dbus-execute.c b/src/dbus-execute.c index 35e6d377e..3cb09c2db 100644 --- a/src/dbus-execute.c +++ b/src/dbus-execute.c @@ -346,7 +346,9 @@ int bus_execute_append_command(Manager *m, DBusMessageIter *i, const char *prope if (!dbus_message_iter_close_container(&sub2, &sub3) || !dbus_message_iter_append_basic(&sub2, DBUS_TYPE_BOOLEAN, &c->ignore) || !dbus_message_iter_append_basic(&sub2, DBUS_TYPE_UINT64, &c->exec_status.start_timestamp.realtime) || + !dbus_message_iter_append_basic(&sub2, DBUS_TYPE_UINT64, &c->exec_status.start_timestamp.monotonic) || !dbus_message_iter_append_basic(&sub2, DBUS_TYPE_UINT64, &c->exec_status.exit_timestamp.realtime) || + !dbus_message_iter_append_basic(&sub2, DBUS_TYPE_UINT64, &c->exec_status.exit_timestamp.monotonic) || !dbus_message_iter_append_basic(&sub2, DBUS_TYPE_UINT32, &pid) || !dbus_message_iter_append_basic(&sub2, DBUS_TYPE_INT32, &code) || !dbus_message_iter_append_basic(&sub2, DBUS_TYPE_INT32, &status)) diff --git a/src/dbus-execute.h b/src/dbus-execute.h index 8bfaaaf12..548738a75 100644 --- a/src/dbus-execute.h +++ b/src/dbus-execute.h @@ -28,7 +28,9 @@ #define BUS_EXEC_STATUS_INTERFACE(prefix) \ " \n" \ + " \n" \ " \n" \ + " \n" \ " \n" \ " \n" \ " \n" @@ -149,13 +151,15 @@ #define BUS_EXEC_STATUS_PROPERTIES(interface, estatus, prefix) \ { interface, prefix "StartTimestamp", bus_property_append_usec, "t", &(estatus).start_timestamp.realtime }, \ + { interface, prefix "StartTimestampMonotonic",bus_property_append_usec, "t", &(estatus).start_timestamp.monotonic }, \ { interface, prefix "ExitTimestamp", bus_property_append_usec, "t", &(estatus).start_timestamp.realtime }, \ + { interface, prefix "ExitTimestampMonotonic", bus_property_append_usec, "t", &(estatus).start_timestamp.monotonic }, \ { interface, prefix "PID", bus_property_append_pid, "u", &(estatus).pid }, \ { interface, prefix "Code", bus_property_append_int, "i", &(estatus).code }, \ { interface, prefix "Status", bus_property_append_int, "i", &(estatus).status } #define BUS_EXEC_COMMAND_PROPERTY(interface, command, name) \ - { interface, name, bus_execute_append_command, "a(sasbttuii)", (command) } + { interface, name, bus_execute_append_command, "a(sasbttttuii)", (command) } int bus_execute_append_output(Manager *m, DBusMessageIter *i, const char *property, void *data); int bus_execute_append_input(Manager *m, DBusMessageIter *i, const char *property, void *data); diff --git a/src/dbus-manager.c b/src/dbus-manager.c index 5b5bda211..e1bf9fd28 100644 --- a/src/dbus-manager.c +++ b/src/dbus-manager.c @@ -155,8 +155,11 @@ " \n" \ " \n" \ " \n" \ + " \n" \ " \n" \ + " \n" \ " \n" \ + " \n" \ " \n" \ " \n" \ " \n" \ @@ -369,8 +372,11 @@ static DBusHandlerResult bus_manager_message_handler(DBusConnection *connection, { "org.freedesktop.systemd1.Manager", "RunningAs", bus_manager_append_running_as, "s", &m->running_as }, { "org.freedesktop.systemd1.Manager", "Tainted", bus_manager_append_tainted, "s", m }, { "org.freedesktop.systemd1.Manager", "InitRDTimestamp", bus_property_append_uint64, "t", &m->initrd_timestamp.realtime }, + { "org.freedesktop.systemd1.Manager", "InitRDTimestampMonotonic", bus_property_append_uint64, "t", &m->initrd_timestamp.monotonic }, { "org.freedesktop.systemd1.Manager", "StartupTimestamp", bus_property_append_uint64, "t", &m->startup_timestamp.realtime }, + { "org.freedesktop.systemd1.Manager", "StartupTimestampMonotonic", bus_property_append_uint64, "t", &m->startup_timestamp.monotonic }, { "org.freedesktop.systemd1.Manager", "FinishTimestamp", bus_property_append_uint64, "t", &m->finish_timestamp.realtime }, + { "org.freedesktop.systemd1.Manager", "FinishTimestampMonotonic", bus_property_append_uint64, "t",&m->finish_timestamp.monotonic }, { "org.freedesktop.systemd1.Manager", "LogLevel", bus_manager_append_log_level, "s", NULL, bus_manager_set_log_level}, { "org.freedesktop.systemd1.Manager", "LogTarget", bus_manager_append_log_target, "s", NULL, bus_manager_set_log_target}, { "org.freedesktop.systemd1.Manager", "NNames", bus_manager_append_n_names, "u", NULL }, diff --git a/src/dbus-unit.h b/src/dbus-unit.h index dfbc82c0c..b9f089552 100644 --- a/src/dbus-unit.h +++ b/src/dbus-unit.h @@ -86,9 +86,13 @@ " \n" \ " \n" \ " \n" \ + " \n" \ " \n" \ + " \n" \ " \n" \ + " \n" \ " \n" \ + " \n" \ " \n" \ " \n" \ " \n" \ @@ -103,6 +107,7 @@ " \n" \ " \n" \ " \n" \ + " \n" \ " \n" \ " \n" @@ -134,10 +139,14 @@ { "org.freedesktop.systemd1.Unit", "ActiveState", bus_unit_append_active_state, "s", u }, \ { "org.freedesktop.systemd1.Unit", "SubState", bus_unit_append_sub_state, "s", u }, \ { "org.freedesktop.systemd1.Unit", "FragmentPath", bus_property_append_string, "s", u->meta.fragment_path }, \ - { "org.freedesktop.systemd1.Unit", "InactiveExitTimestamp",bus_property_append_usec, "t", &u->meta.inactive_exit_timestamp.realtime }, \ - { "org.freedesktop.systemd1.Unit", "ActiveEnterTimestamp", bus_property_append_usec, "t", &u->meta.active_enter_timestamp.realtime }, \ - { "org.freedesktop.systemd1.Unit", "ActiveExitTimestamp", bus_property_append_usec, "t", &u->meta.active_exit_timestamp.realtime }, \ + { "org.freedesktop.systemd1.Unit", "InactiveExitTimestamp",bus_property_append_usec, "t", &u->meta.inactive_exit_timestamp.realtime }, \ + { "org.freedesktop.systemd1.Unit", "InactiveExitTimestampMonotonic",bus_property_append_usec, "t", &u->meta.inactive_exit_timestamp.monotonic }, \ + { "org.freedesktop.systemd1.Unit", "ActiveEnterTimestamp", bus_property_append_usec, "t", &u->meta.active_enter_timestamp.realtime }, \ + { "org.freedesktop.systemd1.Unit", "ActiveEnterTimestampMonotonic", bus_property_append_usec, "t", &u->meta.active_enter_timestamp.monotonic }, \ + { "org.freedesktop.systemd1.Unit", "ActiveExitTimestamp", bus_property_append_usec, "t", &u->meta.active_exit_timestamp.realtime }, \ + { "org.freedesktop.systemd1.Unit", "ActiveExitTimestampMonotonic", bus_property_append_usec, "t", &u->meta.active_exit_timestamp.monotonic }, \ { "org.freedesktop.systemd1.Unit", "InactiveEnterTimestamp",bus_property_append_usec, "t", &u->meta.inactive_enter_timestamp.realtime }, \ + { "org.freedesktop.systemd1.Unit", "InactiveEnterTimestampMonotonic",bus_property_append_usec,"t", &u->meta.inactive_enter_timestamp.monotonic }, \ { "org.freedesktop.systemd1.Unit", "CanStart", bus_unit_append_can_start, "b", u }, \ { "org.freedesktop.systemd1.Unit", "CanStop", bus_unit_append_can_stop, "b", u }, \ { "org.freedesktop.systemd1.Unit", "CanReload", bus_unit_append_can_reload, "b", u }, \ @@ -154,6 +163,7 @@ { "org.freedesktop.systemd1.Unit", "NeedDaemonReload", bus_unit_append_need_daemon_reload, "b", u }, \ { "org.freedesktop.systemd1.Unit", "JobTimeoutUSec", bus_property_append_usec, "t", &u->meta.job_timeout }, \ { "org.freedesktop.systemd1.Unit", "ConditionTimestamp", bus_property_append_usec, "t", &u->meta.condition_timestamp.realtime }, \ + { "org.freedesktop.systemd1.Unit", "ConditionTimestampMonotonic", bus_property_append_usec,"t", &u->meta.condition_timestamp.monotonic }, \ { "org.freedesktop.systemd1.Unit", "ConditionResult", bus_property_append_bool, "b", &u->meta.condition_result } int bus_unit_append_names(Manager *m, DBusMessageIter *i, const char *property, void *data); diff --git a/src/systemctl.c b/src/systemctl.c index 00db47f12..0a7287414 100644 --- a/src/systemctl.c +++ b/src/systemctl.c @@ -1735,7 +1735,7 @@ static void exec_status_info_free(ExecStatusInfo *i) { } static int exec_status_info_deserialize(DBusMessageIter *sub, ExecStatusInfo *i) { - uint64_t start_timestamp, exit_timestamp; + uint64_t start_timestamp, exit_timestamp, start_timestamp_monotonic, exit_timestamp_monotonic; DBusMessageIter sub2, sub3; const char*path; unsigned n; @@ -1789,7 +1789,9 @@ static int exec_status_info_deserialize(DBusMessageIter *sub, ExecStatusInfo *i) if (!dbus_message_iter_next(&sub2) || bus_iter_get_basic_and_next(&sub2, DBUS_TYPE_BOOLEAN, &ignore, true) < 0 || bus_iter_get_basic_and_next(&sub2, DBUS_TYPE_UINT64, &start_timestamp, true) < 0 || + bus_iter_get_basic_and_next(&sub2, DBUS_TYPE_UINT64, &start_timestamp_monotonic, true) < 0 || bus_iter_get_basic_and_next(&sub2, DBUS_TYPE_UINT64, &exit_timestamp, true) < 0 || + bus_iter_get_basic_and_next(&sub2, DBUS_TYPE_UINT64, &exit_timestamp_monotonic, true) < 0 || bus_iter_get_basic_and_next(&sub2, DBUS_TYPE_UINT32, &pid, true) < 0 || bus_iter_get_basic_and_next(&sub2, DBUS_TYPE_INT32, &code, true) < 0 || bus_iter_get_basic_and_next(&sub2, DBUS_TYPE_INT32, &status, false) < 0) @@ -2278,7 +2280,7 @@ static int print_property(const char *name, DBusMessageIter *iter) { /* Yes, heuristics! But we can change this check * should it turn out to not be sufficient */ - if (strstr(name, "Timestamp")) { + if (endswith(name, "Timestamp")) { char timestamp[FORMAT_TIMESTAMP_MAX], *t; if ((t = format_timestamp(timestamp, sizeof(timestamp), u)) || arg_all) diff --git a/src/systemd-analyze b/src/systemd-analyze index 5e3a087e9..6f03d13bd 100755 --- a/src/systemd-analyze +++ b/src/systemd-analyze @@ -15,10 +15,10 @@ def acquire_time_data(): properties = dbus.Interface(bus.get_object('org.freedesktop.systemd1', i[6]), 'org.freedesktop.DBus.Properties') - ixt = int(properties.Get('org.freedesktop.systemd1.Unit', 'InactiveExitTimestamp')) - aet = int(properties.Get('org.freedesktop.systemd1.Unit', 'ActiveEnterTimestamp')) - axt = int(properties.Get('org.freedesktop.systemd1.Unit', 'ActiveExitTimestamp')) - iet = int(properties.Get('org.freedesktop.systemd1.Unit', 'InactiveEnterTimestamp')) + ixt = int(properties.Get('org.freedesktop.systemd1.Unit', 'InactiveExitTimestampMonotonic')) + aet = int(properties.Get('org.freedesktop.systemd1.Unit', 'ActiveEnterTimestampMonotonic')) + axt = int(properties.Get('org.freedesktop.systemd1.Unit', 'ActiveExitTimestampMonotonic')) + iet = int(properties.Get('org.freedesktop.systemd1.Unit', 'InactiveEnterTimestampMonotonic')) l.append((str(i[0]), ixt, aet, axt, iet)) @@ -27,12 +27,14 @@ def acquire_time_data(): def acquire_start_time(): properties = dbus.Interface(bus.get_object('org.freedesktop.systemd1', '/org/freedesktop/systemd1'), 'org.freedesktop.DBus.Properties') - startup_time = int(properties.Get('org.freedesktop.systemd1.Manager', 'StartupTimestamp')) - finish_time = int(properties.Get('org.freedesktop.systemd1.Manager', 'FinishTimestamp')) + initrd_time = int(properties.Get('org.freedesktop.systemd1.Manager', 'InitRDTimestampMonotonic')) + startup_time = int(properties.Get('org.freedesktop.systemd1.Manager', 'StartupTimestampMonotonic')) + finish_time = int(properties.Get('org.freedesktop.systemd1.Manager', 'FinishTimestampMonotonic')) + assert initrd_time <= startup_time assert startup_time <= finish_time - return startup_time, finish_time + return initrd_time, startup_time, finish_time def draw_box(context, j, k, l, m, r = 0, g = 0, b = 0): context.save() @@ -63,7 +65,8 @@ def draw_text(context, x, y, text, size = 12, r = 0, g = 0, b = 0, vcenter = 0.5 context.restore() def help(): - sys.stdout.write("""systemd-analyze blame + sys.stdout.write("""systemd-analyze time +systemd-analyze blame systemd-analyze plot Process systemd profiling information @@ -74,7 +77,24 @@ Process systemd profiling information bus = dbus.SystemBus() -if len(sys.argv) <= 1 or sys.argv[1] == 'blame': +if len(sys.argv) <= 1 or sys.argv[1] == 'time': + + initrd_time, start_time, finish_time = acquire_start_time() + + if initrd_time > 0: + print "Startup finished in %lums (kernel) + %lums (initrd) + %lums (userspace) = %lums" % ( \ + initrd_time/1000, \ + (start_time - initrd_time)/1000, \ + (finish_time - start_time)/1000, \ + finish_time/1000) + else: + print "Startup finished in %lums (kernel) + %lums (userspace) = %lums" % ( \ + startup_time/1000, \ + (finish_time - start_time)/1000, \ + finish_time/1000) + + +elif sys.argv[1] == 'blame': data = acquire_time_data() s = sorted(data, key = lambda i: i[2] - i[1], reverse = True) @@ -92,7 +112,7 @@ if len(sys.argv) <= 1 or sys.argv[1] == 'blame': elif sys.argv[1] == 'plot': import cairo - start_time, finish_time = acquire_start_time() + initrd_time, start_time, finish_time = acquire_start_time() data = acquire_time_data() s = sorted(data, key = lambda i: i[1])