sverlong
(Stephen Verlong)
December 7, 2023, 3:29pm
1
This is my first Fedora install so apologies if I’m missing some information. I have noticed that it takes around 2 minutes for my system to get to a login prompt. Here is my current system config via neofetch:
Kernel: 6.6.4-200.fc39.x86_64
Uptime: 6 mins
Packages: 2489 (rpm)
Shell: bash 5.2.21
Resolution: 3840x2160
DE: Plasma 5.27.9
WM: kwin
Theme: [Plasma], Breeze [GTK2/3]
Icons: [Plasma], breeze [GTK2/3]
Terminal: konsole
CPU: AMD Ryzen 9 7900 (24) @ 5.482GHz
GPU: AMD ATI 15:00.0 Raphael
GPU: AMD ATI Radeon RX 7900 XT/7900 XTX
Memory: 4822MiB / 31289MiB
I’ve also done some digging and ran the systemd-analyze command as well:
Startup finished in 43.552s (firmware) + 1.608s (loader) + 2.806s (kernel) + 1min 3.660s (initrd) + 13.121s (userspace) = 2min 4.749s
graphical.target reached after 13.092s in userspace.
And systemd-analyze critical-chain:
graphical.target @13.092s
└─sddm.service @13.092s
└─plymouth-quit.service @13.022s +57ms
└─systemd-user-sessions.service @12.982s +23ms
└─remote-fs.target @12.965s
└─remote-fs-pre.target @2.179s
└─nfs-client.target @2.178s
└─gssproxy.service @2.166s +11ms
└─network.target @2.162s
└─wpa_supplicant.service @3.074s +9ms
└─basic.target @1.793s
└─dbus-broker.service @1.773s +18ms
└─dbus.socket @1.758s
└─sysinit.target @1.755s
└─systemd-resolved.service @1.681s +73ms
└─systemd-tmpfiles-setup.service @1.573s +93ms
└─local-fs.target @1.571s
└─boot-efi.mount @1.560s +10ms
└─boot.mount @1.548s +10ms
└─systemd-fsck@dev-disk-by\x2duuid-5d001845\x2db8c2\x2d424a\x2db046\x2dda83f7db7f94.service @1.030s +32ms
└─dev-disk-by\x2duuid-5d001845\x2db8c2\x2d424a\x2db046\x2dda83f7db7f94.device @584542y 2w 2d 20h 46.453s +1min 4.085s
It looks like the dev-disk-by is holding up the boot. I’ve looked into that UUID and it looks like it is referencing the boot partition. See the output of fstab:
UUID=b7ae8750-9ac9-4b6f-b464-6a94647f902e / btrfs subvol=root,compress=zstd:1 0 0
UUID=5d001845-b8c2-424a-b046-da83f7db7f94 /boot ext4 defaults 1 2
UUID=82A5-EE24 /boot/efi vfat umask=0077,shortname=winnt 0 2
UUID=b7ae8750-9ac9-4b6f-b464-6a94647f902e /home btrfs subvol=home,compress=zstd:1 0 0
I’m also running another NVMe drive with a Windows 11 install, but these two drives are completely separate physical drives and don’t think should cause an issue. I was hoping someone could point me in the right direction on what might be the fix for this slow boot.
chrisawi
(Chris Williams)
December 7, 2023, 7:53pm
2
Half a million years is definitely too long…
I don’t know what’s going wrong with critical-chain, but please share the boot chart from:
systemd-analyze plot > bootchart.svg
sverlong
(Stephen Verlong)
December 7, 2023, 8:01pm
3
Luckily it isn’t half a million years!
I can’t attach the SVG directly it seems. Here is a link to the SVG: https://www.file.io/VjDA/download/XLbe5RAvo8ma
chrisawi
(Chris Williams)
December 7, 2023, 8:10pm
4
It looks like you may be hitting two separate 30s timeouts in the initramfs (dracut). journalctl -b
should give some idea what’s happening at T+33 and T+66 (just before the pivot_root).
I wonder if this is related to whatever is causing the firmware to take so long.
sverlong
(Stephen Verlong)
December 7, 2023, 8:26pm
5
Not sure exactly what I’m looking for here. Here is the output from a little before and after dracut is invoked:
Dec 07 04:46:28 fedora systemd[1]: Finished systemd-vconsole-setup.service - Virtual Console Setup.
Dec 07 04:46:28 fedora kernel: r8152 6-2.4:1.0: load rtl8153b-2 v2 04/27/23 successfully
Dec 07 04:46:28 fedora systemd[1]: Reached target remote-fs-pre.target - Preparation for Remote File Systems.
Dec 07 04:46:28 fedora systemd[1]: Reached target remote-fs.target - Remote File Systems.
Dec 07 04:46:28 fedora systemd[1]: Reached target sysinit.target - System Initialization.
Dec 07 04:46:28 fedora systemd[1]: dracut-pre-mount.service - dracut pre-mount hook was skipped because no trigger condition checks were met.
Dec 07 04:46:28 fedora kernel: r8152 6-2.4:1.0 eth0: v1.12.13
Dec 07 04:46:28 fedora kernel: usbcore: registered new interface driver r8152
Dec 07 04:46:28 fedora kernel: r8152 6-2.4:1.0 enp21s0f3u2u4: renamed from eth0
Dec 07 04:46:28 fedora kernel: ccp 0000:15:00.2: enabling device (0000 -> 0002)
Dec 07 04:46:28 fedora systemd[1]: Starting plymouth-start.service - Show Plymouth Boot Screen...
Dec 07 04:46:28 fedora systemd[1]: Starting systemd-fsck-root.service - File System Check on /dev/disk/by-uuid/b7ae8750-9ac9-4b6f-b464-6a94647f902e...
Dec 07 04:46:28 fedora systemd[1]: Received SIGRTMIN+20 from PID 705 (plymouthd).
Dec 07 04:46:28 fedora kernel: ccp 0000:15:00.2: tee enabled
Dec 07 04:46:28 fedora kernel: ccp 0000:15:00.2: psp enabled
Dec 07 04:46:28 fedora systemd[1]: Finished systemd-fsck-root.service - File System Check on /dev/disk/by-uuid/b7ae8750-9ac9-4b6f-b464-6a94647f902e.
Dec 07 04:46:28 fedora systemd[1]: Started plymouth-start.service - Show Plymouth Boot Screen.
Dec 07 04:46:28 fedora systemd[1]: systemd-ask-password-console.path - Dispatch Password Requests to Console Directory Watch was skipped because of an unmet condition check (ConditionPathExists=!/run/plymouth/pid).
Dec 07 04:46:28 fedora systemd[1]: Started systemd-ask-password-plymouth.path - Forward Password Requests to Plymouth Directory Watch.
Dec 07 04:46:28 fedora systemd[1]: Reached target paths.target - Path Units.
Dec 07 04:46:28 fedora systemd[1]: Reached target basic.target - Basic System.
Dec 07 04:46:28 fedora systemd[1]: Mounting sysroot.mount - /sysroot...
Dec 07 04:46:28 fedora kernel: BTRFS info (device nvme2n1p3): using crc32c (crc32c-intel) checksum algorithm
Dec 07 04:46:28 fedora kernel: BTRFS info (device nvme2n1p3): using free space tree
Dec 07 04:46:28 fedora kernel: BTRFS info (device nvme2n1p3): enabling ssd optimizations
Dec 07 04:46:28 fedora kernel: BTRFS info (device nvme2n1p3): auto enabling async discard
Dec 07 04:46:28 fedora systemd[1]: Mounted sysroot.mount - /sysroot.
Dec 07 04:46:28 fedora systemd[1]: Reached target initrd-root-fs.target - Initrd Root File System.
Dec 07 04:46:28 fedora systemd[1]: Starting initrd-parse-etc.service - Mountpoints Configured in the Real Root...
Dec 07 04:46:28 fedora systemd[1]: initrd-parse-etc.service: Deactivated successfully.
Dec 07 04:46:28 fedora systemd[1]: Finished initrd-parse-etc.service - Mountpoints Configured in the Real Root.
Dec 07 04:46:28 fedora systemd[1]: Reached target initrd-fs.target - Initrd File Systems.
Dec 07 04:46:28 fedora systemd[1]: Reached target initrd.target - Initrd Default Target.
Dec 07 04:46:28 fedora systemd[1]: dracut-mount.service - dracut mount hook was skipped because no trigger condition checks were met.
Dec 07 04:46:28 fedora systemd[1]: Starting dracut-pre-pivot.service - dracut pre-pivot and cleanup hook...
Dec 07 04:46:28 fedora kernel: usb 3-7: config 1 has an invalid interface number: 2 but max is 1
Dec 07 04:46:28 fedora kernel: usb 3-7: config 1 has no interface number 1
Dec 07 04:46:28 fedora kernel: usb 3-7: New USB device found, idVendor=0b05, idProduct=19af, bcdDevice= 1.00
Dec 07 04:46:28 fedora kernel: usb 3-7: New USB device strings: Mfr=1, Product=2, SerialNumber=3
Dec 07 04:46:28 fedora kernel: usb 3-7: Product: AURA LED Controller
Dec 07 04:46:28 fedora kernel: usb 3-7: Manufacturer: AsusTek Computer Inc.
Dec 07 04:46:28 fedora kernel: usb 3-7: SerialNumber: 9876543210
Dec 07 04:46:28 fedora kernel: hid-generic 0003:0B05:19AF.0008: hiddev99,hidraw5: USB HID v1.11 Device [AsusTek Computer Inc. AURA LED Controller] on usb-0000:12:00.0-7/input2
Dec 07 04:46:29 fedora kernel: [drm] amdgpu kernel modesetting enabled.
Dec 07 04:46:29 fedora kernel: amdgpu: vga_switcheroo: detected switching method \_SB_.PCI0.GP17.VGA_.ATPX handle
Dec 07 04:46:29 fedora kernel: amdgpu: ATPX version 1, functions 0x00000000
Dec 07 04:46:29 fedora kernel: amdgpu: Virtual CRAT table created for CPU
Dec 07 04:46:29 fedora kernel: amdgpu: Topology: Add CPU node
Dec 07 04:46:29 fedora kernel: amdgpu 0000:03:00.0: enabling device (0006 -> 0007)
Dec 07 04:46:29 fedora kernel: [drm] initializing kernel modesetting (IP DISCOVERY 0x1002:0x744C 0x1849:0x5308 0xCC).
Dec 07 04:46:29 fedora kernel: [drm] register mmio base: 0xFCA00000
Dec 07 04:46:29 fedora kernel: [drm] register mmio size: 1048576
Dec 07 04:46:29 fedora kernel: [drm] add ip block number 0 <soc21_common>
I did notice some USB errors as well a little bit later on:
Dec 07 04:47:10 fedora kernel: usb 1-9: device descriptor read/64, error -110
Dec 07 04:47:10 fedora kernel: usb usb1-port9: attempt power cycle
Dec 07 04:47:11 fedora kernel: usb 1-9: new high-speed USB device number 7 using xhci_hcd
Dec 07 04:47:15 fedora kernel: usb 1-9: Device not responding to setup address.
Dec 07 04:47:20 fedora kernel: usb 1-9: Device not responding to setup address.
Dec 07 04:47:21 fedora kernel: usb 1-9: device not accepting address 7, error -71
Dec 07 04:47:21 fedora kernel: usb 1-9: new high-speed USB device number 8 using xhci_hcd
Dec 07 04:47:26 fedora kernel: usb 1-9: Device not responding to setup address.
Dec 07 04:47:28 fedora systemd-udevd[567]: usb1: Worker [584] processing SEQNUM=2408 is taking a long time
Dec 07 04:47:31 fedora kernel: usb 1-9: Device not responding to setup address.
Dec 07 04:47:31 fedora kernel: usb 1-9: device not accepting address 8, error -71
Dec 07 04:47:31 fedora kernel: usb usb1-port9: unable to enumerate USB device
Dec 07 04:47:31 fedora systemd[1]: systemd-udevd.service: Deactivated successfully.
Dec 07 04:47:31 fedora systemd[1]: Stopped systemd-udevd.service - Rule-based Manager for Device Events and Files.
Dec 07 04:47:31 fedora systemd[1]: systemd-udevd.service: Consumed 2.562s CPU time.
Dec 07 04:47:31 fedora systemd[1]: systemd-udevd-control.socket: Deactivated successfully.
Dec 07 04:47:31 fedora systemd[1]: Closed systemd-udevd-control.socket - udev Control Socket.
Dec 07 04:47:31 fedora systemd[1]: systemd-udevd-kernel.socket: Deactivated successfully.
Dec 07 04:47:31 fedora systemd[1]: Closed systemd-udevd-kernel.socket - udev Kernel Socket.
Dec 07 04:47:31 fedora systemd[1]: dracut-pre-udev.service: Deactivated successfully.
Dec 07 04:47:31 fedora systemd[1]: Stopped dracut-pre-udev.service - dracut pre-udev hook.
Dec 07 04:47:31 fedora systemd[1]: dracut-cmdline.service: Deactivated successfully.
Dec 07 04:47:31 fedora systemd[1]: Stopped dracut-cmdline.service - dracut cmdline hook.
Dec 07 04:47:31 fedora systemd[1]: dracut-cmdline-ask.service: Deactivated successfully.
Dec 07 04:47:31 fedora systemd[1]: Stopped dracut-cmdline-ask.service - dracut ask for additional cmdline parameters.
Dec 07 04:47:31 fedora systemd[1]: Starting initrd-udevadm-cleanup-db.service - Cleanup udev Database...
Dec 07 04:47:31 fedora systemd[1]: systemd-tmpfiles-setup-dev.service: Deactivated successfully.
Dec 07 04:47:31 fedora systemd[1]: Stopped systemd-tmpfiles-setup-dev.service - Create Static Device Nodes in /dev.
Dec 07 04:47:31 fedora systemd[1]: systemd-sysusers.service: Deactivated successfully.
Dec 07 04:47:31 fedora systemd[1]: Stopped systemd-sysusers.service - Create System Users.
Dec 07 04:47:31 fedora systemd[1]: initrd-udevadm-cleanup-db.service: Deactivated successfully.
Dec 07 04:47:31 fedora systemd[1]: Finished initrd-udevadm-cleanup-db.service - Cleanup udev Database.
Dec 07 04:47:31 fedora systemd[1]: Reached target initrd-switch-root.target - Switch Root.
Dec 07 04:47:31 fedora systemd[1]: Starting initrd-switch-root.service - Switch Root...
Dec 07 04:47:31 fedora systemd[1]: Switching root.
Dec 07 04:47:31 fedora systemd-journald[436]: Journal stopped
Dec 07 09:47:32 fedora systemd-journald[436]: Received SIGTERM from PID 1 (systemd).
Dec 07 09:47:32 fedora kernel: audit: type=1404 audit(1701942451.512:2): enforcing=1 old_enforcing=0 auid=4294967295 ses=4294967295 enabled=1 old-enabled=1 lsm=selinux res=1
Dec 07 09:47:32 fedora kernel: SELinux: policy capability network_peer_controls=1
Here is a link to the entire journalctl -b
output: https://file.io/yiVUPzDwriAi
chrisawi
(Chris Williams)
December 7, 2023, 8:40pm
6
Sorry, I should have specified that you’re looking for time gaps between timestamps:
Dec 07 04:46:30 fedora kernel: [drm] DSC precompute is not needed.
Dec 07 04:46:33 fedora kernel: usb 1-9: device descriptor read/64, error -110
Dec 07 04:46:49 fedora kernel: usb 1-9: device descriptor read/64, error -110
Dec 07 04:46:49 fedora kernel: usb 1-9: new high-speed USB device number 6 using xhci_hcd
Dec 07 04:46:54 fedora kernel: usb 1-9: device descriptor read/64, error -110
Dec 07 04:46:58 fedora dracut-pre-pivot[739]: Timed out for waiting the udev queue being empty.
Dec 07 04:46:58 fedora systemd[1]: Finished initrd-cleanup.service - Cleaning Up and Shutting Down Daemons.
Dec 07 04:47:10 fedora kernel: usb 1-9: device descriptor read/64, error -110
Dec 07 04:47:10 fedora kernel: usb usb1-port9: attempt power cycle
Dec 07 04:47:11 fedora kernel: usb 1-9: new high-speed USB device number 7 using xhci_hcd
Dec 07 04:47:15 fedora kernel: usb 1-9: Device not responding to setup address.
Dec 07 04:47:20 fedora kernel: usb 1-9: Device not responding to setup address.
Dec 07 04:47:21 fedora kernel: usb 1-9: device not accepting address 7, error -71
Dec 07 04:47:21 fedora kernel: usb 1-9: new high-speed USB device number 8 using xhci_hcd
Dec 07 04:47:26 fedora kernel: usb 1-9: Device not responding to setup address.
Dec 07 04:47:28 fedora systemd-udevd[567]: usb1: Worker [584] processing SEQNUM=2408 is taking a long time
Dec 07 04:47:31 fedora kernel: usb 1-9: Device not responding to setup address.
Dec 07 04:47:31 fedora kernel: usb 1-9: device not accepting address 8, error -71
Dec 07 04:47:31 fedora kernel: usb usb1-port9: unable to enumerate USB device
This USB device is definitely the problem.
arturasb
(Arturas B.)
December 7, 2023, 8:45pm
7
Once I had similar problem, but not with the booting process - GNOME and app became incredibility slow for no apparent reason. And few moments later I decided to unplug USB dongle I plugged in couple of minutes before. Suddenly performance was back.
Some crappy USB implementations (devices and hubs) might cause such effects, it is worth to unplug all USB stuff and check the boot then.
sverlong
(Stephen Verlong)
December 8, 2023, 12:24am
8
OK so I was able to get my boot time down to around 25 seconds! I can’t believe this worked, but I found this article: How to fix "device not accepting address" error | Paul Philippov
I literally powered of my PC and left it set for 5 minutes unplugged from the outlet. Apparently one of my USB ports triggered over-current protection by drawing too much power. Now I just need to figure out why that happened. Otherwise things are great now. I appreciate everyone’s help!
Once again, as previously noted, simply unplug the usb devices and look at the power demand. It seems quite possible that one may be something such as an HDD plugged into a USB2 port – a recipe for exactly what you indicate above.