Long kernel boot time

Got a shiny new nvme ssd(crucial p1 500gb). I installed endeavour os with kde on it. Added luks encryption to the mix. Still the boot times are around 3 mins! Thats higher than what i was getting on my hard-drive installation. Even though i have installed less packages this time.

Some information that might help

[sk@endeavour ~]$ 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 @3.295s
└─sddm.service @3.295s
  └─systemd-user-sessions.service @3.286s +7ms (in red colour)
    └─network.target @3.285s
      └─NetworkManager.service @3.208s +76ms  (in red colour)
        └─dbus.service @3.204s
          └─basic.target @3.197s
            └─sockets.target @3.197s
              └─dbus.socket @3.197s
                └─sysinit.target @3.196s
                  └─systemd-timesyncd.service @3.136s +59ms  (in red colour)
                    └─systemd-tmpfiles-setup.service @3.060s +73ms (in red colour)
                      └─local-fs.target @3.057s
                        └─media-D.mount @2.825s +231ms (in red colour)
                          └─dev-sda1.device @2.823s
[sk@endeavour ~]$ systemd-analyze 
Startup finished in 4.508s (firmware) + 22.602s (loader) + 2min 24.426s (kernel) + 3.333s (userspace) = 2min 54.870s 
graphical.target reached after 3.295s in userspace
[sk@endeavour ~]$ systemd-analyze blame
2.188s lvm2-monitor.service
1.360s systemd-random-seed.service
 968ms dev-mapper-luks\x2d32f5ad67\x2d5539\x2d4083\x2dbb7d\x2d3aa1f08f4539.device
 805ms udisks2.service
 366ms systemd-modules-load.service
 231ms media-D.mount
 182ms systemd-rfkill.service
 164ms systemd-journal-flush.service
 128ms systemd-remount-fs.service
 107ms systemd-udev-trigger.service
 101ms user@1001.service
  93ms upower.service
  87ms power-profiles-daemon.service
  78ms systemd-udevd.service
  76ms NetworkManager.service
  73ms systemd-tmpfiles-setup.service
  70ms systemd-journald.service
  69ms systemd-logind.service
  66ms polkit.service
  63ms systemd-fsck@dev-disk-by\x2duuid-DB19\x2d2EEB.service
  59ms systemd-timesyncd.service
  53ms boot-efi.mount
  41ms avahi-daemon.service
  40ms bluetooth.service
  33ms systemd-tmpfiles-setup-dev.service
  30ms wpa_supplicant.service
  19ms modprobe@fuse.service
  17ms systemd-backlight@backlight:intel_backlight.service
  17ms dev-hugepages.mount
  16ms dev-mqueue.mount
  16ms sys-kernel-debug.mount
  15ms sys-kernel-tracing.mount
  15ms sys-fs-fuse-connections.mount
  15ms alsa-restore.service
  14ms kmod-static-nodes.service
  13ms modprobe@configfs.service
  12ms modprobe@drm.service
  11ms systemd-cryptsetup@luks\x2d32f5ad67\x2d5539\x2d4083\x2dbb7d\x2d3aa1f08f4539.service
  10ms user-runtime-dir@1001.service
   9ms home.mount
   9ms var-cache-pacman-pkg.mount
   9ms swap.mount
   8ms var-cache.mount
   7ms systemd-user-sessions.service
   7ms systemd-update-utmp.service
   7ms var-log.mount
   6ms systemd-sysctl.service
   6ms swap-swapfile.swap
   5ms tmp.mount
   4ms sys-kernel-config.mount
[sk@endeavour ~]$ neofetch
                     ./o.                  sk@endeavour 
                   ./sssso-                ------------ 
                 `:osssssss+-              OS: EndeavourOS Linux x86_64 
               `:+sssssssssso/.            Host: TravelMate P259-G2-MG V1.51 
             `-/ossssssssssssso/.          Kernel: 5.15.7-arch1-1 
           `-/+sssssssssssssssso+:`        Uptime: 3 mins 
         `-:/+sssssssssssssssssso+/.       Packages: 1034 (pacman) 
       `.://osssssssssssssssssssso++-      Shell: bash 5.1.12 
      .://+ssssssssssssssssssssssso++:     Resolution: 1366x768 
    .:///ossssssssssssssssssssssssso++:    DE: Plasma 5.23.4 
  `:////ssssssssssssssssssssssssssso+++.   WM: KWin 
`-////+ssssssssssssssssssssssssssso++++-   Theme: Breeze Light [Plasma], Breeze [GTK2/3] 
 `..-+oosssssssssssssssssssssssso+++++/`   Icons: [Plasma], candy-icons [GTK2/3] 
   ./++++++++++++++++++++++++++++++/:.     Terminal: konsole 
  `:::::::::::::::::::::::::------``       CPU: Intel i5-7200U (4) @ 3.100GHz 
                                           GPU: NVIDIA GeForce 940MX 
                                           GPU: Intel HD Graphics 620 
                                           Memory: 780MiB / 7818MiB 

                                                                   

my disk layout and fstab configuration

[sk@endeavour ~]$ lsblk
NAME                                          MAJ:MIN RM   SIZE RO TYPE  MOUNTPOINTS
sda                                             8:0    0 931.5G  0 disk  
└─sda1                                          8:1    0 931.5G  0 part  /media/D
sr0                                            11:0    1  1024M  0 rom   
nvme0n1                                       259:0    0 465.8G  0 disk  
├─nvme0n1p1                                   259:1    0   512M  0 part  /boot/efi
└─nvme0n1p2                                   259:2    0 465.3G  0 part  
  └─luks-32f5ad67-5539-4083-bb7d-3aa1f08f4539 254:0    0 465.3G  0 crypt /run/timeshift/backup
                                                                         /var/cache/pacman/pkg
                                                                         /home
                                                                         /var/log
                                                                         /var/cache
                                                                         /swap
                                                                         /
[sk@endeavour ~]$ 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>
UUID=DB19-2EEB                                          /boot/efi               vfat    umask=0077                                                                     0 2 
/dev/mapper/luks-32f5ad67-5539-4083-bb7d-3aa1f08f4539   /                       btrfs   subvol=/@,noatime,autodefrag,space_cache=v2,discard=async                      0 0 
/dev/mapper/luks-32f5ad67-5539-4083-bb7d-3aa1f08f4539   /home                   btrfs   subvol=/@home,noatime,autodefrag,space_cache=v2,discard=async                  0 0 
/dev/mapper/luks-32f5ad67-5539-4083-bb7d-3aa1f08f4539   /var/cache              btrfs   subvol=/@cache,noatime,autodefrag,space_cache=v2,discard=async                 0 0 
/dev/mapper/luks-32f5ad67-5539-4083-bb7d-3aa1f08f4539   /var/log                btrfs   subvol=/@log,noatime,autodefrag,space_cache=v2,discard=async                   0 0 
/dev/mapper/luks-32f5ad67-5539-4083-bb7d-3aa1f08f4539   /var/cache/pacman/pkg   btrfs   subvol=/@var-cache-pacman-pkg,noatime,autodefrag,space_cache=v2,discard=async   0 0 
/dev/mapper/luks-32f5ad67-5539-4083-bb7d-3aa1f08f4539   /swap                   btrfs   subvol=/@swap,compress=no                                                      0 0 
/swap/swapfile                                          none                    swap    defaults                                                                       0 0 
UUID=fd67d613-6e33-488f-820c-3b69f2390ffd               /media/D                ext4    defaults                                                                       0 0 

Let me know if i can provide any other info

1 Like

Are there any other differences to the previous installation?

OT

It’s better than one of my systems running Ubuntu…

Startup finished in 38min 41.595s (firmware) + 30.104s (loader) + 3.013s (kernel) + 10min 17.199s (userspace) = 49min 31.912s
graphical.target reached after 10min 17.191s in userspace

:exploding_head:

Nothing much, its the same endeavour os with kde but this time i skipped some packages that i didn’t needed like e-mail app and wallet. The major difference is this time, installation in on ssd as compared to hdd last time.

1 Like

Uefi or bios installation?
latest uefi/bios?
any OC?
checked in uefi/bios that the nvme actually runs in ahci?

You need to check the journal. There should be a huge gap in timestamps somewhere which could indicate for what the kernel is waiting.

EDIT:
Where in the boot process do you see it sitting and waiting? You might want to remove the “quiet” option from kernel cmdline in grub to see the log flying by during boot.

1 Like

UEFI installation

If you mean firmware, then whatever was latest 2 years ago. Haven’t recieved any bios updates from then on.

No overclocks applied.

It says “sata mode : ahci” at the first page. I didn’t see any more mention of nvme, sata or ahci anywhere else

Here are some of the gaps

Dec 16 14:02:10 endeavour kernel: ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
Dec 16 14:02:10 endeavour kernel: ata2.00: failed to IDENTIFY (I/O error, err_mask=0x100)
Dec 16 14:02:10 endeavour kernel: ata2.00: revalidation failed (errno=-5)
Dec 16 14:02:12 endeavour NetworkManager[483]: <info>  [1639643532.8801] manager: startup complete
Dec 16 14:02:16 endeavour kernel: ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
Dec 16 14:02:16 endeavour kernel: ata2.00: configured for UDMA/133

Dec 16 14:02:17 endeavour kernel: ata2.00: configured for UDMA/133
Dec 16 14:02:18 endeavour kernel: ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
Dec 16 14:02:18 endeavour kernel: ata2.00: failed to IDENTIFY (I/O error, err_mask=0x100)
Dec 16 14:02:18 endeavour kernel: ata2.00: revalidation failed (errno=-5)
Dec 16 14:02:23 endeavour kernel: ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
Dec 16 14:02:23 endeavour kernel: ata2.00: configured for UDMA/133

Dec 16 14:02:24 endeavour kernel: ata2.00: configured for UDMA/133
Dec 16 14:02:24 endeavour kernel: ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
Dec 16 14:02:24 endeavour kernel: ata2.00: failed to IDENTIFY (I/O error, err_mask=0x100)
Dec 16 14:02:24 endeavour kernel: ata2.00: revalidation failed (errno=-5)
Dec 16 14:02:30 endeavour kernel: ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
Dec 16 14:02:30 endeavour kernel: ata2.00: configured for UDMA/133
Dec 16 14:02:35 endeavour kernel: ata2.00: qc timeout (cmd 0xef)
Dec 16 14:02:35 endeavour kernel: ata2.00: failed to enable DIPM, Emask 0x5
Dec 16 14:02:35 endeavour kernel: ata2: disabling LPM on the link
Dec 16 14:02:35 endeavour kernel: ata2.00: limiting speed to UDMA/133:PIO2
Dec 16 14:02:35 endeavour kernel: ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
Dec 16 14:02:35 endeavour kernel: ata2.00: configured for UDMA/133

Dec 16 14:02:38 endeavour kernel: ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
Dec 16 14:02:38 endeavour kernel: ata2.00: failed to IDENTIFY (I/O error, err_mask=0x100)
Dec 16 14:02:38 endeavour kernel: ata2.00: revalidation failed (errno=-5)
Dec 16 14:02:43 endeavour kernel: ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
Dec 16 14:02:43 endeavour kernel: ata2.00: configured for UDMA/133

Dec 16 14:02:51 endeavour kernel: ata2.00: configured for UDMA/133
Dec 16 14:02:51 endeavour kernel: ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
Dec 16 14:02:57 endeavour kernel: ata2.00: qc timeout (cmd 0xa1)
Dec 16 14:02:57 endeavour kernel: ata2.00: failed to IDENTIFY (I/O error, err_mask=0x4)
Dec 16 14:02:57 endeavour kernel: ata2.00: revalidation failed (errno=-5)
Dec 16 14:02:57 endeavour kernel: ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
Dec 16 14:02:57 endeavour kernel: ata2.00: failed to IDENTIFY (I/O error, err_mask=0x100)
Dec 16 14:02:57 endeavour kernel: ata2.00: revalidation failed (errno=-5)
Dec 16 14:03:02 endeavour kernel: ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
Dec 16 14:03:02 endeavour kernel: ata2.00: configured for UDMA/133
Dec 16 14:03:04 endeavour systemd-udevd[321]: sr0: Spawned process 'cdrom_id --lock-media /dev/sr0' [555] is taking longer than 27s to complete
Dec 16 14:03:04 endeavour systemd-udevd[310]: sr0: Worker [321] processing SEQNUM=2719 is taking a long time
Dec 16 14:03:07 endeavour kernel: ata2.00: qc timeout (cmd 0xa0)
Dec 16 14:03:07 endeavour kernel: ata2.00: failed to clear UNIT ATTENTION (err_mask=0x5)
Dec 16 14:03:07 endeavour kernel: ata2.00: disabled
Dec 16 14:03:08 endeavour kernel: ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
Dec 16 14:04:12 endeavour sddm-greeter[540]: failed to create compose table
Dec 16 14:04:15 endeavour sddm-greeter[540]: Reading from "/usr/share/xsessions/plasma.desktop"

these are what i found in log, mostly revalidation failed errors are there for ata2 drive. running dmesg for it

[sk@endeavour ~]$ sudo dmesg | grep ata2 | head
[    0.296144] ata2: SATA max UDMA/133 abar m2048@0xb432d000 port 0xb432d180 irq 127
[    0.611603] ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[    0.615307] ata2.00: ATAPI: Slimtype DVD A  DA8AESH, XA11, max UDMA/133
[    0.616546] ata2.00: configured for UDMA/133
[    0.941459] ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[    0.946310] ata2.00: configured for UDMA/133
[    1.271454] ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[    1.276346] ata2.00: configured for UDMA/133
[    1.601466] ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[    1.605017] ata2.00: failed to IDENTIFY (I/O error, err_mask=0x100)

so is it my dvd drive causing delays? i get same errors when booting into live media also.

I mean UEFI. On the Supportsite from your Mainboardvendor you find the available Versions. Install the latest one.

Dec 16 14:02:24 endeavour kernel: ata2.00: failed to IDENTIFY (I/O error, err_mask=0x100)

And this ist a good indication too. I guess your Mainboard tries a very long time to identify your cdrom drive. i would it disconnect and try again.

I have the latest one, i was saying there hasnt been an update since two years.

will try that

Non of the gaps in the journal accounts for 2+ minutes. Do you know by observation when the gap happens? Could it be that the kernel is waiting 2+ minutes right at the beginning before it even starts to log? I suggest you remove the “quiet” option from the kernel commandline and boot again to better observe what is happening.

This time i didn’t see any error and system booted in around 30sec. rebooted again, same result. its been 5th time booting and the results are consistent. maybe it fixed itself?
The output of latest boot

[sk@endeavour ~]$ systemd-analyze 
Startup finished in 4.187s (firmware) + 20.926s (loader) + 7.695s (kernel) + 2.148s (userspace) = 34.958s 
graphical.target reached after 2.111s in userspace