You are not logged in.
Hello Arch Friends,
(an intermediate thanks to the Arch Community for being helpful so far. I'm getting the hang of it slowly but steadily)
My problem is simple (i guess). Long boot time. I see what the title says during the boot process "[*--] [-*-] [--*] [-*-] [*--] A start job is running for Journal Service (32s/1 min 30 s)"
A little bit of digging i found a way to see what specifically is making the boot time taking so long by performing the commands "sudo systemd-analyze" and "sudo systemd-analyze blame" and "sudo systemd-analyze critical-chain". Here's their outputs:
[motherfucker_big_scorpio@Nexus ~]$ sudo 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 @37.905s
└─sddm.service @37.905s
└─plymouth-quit.service @37.878s +24ms
└─systemd-user-sessions.service @37.865s +10ms
└─network.target @37.863s
└─NetworkManager.service @37.440s +422ms
└─network-pre.target @37.438s
[motherfucker_big_scorpio@Nexus ~]$ sudo systemd-analyze
Startup finished in 23.823s (firmware) + 21.259s (loader) + 12.635s (kernel) + 37.910s (userspace) = 1min 35.629s
graphical.target reached after 37.905s in userspace.
[motherfucker_big_scorpio@Nexus ~]$ sudo systemd-analyze blame
36.609s systemd-journald.service
852ms systemd-binfmt.service
775ms lvm2-monitor.service
422ms NetworkManager.service
270ms dev-mapper-SystemVolume\x2droot.device
254ms user@1000.service
205ms systemd-udev-trigger.service
190ms nftables.service
177ms udisks2.service
177ms home.mount
132ms ufw.service
129ms upower.service
103ms systemd-tmpfiles-setup.service
76ms systemd-journal-flush.service
75ms accounts-daemon.service
64ms systemd-tmpfiles-setup-dev-early.service
62ms polkit.service
59ms systemd-logind.service
55ms systemd-udevd.service
52ms systemd-fsck@dev-disk-by\x2duuid-D87B\x2dAFAA.service
51ms systemd-hostnamed.service
48ms dev-zram0.swap
47ms systemd-vconsole-setup.service
39ms dev-disk-by\x2duuid-826ae0ac\x2d254c\x2d4146\x2dadec\x2d1972158dbf9e.swap
38ms dbus-broker.service
38ms systemd-cryptsetup@systemdrive.service
37ms plymouth-start.service
33ms systemd-fsck@dev-disk-by\x2duuid-91EB\x2d4A5D.service
32ms systemd-fsck@dev-disk-by\x2duuid-2f00a55b\x2d4388\x2d42be\x2db77f\x2de4bfa6676b00.service
32ms proc-sys-fs-binfmt_misc.mount
31ms systemd-tmpfiles-setup-dev.service
30ms systemd-update-utmp.service
28ms boot.mount
26ms systemd-userdbd.service
25ms plymouth-quit-wait.service
25ms systemd-zram-setup@zram0.service
24ms plymouth-quit.service
20ms plymouth-read-write.service
19ms systemd-random-seed.service
19ms dev-hugepages.mount
19ms dev-mqueue.mount
18ms sys-kernel-debug.mount
18ms sys-kernel-tracing.mount
17ms rtkit-daemon.service
17ms user-runtime-dir@1000.service
17ms boot-efi.mount
17ms kmod-static-nodes.service
16ms systemd-modules-load.service
15ms modprobe@dm_mod.service
15ms modprobe@drm.service
15ms sys-fs-fuse-connections.mount
15ms sys-kernel-config.mount
14ms modprobe@configfs.service
14ms modprobe@loop.service
14ms tmp.mount
14ms modprobe@fuse.service
13ms systemd-sysctl.service
11ms systemd-rfkill.service
10ms systemd-user-sessions.service
10ms systemd-remount-fs.service
10ms systemd-udev-load-credentials.service
[motherfucker_big_scorpio@Nexus ~]$
I noticed, that it looks like the NetworkManager is taking long to boot up from these last lines in the chain.
└─NetworkManager.service @37.440s +422ms
└─network-pre.target @37.438s
Indeed, I do something on startup with the NetworkManager but more specifically I am using Wireguard (wireguard-tools) to connect to a VPN automatically on startup. At the same time whenever I first log in to the system, the VPN is connected but there is no network activity going on until I disconnect and then reconnect that same VPN manually from the taskbar (plasmashell as I'm using KDE).
So there's 2 problems I see, perhaps one of it causing both at the same time. This sounds more like a networking/VPN problem causing both the increased boot time AND having no network activity going on. Here's my basic Network configuration (as i see from NetworkManager GUI):
Wired Connection (my primary internet connection):
[✔️] Connect automatically with priority -100
[✔️] All users may connect
My VPN Connection:
[✔️] Connect automatically with priority 0
[✔️] All users may connect
and the "ip addr" output:
[motherfucker_big_scorpio@Nexus ~]$ ip addr
1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN group default qlen 1000
link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
inet 127.0.0.1/8 scope host lo
valid_lft forever preferred_lft forever
inet6 ::1/128 scope host noprefixroute
valid_lft forever preferred_lft forever
2: enp7s0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc mq state UP group default qlen 1000
link/ether 40:8d:5c:52:20:38 brd ff:ff:ff:ff:ff:ff
altname enx408d5c522038
inet 192.168.1.10/24 brd 192.168.1.255 scope global dynamic noprefixroute enp7s0
valid_lft 5826sec preferred_lft 5826sec
inet6 fe80::52d:a5f6:40ec:ed5c/64 scope link noprefixroute
valid_lft forever preferred_lft forever
3: enp0s31f6: <NO-CARRIER,BROADCAST,MULTICAST,UP> mtu 1500 qdisc fq_codel state DOWN group default qlen 1000
link/ether 40:8d:5c:52:20:3a brd ff:ff:ff:ff:ff:ff
altname enx408d5c52203a
5: my-vpn: <POINTOPOINT,NOARP,UP,LOWER_UP> mtu 1400 qdisc noqueue state UNKNOWN group default qlen 1000
link/none
inet 10.10.97.89/32 scope global noprefixroute cs-portugal
valid_lft forever preferred_lft forever
inet6 fd00:10:10::9113/128 scope global noprefixroute
valid_lft forever preferred_lft forever
inet6 fe80::7c09:5812:186e:562e/64 scope link noprefixroute
valid_lft forever preferred_lft forever
[motherfucker_big_scorpio@Nexus ~]$
Please advise.
Last edited by Big Scorpio (2025-03-09 18:48:08)
Offline
Just from these outputs networkmanager doesn't take long but journal service does which is weird already, post a complete journal
sudo journalctl -b | curl -F 'file=@-' 0x0.st
and maybe throw in
find /etc/systemd -type l -exec test -f {} \; -print | awk -F'/' '{ printf ("%-40s | %s\n", $(NF-0), $(NF-1)) }' | sort -f
Offline
Complying.
Journal http://0x0.st/8A-o.txt
[motherfucker_big_scorpio@Nexus ~]$ find /etc/systemd -type l -exec test -f {} \; -print | awk -F'/' '{ printf ("%-40s | %s\n", $(NF-0), $(NF-1)) }' | sort -f
ceserver.service | multi-user.target.wants
dbus-org.freedesktop.nm-dispatcher.service | system
display-manager.service | system
getty@tty1.service | getty.target.wants
NetworkManager-wait-online.service | network-online.target.wants
NetworkManager.service | multi-user.target.wants
nftables.service | multi-user.target.wants
nvidia-hibernate.service | systemd-hibernate.service.wants
nvidia-resume.service | systemd-hibernate.service.wants
nvidia-resume.service | systemd-suspend.service.wants
nvidia-suspend.service | systemd-suspend.service.wants
p11-kit-server.socket | sockets.target.wants
pipewire-pulse.socket | sockets.target.wants
pipewire-session-manager.service | user
pipewire.socket | sockets.target.wants
remote-fs.target | multi-user.target.wants
systemd-userdbd.socket | sockets.target.wants
ufw.service | multi-user.target.wants
wireplumber.service | pipewire.service.wants
xdg-user-dirs-update.service | default.target.wants
[motherfucker_big_scorpio@Nexus ~]$
Offline
From your journal:
Feb 23 22:56:51 Nexus systemd[1]: Startup finished in 21.571s (firmware) + 16.770s (loader) + 28.851s (kernel) + 37.816s (userspace) = 1min 45.009s.
From my journal:
Feb 24 06:48:08 box systemd[1]: Startup finished in 14.492s (firmware) + 2.064s (loader) + 2.672s (kernel) + 1.877s (userspace) = 21.106s.
That is not a question of recent hardware. My old/secondary PC (12 year old motherboard/processor with a 14 year old SATA II SSD) shows this:
Feb 24 07:32:18 old_box systemd[1]: Startup finished in 10.664s (firmware) + 4.315s (loader) + 2.291s (kernel) + 2.833s (userspace) = 20.154s.
Fun fact: Your log shows no holdup for NetworkManager although your VPN gets activated before your Ethernet connection is fully functional.
Try setting the priorities to "10" for Ethernet and "5" for the VPN.
Feb 23 22:56:14 Nexus kernel: hub 1-0:1.0: 16 ports detected Feb 23 22:56:18 Nexus kernel: usb usb2: New USB device found, idVendor=1d6b, idProduct=0003, bcdDevice= 6.13 Feb 23 22:56:26 Nexus kernel: usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1 Feb 23 22:56:34 Nexus kernel: usb usb2: Product: xHCI Host Controller Feb 23 22:56:42 Nexus kernel: usb usb2: Manufacturer: Linux 6.13.2-arch1-1 xhci-hcd Feb 23 22:56:50 Nexus kernel: usb usb2: SerialNumber: 0000:00:14.0
Your system needs 32 seconds to initialize this USB 3 controller. Try removing all non-essential USB devices and/or not connecting any devices to this controller.
Feb 23 22:56:51 Nexus systemd-tmpfiles[782]: Cannot set file attributes for '/var/log/journal', maybe due to incompatibility in specified attributes, previous=0x10001000, current=0x10001000, expected=0x10801000, ignoring. Feb 23 22:56:51 Nexus systemd-tmpfiles[782]: Cannot set file attributes for '/var/log/journal/885e9e5e940e4b40bcfe180d7ba6cfb5', maybe due to incompatibility in specified attributes, previous=0x00001000, current=0x00001000, expected=0x00801000, ignoring. Feb 23 22:56:51 Nexus systemd-tmpfiles[782]: Cannot set file attributes for '/var/log/journal/remote', maybe due to incompatibility in specified attributes, previous=0x10001000, current=0x10001000, expected=0x10801000, ignoring.
This is probably the cause of the journald holdup. Check the attributes.
Offline
You are onto something -thc. I attempted your suggestion and i have disconnected all USB devices and then started up my machine. The boot time is swift now. See the new results:
Journal -> http://0x0.st/8A4A.txt
Some system analyze commands:
[motherfucker_big_scorpio@Nexus ~]$ sudo 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 @3.235s
└─sddm.service @3.235s
└─plymouth-quit.service @3.202s +28ms
└─systemd-user-sessions.service @3.184s +16ms
└─network.target @3.182s
└─NetworkManager.service @2.709s +472ms
└─network-pre.target @2.707s
[motherfucker_big_scorpio@Nexus ~]$
[motherfucker_big_scorpio@Nexus ~]$ sudo systemd-analyze
[sudo] password for motherfucker_big_scorpio:
Startup finished in 17.525s (firmware) + 44.028s (loader) + 7.694s (kernel) + 3.238s (userspace) = 1min 12.486s
graphical.target reached after 3.235s in userspace.
[motherfucker_big_scorpio@Nexus ~]$
[motherfucker_big_scorpio@Nexus ~]$ sudo systemd-analyze blame
882ms systemd-binfmt.service
472ms NetworkManager.service
268ms user@1000.service
264ms dev-zram0.swap
264ms systemd-fsck@dev-disk-by\x2duuid-2f00a55b\x2d4388\x2d42be\x2db77f\x2de4bfa6676b00.service
261ms dev-mapper-SystemVolume\x2droot.device
249ms systemd-cryptsetup@systemdrive.service
249ms dev-disk-by\x2duuid-826ae0ac\x2d254c\x2d4146\x2dadec\x2d1972158dbf9e.swap
203ms systemd-udev-trigger.service
171ms udisks2.service
162ms home.mount
141ms nftables.service
133ms ufw.service
110ms upower.service
93ms systemd-hostnamed.service
89ms systemd-journald.service
75ms systemd-journal-flush.service
74ms dbus-broker.service
70ms systemd-tmpfiles-setup.service
70ms systemd-tmpfiles-setup-dev-early.service
60ms lvm2-monitor.service
60ms systemd-udevd.service
55ms accounts-daemon.service
51ms systemd-fsck@dev-disk-by\x2duuid-D87B\x2dAFAA.service
47ms polkit.service
44ms plymouth-start.service
40ms proc-sys-fs-binfmt_misc.mount
33ms systemd-logind.service
31ms systemd-zram-setup@zram0.service
30ms systemd-userdbd.service
30ms systemd-tmpfiles-setup-dev.service
29ms systemd-fsck@dev-disk-by\x2duuid-91EB\x2d4A5D.service
28ms boot.mount
28ms plymouth-quit.service
26ms plymouth-quit-wait.service
23ms systemd-vconsole-setup.service
23ms rtkit-daemon.service
21ms systemd-update-utmp.service
20ms plymouth-read-write.service
18ms systemd-modules-load.service
18ms systemd-random-seed.service
17ms dev-hugepages.mount
17ms dev-mqueue.mount
17ms sys-kernel-debug.mount
16ms sys-kernel-tracing.mount
16ms boot-efi.mount
16ms systemd-user-sessions.service
15ms kmod-static-nodes.service
15ms tmp.mount
15ms systemd-udev-load-credentials.service
14ms modprobe@configfs.service
14ms modprobe@drm.service
14ms modprobe@dm_mod.service
14ms user-runtime-dir@1000.service
13ms modprobe@fuse.service
13ms modprobe@loop.service
13ms systemd-sysctl.service
9ms systemd-remount-fs.service
5ms sys-fs-fuse-connections.mount
5ms sys-kernel-config.mount
[motherfucker_big_scorpio@Nexus ~]$
[motherfucker_big_scorpio@Nexus ~]$ sudo systemd-analyze blame | grep journal
89ms systemd-journald.service
75ms systemd-journal-flush.service
[motherfucker_big_scorpio@Nexus ~]$
Therefore we have deduced, that it is a USB device causing the slow boot times. I will have to figure out (on my own from now on) which one (or multiples) of those it is.
However I don't understand why "systemd-analyze" reports over 1 minute. Physically I saw, that my machine booted swiftly to the login screen and in blame we can see the journal took less than 0.1 seconds to finish.
Try setting the priorities to "10" for Ethernet and "5" for the VPN.
Complied. Same results. See this screenshot -> https://i.imgur.com/YFoF5Pf.png
Your system needs 32 seconds to initialize this USB 3 controller.
This is probably the cause of the journald holdup. Check the attributes.
How do i find out which one it is "programmatically"? Or do i have to disconnect each device like i planned to?
And how do i check those attributes?
Offline
Look at the line
Feb 25 14:56:36 Nexus systemd[1]: Startup finished in 17.525s (firmware) + 44.028s (loader) + 7.694s (kernel) + 3.238s (userspace) = 1min 12.486s.
from your log - "firmware" and "loader" are to blame.
The priorities doesn't change anything? Maybe auto-activation and/or WireGuard auto-activation don't work.
Attach a recognizable and unique USB device to every port and verify via lsusb tree view
lsusb -t
where it's at.
Check
ls -lah /var/log/journal
ls -lah /var/log/journal/885e9e5e940e4b40bcfe180d7ba6cfb5
ls -lah /var/log/journal/remote
first.
Offline
Hey,
Can you take a look at this thread and see if it's similar ? Have you tried booting with a higher loglevel to see what could be wrong here ?
Offline
Alright, i experimented with this problem by disconnecting my USB devices 1 by 1 and doing some other things. What's weird is that my USB mouse has been causing the long boot times *if* it was connected to a USB port (extension card), that is extended on the PCIE slot on my motherboard below the GPU plate. My mouse functions just fine and I don't know what Linux finds so disturbing about it. Windows doesn't care about that and just works "swiftly".
Some background however why that's not a feasible solution but only a less-than-optimal workaround just for convenience. Since the beginning Linux system has been spamming at me this
Jan 03 09:48:26 Nexus kernel: usb usb2-port1: Cannot enable. Maybe the USB cable is bad?
Jan 03 09:48:30 Nexus kernel: usb usb2-port1: Cannot enable. Maybe the USB cable is bad?
Jan 03 09:48:34 Nexus kernel: usb usb2-port1: Cannot enable. Maybe the USB cable is bad?
To which seth replied to me, that it's a symptom of a problem, possibly IO and stalling. I had X11 being affected by it (or not, I'm not sure), so that X11 and KDE would take 3 minutes to wake up after being AFK. ( https://bbs.archlinux.org/viewtopic.php?id=302113 ). Long story short, this USB port is on my motherboard's back panel and it happens regardless how many USB devices are connected to it (i tried previously. same result). To my dismay, as i haven't found any other way to deal with it, i ended up creating a udev rule to blacklist this USB port (this inadvertently affected the entire backpanel with all USB connectors on them) by creating a file "/etc/udev/rules.d/99-disable-usb2-port1.rules" and then adding <file contents start>ACTION=="add", SUBSYSTEM=="usb", KERNEL=="usb2", ATTR{authorized}="0"<file contents end> to it.
So essentially by connecting my USB optical mouse from the USB port of my extension card to the motherboard's back panel USB port, which has been blacklisted by a udev rule (because Linux wouldn't shut up about usb2-port1 and causing some performance problems), the system booted faster (26 seconds i recall), although right now i cannot post the matching results. This time it booted in 50 seconds as i've experimented with things like switching from the bloated and incessant CPU and RAM gobbling KDE to XFCE. That one is a story for another thread.
[motherfucker_big_scorpio@Nexus ~]$ sudo 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 @3.216s
└─multi-user.target @3.215s
└─plymouth-quit.service @3.190s +24ms
└─systemd-user-sessions.service @3.174s +13ms
└─network.target @3.172s
└─NetworkManager.service @2.802s +369ms
└─network-pre.target @2.800s
[motherfucker_big_scorpio@Nexus ~]$ sudo systemd-analyze
Startup finished in 20.979s (firmware) + 18.445s (loader) + 7.855s (kernel) + 3.216s (userspace) = 50.497s
graphical.target reached after 3.216s in userspace.
[motherfucker_big_scorpio@Nexus ~]$ sudo systemd-analyze blame
1.337s systemd-fsck@dev-disk-by\x2duuid-2f00a55b\x2d4388\x2d42be\x2db77f\x2de4bfa6676b00.service
369ms NetworkManager.service
332ms user@1000.service
263ms dev-mapper-SystemVolume\x2droot.device
257ms ldconfig.service
Offline
"Solved".
Summary: blacklisted the USB port that spams in system journal "Bad cable?" using udev rule (to my dismay). Connected my USB mouse from the USB port on my extension card to the USB port on my motherboard's backpanel.
[motherfucker_big_scorpio@Nexus ~]$ sudo systemd-analyze
Startup finished in 7.415s (kernel) + 3.170s (userspace) = 10.585s
graphical.target reached after 3.170s in userspace.
[motherfucker_big_scorpio@Nexus ~]$ sudo 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 @3.170s
└─sddm.service @3.170s
└─plymouth-quit.service @3.144s +24ms
└─systemd-user-sessions.service @3.128s +13ms
└─network.target @3.125s
└─NetworkManager.service @2.677s +447ms
└─network-pre.target @2.675s
[motherfucker_big_scorpio@Nexus ~]$ sudo systemd-analyze blame
890ms systemd-binfmt.service
447ms NetworkManager.service
284ms dev-mapper-SystemVolume\x2droot.device
281ms user@1000.service
266ms systemd-cryptsetup@systemdrive.service
266ms systemd-fsck@dev-disk-by\x2duuid-2f00a55b\x2d4388\x2d42be\x2db77f\x2de4bfa6676b00.service
265ms systemd-fsck@dev-disk-by\x2duuid-91EB\x2d4A5D.service
265ms dev-zram0.swap
263ms dev-disk-by\x2duuid-826ae0ac\x2d254c\x2d4146\x2dadec\x2d1972158dbf9e.swap
250ms ldconfig.service
214ms nftables.service
212ms systemd-udev-trigger.service
155ms home.mount
151ms udisks2.service
131ms ufw.service
111ms upower.service
111ms lvm2-monitor.service
108ms systemd-journald.service
73ms systemd-tmpfiles-setup-dev-early.service
70ms systemd-tmpfiles-setup.service
69ms dbus-broker.service
61ms accounts-daemon.service
60ms systemd-fsck@dev-disk-by\x2duuid-D87B\x2dAFAA.service
59ms systemd-journal-flush.service
59ms systemd-logind.service
56ms polkit.service
50ms systemd-udevd.service
47ms systemd-hostnamed.service
44ms plymouth-start.service
43ms proc-sys-fs-binfmt_misc.mount
40ms systemd-journal-catalog-update.service
38ms systemd-sysusers.service
35ms systemd-userdbd.service
30ms systemd-vconsole-setup.service
26ms boot.mount
24ms plymouth-quit-wait.service
24ms rtkit-daemon.service
24ms plymouth-quit.service
24ms systemd-tmpfiles-setup-dev.service
22ms systemd-zram-setup@zram0.service
21ms plymouth-read-write.service
20ms user-runtime-dir@1000.service
19ms systemd-random-seed.service
18ms systemd-update-utmp.service
17ms systemd-modules-load.service
17ms dev-hugepages.mount
16ms systemd-update-done.service
16ms dev-mqueue.mount
16ms sys-kernel-debug.mount
15ms sys-kernel-tracing.mount
15ms boot-efi.mount
15ms kmod-static-nodes.service
15ms systemd-udev-load-credentials.service
13ms modprobe@dm_mod.service
13ms systemd-user-sessions.service
13ms modprobe@configfs.service
13ms systemd-sysctl.service
13ms tmp.mount
13ms modprobe@drm.service
13ms modprobe@fuse.service
12ms modprobe@loop.service
9ms systemd-remount-fs.service
6ms sys-fs-fuse-connections.mount
5ms sys-kernel-config.mount
[motherfucker_big_scorpio@Nexus ~]$
Offline