[Bug 1183568] New: └─kmod-static-nodes.service @4.168s +10.122s makes init unduly long
http://bugzilla.opensuse.org/show_bug.cgi?id=1183568 Bug ID: 1183568 Summary: ������kmod-static-nodes.service @4.168s +10.122s makes init unduly long Classification: openSUSE Product: openSUSE Distribution Version: Leap 15.3 Hardware: Other OS: Other Status: NEW Severity: Normal Priority: P5 - None Component: Basesystem Assignee: screening-team-bugs@suse.de Reporter: mrmazda@earthlink.net QA Contact: qa-bugs@suse.de Found By: --- Blocker: --- Original summary: ������kmod-static-nodes.service @4.168s +10.122s makes init unduly long Same PC also has another 15.3 and TW and 15.2. TW takes under 4s to reach multi-user. 15.2 takes much less than the two 15.3s, but much more than TW, to same target. kmod-static-nodes seems the biggest delay in the 15.3s. Every installation except one 15.3 is on SATA SSD in UEFI. The odd one is on NVME except for /boot on SATA, and it has its own unshared ESP there. All are being booted from TW's custom.cfg. Following is from the 15.3 on SATA: # inxi -SMdy System: Host: asa88 Kernel: 5.3.18-51-default x86_64 bits: 64 Console: tty 3 Distro: openSUSE Leap 15.3 Beta Machine: Type: Desktop Mobo: ASUSTeK model: A88X-PRO v: Rev X.0x serial: 140323952800121 UEFI: American Megatrends v: 2603 date: 03/10/2016 Drives: Local Storage: total: 715.41 GiB used: 728.23 GiB (101.8%) ID-1: /dev/nvme0n1 vendor: TeamGroup model: TM8FP6256G size: 238.47 GiB ID-2: /dev/sda model: T-FORCE 512GB size: 476.94 GiB Message: No Optical or Floppy data was found. # systemd-analyze blame | head -n22 10.566s systemd-udev-trigger.service 10.385s systemd-modules-load.service 10.383s systemd-remount-fs.service 10.379s systemd-journald.service 10.190s dev-disk-by\x2dlabel-tvgp02swap.swap 10.161s modprobe@drm.service 10.144s dev-hugepages.mount 10.144s dev-mqueue.mount 10.143s sys-kernel-debug.mount 10.142s sys-kernel-tracing.mount 10.131s modprobe@fuse.service 10.125s modprobe@configfs.service 10.122s kmod-static-nodes.service 3.967s initrd-switch-root.service 2.183s systemd-random-seed.service 2.076s kbdsettings.service 1.699s wicked.service 1.188s dracut-initqueue.service 584ms systemd-logind.service 509ms systemd-udevd.service 301ms initrd-parse-etc.service 269ms user@0.service # 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. ������multi-user.target @16.889s ������sshd.service @16.827s +60ms ������network.target @16.826s ������wicked.service @15.124s +1.699s ������wickedd-nanny.service @15.059s +63ms ������wickedd.service @14.982s +75ms ������wickedd-auto4.service @14.853s +127ms ������dbus.service @14.791s ������basic.target @14.787s ������sockets.target @14.787s ������dbus.socket @14.786s ������sysinit.target @14.781s ������systemd-udevd.service @14.271s +509ms ������systemd-tmpfiles-setup-dev.service @14.225s +29ms ������kmod-static-nodes.service @3.821s +10.122s ������systemd-journald.socket ������system.slice ������-.slice -- You are receiving this mail because: You are on the CC list for the bug.
http://bugzilla.opensuse.org/show_bug.cgi?id=1183568 http://bugzilla.opensuse.org/show_bug.cgi?id=1183568#c1 --- Comment #1 from Felix Miata <mrmazda@earthlink.net> --- Created attachment 847256 --> http://bugzilla.opensuse.org/attachment.cgi?id=847256&action=edit systemctl list-units --no-legend --type device # 66 lines output -- You are receiving this mail because: You are on the CC list for the bug.
http://bugzilla.opensuse.org/show_bug.cgi?id=1183568 http://bugzilla.opensuse.org/show_bug.cgi?id=1183568#c6 Felix Miata <mrmazda@earthlink.net> changed: What |Removed |Added ---------------------------------------------------------------------------- Flags|needinfo?(mrmazda@earthlink | |.net) | --- Comment #6 from Felix Miata <mrmazda@earthlink.net> --- On the asa88 host's SSD 15.3 (I removed its NVME last week sometime), sda blame reported 10.005s for kmod-static-nodes.service on boot prior to fresh zypper dup, 10.075s on next boot. # time /usr/bin/kmod static-nodes --format=tmpfiles --output=/run/tmpfiles.d/kmod.conf real 0m0.005s user 0m0.005s sys 0m0.001s Without using time, shell prompt returned just as fast as simply hitting <ENTER> without typing anything, so no perceptible delay. # cat /run/tmpfiles.d/kmod.conf c! /dev/fuse 0600 - - - 10:229 c! /dev/cuse 0600 - - - 10:203 c! /dev/btrfs-control 0600 - - - 10:234 c! /dev/loop-control 0600 - - - 10:237 d /dev/net 0755 - - - c! /dev/net/tun 0600 - - - 10:200 c! /dev/ppp 0600 - - - 108:0 c! /dev/uinput 0600 - - - 10:223 d /dev/mapper 0755 - - - c! /dev/mapper/control 0600 - - - 10:236 c! /dev/uhid 0600 - - - 10:239 d /dev/vfio 0755 - - - c! /dev/vfio/vfio 0600 - - - 10:196 c! /dev/vhci 0600 - - - 10:137 c! /dev/vhost-net 0600 - - - 10:238 c! /dev/vhost-vsock 0600 - - - 10:241 d /dev/snd 0755 - - - c! /dev/snd/timer 0600 - - - 116:33 d /dev/snd 0755 - - - c! /dev/snd/seq 0600 - - - 116:1 c! /dev/rfkill 0600 - - - 10:242 -- You are receiving this mail because: You are on the CC list for the bug.
http://bugzilla.opensuse.org/show_bug.cgi?id=1183568 http://bugzilla.opensuse.org/show_bug.cgi?id=1183568#c7 --- Comment #7 from Michal Suchanek <msuchanek@suse.com> --- then it's not kmod-static service what causes the delay. (In reply to Felix Miata from comment #0)
# systemd-analyze blame | head -n22 10.566s systemd-udev-trigger.service 10.385s systemd-modules-load.service 10.383s systemd-remount-fs.service 10.379s systemd-journald.service 10.190s dev-disk-by\x2dlabel-tvgp02swap.swap 10.161s modprobe@drm.service 10.144s dev-hugepages.mount 10.144s dev-mqueue.mount 10.143s sys-kernel-debug.mount 10.142s sys-kernel-tracing.mount 10.131s modprobe@fuse.service 10.125s modprobe@configfs.service 10.122s kmod-static-nodes.service
You can see here that there are many services that take about 10s, and most of them are module related. I would suspect one of the drivers slows down the boot. Can you attach full dmesg? Does systemd-remount-fs.service or dev-disk-by\x2dlabel-tvgp02swap.swap or systemd-journald.service depend on kmod-static-nodes.service? If not even if kmod-static-nodes.service is instanteous these other services will still require time to complete. -- You are receiving this mail because: You are on the CC list for the bug.
http://bugzilla.opensuse.org/show_bug.cgi?id=1183568 http://bugzilla.opensuse.org/show_bug.cgi?id=1183568#c8 --- Comment #8 from Felix Miata <mrmazda@earthlink.net> --- Created attachment 848079 --> http://bugzilla.opensuse.org/attachment.cgi?id=848079&action=edit dmesg from 15.3 on SATA SSD on host asa88 (In reply to Michal Suchanek from comment #7)
Can you attach full dmesg?
Done.
Does systemd-remount-fs.service or dev-disk-by\x2dlabel-tvgp02swap.swap or systemd-journald.service depend on kmod-static-nodes.service? If not even if kmod-static-nodes.service is instanteous these other services will still require time to complete.
I have no idea. How can I tell? Neither swap nor remount show up in critical-chain. Is this it?: # systemd-analyze blame | head -n5 10.605s systemd-udev-trigger.service 10.556s systemd-modules-load.service 10.556s systemd-remount-fs.service 10.551s systemd-journald.service 10.106s dev-disk-by\x2dlabel-tvgp02swap.swap -- You are receiving this mail because: You are on the CC list for the bug.
http://bugzilla.opensuse.org/show_bug.cgi?id=1183568 http://bugzilla.opensuse.org/show_bug.cgi?id=1183568#c9 --- Comment #9 from Franck Bui <fbui@suse.com> --- (In reply to Michal Suchanek from comment #7)
Does systemd-remount-fs.service or dev-disk-by\x2dlabel-tvgp02swap.swap or systemd-journald.service depend on kmod-static-nodes.service? If not even if kmod-static-nodes.service is instanteous these other services will still require time to complete.
kmod-static-nodes.service is not instantaneous during the boot process as `systemd-analyze {blame,critical-chain}` showed. As you pointed there's something happening in the kernel that basically stopped all module related services during 10 sec preventing most of the rest of the services to start (because sysinit.target depends on those module related services). -- You are receiving this mail because: You are on the CC list for the bug.
http://bugzilla.opensuse.org/show_bug.cgi?id=1183568 http://bugzilla.opensuse.org/show_bug.cgi?id=1183568#c10 Franck Bui <fbui@suse.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Flags| |needinfo?(mrmazda@earthlink | |.net) --- Comment #10 from Franck Bui <fbui@suse.com> --- (In reply to Felix Miata from comment #8)
Created attachment 848079 [details] dmesg from 15.3 on SATA SSD on host asa88
The dmesg output is hard to read because it does contain only a small part of the systemd logs. Can you please instead attach the output of `journalctl -b -o short-monotonic` ? -- You are receiving this mail because: You are on the CC list for the bug.
http://bugzilla.opensuse.org/show_bug.cgi?id=1183568 http://bugzilla.opensuse.org/show_bug.cgi?id=1183568#c11 --- Comment #11 from Michal Suchanek <msuchanek@suse.com> --- Created attachment 848108 --> http://bugzilla.opensuse.org/attachment.cgi?id=848108&action=edit kmod debug script Attaching tar archive with kmod debug script. This will definitely slow down boot because it will make every kmod invocation take at least one second but it will report if any invocation takes over one second. To use this 1) download 00aaakmodhack.tar 2) backup initrd cp -a /boot/initrd-$(uname -r) /boot/initrd-$(uname -r).backup 3) unpack the module tar -xvf 00aaakmodhack.tar -C /usr/lib/dracut/modules.d/ 4) regenerate ramdisk dracut -f to remove rm -r /usr/lib/dracut/modules.d/00aaakmodhack mv /boot/initrd-$(uname -r).backup /boot/initrd-$(uname -r) If a kmod process is stuck in the kernel for more than 1s the stack trace should be shown in dmesg. The other thing you can do is add the initcall_debug option to the kernel commandline. It should tell you if the kernel is initializing a driver during that time gap. -- You are receiving this mail because: You are on the CC list for the bug.
http://bugzilla.opensuse.org/show_bug.cgi?id=1183568 http://bugzilla.opensuse.org/show_bug.cgi?id=1183568#c12 Felix Miata <mrmazda@earthlink.net> changed: What |Removed |Added ---------------------------------------------------------------------------- Flags|needinfo?(mrmazda@earthlink | |.net) | --- Comment #12 from Felix Miata <mrmazda@earthlink.net> --- Created attachment 848145 --> http://bugzilla.opensuse.org/attachment.cgi?id=848145&action=edit journalctl -b -o short-monotonic from 15.3 on SATA SSD on host asa88 -- You are receiving this mail because: You are on the CC list for the bug.
http://bugzilla.opensuse.org/show_bug.cgi?id=1183568 http://bugzilla.opensuse.org/show_bug.cgi?id=1183568#c13 --- Comment #13 from Felix Miata <mrmazda@earthlink.net> --- Created attachment 848146 --> http://bugzilla.opensuse.org/attachment.cgi?id=848146&action=edit dmesg from 15.3 on SATA SSD on host asa88 and comment #11 hack & initcall_debug employed Michal, in the process of appending initcall_debug I found cmdline also included debug and rd.debug, which I removed for the current test with the hack initrd. This resulted in no excess delay, multi-user reached in ~3.6s. Restoring previous initrd and booting without any *debug* options maintain the ~3.6s boot times. The attachment is from booting with no *debug* options except initcall_debug. I suspect highly this bug is invalid because of the debug and rd.debug boot options, which I have now removed from the grub stanzas. Last boot time was <3.5s. -- You are receiving this mail because: You are on the CC list for the bug.
http://bugzilla.opensuse.org/show_bug.cgi?id=1183568 http://bugzilla.opensuse.org/show_bug.cgi?id=1183568#c14 Michal Suchanek <msuchanek@suse.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Attachment #848108|0 |1 is obsolete| | CC| |dracut-maintainers@suse.de Flags| |needinfo?(dracut-maintainer | |s@suse.de) --- Comment #14 from Michal Suchanek <msuchanek@suse.com> --- Created attachment 848148 --> http://bugzilla.opensuse.org/attachment.cgi?id=848148&action=edit kmod debug script The messages from the debug script are not in the kernel buffer because there was a typo in the script. Anyway, you don't need the script because the problem is in the dracut debug options and not the kernel module loading. I think the 10s overhead is a bit too much for dracut debug options but I will leave that for dracut maintainers to investigate. -- You are receiving this mail because: You are on the CC list for the bug.
http://bugzilla.opensuse.org/show_bug.cgi?id=1183568 Michal Suchanek <msuchanek@suse.com> changed: What |Removed |Added ---------------------------------------------------------------------------- Assignee|systemd-maintainers@suse.de |dracut-maintainers@suse.de -- You are receiving this mail because: You are on the CC list for the bug.
http://bugzilla.opensuse.org/show_bug.cgi?id=1183568 http://bugzilla.opensuse.org/show_bug.cgi?id=1183568#c15 Felix Miata <mrmazda@earthlink.net> changed: What |Removed |Added ---------------------------------------------------------------------------- Summary|������kmod-static-nodes.service |undue delay when debug and |@4.168s +10.122s makes init |rd.debug on kernel cmdline |unduly long | --- Comment #15 from Felix Miata <mrmazda@earthlink.net> --- (In reply to Michal Suchanek from comment #14)
Anyway, you don't need the script because the problem is in the dracut debug options
Update to summary accordingly: undue delay when debug and rd.debug on kernel cmdline -- You are receiving this mail because: You are on the CC list for the bug.
http://bugzilla.opensuse.org/show_bug.cgi?id=1183568 http://bugzilla.opensuse.org/show_bug.cgi?id=1183568#c16 --- Comment #16 from Franck Bui <fbui@suse.com> --- It's not clear to me why rd.debug would impact the timings of various systemd services reported by systemd-analyze though... -- You are receiving this mail because: You are on the CC list for the bug.
http://bugzilla.opensuse.org/show_bug.cgi?id=1183568 http://bugzilla.opensuse.org/show_bug.cgi?id=1183568#c17 --- Comment #17 from Felix Miata <mrmazda@earthlink.net> --- Still happening with 15.3 release imminent. :( -- You are receiving this mail because: You are on the CC list for the bug.
http://bugzilla.opensuse.org/show_bug.cgi?id=1183568 http://bugzilla.opensuse.org/show_bug.cgi?id=1183568#c19 --- Comment #19 from Felix Miata <mrmazda@earthlink.net> --- (In reply to Thomas Blume from comment #18)
Could you attach the boot log with rd.debug from 15.3?
No such file /var/log/boot.log. What log is it you want? Host asa88, with rd.debug on kernel cmdline, booted tonight to multi-user in 3.966s. Using debug instead of rd.debug took 17.504s. I saved journalctl -b -o short-monotonic from each to files. -- You are receiving this mail because: You are on the CC list for the bug.
http://bugzilla.opensuse.org/show_bug.cgi?id=1183568 http://bugzilla.opensuse.org/show_bug.cgi?id=1183568#c21 --- Comment #21 from Felix Miata <mrmazda@earthlink.net> --- Created attachment 849430 --> http://bugzilla.opensuse.org/attachment.cgi?id=849430&action=edit journalctl -b -o short-monotonic booted to host asa88 with debug but not rd.debug on kernel cmdline I still don't know what "the boot log" requested means, so again I'm not clearing the needinfo request. IIRC, all attachments and runtime details provided in this report are from the one host asa88. I can try with up to 10 other already installed 15.3 hosts if necessary. -- You are receiving this mail because: You are on the CC list for the bug.
http://bugzilla.opensuse.org/show_bug.cgi?id=1183568 http://bugzilla.opensuse.org/show_bug.cgi?id=1183568#c24 Felix Miata <mrmazda@earthlink.net> changed: What |Removed |Added ---------------------------------------------------------------------------- Flags|needinfo?(mrmazda@earthlink | |.net) | --- Comment #24 from Felix Miata <mrmazda@earthlink.net> --- Created attachment 849441 --> http://bugzilla.opensuse.org/attachment.cgi?id=849441&action=edit journalctl -b -o short-monotonic booted to host asa88 with systemd.log_level=debug 78599 bytes, 2.9%, shorter than attachment 849430 -- You are receiving this mail because: You are on the CC list for the bug.
http://bugzilla.opensuse.org/show_bug.cgi?id=1183568 http://bugzilla.opensuse.org/show_bug.cgi?id=1183568#c27 Felix Miata <mrmazda@earthlink.net> changed: What |Removed |Added ---------------------------------------------------------------------------- Status|NEW |RESOLVED Resolution|--- |WORKSFORME Flags|needinfo?(mrmazda@earthlink | |.net) | --- Comment #27 from Felix Miata <mrmazda@earthlink.net> --- The motherboard of the comment #0 PC refuses to POST. I have no other PCs with both SATA and NVME SSDs to boot from to test with. I tried a different PC using comment #0's CPU and cannot reproduce with 15.3, 15.4 or TW. Reproduction failed on two other PCs with TW, 15.3, 15.4 & 15.5, with systemd-analyze blame | grep kmod-static-nodes producing results in the 32ns-480ns range. -- You are receiving this mail because: You are on the CC list for the bug.
participants (1)
-
bugzilla_noreply＠suse.com