Arch Linux

schard

Forum Moderator

From: Hannover

Registered: 2016-05-06

Posts: 1,972

Website

Preposterous values in systemd-analyze critical-chain

While investigating a system I just stumbled over this:

$ systemd-analyze critical-chain 
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.

graphical.target @8.674s
└─xorg-server.service @3.159s +5.514s
  └─basic.target @3.114s
    └─sockets.target @3.110s
      └─dbus.socket @3.107s
        └─sysinit.target @3.076s
          └─systemd-resolved.service @2.729s +342ms
            └─systemd-tmpfiles-setup.service @2.316s +405ms
              └─local-fs.target @2.306s
                └─boot.mount @1.999s +302ms
                  └─dev-sda1.device @584542y 2w 2d 20h 1min 48.121s +3.427s

The times for dev-sda1.device are clearly bogus, since the system booted in a few seconds in total.
Where do they come from?

$ pacman -Q linux-lts systemd
linux-lts 5.15.67-1
systemd 251.4-1

PS: Same issue after an update and reboot:

$ systemd-analyze critical-chain 
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.

graphical.target @6.270s
└─xorg-server.service @2.448s +3.820s
  └─basic.target @2.386s
    └─sockets.target @2.382s
      └─dbus.socket @2.376s
        └─sysinit.target @2.343s
          └─systemd-resolved.service @2.035s +304ms
            └─systemd-tmpfiles-setup.service @1.708s +316ms
              └─local-fs.target @1.699s
                └─boot.mount @1.608s +88ms
                  └─dev-sda1.device @584542y 2w 2d 20h 1min 48.535s +2.616s
$ pacman -Q linux-lts systemd
linux-lts 5.15.74-1
systemd 251.7-1

Edit:
I just made some calculations. The time value represented in microsecods is close to the usize max of 18446744073709551615:

$ python
Python 3.10.8 (main, Oct 13 2022, 21:13:48) [GCC 12.2.0] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> from datetime import timedelta
>>> delta = timedelta(days=584542*365 + 2*7 + 2, hours=20, minutes=1, seconds=48.535)
>>> delta.total_seconds()
18434117966508.535
>>> int(delta.total_seconds() * 1000)
18434117966508536
>>> 

Smells like a uint underflow.

Last edited by schard (2022-10-26 11:37:09)

---

macro_rules! yolo { { $($tokens:tt)* } => { unsafe { $($tokens)* } }; }

seth

Member

Registered: 2012-09-03

Posts: 50,970

Re: Preposterous values in systemd-analyze critical-chain

Any indication of a timew… jump (ntp) in the journal?
Does the system have an RTC?

---

How to upload text · How to boot w/o GUI · Disable Windows Fast-Start! · Fix your xinitrc

schard

Forum Moderator

From: Hannover

Registered: 2016-05-06

Posts: 1,972

Website

Re: Preposterous values in systemd-analyze critical-chain

There are no time jumps in the journal.
I also suspected it might be systemd-timesyncd kicking in resetting the system clock that might be broken due to an empty CMOS battery, but no.
Excerpt:

Okt 28 13:13:58 1545 kernel: mousedev: PS/2 mouse device common for all mice
Okt 28 13:13:58 1545 kernel: Creating 1 MTD partitions on "intel-spi":
Okt 28 13:13:58 1545 kernel: 0x000000000000-0x000000800000 : "BIOS"
Okt 28 13:13:58 1545 audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-timesyncd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Okt 28 13:13:58 1545 systemd[1]: Started Network Time Synchronization.
Okt 28 13:13:58 1545 systemd[1]: Reached target System Time Set.
Okt 28 13:13:58 1545 systemd-resolved[294]: Positive Trust Anchors:
Okt 28 13:13:58 1545 kernel: iTCO_wdt iTCO_wdt.1.auto: Found a Bay Trail SoC TCO device (Version=3, TCOBASE=0x0460)
Okt 28 13:13:58 1545 kernel: iTCO_wdt iTCO_wdt.1.auto: initialized. heartbeat=30 sec (nowayout=0)
Okt 28 13:13:58 1545 systemd-resolved[294]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d
Okt 28 13:13:58 1545 systemd-resolved[294]: Negative trust anchors: home.arpa 10.in-addr.arpa 16.172.in-addr.arpa 17.172.in-addr.arpa 18.172.in-addr.arpa 19.172.in-addr.arpa 20.172.in-addr.arpa 21.172.in-addr.arpa 22.172.in-addr.arpa 23.>
Okt 28 13:13:58 1545 systemd-resolved[294]: Using system hostname '1545'.
Okt 28 13:13:58 1545 systemd[1]: Started Network Name Resolution.
Okt 28 13:13:58 1545 systemd[1]: Reached target Host and Network Name Lookups.

---

macro_rules! yolo { { $($tokens:tt)* } => { unsafe { $($tokens)* } }; }

merlock

Member

Registered: 2018-10-30

Posts: 235

Re: Preposterous values in systemd-analyze critical-chain

ISTR this appeared (and disappeared) in the systemd-24x series.

---

Eenie meenie, chili beanie, the spirits are about to speak -- Bullwinkle J. Moose
It's a big club...and you ain't in it -- George Carlin
Registered Linux user #149839
perl -e 'print$i=pack(c5,(41*2),sqrt(7056),(unpack(c,H)-2),oct(115),10); '