dbus: expose monotonic timestamps on the bus

7 files changed, 60 insertions, 18 deletions

diff --git a/TODO b/TODO
index 5a3944fe0c..e16fdeef7e 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 35e6d377ee..3cb09c2dbf 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 8bfaaaf120..548738a756 100644
--- a/src/dbus-execute.h
+++ b/src/dbus-execute.h
@@ -28,7 +28,9 @@
 
 #define BUS_EXEC_STATUS_INTERFACE(prefix)                               \
         "  <property name=\"" prefix "StartTimestamp\" type=\"t\" access=\"read\"/>\n" \
+        "  <property name=\"" prefix "StartTimestampMonotonic\" type=\"t\" access=\"read\"/>\n" \
         "  <property name=\"" prefix "ExitTimestamp\" type=\"t\" access=\"read\"/>\n" \
+        "  <property name=\"" prefix "ExitTimestampMonotonic\" type=\"t\" access=\"read\"/>\n" \
         "  <property name=\"" prefix "PID\" type=\"u\" access=\"read\"/>\n" \
         "  <property name=\"" prefix "Code\" type=\"i\" access=\"read\"/>\n" \
         "  <property name=\"" prefix "Status\" type=\"i\" access=\"read\"/>\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 5b5bda2119..e1bf9fd28c 100644
--- a/src/dbus-manager.c
+++ b/src/dbus-manager.c
@@ -155,8 +155,11 @@
         "  <property name=\"Tainted\" type=\"s\" access=\"read\"/>\n"   \
         "  <property name=\"RunningAs\" type=\"s\" access=\"read\"/>\n" \
         "  <property name=\"InitRDTimestamp\" type=\"t\" access=\"read\"/>\n" \
+        "  <property name=\"InitRDTimestampMonotonic\" type=\"t\" access=\"read\"/>\n" \
         "  <property name=\"StartupTimestamp\" type=\"t\" access=\"read\"/>\n" \
+        "  <property name=\"StartupTimestampMonotonic\" type=\"t\" access=\"read\"/>\n" \
         "  <property name=\"FinishTimestamp\" type=\"t\" access=\"read\"/>\n" \
+        "  <property name=\"FinishTimestampMonotonic\" type=\"t\" access=\"read\"/>\n" \
         "  <property name=\"LogLevel\" type=\"s\" access=\"readwrite\"/>\n"  \
         "  <property name=\"LogTarget\" type=\"s\" access=\"readwrite\"/>\n" \
         "  <property name=\"NNames\" type=\"u\" access=\"read\"/>\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 dfbc82c0c5..b9f0895525 100644
--- a/src/dbus-unit.h
+++ b/src/dbus-unit.h
@@ -86,9 +86,13 @@
         "  <property name=\"SubState\" type=\"s\" access=\"read\"/>\n"  \
         "  <property name=\"FragmentPath\" type=\"s\" access=\"read\"/>\n" \
         "  <property name=\"InactiveExitTimestamp\" type=\"t\" access=\"read\"/>\n" \
+        "  <property name=\"InactiveExitTimestampMonotonic\" type=\"t\" access=\"read\"/>\n" \
         "  <property name=\"ActiveEnterTimestamp\" type=\"t\" access=\"read\"/>\n" \
+        "  <property name=\"ActiveEnterTimestampMonotonic\" type=\"t\" access=\"read\"/>\n" \
         "  <property name=\"ActiveExitTimestamp\" type=\"t\" access=\"read\"/>\n" \
+        "  <property name=\"ActiveExitTimestampMonotonic\" type=\"t\" access=\"read\"/>\n" \
         "  <property name=\"InactiveEnterTimestamp\" type=\"t\" access=\"read\"/>\n" \
+        "  <property name=\"InactiveEnterTimestampMonotonic\" type=\"t\" access=\"read\"/>\n" \
         "  <property name=\"CanReload\" type=\"b\" access=\"read\"/>\n" \
         "  <property name=\"CanStart\" type=\"b\" access=\"read\"/>\n"  \
         "  <property name=\"CanStop\" type=\"b\" access=\"read\"/>\n"   \
@@ -103,6 +107,7 @@
         "  <property name=\"NeedDaemonReload\" type=\"b\" access=\"read\"/>\n" \
         "  <property name=\"JobTimeoutUSec\" type=\"t\" access=\"read\"/>\n" \
         "  <property name=\"ConditionTimestamp\" type=\"t\" access=\"read\"/>\n" \
+        "  <property name=\"ConditionTimestampMonotonic\" type=\"t\" access=\"read\"/>\n" \
         "  <property name=\"ConditionResult\" type=\"b\" access=\"read\"/>\n" \
         " </interface>\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 00db47f125..0a72874145 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 5e3a087e9d..6f03d13bd0 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])