[SOLVED] Machine suddenly taking too long to boot

NachoGoro · 2021-09-04 17:54:56

At some point these past few weeks, it started to take over a minute from the point I entered my root partition decryption password until Plasma's log-in screen is displayed. Traditionally it took a few seconds.

I have not changed any configuration knowingly, and simply updated my machine regularly, so I assume it's related to some update.

This are the relevant outputs I can think of:

$ systemd-analyze blame
1min 18.845s systemd-udev-settle.service
      1.146s systemd-random-seed.service
       324ms dev-mapper-cryptroot.device
       158ms systemd-modules-load.service
       148ms zfs-import-cache.service
        96ms cups.service
        84ms ldconfig.service
        81ms lvm2-monitor.service
        73ms user@1000.service
        68ms systemd-journal-flush.service
        67ms boot.mount
        54ms systemd-udev-trigger.service
        45ms udisks2.service
        45ms polkit.service
        41ms upower.service
        35ms systemd-udevd.service
        31ms systemd-journald.service
        31ms systemd-timesyncd.service
        31ms NetworkManager.service
        25ms avahi-daemon.service
        25ms systemd-logind.service
        23ms systemd-fsck@dev-disk-by\x2duuid-43E9\x2d06FD.service
        21ms systemd-machined.service
        18ms systemd-tmpfiles-setup.service
        17ms systemd-sysusers.service
        14ms modprobe@drm.service
        13ms systemd-tmpfiles-setup-dev.service
        12ms colord.service
         9ms wpa_supplicant.service
         8ms systemd-journal-catalog-update.service
         8ms dev-hugepages.mount
         8ms zfs-mount.service
         8ms dev-mqueue.mount
         7ms zfs-load-key.service
         7ms sys-kernel-debug.mount
         7ms sys-kernel-tracing.mount
         6ms modprobe@fuse.service
         6ms tmp.mount
         6ms user-runtime-dir@1000.service
         6ms kmod-static-nodes.service
         5ms systemd-update-utmp.service
         5ms modprobe@configfs.service
         4ms alsa-restore.service
         3ms systemd-remount-fs.service
         3ms systemd-update-done.service
         3ms systemd-sysctl.service
         3ms systemd-user-sessions.service
         2ms systemd-rfkill.service
         2ms rtkit-daemon.service
         1ms mdmonitor.service
         1ms sys-fs-fuse-connections.mount
         1ms sys-kernel-config.mount

$ 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 @1min 19.343s
└─sddm.service @1min 19.343s
  └─systemd-user-sessions.service @1min 19.339s +3ms
    └─network.target @1min 19.337s
      └─NetworkManager.service @1min 19.305s +31ms
        └─dbus.service @1min 19.304s
          └─basic.target @1min 19.303s
            └─sockets.target @1min 19.303s
              └─virtlogd.socket @1min 19.303s
                └─sysinit.target @1min 19.301s
                  └─systemd-update-done.service @1min 19.297s +3ms
                    └─ldconfig.service @1min 19.212s +84ms
                      └─local-fs.target @1min 19.211s
                        └─zfs-mount.service @1min 19.203s +8ms
                          └─zfs-load-key.service @1min 19.194s +7ms
                            └─zfs-import.target @1min 19.193s
                              └─zfs-import-cache.service @1min 19.045s +148ms
                                └─systemd-udev-settle.service @199ms +1min 18.845s
                                  └─systemd-udev-trigger.service @144ms +54ms
                                    └─systemd-udevd-kernel.socket @136ms
                                      └─system.slice @128ms
                                        └─-.slice @128ms

For the looks of it, it might be network related, but I don't think anything in my network connection has changed significantly.

This is my system information:

Operating System: Arch Linux
KDE Plasma Version: 5.22.5
KDE Frameworks Version: 5.85.0
Qt Version: 5.15.2
Kernel Version: 5.13.13-arch1-1 (64-bit)
Graphics Platform: X11
Processors: 24 × AMD Ryzen 9 3900X 12-Core Processor
Memory: 31.3 GiB of RAM
Graphics Processor: NVIDIA GeForce GTX 1650/PCIe/SSE2

Thanks in advance for the help!

Last edited by NachoGoro (2021-09-04 20:55:55)

seth · 2021-09-04 19:04:24

systemd-udev-settle.service times out.
https://man.archlinux.org/man/systemd-u … .service.8

Using this service is not recommended.

=> Why is that there?

loqs · 2021-09-04 19:28:36

seth wrote:

=> Why is that there?

https://github.com/openzfs/zfs/blob/mas … service.in

seth · 2021-09-04 19:51:26

Used since its inception...
And look, even my most favorite word: https://github.com/openzfs/zfs/commit/8 … 8#r6057966

So I guess the service should rather wait for the devices in the pool and not random stuff, but because https://www.youtube.com/watch?v=5RyYrs5tu60 you need to look in the journal for udev issues and maybe https://wiki.archlinux.org/title/Udev#Debug_output

Any HW stalling udev could be causing this.

NachoGoro · 2021-09-04 20:52:38

Ah, I see! Indeed, there are tickets open in openzfs to remove use of that service: https://github.com/openzfs/zfs/issues/10891
I was not aware of that service in particular.

Thank you both of you for the hint. I am taking a look at the journalctl from that boot (no udev debug information, pastebin link).

I believe this to be the relevant bit, but I'm a complete ignoramus:

Sep 04 21:49:00 socrates kernel: audit: type=1100 audit(1630784940.097:142): pid=1775 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:authentication grantors=pam_shells,pam_faillock,pam_permit,pam_faillock acct="ic" exe="/usr/lib/sddm>
Sep 04 21:44:09 socrates systemd-udevd[603]: usb1: Worker [671] processing SEQNUM=3486 is taking a long time
Sep 04 21:44:12 socrates kernel: usb 1-3: Device not responding to setup address.
Sep 04 21:44:17 socrates kernel: usb 1-3: Device not responding to setup address.
Sep 04 21:44:17 socrates kernel: usb 1-3: device not accepting address 4, error -71
Sep 04 21:44:17 socrates kernel: usb 1-3: new full-speed USB device number 5 using xhci_hcd
Sep 04 21:44:22 socrates kernel: usb 1-3: Device not responding to setup address.
Sep 04 21:44:27 socrates kernel: usb 1-3: Device not responding to setup address.
Sep 04 21:44:27 socrates kernel: usb 1-3: device not accepting address 5, error -71
Sep 04 21:44:27 socrates kernel: usb usb1-port3: unable to enumerate USB device
Sep 04 21:44:28 socrates kernel: usb 1-6: new full-speed USB device number 6 using xhci_hcd
Sep 04 21:44:28 socrates kernel: usb 1-6: config 1 has an invalid interface number: 2 but max is 1
Sep 04 21:44:28 socrates kernel: usb 1-6: config 1 has no interface number 1

I have enabled udev debug logging, and got a massive log, which can be found here. There are some mentions of missing vdev_id.conf files, but I don't think those were ever necessary. There is also an error "device descriptor read/64, error -110", which seems to be "insufficient USB power". I do have a USB hub with a microphone, webcam and speakers connected to it, and it does not use any external power, so it might be that.

I'll give it a go without that USB hub plugged in.

EDIT: Indeed, not having the USB hub connected at boot diminishes the boot up time to just a few seconds! Time to plug the stuff directly into the machine or buy a powered USB device. Thank you everyone!

Last edited by NachoGoro (2021-09-04 20:55:38)

Arch Linux

#1 2021-09-04 17:54:56

[SOLVED] Machine suddenly taking too long to boot

#2 2021-09-04 19:04:24

Re: [SOLVED] Machine suddenly taking too long to boot

#3 2021-09-04 19:28:36

Re: [SOLVED] Machine suddenly taking too long to boot

#4 2021-09-04 19:51:26

Re: [SOLVED] Machine suddenly taking too long to boot

#5 2021-09-04 20:52:38

Re: [SOLVED] Machine suddenly taking too long to boot

Board footer