Boot time has increased after 2022-12-20 Stable update (due to userspace)

Support
1

With the Stable update of 2022-12-20 the startup time has increased. Usually my system used to boot in about 2.277 seconds:

Startup finished in 1.123s (kernel) + 595ms (initrd) + 558ms (userspace) = 2.277s 
graphical.target reached after 558ms in userspace

Now it takes about 4 seconds:

Startup finished in 1.212s (kernel) + 706ms (initrd) + 2.125s (userspace) = 4.043s 
graphical.target reached after 2.118s in userspace.

The culprit is clearly userspace: before 558ms - now 2.125s

systemd-analyze critical-chain:

graphical.target @2.219s
└─multi-user.target @2.218s
  └─getty.target @2.218s
    └─getty@tty1.service @2.216s
      └─systemd-user-sessions.service @2.191s +21ms
        └─network.target @2.188s
          └─NetworkManager.service @2.095s +91ms
            └─dbus.service @2.041s +48ms
              └─basic.target @2.036s
                └─sockets.target @2.034s
                  └─dbus.socket @2.033s
                    └─sysinit.target @2.024s
                      └─systemd-update-utmp.service @1.960s +44ms
                        └─systemd-tmpfiles-setup.service @1.887s +69ms
                          └─local-fs.target @1.886s
                            └─run-credentials-systemd\x2dtmpfiles\x2dsetup.service.mount @1.890s
                              └─local-fs-pre.target @1.051s
                                └─systemd-tmpfiles-setup-dev.service @949ms +101ms
                                  └─kmod-static-nodes.service @869ms +18ms
                                    └─systemd-journald.socket

systemd-analyze blame:

1.644s dev-disk-by\x2dpath-pci\x2d0000:00:1f.2\x2data\x2d1.device
1.644s dev-disk-by\x2did-wwn\x2d0x5002538f426004e7.device
1.644s dev-disk-by\x2did-ata\x2dSamsung_SSD_870_EVO_500GB_S6PYNX0T601255K.device
1.644s sys-devices-pci0000:00-0000:00:1f.2-ata1-host0-target0:0:0-0:0:0:0-block-sda.device
1.644s dev-sda.device
1.644s dev-disk-by\x2dpath-pci\x2d0000:00:1f.2\x2data\x2d1.0.device
1.644s dev-disk-by\x2duuid-0d37cf27\x2d2ff0\x2d4234\x2da80e\x2d4be323299166.device
1.644s dev-disk-by\x2did-wwn\x2d0x5002538f426004e7\x2dpart1.device
1.644s dev-disk-by\x2dpath-pci\x2d0000:00:1f.2\x2data\x2d1.0\x2dpart1.device
1.644s sys-devices-pci0000:00-0000:00:1f.2-ata1-host0-target0:0:0-0:0:0:0-block-sda-sda1.device
1.644s dev-disk-by\x2did-ata\x2dSamsung_SSD_870_EVO_500GB_S6PYNX0T601255K\x2dpart1.device
1.644s dev-sda1.device
1.644s dev-disk-by\x2dpartuuid-812a6590\x2d01.device
1.644s dev-disk-by\x2dpath-pci\x2d0000:00:1f.2\x2data\x2d1\x2dpart1.device
1.635s dev-disk-by\x2dpath-pci\x2d0000:00:1f.2\x2data\x2d2.0.device
1.635s dev-sdb.device
1.635s dev-disk-by\x2did-wwn\x2d0x500a0751e109f5e0.device
1.635s dev-disk-by\x2dpath-pci\x2d0000:00:1f.2\x2data\x2d2.device
1.635s dev-disk-by\x2did-ata\x2dCT250MX500SSD1_1801E109F5E0.device
1.635s sys-devices-pci0000:00-0000:00:1f.2-ata2-host1-target1:0:0-1:0:0:0-block-sdb.device
1.631s sys-devices-platform-serial8250-tty-ttyS27.device
1.631s dev-ttyS27.device
1.622s sys-devices-platform-serial8250-tty-ttyS3.device
1.622s dev-ttyS3.device
1.622s dev-ttyS24.device
1.622s sys-devices-platform-serial8250-tty-ttyS28.device
1.622s dev-ttyS28.device
1.622s sys-devices-platform-serial8250-tty-ttyS24.device
1.621s sys-devices-platform-serial8250-tty-ttyS30.device
1.621s dev-ttyS30.device
1.621s sys-devices-platform-serial8250-tty-ttyS20.device
1.621s dev-ttyS20.device
1.621s sys-devices-platform-serial8250-tty-ttyS6.device
1.621s dev-ttyS6.device
1.620s dev-ttyS0.device
1.620s sys-devices-platform-serial8250-tty-ttyS0.device
1.620s dev-ttyS4.device
1.620s sys-devices-platform-serial8250-tty-ttyS4.device
1.620s dev-ttyS31.device
1.620s sys-devices-platform-serial8250-tty-ttyS31.device
1.620s sys-devices-platform-serial8250-tty-ttyS1.device
1.620s dev-ttyS1.device
1.619s dev-ttyS25.device
1.619s sys-devices-platform-serial8250-tty-ttyS25.device
1.619s sys-devices-platform-serial8250-tty-ttyS7.device
1.619s dev-ttyS7.device
1.619s dev-ttyS10.device
1.619s sys-devices-platform-serial8250-tty-ttyS10.device
1.618s dev-ttyS8.device
1.618s sys-devices-platform-serial8250-tty-ttyS8.device
1.613s dev-ttyS5.device
1.613s sys-devices-platform-serial8250-tty-ttyS5.device
1.612s sys-module-configfs.device
1.611s dev-ttyS9.device
1.611s sys-devices-platform-serial8250-tty-ttyS9.device
1.604s dev-ttyS13.device
1.604s sys-devices-platform-serial8250-tty-ttyS13.device
1.602s dev-ttyS14.device
1.602s sys-devices-platform-serial8250-tty-ttyS14.device
1.601s dev-ttyS15.device
1.601s sys-devices-platform-serial8250-tty-ttyS15.device
1.599s sys-devices-platform-serial8250-tty-ttyS17.device
1.599s dev-ttyS17.device
1.599s sys-devices-platform-serial8250-tty-ttyS21.device
1.599s dev-ttyS21.device
1.599s sys-devices-platform-serial8250-tty-ttyS22.device
1.599s dev-ttyS22.device
1.599s dev-ttyS16.device
1.599s sys-devices-platform-serial8250-tty-ttyS16.device
1.598s sys-devices-platform-serial8250-tty-ttyS18.device
1.598s dev-ttyS18.device
1.598s sys-devices-platform-serial8250-tty-ttyS12.device
1.598s dev-ttyS12.device
1.597s sys-devices-platform-serial8250-tty-ttyS23.device
1.597s dev-ttyS23.device
1.596s dev-ttyS2.device
1.596s sys-devices-platform-serial8250-tty-ttyS2.device
1.593s dev-ttyS19.device
1.593s sys-devices-platform-serial8250-tty-ttyS19.device
1.591s dev-ttyS29.device
1.591s sys-devices-platform-serial8250-tty-ttyS29.device
1.589s dev-ttyS26.device
1.589s sys-devices-platform-serial8250-tty-ttyS26.device
1.587s sys-devices-platform-serial8250-tty-ttyS11.device
1.587s dev-ttyS11.device
 964ms initrd-switch-root.service
 344ms udisks2.service
 155ms user@1000.service
 151ms upower.service
 147ms iwd.service
 142ms rtirq.service
 138ms systemd-udev-trigger.service
 102ms accounts-daemon.service
 101ms systemd-tmpfiles-setup-dev.service
  93ms systemd-logind.service
  91ms NetworkManager.service
  84ms systemd-modules-load.service
  69ms systemd-tmpfiles-setup.service
  66ms systemd-remount-fs.service
  61ms systemd-udevd.service
  48ms dbus.service
  48ms systemd-journald.service
  44ms systemd-update-utmp.service
  36ms modprobe@fuse.service
  35ms alsa-restore.service
  30ms systemd-fsck@dev-disk-by\x2duuid-8412b438\x2d5d7b\x2d48bd\x2dbfb1\x2d46666bb7ac64.service
  30ms systemd-fsck-root.service
  27ms user-runtime-dir@1000.service
  24ms modprobe@drm.service
  21ms systemd-user-sessions.service
  18ms kmod-static-nodes.service
  18ms dev-hugepages.mount
  17ms dev-mqueue.mount
  15ms systemd-sysctl.service
  15ms sys-kernel-debug.mount
  15ms sys-fs-fuse-connections.mount
  13ms sys-kernel-tracing.mount
  13ms polkit.service
  12ms initrd-cleanup.service
  12ms initrd-parse-etc.service
  11ms home-dave-mounts-servicedisk.mount
   8ms thermald.service
   7ms user-chown.service
   5ms initrd-udevadm-cleanup-db.service
   4ms modprobe@configfs.service
   3ms sys-kernel-config.mount
   3ms tmp.mount
   3ms rtkit-daemon.service
   3ms incrond.service
   2ms var-tmp.mount

What else can I check?

2

It clearly has todo with your /dev/sda (Samsung_SSD_870_EVO_500GB)
I would check your drive or settings related to that…

3

From /etc/fstab:

UUID=0d37cf27-2ff0-4234-a80e-4be323299166 / ext4 defaults,noatime,commit=60 0 1

SMART values (which are OK):

2022-12-21_14-00
2022-12-21_14-001047×430 24.5 KB

Do I need to check something else?

4

I forgot to mention that /dev/sdb and the serial ports shows same stuff…

You might check related logs for those :woman_shrugging:
eg. something similar to:

journalctl --grep "/dev/(sd(a|b)|ttyS*)"
5

It only give:

dic 21 15:21:21 manjaro systemd-fsck[180]: /dev/sda1: clean, 804400/30531584 files, 17147059/122096128 blocks
6

hmmm :thinking:
It should have give a lot more i think, on my non-Manjaro system i get a lot more, but ahh well… :woman_shrugging:

Maybe you need to check your drivers for your serial port 8250 or disable them in your BIOS if you dont use them…

I have no other ideas for you at moment.
:woman_shrugging:

7

Is already disabled in the BIOS.

8

Then it’s even weirder that it tries to initialize them see your own logs mentioning /dev/ttyS...
:woman_shrugging:

9

This is an only mildly useful addition at best but I confirm increased boot time in that same (in absolute times) slight sense on an older legacy system and with the rootfs on dual RAID0 Intel SSDs.

Haven’t had time yet to look into anything but definitely started happening directly after the 12-20 stable update.

10

Just for what its worth, i found this:

11

Thanks you, seems interesting for sure, although there poster was adamant it regressed from systemd 250 to 251 – and unless I’m mistaken we on stable went from 251.8-1 to 252.3-1?

Anyways still a good inroad to start looking; hope to do so in some more detail tonight.

12

Just throwing this out here;

fstrim -A or -a

13

@herbie; that might actually be…

Tried tracking it down and I can’t find it. On this older system time from the BIOS loading Grub to the desktop being fully up is consistently between 16 and 18 seconds – and even though I have the “feeling” that it’s now more commonly on the high end of that spectrum whereas it used to be on the low I can not objectively confirm. Have been scrounging around journalctl -b -<number> and it seems that also before the stable update I had that same two second variance even between first kernel startup timestamp and “systemctl[...]: Startup finished [ ... ]” already.

Directly after the stable update I also had Firefox crap out on me (started with no Window) and reboot failing from the Xfce logout/reboot dialogue with a dbus error. And again on the first boot after said stable update. And then not on the second and not up to now. As in “err, what? err, whatever…”

Strange goings on perhaps but I believe I need to in any case withdraw my “confirm”. Given the mentioned times, OP has a very different system anyway; shall butt out of his/her issue which then seemingly is consistently reproducible.

14

Already done: doesn’t solve the long boot time.

15

Maybe you could from the boot screen
Enter e to edit the boot options
find the line with quiet splash and delete that
then press F10 or ctrl X
and watch the boot up and you might see what is taking so long.

17

Done, but the output is fast… I recorded a video:

https://streamable.com/6byahd

18

Was I dreaming or was there a reply here earlier that you pinned it down to NetworkManager? I was just starting to test that and came back here to see what you said as to versions . Seems gone?

19

You didn’t dreaming. Was just an error and then I edited the post.

20

Mine has also increased significantly. Previously it was about 11s total, now 17s
The culprit in my case seems to be NetworkManager-wait-online.service

systemd-analyze                                                  ✔ 
Startup finished in 3.019s (firmware) + 757ms (loader) 
+ 1.991s (kernel) + 11.517s (userspace) = 17.285s 
graphical.target reached after 11.517s in userspace.
 
   ~  systemd-analyze blame                                            ✔ 
8.683s NetworkManager-wait-online.service
7.179s plymouth-quit-wait.service
2.350s snapd.service
2.133s ModemManager.service
 887ms dev-nvme0n1p2.device
21

We can not tell from what you posted. Networkmanager-wait-online.service “is not a service in and of itself” but something which some other service gets to depend on if it wants to wait for a by NetworkManager managed connection to be in fact up. The displayed time is moreover just total time from invocation to completion of said service itself; it doesn’t hold up anything that does not depend on it.

In any case it’s only relevant here if you’d on a previous boot had that same figure display as 8.7s-(17s-11s)=1.7s which I doubt; 8.7 sounds not strange for a standard, by NetworkManager managed internet connection.