Diagnosing absurdly long boot time on Pop!_OS 21.10

Question

Recently switched my computer from Win10 to Pop OS. Noticed that it takes significantly longer to reach the login screen: before it felt pretty much instant and now it takes >1 minute. It's booting off a fast NVME M.2 and with a Ryzen 7-5800h, so I know it's not hardware limited.

Did some digging in the terminal and this is what I found:

jianzen@dragon-7:~$ systemd-analyze
Startup finished in 5.520s (firmware) + 388ms (loader) + 4.798s (kernel) + 1min 37.591s (userspace) = 1min 48.299s 
graphical.target reached after 1min 37.544s in userspace

jianzen@dragon-7:~$ systemd-analyze blame
6.388s NetworkManager-wait-online.service
5.102s plymouth-quit-wait.service
 562ms docker.service
 305ms accounts-daemon.service
 274ms man-db.service
...

jianzen@dragon-7:~$ 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 37.544s
└─multi-user.target @1min 37.544s
  └─docker.service @1min 36.981s +562ms
    └─network-online.target @1min 36.950s
      └─NetworkManager-wait-online.service @1min 30.560s +6.388s
        └─NetworkManager.service @1min 30.483s +64ms
          └─dbus.service @1min 30.481s
            └─basic.target @1min 30.477s
              └─sockets.target @1min 30.477s
                └─cups.socket @1min 30.589s
                  └─sysinit.target @1min 30.443s
                    └─systemd-backlight@backlight:acpi_video0.service @1.820s +3ms
                      └─system-systemd\x2dbacklight.slice @1.819s
                        └─system.slice @130ms
                          └─-.slice @130ms

Nothing in blame points towards a culprint, and in critical-chain it bottlenecks at sysinit.target, so I really don't know where to go next in working out what's causing such a slow boot.

EDIT: Additional information to clarify filesystem.

jianzen@dragon-7:~$ lsblk
NAME        MAJ:MIN RM   SIZE RO TYPE MOUNTPOINT
nvme1n1     259:0    0 931.5G  0 disk 
├─nvme1n1p1 259:1    0 431.5G  0 part /mnt/SLibrary
└─nvme1n1p2 259:2    0   500G  0 part /mnt/Drive 2
nvme0n1     259:3    0 476.9G  0 disk 
├─nvme0n1p1 259:4    0     3G  0 part /boot/efi
├─nvme0n1p2 259:5    0    30G  0 part /home
├─nvme0n1p3 259:6    0    30G  0 part [SWAP]
└─nvme0n1p4 259:7    0 413.9G  0 part /

jianzen@dragon-7:~$ cat /etc/fstab
# /etc/fstab: static file system information.
#
# Use 'blkid' to print the universally unique identifier for a
# device; this may be used with UUID= as a more robust way to name devices
# that works even if disks are added and removed. See fstab(5).
#
# <file system>  <mount point>  <type>  <options>  <dump>  <pass>
PARTUUID=1e9f9308-e092-4249-b178-4c1e61d9bd37  /boot/efi  vfat  umask=0077  0  0
UUID=375f4eac-da6d-4d87-a17a-aed548fe7961  /home  ext4  noatime,errors=remount-ro  0  0
/dev/mapper/cryptswap  none  swap  defaults  0  0
UUID=7f37168f-738f-475e-b593-237ccf58d0a5  /  ext4  noatime,errors=remount-ro  0  0
/dev/disk/by-uuid/FCC2A5FFC2A5BE70 /mnt/Drive\0402 auto nosuid,nodev,nofail,x-gvfs-show,x-gvfs-name=Drive%202 0 0
/dev/disk/by-uuid/6bee998f-b10b-4d1e-951a-a86b6d1b8b59 /mnt/SLibrary auto nosuid,nodev,nofail,x-gvfs-show,x-gvfs-name=SLibrary 0 0

EDIT Pt. 2 Running dmesg puts out the following errors (along with everything else):

[    0.240256] ACPI BIOS Error (bug): Could not resolve symbol [\_SB.PCI0.PB2], AE_NOT_FOUND (20210930/dswload2-162)
[    0.240269] ACPI Error: AE_NOT_FOUND, During name lookup/catalog (20210930/psobject-220)
[    0.839449] integrity: Problem loading X.509 certificate -65

[    4.826083] ================================================================================
[    4.826138] UBSAN: invalid-load in /build/linux-RFp8Q8/linux-5.16.19/drivers/net/wireless/mediatek/mt76/dma.c:162:13
[    4.826199] load of value 103 is not a valid value for type '_Bool'

[   98.377451] [drm:nv_drm_master_set [nvidia_drm]] *ERROR* [nvidia-drm] [GPU ID 0x00000100] Failed to grab modeset ownership

[  114.634906] ================================================================================
[  114.634914] UBSAN: invalid-load in /build/linux-RFp8Q8/linux-5.16.19/net/mac80211/status.c:1164:21
[  114.634921] load of value 255 is not a valid value for type '_Bool'
[  120.040061] [drm:nv_drm_master_set [nvidia_drm]] *ERROR* [nvidia-drm] [GPU ID 0x00000100] Failed to grab modeset ownership

[  355.714107] TCP: wlp4s0: Driver has suspect GRO implementation, TCP performance may be compromised.

Edited: The `sysinit.target` (in my test machine) has requirements regarding the local filesystem (`Wants=local-fs.target swap.target || After=local-fs.target swap.target emergency.service emergency.target`). Do you have anything "fancy" in `/etc/fstab` which could cause a delayed mount of the partitions/LVs? — eblock, Apr 19 '22 at 10:58
Currently, I have my main nvme partitioned, each mounted at `/boot/eft`, `/home` and `/` respectively. My second nvme is also partitioned, one mounting at `/mnt/Drive\0402` and the other at `/mnt/SLibrary` (my steam library partition). — JianZen, Apr 19 '22 at 11:03
Please add that information to your initial question (edit). Something like `lsblk` and `cat /etc/fstab` would help. — eblock, Apr 19 '22 at 11:36
That looks ok, I don't see an issue with the mountpoints, so it's probably not related to the local-fs dependency. Just out of curiosity, have you tried a different OS and experiences the same? In that case it could something Pop OS related. — eblock, Apr 20 '22 at 07:01
This definitely wasn't happening with Win10. I'm yet to try another linux distro, but was thinking about just switching to Ubuntu. This isn't the only not-insignificant basic issue I've had since switching to pop. — JianZen, Apr 20 '22 at 14:49
what does the `dmesg` show? Do you have any errors? My guess is that it does have to do something with video alias graphics card. Your *1min 37.591s (userspace)* is way too long. — tukan, Apr 22 '22 at 09:41
Yeah a couple of things come up GPU wise. I've added it to the question @tukan — JianZen, Apr 23 '22 at 14:15

tukan · Accepted Answer · 2022-04-29T09:03:46.257

Oh my, you have quite some list.

I'll look at it:

[ 0.240256] ACPI BIOS Error (bug): Could not resolve symbol [_SB.PCI0.PB2], AE_NOT_FOUND (20210930/dswload2-162) [ 0.240269] ACPI Error: AE_NOT_FOUND, During name lookup/catalog (20210930/psobject-220)

This is nothing serious, only that your kernel does not support some BIOS feature. You can live with it or turn acpi off with acpi=off at boot. Not a big deal.

[ 0.839449] integrity: Problem loading X.509 certificate -65

This should be addressed. It looks like you are booting via UEFI, please check on implications. (You have to have signed boot process and modules - see signing kernel modules)

[ 4.826138] UBSAN: invalid-load in /build/linux-RFp8Q8/linux-5.16.19/drivers/net/wireless/mediatek/mt76/dma.c:162:13 [ 4.826199] load of value 103 is not a valid value for type '_Bool' 114.634914] UBSAN: invalid-load in /build/linux-RFp8Q8/linux-5.16.19/net/mac80211/status.c:1164:21 [ 114.634921] load of value 255 is not a valid value for type '_Bool'

You have issue with your wireless driver there is probably some bug as you see having value 103 or 255 is not _Bool. Probably something is not identified correctly. You can check the sources.

[ 98.377451] [drm:nv_drm_master_set [nvidia_drm]] ERROR [nvidia-drm] [GPU ID 0x00000100] Failed to grab modeset ownership

Ah nvidia issues with proprietary drivers. Well you have to search for the bug, this must be fixed by Nvidia themselves as you can't check the source here. Try to search for it. Probably some bug in the nvidia-drm module.

[ 355.714107] TCP: wlp4s0: Driver has suspect GRO implementation, TCP performance may be compromised.

This is trying to setup GRO (Generic Receive Offload) and it does not like the values. You could check if your kernel has the RH fix that went into kernel. For more information see Driver has suspect GRO implementation...

Edit: To post my boot speed on Debian bookworm (Intel notebook with Intel(R) Core(TM) i5-8350U CPU):

systemd-analyze
Startup finished in 18.763s (firmware) + 7.674s (loader) + 13.889s (kernel) + 6.821s (userspace) = 47.148s 
graphical.target reached after 6.795s in userspace

If I would have to guess on what is eating your boot time it would be that the Nvidia drivers. You could try Nouveau drivers just to see if the boot improves.

@JianZen you are welcome. Edited the wording around the BIOS so it will have correct meaning. — tukan, Apr 26 '22 at 16:12

Diagnosing absurdly long boot time on Pop!_OS 21.10

1 Answers1