Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Merged
merged 1 commit into from
May 20, 2024

Conversation

keszybz
Copy link
Member

@keszybz keszybz commented May 20, 2024

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 #17191.

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 systemd#17191.
@github-actions github-actions bot added the please-review PR is ready for (re-)review by a maintainer label May 20, 2024
Copy link

Important

An -rc1 tag has been created and a release is being prepared, so please note that PRs introducing new features and APIs will be held back until the new version has been released.

@bluca bluca added analyze good-to-merge/waiting-for-ci 👍 PR is good to merge, but CI hasn't passed at time of review. Please merge if you see CI has passed and removed please-review PR is ready for (re-)review by a maintainer labels May 20, 2024
@bluca bluca merged commit 1d640a0 into systemd:main May 20, 2024
44 of 49 checks passed
@github-actions github-actions bot removed the good-to-merge/waiting-for-ci 👍 PR is good to merge, but CI hasn't passed at time of review. Please merge if you see CI has passed label May 20, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Development

Successfully merging this pull request may close these issues.

systemd-analyze critical-chain reports invalid timestamp
2 participants