Since a few weeks (I can't pin down when the problem started occurring exactly) booting my system takes forever, at least compared to the before-state. The logs while booting show
2024-07-15T00:38:56.074118+02:00 kubuntu-leptop kernel: Bluetooth: hci0: Bad flag given (0x1) vs supported (0x0)
before the big delay happens (1m and 3s).
Here's what I believe to be the relevant portion of my kernel.log (the two lines concerning ucsi_acpi which here are technically the last before the delay are just due to a troublesome USB device, when removed the behavior doesn't change) as well as all the other logs:
2024-07-15T00:38:55.752966+02:00 kubuntu-leptop kernel: snd_hda_intel 0000:00:1f.3: bound 0000:00:02.0 (ops i915_audio_component_bind_ops [i915])
2024-07-15T00:38:55.762049+02:00 kubuntu-leptop kernel: fbcon: i915drmfb (fb0) is primary device
2024-07-15T00:38:55.762094+02:00 kubuntu-leptop kernel: fbcon: Deferring console take-over
2024-07-15T00:38:55.762096+02:00 kubuntu-leptop kernel: i915 0000:00:02.0: [drm] fb0: i915drmfb frame buffer device
2024-07-15T00:38:55.785997+02:00 kubuntu-leptop kernel: snd_hda_codec_realtek hdaudioC0D0: autoconfig for ALC289: line_outs=2 (0x14/0x17/0x0/0x0/0x0) type:speaker
2024-07-15T00:38:55.786003+02:00 kubuntu-leptop kernel: snd_hda_codec_realtek hdaudioC0D0: speaker_outs=0 (0x0/0x0/0x0/0x0/0x0)
2024-07-15T00:38:55.786004+02:00 kubuntu-leptop kernel: snd_hda_codec_realtek hdaudioC0D0: hp_outs=1 (0x21/0x0/0x0/0x0/0x0)
2024-07-15T00:38:55.786004+02:00 kubuntu-leptop kernel: snd_hda_codec_realtek hdaudioC0D0: mono: mono_out=0x0
2024-07-15T00:38:55.786004+02:00 kubuntu-leptop kernel: snd_hda_codec_realtek hdaudioC0D0: inputs:
2024-07-15T00:38:55.786005+02:00 kubuntu-leptop kernel: snd_hda_codec_realtek hdaudioC0D0: Headset Mic=0x19
2024-07-15T00:38:55.786005+02:00 kubuntu-leptop kernel: snd_hda_codec_realtek hdaudioC0D0: Headphone Mic=0x1b
2024-07-15T00:38:55.786006+02:00 kubuntu-leptop kernel: snd_hda_codec_realtek hdaudioC0D0: Internal Mic=0x12
2024-07-15T00:38:55.925974+02:00 kubuntu-leptop kernel: Bluetooth: hci0: Waiting for firmware download to complete
2024-07-15T00:38:55.925982+02:00 kubuntu-leptop kernel: Bluetooth: hci0: Firmware loaded in 1605085 usecs
2024-07-15T00:38:55.925983+02:00 kubuntu-leptop kernel: Bluetooth: hci0: Waiting for device to boot
2024-07-15T00:38:55.941968+02:00 kubuntu-leptop kernel: Bluetooth: hci0: Device booted in 15587 usecs
2024-07-15T00:38:55.941970+02:00 kubuntu-leptop kernel: Bluetooth: hci0: Malformed MSFT vendor event: 0x02
2024-07-15T00:38:55.950978+02:00 kubuntu-leptop kernel: Bluetooth: hci0: Found Intel DDC parameters: intel/ibt-0040-0041.ddc
2024-07-15T00:38:55.951969+02:00 kubuntu-leptop kernel: Bluetooth: hci0: Applying Intel DDC parameters completed
2024-07-15T00:38:55.954982+02:00 kubuntu-leptop kernel: Bluetooth: hci0: Firmware timestamp 2023.48 buildtype 1 build 75324
2024-07-15T00:38:55.954983+02:00 kubuntu-leptop kernel: Bluetooth: hci0: Firmware SHA1: 0x23bac558
2024-07-15T00:38:56.031037+02:00 kubuntu-leptop kernel: Bluetooth: MGMT ver 1.22
2024-07-15T00:38:56.034994+02:00 kubuntu-leptop kernel: NET: Registered PF_ALG protocol family
2024-07-15T00:38:56.074118+02:00 kubuntu-leptop kernel: Bluetooth: hci0: Bad flag given (0x1) vs supported (0x0)
2024-07-15T00:38:56.487075+02:00 kubuntu-leptop kernel: input: HDA Intel PCH Headphone Mic as /devices/pci0000:00/0000:00:1f.3/sound/card0/input36
2024-07-15T00:38:56.487080+02:00 kubuntu-leptop kernel: input: HDA Intel PCH HDMI/DP,pcm=3 as /devices/pci0000:00/0000:00:1f.3/sound/card0/input37
2024-07-15T00:38:56.487081+02:00 kubuntu-leptop kernel: input: HDA Intel PCH HDMI/DP,pcm=7 as /devices/pci0000:00/0000:00:1f.3/sound/card0/input38
2024-07-15T00:38:56.487082+02:00 kubuntu-leptop kernel: input: HDA Intel PCH HDMI/DP,pcm=8 as /devices/pci0000:00/0000:00:1f.3/sound/card0/input39
2024-07-15T00:38:56.487082+02:00 kubuntu-leptop kernel: input: HDA Intel PCH HDMI/DP,pcm=9 as /devices/pci0000:00/0000:00:1f.3/sound/card0/input40
2024-07-15T00:38:57.479009+02:00 kubuntu-leptop kernel: ucsi_acpi USBC000:00: unknown error 0
2024-07-15T00:38:57.479013+02:00 kubuntu-leptop kernel: ucsi_acpi USBC000:00: UCSI_GET_PDOS failed (-5)
2024-07-15T00:39:00.170470+02:00 kubuntu-leptop kernel: fbcon: Taking over console
2024-07-15T00:39:00.193162+02:00 kubuntu-leptop kernel: Console: switching to colour frame buffer device 240x75
2024-07-15T00:39:55.240044+02:00 kubuntu-leptop kernel: iwlwifi 0000:00:14.3: WRT: Invalid buffer destination
2024-07-15T00:39:55.279986+02:00 kubuntu-leptop kernel: kauditd_printk_skb: 158 callbacks suppressed
2024-07-15T00:39:55.279996+02:00 kubuntu-leptop kernel: audit: type=1400 audit(1720996795.278:169): apparmor="DENIED" operation="capable" class="cap" profile="/usr/sbin/cupsd" pid=1615 comm="cupsd" capability=12 capname="net_admin"
2024-07-15T00:39:55.393989+02:00 kubuntu-leptop kernel: iwlwifi 0000:00:14.3: WFPM_UMAC_PD_NOTIFICATION: 0x20
2024-07-15T00:39:55.394001+02:00 kubuntu-leptop kernel: iwlwifi 0000:00:14.3: WFPM_LMAC2_PD_NOTIFICATION: 0x1f
2024-07-15T00:39:55.394002+02:00 kubuntu-leptop kernel: iwlwifi 0000:00:14.3: WFPM_AUTH_KEY_0: 0x90
2024-07-15T00:39:55.394003+02:00 kubuntu-leptop kernel: iwlwifi 0000:00:14.3: CNVI_SCU_SEQ_DATA_DW9: 0x0
2024-07-15T00:39:55.394976+02:00 kubuntu-leptop kernel: iwlwifi 0000:00:14.3: RFIm is deactivated, reason = 4
2024-07-15T00:39:55.486984+02:00 kubuntu-leptop kernel: iwlwifi 0000:00:14.3: Registered PHC clock: iwlwifi-PTP, with index: 0
2024-07-15T00:39:55.807982+02:00 kubuntu-leptop kernel: Bluetooth: RFCOMM TTY layer initialized
2024-07-15T00:39:55.807993+02:00 kubuntu-leptop kernel: Bluetooth: RFCOMM socket layer initialized
2024-07-15T00:39:55.807994+02:00 kubuntu-leptop kernel: Bluetooth: RFCOMM ver 1.11
2024-07-15T00:39:58.922061+02:00 kubuntu-leptop kernel: wlp0s20f3: 80 MHz not supported, disabling VHT
2024-07-15T00:39:58.930111+02:00 kubuntu-leptop kernel: wlp0s20f3: authenticate with c8:0e:14:f4:c2:52 (local address=70:a8:d3:96:3a:bb)
2024-07-15T00:39:58.931017+02:00 kubuntu-leptop kernel: wlp0s20f3: send auth to c8:0e:14:f4:c2:52 (try 1/3)
2024-07-15T00:39:58.964022+02:00 kubuntu-leptop kernel: wlp0s20f3: authenticated
2024-07-15T00:39:58.964025+02:00 kubuntu-leptop kernel: wlp0s20f3: associate with c8:0e:14:f4:c2:52 (try 1/3)
2024-07-15T00:39:58.974303+02:00 kubuntu-leptop kernel: wlp0s20f3: RX AssocResp from c8:0e:14:f4:c2:52 (capab=0x1431 status=0 aid=9)
2024-07-15T00:39:58.985139+02:00 kubuntu-leptop kernel: wlp0s20f3: associated
2024-07-15T00:39:59.035976+02:00 kubuntu-leptop kernel: wlp0s20f3: Limiting TX power to 20 (20 - 0) dBm as advertised by c8:0e:14:f4:c2:52
2024-07-15T00:39:59.889976+02:00 kubuntu-leptop kernel: rfkill: input handler disabled
2024-07-15T00:40:00.396978+02:00 kubuntu-leptop kernel: usb 3-9: reset full-speed USB device number 4 using xhci_hcd
2024-07-15T00:40:06.846980+02:00 kubuntu-leptop kernel: usb 3-9: reset full-speed USB device number 4 using xhci_hcd
2024-07-15T00:40:15.388974+02:00 kubuntu-leptop kernel: rfkill: input handler enabled
Note the delay between 2024-07-15T00:38:57.479013+02:00 and 2024-07-15T00:39:00.170470+02:00.
➜ ~ systemd-analyze
Startup finished in 1min 25.222s (firmware) + 6.087s (loader) + 2.351s (kernel) + 1min 8.903s (userspace) = 2min 42.565s
graphical.target reached after 1min 8.887s in userspace.
➜ ~ systemd-analyze blame
1min 48.208s fstrim.service
1min 634ms thermald.service
1min 633ms gpu-manager.service
1min 623ms snapd.seeded.service
1min 575ms NetworkManager.service
1min 379ms upower.service
55.419s plocate-updatedb.service
5.824s plymouth-quit-wait.service
3.958s NetworkManager-wait-online.service
2.406s fwupd.service
2.091s systemd-suspend.service
1.334s nvidia-persistenced.service
1.242s nvidia-suspend.service
472ms systemd-tmpfiles-setup.service
456ms snapd.apparmor.service
442ms systemd-binfmt.service
433ms proc-sys-fs-binfmt_misc.mount
376ms dev-nvme1n1p2.device
352ms boot-efi.mount
340ms snapd.service
265ms dev-loop30.device
233ms accounts-daemon.service
225ms dev-loop29.device
224ms dev-loop28.device
199ms dev-loop6.device
196ms dev-loop5.device
195ms dev-loop0.device
193ms udisks2.service
190ms dev-loop7.device
190ms dev-loop3.device
189ms dev-loop2.device
182ms apport.service
177ms dev-loop4.device
172ms systemd-backlight@leds:dell::kbd_backlight.service
159ms e2scrub_reap.service
151ms dev-loop27.device
148ms dev-loop9.device
148ms dev-loop26.device
142ms user@1000.service
141ms fwupd-refresh.service
136ms networkd-dispatcher.service
126ms systemd-journal-flush.service
113ms gnome-remote-desktop.service
110ms update-notifier-download.service
108ms systemd-udev-trigger.service
106ms rsyslog.service
93ms iio-sensor-proxy.service
92ms dpkg-db-backup.service
89ms systemd-resolved.service
88ms power-profiles-daemon.service
87ms gdm.service
86ms polkit.service
85ms avahi-daemon.service
84ms bluetooth.service
79ms dev-loop1.device
77ms dbus.service
71ms dev-loop20.device
71ms dev-loop25.device
68ms dev-loop21.device
67ms dev-loop22.device
67ms usbguard.service
66ms smartmontools.service
66ms dev-loop24.device
66ms dev-loop18.device
65ms dev-loop23.device
65ms ModemManager.service
65ms dev-loop19.device
65ms switcheroo-control.service
65ms dev-loop16.device
64ms dev-loop17.device
63ms dev-loop15.device
63ms dev-loop14.device
62ms dev-loop13.device
62ms usbguard-dbus.service
61ms dev-loop11.device
60ms dev-loop10.device
60ms systemd-timesyncd.service
59ms dev-loop12.device
59ms dev-loop8.device
56ms apparmor.service
54ms systemd-logind.service
52ms systemd-random-seed.service
48ms systemd-udevd.service
46ms secureboot-db.service
45ms plymouth-start.service
44ms snap-bare-5.mount
44ms snap-blender-4786.mount
42ms snap-core18-2823.mount
42ms logrotate.service
38ms snap-core18-2829.mount
37ms snap-core20-2318.mount
37ms snap-core22-1122.mount
35ms snap-core22-1380.mount
34ms snap-dbgate-438.mount
34ms systemd-remount-fs.service
34ms snap-firefox-4451.mount
33ms systemd-fsck@dev-disk-by\x2duuid-3259\x2d845A.service
33ms systemd-journald.service
32ms systemd-tmpfiles-clean.service
32ms snap-firefox-4483.mount
31ms keyboard-setup.service
31ms snap-fusion360-33.mount
30ms bolt.service
30ms snap-gnome\x2d3\x2d28\x2d1804-198.mount
30ms systemd-modules-load.service
29ms snap-gnome\x2d3\x2d38\x2d2004-143.mount
29ms cups.service
28ms snap-gnome\x2d42\x2d2204-141.mount
27ms snap-gnome\x2d42\x2d2204-176.mount
26ms snap-gtk\x2dcommon\x2dthemes-1535.mount
25ms snap-kf5\x2d5\x2d111\x2dqt\x2d5\x2d15\x2d11\x2dcore22-7.mount
24ms snap-kf5\x2d5\x2d113\x2dqt\x2d5\x2d15\x2d11\x2dcore22-1.mount
23ms snap-postman-254.mount
22ms snap-r\x2dquick\x2dshare-x1.mount
21ms grub-initrd-fallback.service
21ms wpa_supplicant.service
21ms snap-snapd-21465.mount
20ms colord.service
20ms snap-snapd-21759.mount
19ms snap-thunderbird-482.mount
19ms snap-thunderbird-490.mount
18ms snap-tio-1157.mount
17ms snap-tio-1172.mount
16ms snap-wine\x2dplatform\x2d9\x2ddevel\x2dcore22-20.mount
16ms snapd.socket
15ms grub-common.service
15ms snap-wine\x2dplatform\x2d9\x2ddevel\x2dcore22-21.mount
14ms snap-wine\x2dplatform\x2druntime\x2dcore22-74.mount
14ms plymouth-read-write.service
14ms snap-wine\x2dplatform\x2druntime\x2dcore22-75.mount
13ms systemd-tmpfiles-setup-dev-early.service
13ms snap-xournalpp-94.mount
13ms kerneloops.service
12ms systemd-backlight@backlight:intel_backlight.service
12ms var-snap-firefox-common-host\x2dhunspell.mount
12ms rtkit-daemon.service
11ms dev-hugepages.mount
10ms dev-mqueue.mount
10ms systemd-rfkill.service
10ms sys-kernel-debug.mount
9ms sys-kernel-tracing.mount
9ms systemd-sysctl.service
9ms modprobe@efi_pstore.service
9ms modprobe@loop.service
8ms alsa-restore.service
8ms systemd-update-utmp.service
8ms kmod-static-nodes.service
8ms modprobe@configfs.service
8ms nvidia-resume.service
7ms modprobe@drm.service
7ms systemd-user-sessions.service
7ms modprobe@fuse.service
7ms modprobe@dm_mod.service
6ms systemd-tmpfiles-setup-dev.service
5ms console-setup.service
4ms systemd-update-utmp-runlevel.service
4ms user-runtime-dir@1000.service
4ms ufw.service
3ms swapfile.swap
3ms sys-kernel-config.mount
2ms sys-fs-fuse-connections.mount
1ms setvtrgb.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.
graphical.target @1min 8.887s
└─multi-user.target @1min 8.886s
└─plymouth-quit-wait.service @1min 3.062s +5.824s
└─systemd-user-sessions.service @1min 3.046s +7ms
└─network.target @1min 3.034s
└─NetworkManager.service @2.455s +1min 575ms
└─dbus.service @2.374s +77ms
└─basic.target @2.349s
└─sockets.target @2.349s
└─cups.socket @2.519s
└─sysinit.target @2.331s
└─systemd-backlight@backlight:intel_backlight.service @1min 3.127s +12ms
└─system-systemd\x2dbacklight.slice @2.157s
└─system.slice @189ms
└─-.slice @189ms
