systemd-journald.service slowing boot [SOLVED]

AntaresVII · 2024-07-05 21:13:46

The posts I could find on the topic suggested limiting the journal size; I have set max use to 50M (including restarting the service then rotate + vacuuming) but the issue persists.
On boot I get the line "A start job for Journal Service is running ([time elapsed]/1 min 30 sec)" displayed for the ~1min it takes to finish and complete booting

Output of systemd-analyze:

Startup finished in 27.819s (firmware) + 1.701s (loader) + 5.029s (kernel) + 1min 5.854s (userspace) = 1min 40.405s 
graphical.target reached after 1min 5.854s in userspace.

Output of systemd-analyze blame:

1min 3.992s systemd-journald.service
      952ms NetworkManager.service
      827ms boot.mount
      280ms home.mount
      255ms tmp.mount
      231ms dev-nvme0n1p2.device
      118ms systemd-rfkill.service
      107ms ufw.service
      106ms systemd-udev-trigger.service
      100ms user@1000.service
       87ms ldconfig.service
       82ms systemd-timesyncd.service
       72ms systemd-localed.service
       71ms upower.service
       67ms wpa_supplicant.service
       66ms systemd-journal-catalog-update.service
       64ms systemd-tmpfiles-setup-dev-early.service
       60ms systemd-update-utmp.service
       51ms systemd-remount-fs.service
       48ms user-runtime-dir@1000.service
       48ms systemd-timedated.service
       46ms systemd-journal-flush.service
       43ms udisks2.service
       41ms systemd-userdbd.service
       40ms systemd-tmpfiles-setup.service
       36ms polkit.service
       34ms systemd-logind.service
       33ms systemd-udevd.service
       31ms systemd-fsck@dev-disk-by\x2duuid-3abb09ec\x2dea53\x2d4040\x2db1c8\x2d8a39dfff39b2.service
       30ms systemd-hostnamed.service
       20ms dbus-broker.service
       20ms systemd-vconsole-setup.service
       17ms systemd-boot-random-seed.service
       16ms systemd-zram-setup@zram0.service
       16ms dev-zram0.swap
       16ms modprobe@dm_mod.service
       16ms systemd-modules-load.service
       15ms systemd-tmpfiles-setup-dev.service
       13ms lm_sensors.service
       11ms systemd-sysusers.service
       10ms dev-hugepages.mount
       10ms dev-mqueue.mount
       10ms sys-kernel-debug.mount
       10ms sys-kernel-tracing.mount
       10ms kmod-static-nodes.service
       10ms modprobe@configfs.service
        9ms modprobe@drm.service
        9ms modprobe@fuse.service
        9ms modprobe@loop.service
        9ms systemd-binfmt.service
        8ms rtkit-daemon.service
        7ms systemd-random-seed.service
        7ms systemd-udev-load-credentials.service
        5ms systemd-sysctl.service
        4ms systemd-user-sessions.service
        4ms systemd-update-done.service
        4ms sys-fs-fuse-connections.mount
        3ms sys-kernel-config.mount
        3ms proc-sys-fs-binfmt_misc.mount

Output of systemd-analyze critical-chain:

graphical.target @1min 5.854s
└─sddm.service @1min 5.853s
  └─systemd-user-sessions.service @1min 5.847s +4ms
    └─network.target @1min 5.845s
      └─wpa_supplicant.service @1min 5.777s +67ms
        └─basic.target @1min 4.821s
          └─dbus-broker.service @1min 4.799s +20ms
            └─dbus.socket @1min 4.797s
              └─sysinit.target @1min 4.796s
                └─systemd-timesyncd.service @1min 4.714s +82ms
                  └─systemd-tmpfiles-setup.service @1min 4.671s +40ms
                    └─run-credentials-systemd\x2dtmpfiles\x2dsetup.service.mount @1min 4.674s

Last edited by AntaresVII (2024-08-29 06:01:44)

ethanh762287 · 2024-07-06 12:39:51

Also having this issue, started recently.

ReD55 · 2024-07-06 17:08:16

For me, it looks like an issue with xhci_hcd and USB in genernal...

I am using linux-lts 6.6.37-1 systemd 256.1-1

blame

1min 22.765s systemd-journald.service
      1.659s docker.service
      1.646s systemd-modules-load.service
       852ms dev-sdb3.device
       530ms systemd-journal-flush.service
       431ms containerd.service
       379ms storage-container\x2d250G-0.mount
       363ms user@1000.service
       353ms systemd-udev-trigger.service
       346ms ldconfig.service
       334ms systemd-udev-load-credentials.service
       325ms storage-container\x2d250G-2.mount
       315ms systemd-remount-fs.service
       299ms storage-container\x2da100G-0.mount
       261ms lvm2-monitor.service
       256ms storage-container\x2d250G-1.mount
       230ms systemd-networkd-persistent-storage.service
       175ms modprobe@fuse.service
       174ms systemd-tmpfiles-setup.service
       161ms systemd-journal-catalog-update.service
       158ms systemd-resolved.service
       154ms systemd-networkd.service
       152ms systemd-fsck@dev-disk-by\x2ddiskseq-2\x2dpart1.service
       144ms ntpd.service
       140ms systemd-vconsole-setup.service
       139ms modprobe@drm.service
       135ms systemd-user-sessions.service
       113ms polkit.service
       111ms systemd-binfmt.service
       110ms systemd-tmpfiles-clean.service
       108ms user-runtime-dir@1000.service
       101ms dev-disk-by\x2duuid-1bbd00ec\x2d01ea\x2d4b3d\x2d9c9f\x2d3f9306c07bc3.swap
        98ms systemd-udevd.service
        87ms systemd-sysctl.service
        85ms systemd-tmpfiles-setup-dev.service
        85ms storage-super\x2dcontainer-0.mount
        82ms alsa-restore.service
        78ms efi.mount
        76ms systemd-logind.service
        72ms kmod-static-nodes.service
        72ms modprobe@configfs.service
        72ms systemd-sysusers.service
        69ms modprobe@loop.service
        69ms systemd-tmpfiles-setup-dev-early.service
        69ms systemd-timesyncd.service
        67ms systemd-update-utmp.service
        62ms systemd-update-done.service
        54ms tmp.mount
        51ms rtkit-daemon.service
        44ms systemd-random-seed.service
        40ms dbus-broker.service
        33ms docker.socket
        30ms modprobe@dm_mod.service
        20ms sys-fs-fuse-connections.mount
        19ms sys-kernel-config.mount
        17ms dev-hugepages.mount
        17ms dev-mqueue.mount

Journal

Jul 06 17:28:15 workstation kernel: Linux version 6.6.36-1-lts (linux-lts@archlinux) (gcc (GCC) 14.1.1 20240522, GNU ld (GNU Binutils) 2.42.0) #1 SMP PREEMPT_DYNAMIC Thu, 27 Jun 2024 12:26:27 +0000
...
Jul 06 17:28:15 workstation kernel: Console: switching to colour frame buffer device 128x48
Jul 06 17:29:38 workstation kernel: usb 1-10.3: new high-speed USB device number 3 using xhci_hcd
Jul 06 17:29:38 workstation kernel: usb 3-3.1: new high-speed USB device number 3 using xhci_hcd

    (async stropping / nothing happening)

Jul 06 17:29:38 workstation kernel: usb 1-10.3.2: Device not responding to setup address.
Jul 06 17:29:38 workstation kernel: usb 1-10.3.2: Device not responding to setup address.
Jul 06 17:29:38 workstation kernel: usb 1-10.3.2: device not accepting address 7, error -71
Jul 06 17:29:38 workstation kernel: usb 1-10.3-port2: unable to enumerate USB device
Jul 06 17:29:38 workstation systemd-journald[390]: Journal started
Jul 06 17:29:38 workstation systemd-journald[390]: Runtime Journal (/run/log/journal/566285e062b649c5a4f51a9c55d0459e) is 8M, max 797.1M, 789.1M free.
Jul 06 17:28:16 workstation mtp-probe[510]: checking bus 3, device 6: "/sys/devices/pci0000:00/0000:00:07.1/0000:0a:00.3/usb3/3-3/3-3.3"
Jul 06 17:28:15 workstation systemd-modules-load[391]: Failed to find module 'vboxdrv'
Jul 06 17:28:16 workstation mtp-probe[507]: checking bus 3, device 4: "/sys/devices/pci0000:00/0000:00:07.1/0000:0a:00.3/usb3/3-3/3-3.2"
Jul 06 17:28:15 workstation systemd-modules-load[391]: Failed to find module 'vboxnetadp'
Jul 06 17:28:16 workstation mtp-probe[507]: bus: 3, device: 4 was not an MTP device
Jul 06 17:28:15 workstation systemd-modules-load[391]: Failed to find module 'vboxnetflt'
Jul 06 17:28:16 workstation mtp-probe[510]: bus: 3, device: 6 was not an MTP device
Jul 06 17:28:16 workstation systemd-udevd[409]: Using default interface naming scheme 'v255'.
Jul 06 17:28:16 workstation mtp-probe[555]: checking bus 3, device 6: "/sys/devices/pci0000:00/0000:00:07.1/0000:0a:00.3/usb3/3-3/3-3.3"
Jul 06 17:28:16 workstation systemd-networkd[415]: lo: Link UP
Jul 06 17:28:16 workstation mtp-probe[555]: bus: 3, device: 6 was not an MTP device
 
    journal catching up

Jul 06 17:28:18 workstation mtp-probe[629]: checking bus 3, device 12: "/sys/devices/pci0000:00/0000:00:07.1/0000:0a:00.3/usb3/3-3/3-3.1/3-3.1.1/3-3.1.1.4/3-3.1.1.4.4"
Jul 06 17:29:17 workstation systemd-udevd[409]: 1-10.3: Worker [417] processing SEQNUM=3418 is taking a long time
Jul 06 17:28:18 workstation mtp-probe[628]: checking bus 3, device 11: "/sys/devices/pci0000:00/0000:00:07.1/0000:0a:00.3/usb3/3-3/3-3.1/3-3.1.1/3-3.1.1.4/3-3.1.1.4.3"
Jul 06 17:29:19 workstation systemd-udevd[409]: 3-3.1.1.4.4: Worker [419] processing SEQNUM=4224 is taking a long time
Jul 06 17:28:18 workstation mtp-probe[627]: bus: 3, device: 9 was not an MTP device
Jul 06 17:29:19 workstation (udev-worker)[419]: 3-3.1.1.4.4: Spawned process '/usr/lib/udev/mtp-probe /sys/devices/pci0000:00/0000:00:07.1/0000:0a:00.3/usb3/3-3/3-3.1/3-3.1.1/3-3.1.1.4/3-3.1.1.4.4 3 12' [629] is taking longer than 59s to complete.
Jul 06 17:28:18 workstation mtp-probe[626]: bus: 3, device: 10 was not an MTP device


    The end of it


Jul 06 17:28:18 workstation mtp-probe[626]: bus: 3, device: 10 was not an MTP device
Jul 06 17:28:18 workstation mtp-probe[628]: bus: 3, device: 11 was not an MTP device
Jul 06 17:28:18 workstation mtp-probe[669]: checking bus 3, device 11: "/sys/devices/pci0000:00/0000:00:07.1/0000:0a:00.3/usb3/3-3/3-3.1/3-3.1.1/3-3.1.1.4/3-3.1.1.4.3"
Jul 06 17:28:18 workstation mtp-probe[669]: bus: 3, device: 11 was not an MTP device
Jul 06 17:28:20 workstation mtp-probe[671]: checking bus 3, device 10: "/sys/devices/pci0000:00/0000:00:07.1/0000:0a:00.3/usb3/3-3/3-3.1/3-3.1.1/3-3.1.1.4/3-3.1.1.4.2"
Jul 06 17:28:20 workstation mtp-probe[671]: bus: 3, device: 10 was not an MTP device
Jul 06 17:28:20 workstation mtp-probe[672]: checking bus 3, device 9: "/sys/devices/pci0000:00/0000:00:07.1/0000:0a:00.3/usb3/3-3/3-3.1/3-3.1.1/3-3.1.1.4/3-3.1.1.4.1"
Jul 06 17:28:20 workstation mtp-probe[672]: bus: 3, device: 9 was not an MTP device
Jul 06 17:29:38 workstation mtp-probe[629]: bus: 3, device: 12 was not an MTP device

Jul 06 17:29:41 workstation systemd[1]: Startup finished in 28.242s (firmware) + 3.281s (loader) + 6.471s (kernel) + 1min 27.119s (userspace) = 2min 5.115s.

dmesg

[    7.843376] usb 3-3.1.1.4.4: new full-speed USB device number 12 using xhci_hcd
[    7.858653] systemd[1]: Mounting Arbitrary Executable File Formats File System...
[    7.866909] systemd[1]: Mounted Arbitrary Executable File Formats File System.
[    7.893674] systemd[1]: Finished Set Up Additional Binary Formats.
[    7.939715] usb 3-3.1.1.4.4: New USB device found, idVendor=1050, idProduct=0407, bcdDevice= 5.43
[    7.939720] usb 3-3.1.1.4.4: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[    7.939723] usb 3-3.1.1.4.4: Product: YubiKey OTP+FIDO+CCID
[    7.939726] usb 3-3.1.1.4.4: Manufacturer: Yubico
[    8.000286] r8169 0000:05:00.0 enp5s0: Link is Down
[    8.013790] systemd[1]: Finished Enable Persistent Storage in systemd-networkd.
[    8.094361] input: Yubico YubiKey OTP+FIDO+CCID as /devices/pci0000:00/0000:00:07.1/0000:0a:00.3/usb3/3-3/3-3.1/3-3.1.1/3-3.1.1.4/3-3.1.1.4.4/3-3.1.1.4.4:1.0/0003:1050:0407.000B/input/input24
[    8.127048] systemd[1]: Finished Rebuild Dynamic Linker Cache.
[    8.150292] hid-generic 0003:1050:0407.000B: input,hidraw10: USB HID v1.10 Keyboard [Yubico YubiKey OTP+FIDO+CCID] on usb-0000:0a:00.3-3.1.1.4.4/input0
[    8.151745] hid-generic 0003:1050:0407.000C: hiddev100,hidraw11: USB HID v1.10 Device [Yubico YubiKey OTP+FIDO+CCID] on usb-0000:0a:00.3-3.1.1.4.4/input1
[    8.207402] mc: Linux media interface: v0.10
[    8.231454] videodev: Linux video capture interface: v2.00
[    8.260896] usb 3-3.1.1.4.2: Found UVC 1.00 device <unnamed> (046d:081b)
[    8.331962] usbcore: registered new interface driver uvcvideo
[   10.022346] usb 3-3.1.1.4.2: set resolution quirk: cval->res = 384
[   10.022946] usbcore: registered new interface driver snd-usb-audio
[   10.063687] systemd[1]: Starting Load Kernel Module dm_mod...
[   10.065073] systemd[1]: Starting Load Kernel Module loop...
[   10.065120] systemd[1]: Update Boot Loader Random Seed was skipped because no trigger condition checks were met.
[   10.065164] systemd[1]: Clear Stale Hibernate Storage Info was skipped because of an unmet condition check (ConditionPathExists=/sys/firmware/efi/efivars/HibernateLocation-8cf2644b-4b0b-428f-9387-6d876050dc67).
[   10.065276] systemd[1]: Rebuild Hardware Database was skipped because no trigger condition checks were met.
[   10.065321] systemd[1]: TPM PCR Machine ID Measurement was skipped because of an unmet condition check (ConditionSecurity=measured-uki).
[   10.065363] systemd[1]: Early TPM SRK Setup was skipped because of an unmet condition check (ConditionSecurity=measured-uki).
[   10.065386] systemd[1]: TPM SRK Setup was skipped because of an unmet condition check (ConditionSecurity=measured-uki).
[   10.094083] systemd[1]: modprobe@dm_mod.service: Deactivated successfully.
[   10.134075] systemd[1]: Finished Load Kernel Module dm_mod.
[   10.134759] systemd[1]: modprobe@loop.service: Deactivated successfully.
[   10.177592] systemd[1]: Finished Load Kernel Module loop.
[   10.177938] systemd[1]: Repartition Root Disk was skipped because no trigger condition checks were met.
[   10.248564] r8169 0000:05:00.0 enp5s0: Link is Up - 1Gbps/Full - flow control rx/tx
[   20.610464] usb 1-10.3.2: device descriptor read/64, error -110
[   36.183973] usb 1-10.3.2: device descriptor read/64, error -110
[   36.400442] usb 1-10.3.2: new full-speed USB device number 5 using xhci_hcd
[   51.970452] usb 1-10.3.2: device descriptor read/64, error -110
[   67.543819] usb 1-10.3.2: device descriptor read/64, error -110
[   67.653365] usb 1-10.3-port2: attempt power cycle
[   68.320422] usb 1-10.3.2: new full-speed USB device number 6 using xhci_hcd
[   73.147473] usb 1-10.3.2: Device not responding to setup address.
[   78.180731] usb 1-10.3.2: Device not responding to setup address.
[   78.387055] usb 1-10.3.2: device not accepting address 6, error -71
[   78.497073] usb 1-10.3.2: new full-speed USB device number 7 using xhci_hcd
[   83.323889] usb 1-10.3.2: Device not responding to setup address.
[   88.357082] usb 1-10.3.2: Device not responding to setup address.
[   88.563675] usb 1-10.3.2: device not accepting address 7, error -71
[   88.567095] usb 1-10.3-port2: unable to enumerate USB device
[   88.612130] systemd[1]: Reached target Smart Card.
[   88.617778] systemd[1]: Started Journal Service.
[   88.680583] systemd-journald[396]: Received client request to flush runtime journal.
[   90.383953] input: ckb1: CORSAIR K100 RGB Optical-Mechanical Gaming Keyboard vKB as /devices/virtual/input/input25
[   90.384162] input: ckb1: CORSAIR K100 RGB Optical-Mechanical Gaming Keyboard vM as /devices/virtual/input/input26
[   91.163788] bridge: filtering via arp/ip/ip6tables is no longer available by default. Update your scripts to load br_netfilter if you need this.
[   91.168307] Bridge firewalling registered
[  141.116259] usb 3-3.1.1.4.2: reset high-speed USB device number 10 using xhci_hcd
[ 2765.010665] usb 3-3.1.1.1: new high-speed USB device number 13 using xhci_hcd
[ 2765.119334] usb 3-3.1.1.1: New USB device found, idVendor=24a9, idProduct=205a, bcdDevice= 2.00
[ 2765.119343] usb 3-3.1.1.1: New USB device strings: Mfr=2, Product=3, SerialNumber=4
[ 2765.119347] usb 3-3.1.1.1: Product: Intenso High Speed Line
[ 2765.119350] usb 3-3.1.1.1: Manufacturer: Asolid
[ 2765.119353] usb 3-3.1.1.1: SerialNumber: 23102577500034
[ 2765.169659] usb-storage 3-3.1.1.1:1.0: USB Mass Storage device detected
[ 2765.169835] scsi host10: usb-storage 3-3.1.1.1:1.0
[ 2765.169933] usbcore: registered new interface driver usb-storage
[ 2765.174567] usbcore: registered new interface driver uas
[ 2766.194299] scsi 10:0:0:0: Direct-Access     Intenso  High Speed Line       PQ: 0 ANSI: 4
[ 2766.195584] sd 10:0:0:0: [sde] 122060800 512-byte logical blocks: (62.5 GB/58.2 GiB)
[ 2766.195957] sd 10:0:0:0: [sde] Write Protect is off
[ 2766.195964] sd 10:0:0:0: [sde] Mode Sense: 23 00 00 00
[ 2766.196121] sd 10:0:0:0: [sde] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
[ 2766.200147]  sde: sde1 sde2
[ 2766.200513] sd 10:0:0:0: [sde] Attached SCSI removable disk
[ 2885.313400]  sde: sde1 sde2
[ 3042.046133] usb 3-3.1.1.1: USB disconnect, device number 13

Last edited by ReD55 (2024-07-06 22:07:42)

Varen · 2024-07-15 08:26:51

Also got the same issue since recently.

systemd-analyze:

Startup finished in 9.534s (firmware) + 6.112s (loader) + 3.281s (kernel) + 9.271s (userspace) = 28.200s

systemd-analyze critical-chain systemd-journald.service:

systemd-journald.service +7.853s
└─systemd-journald.socket @428ms

systemd-analyze blame:

7.853s systemd-journald.service
2.152s systemd-modules-load.service
1.147s \x2esnapshots.mount
715ms NetworkManager.service
229ms dev-nvme1n1p2.device

I tried to do a systemctl restart systemd-journald.service once booted up and the service takes around 30ms, so from my point of view it is narrowed down to the boot ... but I don't know how to approach it further...

Last edited by Varen (2024-07-15 08:27:04)

retalak · 2024-07-16 16:20:12

I also have the same issue!

9.307s systemd-journald.service

seth · 2024-07-17 06:52:12

It's most likely symptom of any underlying problem (might not even be the same for everyone, the delay times are all over the place)
Eg. for ReD55 it seems the combination of a bad USB device and some udev rule
=> You've to look at the entire journal in context

analyze blame can bt. be deceptive (worst offenders here are mandb and updatedb, except they don't run during the boot…), but a long run there might indicate issues w/ flushing the journal to disk.

Varen · 2024-07-17 13:35:34

seth wrote:

It's most likely symptom of any underlying problem (might not even be the same for everyone, the delay times are all over the place)
Eg. for ReD55 it seems the combination of a bad USB device and some udev rule
=> You've to look at the entire journal in context
analyze blame can bt. be deceptive (worst offenders here are mandb and updatedb, except they don't run during the boot…), but a long run there might indicate issues w/ flushing the journal to disk.

while I agree, that it might be because of some other, underlying problem(s), its kinda strange that some people started to have this issue recently (like, in the last 2-3 weeks)? It wasn't an issue before (as I understood or is, in my case), so why did it start now, what's the reason behind that and why didn't it show up before? and - underlying problem or not - if it worked better before, why can't it run better again now (I totally agree, that if there are underlying problems with e.g. bad usb devices, that they need to be fixed ...).

In my case, I do also have some entries in my journal, which point in that bad USB direction - but even if boot takes now longer, everything works afterwards...so?

seth · 2024-07-17 14:25:25

For USB errors I'd try a kernel downgrade, bad udev rules are most likely to come out of systemd (but so is journald)
I can't tell you more based only on "entries in my journal, which point in that bad USB direction" but you want to check older journals (if you have) whether those errors appear there as well and whether they differ.

Varen · 2024-07-23 16:16:50

So I tried to narrow it down further. I tried booting with ABSOLUTELY NO USB-devices attached. Nothing, still having the issue. I went through my journal and there are indeed here and there some seconds lost and some errors, but from my understanding and knowledge (after all sitting here in the newb-corner…) nothing too crazy.

I don‘t know, if someone in here wants to have a detailed look into it, I‘ll happily provide logs and informations, let me know whats needed.

But still, not being the only one where it started recently to be bad, I still fail to wrap my head around it what might be the issue here

Last edited by Varen (2024-07-23 16:17:38)

seth · 2024-07-23 20:43:57

If you're "losing seconds here and there" you're not gonna stall the boot for 90s
Please post your complete system journal for the boot:

sudo journalctl -b | curl -F 'file=@-' 0x0.st

Varen · 2024-07-25 21:30:02

thankfully I'm not losing about 90s on boot, but still:

Startup finished in 8.628s (firmware) + 2.430s (loader) + 2.417s (kernel) + 12.337s (userspace) = 25.813s 
graphical.target reached after 12.334s in userspace.

11.024s systemd-journald.service
  975ms \x2esnapshots.mount
  770ms NetworkManager.service
  321ms systemd-modules-load.service
  278ms dev-nvme1n1p2.device
  175ms systemd-tmpfiles-clean.service
  148ms ldconfig.service
  113ms systemd-udev-trigger.service
  108ms user@1000.service
  108ms upower.service

he 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-journald.service +11.024s
└─systemd-journald.socket @274ms
  └─-.mount @254ms
    └─-.slice @254ms

here's my journalctl -b
https://pastebin.com/isBSP12n

seth · 2024-07-26 06:07:33

Jul 25 21:13:15 NALX kernel: Linux version 6.10.1-1-cachyos-eevdf (linux-cachyos-eevdf@cachyos) (gcc (GCC) 14.1.1 20240720, GNU ld (GNU Binutils) 2.42.0) #1 SMP PREEMPT_DYNAMIC Wed, 24 Jul 2024 21:50:01 +0000

https://bbs.archlinux.org/misc.php?action=rules

Jul 25 21:13:15 NALX kernel: nvme nvme0: 16/0/0 default/read/poll queues
Jul 25 21:13:15 NALX kernel:  nvme0n1: p1 p2 p3 p4 p5 p6
Jul 25 21:13:15 NALX kernel: nvme nvme1: 16/0/0 default/read/poll queues
Jul 25 21:13:15 NALX kernel:  nvme1n1: p1 p2
Jul 25 21:13:15 NALX kernel: xhci_hcd 0000:0a:00.0: hcc params 0x0200ef81 hci version 0x110 quirks 0x0000000200000010
Jul 25 21:13:15 NALX kernel: xhci_hcd 0000:0a:00.0: xHCI Host Controller
Jul 25 21:13:15 NALX kernel: xhci_hcd 0000:0a:00.0: new USB bus registered, assigned bus number 2
Jul 25 21:13:15 NALX kernel: xhci_hcd 0000:0a:00.0: Host supports USB 3.2 Enhanced SuperSpeed
Jul 25 21:13:26 NALX kernel: usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 6.10
Jul 25 21:13:26 NALX kernel: usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
Jul 25 21:13:26 NALX kernel: usb usb1: Product: xHCI Host Controller
Jul 25 21:13:26 NALX kernel: usb usb1: Manufacturer: Linux 6.10.1-1-cachyos-eevdf xhci-hcd
Jul 25 21:13:26 NALX kernel: usb usb1: SerialNumber: 0000:0a:00.0
Jul 25 21:13:26 NALX kernel: hub 1-0:1.0: USB hub found
…
Jul 25 21:13:26 NALX systemd-journald[398]: Runtime Journal (/run/log/journal/c6c25d6d14c142c4bf141dc6d05e029a) is 8M, max 1.5G, 1.5G free.
Jul 25 21:13:16 NALX mtp-probe[526]: checking bus 5, device 4: "/sys/devices/pci0000:00/0000:00:08.1/0000:0c:00.4/usb5/5-2/5-2.4"
Jul 25 21:13:15 NALX systemd-modules-load[399]: Inserted module 'crypto_user'
Jul 25 21:13:16 NALX mtp-probe[527]: checking bus 5, device 3: "/sys/devices/pci0000:00/0000:00:08.1/0000:0c:00.4/usb5/5-2/5-2.1"
Jul 25 21:13:15 NALX systemd-modules-load[399]: Inserted module 'i2c_dev'
Jul 25 21:13:16 NALX mtp-probe[527]: bus: 5, device: 3 was not an MTP device
Jul 25 21:13:15 NALX systemd-udevd[424]: Using default interface naming scheme 'v255'.
Jul 25 21:13:16 NALX mtp-probe[526]: bus: 5, device: 4 was not an MTP device
Jul 25 21:13:15 NALX systemd-modules-load[399]: Inserted module 'nvidia_uvm'
Jul 25 21:13:16 NALX mtp-probe[528]: checking bus 5, device 3: "/sys/devices/pci0000:00/0000:00:08.1/0000:0c:00.4/usb5/5-2/5-2.1"
Jul 25 21:13:15 NALX systemd-modules-load[399]: Inserted module 'pkcs8_key_parser'
Jul 25 21:13:16 NALX mtp-probe[528]: bus: 5, device: 3 was not an MTP device
Jul 25 21:13:15 NALX systemd-modules-load[399]: Inserted module 'winesync'
Jul 25 21:13:16 NALX mtp-probe[535]: checking bus 5, device 4: "/sys/devices/pci0000:00/0000:00:08.1/0000:0c:00.4/usb5/5-2/5-2.4"
Jul 25 21:13:15 NALX (udev-worker)[465]: event5: Failed to call EVIOCSKEYCODE with scan code 0x7c, and key code 190: Invalid argument
Jul 25 21:13:16 NALX mtp-probe[535]: bus: 5, device: 4 was not an MTP device
Jul 25 21:13:26 NALX mtp-probe[571]: checking bus 1, device 2: "/sys/devices/pci0000:00/0000:00:02.1/0000:03:00.0/0000:04:0c.0/0000:0a:00.0/usb1/1-6"
Jul 25 21:13:26 NALX mtp-probe[570]: checking bus 1, device 3: "/sys/devices/pci0000:00/0000:00:02.1/0000:03:00.0/0000:04:0c.0/0000:0a:00.0/usb1/1-7"

There's no error surrounding the stall and the time jumps backwards afterwards.
Gut feeling would be to disable /usr/lib/udev/rules.d/69-libmtp.rules (adding a symlink to dev/null in /etc/udev/rules.d should™ be sufficient)

with ABSOLUTELY NO USB-devices attached

Jul 25 21:13:26 NALX kernel: usb 5-2.1: Product: Gaming Keyboard G910
Jul 25 21:13:26 NALX kernel: usb 5-2.4: Product: Razer BlackShark V2 Pro 2.4
Jul 25 21:13:26 NALX kernel: usb 1-6: Product: USB Audio
Jul 25 21:13:26 NALX kernel: usb 1-7: Product: AURA LED Controller
Jul 25 21:13:26 NALX kernel: usb 1-8: Product: USB2.0 Hub
Jul 25 21:13:26 NALX kernel: usb 1-9: Product: Razer Naga Pro
Jul 25 21:13:26 NALX kernel: usb 1-8.2: Product: ITE Device(8910)
Jul 25 21:13:26 NALX kernel: usb 1-10: Product: Razer Naga Pro
Jul 25 21:13:26 NALX kernel: usb 1-11: Product: Wireless_Device
Jul 25 21:13:26 NALX kernel: usb 1-12: Product: Razer Firefly V2

I blame the g4m0rz stuff…

Varen · 2024-07-26 06:15:24

https://bbs.archlinux.org/misc.php?action=rules

It is vanilla Arch. Just using the CachyOS kernel, but not the whole OS

And yeah, this was "just" a normal boot, with everything attached normally - I'll upload one with everything detached if that helps.

Gut feeling would be to disable /usr/lib/udev/rules.d/69-libmtp.rules (adding a symlink to dev/null in /etc/udev/rules.d should™ be sufficient)

will try and report back.

Thanks for having a look and taking the time, appreciate it!

Last edited by Varen (2024-07-26 06:15:49)

Oikio · 2024-08-06 10:10:31

For other people looking for solution. I had exactly the same problem as OP after last update. Everything pointed out to `run-credentials-systemd\x2dtmpfiles\x2dsetup.service.mount` taking too long because of some USB devices. Removing all USB devices did not help, I've even tried restoring weekly backup - same issue. And last step left me clueless, until I tried to power off my PC and all related devices completely. My assumption was that there might have been physical issue, like with condenser or whatever. Inspection showed nothing, but after I plugged PC in and turned it on - it just loaded system without delays.

Last edited by Oikio (2024-08-06 10:15:21)

AntaresVII · 2024-08-09 07:06:38

No longer having this issue, can't be sure what changed; I'm reasonably confident I didn't update between the original post and the problem desisting. It's possible that like Oikio I did a complete power cycle for the first time since it coming up, but I can't be sure.

I suppose I'm due some embarrassment either way for not trying "turning it off and on again" beforehand.

Last edited by AntaresVII (2024-08-09 07:11:00)

Varen · 2024-08-12 09:19:29

I was off due to vacancy, so apologies for the long waiting of an answer.

Power cycling the machine didn't help in my case and I'm still stuck with the issue - I'll have to do the boot with all USBs unplugged and paste Log.

But since the issue for the original poster is solved, feel free to close it down, wasn't my intention to hijack it. I'll open up a new post as soon I was able to gather the necessary logs.

Varen · 2024-08-14 22:15:18

Mine‘s solved as well. Turns out, it was most probably a Kernel Issue, since its not happening anymore with todays kernel update to 6.10.5-1

Arch Linux

#1 2024-07-05 21:13:46

systemd-journald.service slowing boot [SOLVED]

#2 2024-07-06 12:39:51

Re: systemd-journald.service slowing boot [SOLVED]

#3 2024-07-06 17:08:16

Re: systemd-journald.service slowing boot [SOLVED]

#4 2024-07-15 08:26:51

Re: systemd-journald.service slowing boot [SOLVED]

#5 2024-07-16 16:20:12

Re: systemd-journald.service slowing boot [SOLVED]

#6 2024-07-17 06:52:12

Re: systemd-journald.service slowing boot [SOLVED]

#7 2024-07-17 13:35:34

Re: systemd-journald.service slowing boot [SOLVED]

#8 2024-07-17 14:25:25

Re: systemd-journald.service slowing boot [SOLVED]

#9 2024-07-23 16:16:50

Re: systemd-journald.service slowing boot [SOLVED]

#10 2024-07-23 20:43:57

Re: systemd-journald.service slowing boot [SOLVED]

#11 2024-07-25 21:30:02

Re: systemd-journald.service slowing boot [SOLVED]

#12 2024-07-26 06:07:33

Re: systemd-journald.service slowing boot [SOLVED]

#13 2024-07-26 06:15:24

Re: systemd-journald.service slowing boot [SOLVED]

#14 2024-08-06 10:10:31

Re: systemd-journald.service slowing boot [SOLVED]

#15 2024-08-09 07:06:38

Re: systemd-journald.service slowing boot [SOLVED]

#16 2024-08-12 09:19:29

Re: systemd-journald.service slowing boot [SOLVED]

#17 2024-08-14 22:15:18

Re: systemd-journald.service slowing boot [SOLVED]

Board footer