From 1d640a044f30d824d19e647ecf477fbd1bc95602 Mon Sep 17 00:00:00 2001
From: =?utf8?q?Zbigniew=20J=C4=99drzejewski-Szmek?= <zbyszek@in.waw.pl>
Date: Mon, 20 May 2024 15:10:32 +0200
Subject: [PATCH] analyze: do not print timestamps before "start of userspace"
MIME-Version: 1.0
Content-Type: text/plain; charset=utf8
Content-Transfer-Encoding: 8bit

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.
---
 src/analyze/analyze-critical-chain.c | 13 +++++--------
 1 file changed, 5 insertions(+), 8 deletions(-)

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;
 }
-- 
2.47.3