| View previous topic :: View next topic |
| Author |
Message |
btalcox0715
n00b
Joined: 09 Feb 2013
Posts: 40
|
 Posted: Thu Jan 02, 2025 6:35 pm Post subject: systemd-journald slow to start -- kernel to blame? |
 |
|
Hey there,
I've got 2 machines, a desktop and a laptop, both running Gentoo with systemd profile. I've noticed that my desktop starts quite a bit slower than the laptop (25-30 seconds vs 10-15 seconds). As part of my analysis, I discovered that systemd-journald takes a bit to finish starting up:
systemd-analyze
| Code: |
Startup finished in 12.285s (firmware) + 1.636s (loader) + 1.056s (kernel) + 10.695s (userspace) = 25.673s
graphical.target reached after 10.693s in userspace.
|
systemd-analyze blame
| Code: |
9.416s systemd-journald.service
675ms NetworkManager.service
236ms user@1000.service
135ms dev-nvme0n1p2.device
66ms systemd-vconsole-setup.service
62ms systemd-tmpfiles-setup.service
59ms systemd-machine-id-commit.service
52ms systemd-udev-trigger.service
51ms efi.mount
51ms systemd-boot-random-seed.service
44ms systemd-fsck@dev-disk-by\x2duuid-8649\x2dB91C.service
41ms wpa_supplicant.service
41ms systemd-user-sessions.service
40ms udisks2.service
34ms user-runtime-dir@1000.service
32ms systemd-journal-flush.service
30ms systemd-udevd.service
28ms systemd-update-utmp.service
27ms bluetooth.service
22ms dbus.service
21ms polkit.service
18ms systemd-remount-fs.service
16ms systemd-logind.service
16ms systemd-tmpfiles-setup-dev-early.service
14ms systemd-timesyncd.service
14ms systemd-hostnamed.service
13ms alsa-restore.service
13ms dev-hugepages.mount
12ms dev-mqueue.mount
11ms modprobe@configfs.service
11ms sys-kernel-debug.mount
11ms modprobe@dm_mod.service
11ms systemd-fsck-root.service
10ms sys-kernel-tracing.mount
10ms systemd-random-seed.service
10ms modprobe@drm.service
10ms modprobe@fuse.service
10ms tmp.mount
8ms modprobe@loop.service
7ms systemd-udev-load-credentials.service
7ms systemd-rfkill.service
6ms systemd-modules-load.service
6ms systemd-sysctl.service
5ms systemd-tmpfiles-setup-dev.service
3ms sys-fs-fuse-connections.mount
|
systemd-analyze critical-chain
| Code: |
graphical.target @10.693s
└─multi-user.target @10.691s
└─getty.target @10.688s
└─getty@tty1.service @10.685s
└─systemd-user-sessions.service @10.626s +41ms
└─network.target @10.620s
└─wpa_supplicant.service @10.569s +41ms
└─dbus.service @9.864s +22ms
└─basic.target @9.857s
└─sockets.target @9.856s
└─systemd-hostnamed.socket @9.855s
└─sysinit.target @9.845s
└─systemd-update-utmp.service @9.813s +28ms
└─systemd-tmpfiles-setup.service @9.747s +62ms
└─systemd-journal-flush.service @9.713s +32ms
└─systemd-journald.service @276ms +9.416s
└─systemd-journald.socket @265ms
└─-.mount @230ms
└─-.slice @230ms
|
I ended up making an issue on the systemd repo to see if I could get some support/direction there (https://github.com/systemd/systemd/issues/35795). Lennart responded:
| Quote: |
do not misunderstand what "systemd-analyze" displays here: it just says that a specific component took a long time to initialize, but not that it is actally really that components fault. if you look at your logs you see that journald doesn't get scheduled for more than 9s at all, look for this message in your output:
Dec 31 10:53:39 systemd-journald[313]: Missed 1141 kernel messages
the immediately preceeding message is 9s earlier.
So it appears you have some kernel driver problem, and there's a ton load of messages generated even, but because userspace doesn't get scheduled at all journald can't catch it.
hence, this is almost certainly a local drivre/kernel issue, and this just surfaces as a 10s gap in journalds scheduling.
Closing hence. please track down what this blocks on in the kernel.
|
Any thoughts on how I should go about narrowing this down? I've attached some relevant logs and kernel config below. Nothing is really jumping out though, at least to my eyes. As a first start to troubleshooting, I've unplugged all USB devices (except those from USB headers on MB--a fan controller) and booted, just to see if it was a USB device issue, but no change.
dmesg output: https://dpaste.org/7NKEu
journalctl -b output: https://dpaste.org/bm7xO
kernel config: https://dpaste.org/ks6NR
bootchart image: https://imgur.com/a/nXYwqWn
Any help or direction would be appreciated! Thanks in advance |
|
| Back to top |
|
 |
btalcox0715
n00b
Joined: 09 Feb 2013
Posts: 40
|
| Posted: Fri Jan 03, 2025 2:52 pm Post subject: |
|
|
| To try and get some more info, I enabled CONFIG_DEBUG_KERNEL=y, and booted with dyndgb="+p". Interestingly, systemd-journald starts way earlier, and my userspace start time dropped from 10.5 seconds to 2.5 seconds. I get the login prompt _way_ sooner, and most of the USB/bluetooth logging overruns the login prompt (generally its just the network logging I see doing this in previous state). Why would enabling dynamic debugging cause the service initialization to change like this? |
|
| Back to top |
|
|
|
|
You cannot post new topics in this forum
You cannot reply to topics in this forum
You cannot edit your posts in this forum
You cannot delete your posts in this forum
You cannot vote in polls in this forum
|
|
Kernel & Hardware
