systemd-journald and systemd-rfkill slowing down boot recently

KamiKevin · 2024-06-28 00:43:28

Since about 2-3 days ago I've noticed my system taking longer during the plymouth animation.
So first of all I ran systemd-analyze blame and found the culprit to be systemd-journald, and after several reboots trying diferent solutions, systemd-rfkill randomly joins the party (i.e. it doesn't appear to be consistent), both taking about 6 to 8 seconds to start.

8.481s systemd-journald.service
6.965s systemd-rfkill.service
685ms NetworkManager.service
215ms dev-nvme0n1p3.device
153ms user@1000.service
123ms plymouth-quit-wait.service
123ms plymouth-quit.service
111ms systemd-udev-trigger.service
100ms storage.mount
86ms home.mount
73ms upower.service
70ms systemd-journal-flush.service
68ms boot.mount
59ms accounts-daemon.service
57ms tmp.mount
56ms user-runtime-dir@1000.service
55ms polkit.service
47ms udisks2.service
44ms wpa_supplicant.service

About what I've tried so far:

flushing the logs, then rotating/vacuuming
verifying the logs, none were corrupt
running memtest, fsck and badblocks from the Arch iso. There are no apparent faults on either RAM or OS drive
reinstalling the systemd package
booting with different USB peripherals connected. This is the closest I've got to solving the issue, since connecting either the webcam or mouse causes one or both services to slow down again

Here are the results for journalctl -b and the last pacman log entries

seth · 2024-06-28 06:10:42

"systemd-analyze critical-chain", but

jun 27 17:13:40 naechsterstern kernel: usb usb8: We don't know the algorithms for LPM for this host, disabling LPM.
jun 27 17:13:40 naechsterstern kernel: usb usb8: New USB device found, idVendor=1d6b, idProduct=0003, bcdDevice= 6.09
jun 27 17:13:40 naechsterstern kernel: usb usb8: New USB device strings: Mfr=3, Product=2, SerialNumber=1
jun 27 17:13:40 naechsterstern kernel: usb usb8: Product: xHCI Host Controller
jun 27 17:13:40 naechsterstern kernel: usb usb8: Manufacturer: Linux 6.9.6-arch1-1 xhci-hcd
jun 27 17:13:40 naechsterstern kernel: usb usb8: SerialNumber: 0000:0e:00.0
jun 27 17:13:40 naechsterstern kernel: hub 8-0:1.0: USB hub found
jun 27 17:13:40 naechsterstern kernel: hub 8-0:1.0: config failed, hub doesn't have any ports! (err -19)
jun 27 17:13:40 naechsterstern kernel: usb 5-2: new high-speed USB device number 2 using xhci_hcd
jun 27 17:13:45 naechsterstern kernel: usb 1-6: new high-speed USB device number 2 using xhci_hcd
jun 27 17:13:45 naechsterstern kernel: usb 5-2: New USB device found, idVendor=174c, idProduct=2074, bcdDevice= 0.01
jun 27 17:13:45 naechsterstern kernel: usb 5-2: New USB device strings: Mfr=2, Product=3, SerialNumber=0
jun 27 17:13:45 naechsterstern kernel: usb 5-2: Product: ASM107x
jun 27 17:13:45 naechsterstern kernel: usb 5-2: Manufacturer: ASUS TEK.
jun 27 17:13:45 naechsterstern kernel: hub 5-2:1.0: USB hub found
jun 27 17:13:45 naechsterstern kernel: hub 5-2:1.0: 4 ports detected

There's a 5s gap - 1-6 is a usb audio device, 5-2 razer basilisk & blackwindow what fits your last finding (which is most likely the only relevant aspect here)
Is 5-2 an external hub? Did you try other ports?

lsusb -tv

KamiKevin · 2024-06-28 17:18:42

sytemd-analyze critical-chain:

graphical.target @3.098s
└─sddm.service @3.097s
  └─plymouth-quit.service @2.991s +105ms
    └─systemd-user-sessions.service @2.986s +3ms
      └─network.target @2.985s
        └─NetworkManager.service @2.919s +66ms
          └─basic.target @2.918s
            └─dbus-broker.service @2.896s +21ms
              └─dbus.socket @2.894s
                └─sysinit.target @2.893s
                  └─systemd-update-utmp.service @2.887s +6ms
                    └─systemd-tmpfiles-setup.service @2.819s +67ms
                      └─run-credentials-systemd\x2dtmpfiles\x2dsetup.service.mount @2.852s

I'm dumbfounded, today's times were not bad, same ports

Startup finished in 9.997s (firmware) + 488ms (loader) + 5.602s (kernel) + 3.098s (userspace) = 19.186s

systemd-journald start time is still somewhat high, but then would it be waiting for the Razer Basilisk?

2.069s systemd-journald.service
 221ms dev-nvme0n1p3.device
 142ms user@1000.service
 109ms systemd-udev-trigger.service
 105ms plymouth-quit-wait.service
 105ms plymouth-quit.service
  98ms systemd-journal-flush.service
  98ms storage.mount
  92ms accounts-daemon.service
  89ms systemd-localed.service
  84ms polkit.service
  83ms home.mount
  74ms systemd-tmpfiles-setup-dev-early.service
  73ms upower.service
  67ms systemd-tmpfiles-setup.service
...

lsusb -tv

5-1 and 5-2 are USB 3.2 Gen1 ports at the back of the motherboard.
I'll try plugging it to different ports tomorrow and report back any findings.

seth · 2024-06-28 21:48:16

The journal startup is probably caused by it flushing to disk, you'd have to look at the journal to see what's going on there.
If the behavior is non-deterministic you'd basically have to boot w/o the razer devices for a while to see whether you're still running into a stall.

KamiKevin · 2024-06-29 19:55:04

Thank you for your help so far seth.

By flushing to disk do you mean writing to /var/log/journal, or to /run/log/journal first? Below are the logs for journald and the flush to /var/log/journal takes milliseconds.
journalctl -u systemd-journald.service
~~There are a lot of these though.~~ I realized after posting that these logs span multiple days.

Anyways like you said I'll stick with my former mouse & keyboard for a while. journald startup also averages to 1-2s with those.

Last edited by KamiKevin (2024-06-29 19:57:45)

seth · 2024-06-29 22:15:38

Filtering for the journald.service likely won't tell much about the stall anyway, you need to look at the journal of a concerned boot in context to see what might slow down things when journald starts.

Arch Linux

#1 2024-06-28 00:43:28

systemd-journald and systemd-rfkill slowing down boot recently

#2 2024-06-28 06:10:42

Re: systemd-journald and systemd-rfkill slowing down boot recently

#3 2024-06-28 17:18:42

Re: systemd-journald and systemd-rfkill slowing down boot recently

#4 2024-06-28 21:48:16

Re: systemd-journald and systemd-rfkill slowing down boot recently

#5 2024-06-29 19:55:04

Re: systemd-journald and systemd-rfkill slowing down boot recently

#6 2024-06-29 22:15:38

Re: systemd-journald and systemd-rfkill slowing down boot recently

Board footer