From: Zbigniew Jędrzejewski-Szmek <zbyszek@in.waw.pl>
Date: Mon, 20 May 2024 13:10:32 +0000 (+0200)
Subject: analyze: do not print timestamps before "start of userspace"
X-Git-Tag: v256-rc3~24
X-Git-Url: http://git.ipfire.org/gitweb.cgi?a=commitdiff_plain;h=1d640a044f30d824d19e647ecf477fbd1bc95602;p=thirdparty%2Fsystemd.git

analyze: do not print timestamps before "start of userspace"

We have the following timestamp status:

  $ systemctl show systemd-fsck-root.service | grep InactiveExitTimestamp
  InactiveExitTimestamp=Thu 2023-11-02 12:27:24 CET
  InactiveExitTimestampMonotonic=15143158

  $ systemctl show | grep UserspaceTimestamp
  UserspaceTimestamp=Thu 2023-11-02 12:27:25 CET
  UserspaceTimestampMonotonic=15804273

i.e. UserspaceTimestamp is before InactiveExit of systemd-fsck-root.service.
This is fine, but on display, we'd subtract those values and print a huge
negative value bogusly:

  $ build/systemd-analyze critical-chain systemd-remount-fs.service
  The time when unit became active or started is printed after the "@" character.
  The time the unit took to start is printed after the "+" character.

  systemd-remount-fs.service +137ms
  └─systemd-fsck-root.service @584542y 2w 2d 20h 1min 48.890s +45ms
    └─systemd-journald.socket
      └─system.slice
        └─-.slice

In fact, list_dependencies_print() already had a branch where the check that
'times->activating > boot->userspace_time', but it didn't cover all cases. So
make it cover both branches, and also change to '>=', since it's fine if
something happened with the same timestamp.

With the patch:

  $ build/systemd-analyze critical-chain systemd-remount-fs.service
  The time when unit became active or started is printed after the "@" character.
  The time the unit took to start is printed after the "+" character.

  systemd-remount-fs.service +42ms
  └─systemd-fsck-root.service
    └─systemd-journald.socket
      └─system.slice
        └─-.slice

Fixes https://github.com/systemd/systemd/issues/17191.
---

diff --git a/src/analyze/analyze-critical-chain.c b/src/analyze/analyze-critical-chain.c
index 4a7f452eaf5..7d78de3d388 100644
--- a/src/analyze/analyze-critical-chain.c
+++ b/src/analyze/analyze-critical-chain.c
@@ -23,23 +23,20 @@ static int list_dependencies_print(
                 UnitTimes *times,
                 BootTimes *boot) {
 
-        for (unsigned i = level; i != 0; i--)
+        for (unsigned i = level; i > 0; i--)
                 printf("%s", special_glyph(branches & (1 << (i-1)) ? SPECIAL_GLYPH_TREE_VERTICAL : SPECIAL_GLYPH_TREE_SPACE));
 
         printf("%s", special_glyph(last ? SPECIAL_GLYPH_TREE_RIGHT : SPECIAL_GLYPH_TREE_BRANCH));
 
-        if (times) {
+        if (times && times->activating >= boot->userspace_time) {
                 if (timestamp_is_set(times->time))
-                        printf("%s%s @%s +%s%s", ansi_highlight_red(), name,
+                        printf("%s%s @%s +%s%s\n", ansi_highlight_red(), name,
                                FORMAT_TIMESPAN(times->activating - boot->userspace_time, USEC_PER_MSEC),
                                FORMAT_TIMESPAN(times->time, USEC_PER_MSEC), ansi_normal());
-                else if (times->activated > boot->userspace_time)
-                        printf("%s @%s", name, FORMAT_TIMESPAN(times->activated - boot->userspace_time, USEC_PER_MSEC));
                 else
-                        printf("%s", name);
+                        printf("%s @%s\n", name, FORMAT_TIMESPAN(times->activated - boot->userspace_time, USEC_PER_MSEC));
         } else
-                printf("%s", name);
-        printf("\n");
+                printf("%s\n", name);
 
         return 0;
 }