Optimizing kernel startup times

[caranthir]

Hello, I am trying to trim a few more seconds off my boot time where possible.

Code: Select all

~ $ systemd-analyze
Startup finished in 15.034s (kernel) + 3.760s (userspace) = 18.795s
graphical.target reached after 3.751s in userspace

It used to take closer to 10 seconds total, but a Windows 10 update ruined my bootloader and I had to reinstall grub. I was never able to get the same speed ever since.

Here is some more information on my system (and a strange bug there as well):

Code: Select all

~ $ inxi -Fxz
System:    Host: lich-MS-7850 Kernel: 5.4.0-87-generic x86_64 bits: 64 compiler: gcc v: 7.5.0 
           Desktop: Cinnamon 4.4.8 Distro: Linux Mint 19.3 Tricia base: Ubuntu 18.04 bionic 
Machine:   Type: Desktop Mobo: MSI model: Z97 PC Mate(MS-7850) v: 1.0 serial: <filter> 
           UEFI [Legacy]: American Megatrends v: 4.10 date: 08/11/2015 
CPU:       Topology: Quad Core model: Intel Core i7-4790K bits: 64 type: MT MCP arch: Haswell rev: 3 
           L2 cache: 8192 KiB 
           flags: lm nx pae sse sse2 sse3 sse4_1 sse4_2 ssse3 vmx bogomips: 63998 
           Speed: 1600 MHz min/max: 800/4400 MHz Core speeds (MHz): 1: 1600 2: 1600 3: 1600 4: 1600 5: 1603 6: 1600 
           7: 1600 8: 1600 
Graphics:  Device-1: Advanced Micro Devices [AMD/ATI] Hawaii PRO [Radeon R9 290/390] vendor: Tul driver: amdgpu 
           v: kernel bus ID: 01:00.0 
           Display: x11 server: X.Org 1.20.8 driver: amdgpu resolution: 1920x1080~60Hz, 1920x1080~60Hz 
           OpenGL: renderer: AMD Radeon R9 390 Series (HAWAII DRM 3.35.0 5.4.0-87-generic LLVM 10.0.1) 
           v: 4.6 Mesa 20.2.0-devel (git-0ca7bd7 2020-07-08 bionic-oibaf-ppa) direct render: Yes 
Audio:     Device-1: Intel 9 Series Family HD Audio vendor: Micro-Star MSI driver: snd_hda_intel v: kernel 
           bus ID: 00:1b.0 
           Device-2: Advanced Micro Devices [AMD/ATI] Hawaii HDMI Audio [Radeon R9 290/290X / 390/390X] vendor: Tul 
           driver: snd_hda_intel v: kernel bus ID: 01:00.1 
           Device-3: SteelSeries ApS type: USB driver: hid-generic,snd-usb-audio,usbhid bus ID: 3-9.3:6 
           Sound Server: ALSA v: k5.4.0-87-generic 
Network:   Device-1: Intel Wireless 7260 driver: iwlwifi v: kernel port: e000 bus ID: 02:00.0 
           IF: wlp2s0 state: down mac: <filter> 
           Device-2: Realtek RTL8111/8168/8411 PCI Express Gigabit Ethernet vendor: Micro-Star MSI driver: r8169 
           v: kernel port: d000 bus ID: 03:00.0 
           IF: enp3s0 state: up speed: 100 Mbps duplex: full mac: <filter> 
           IF-ID-1: docker0 state: down mac: <filter> 
Drives:    Local Storage: total: 1.58 TiB used: 426.90 GiB (26.3%) 
           ID-1: /dev/sda vendor: Samsung model: SSD 860 EVO 500GB size: 465.76 GiB 
           ID-2: /dev/sdb vendor: OCZ model: ARC100 size: 223.57 GiB 
           ID-3: /dev/sdc vendor: Crucial model: CT1000MX500SSD1 size: 931.51 GiB temp: 31 C 
Partition: ID-1: / size: 456.95 GiB used: 426.90 GiB (93.4%) fs: ext4 dev: /dev/sda5 
Sensors:   System Temperatures: cpu: 39.0 C mobo: N/A 
Use of uninitialized value $val2 in string eq at /usr/bin/inxi line 5759.
Use of uninitialized value $val2 in split at /usr/bin/inxi line 5764.
Use of uninitialized value $val2 in concatenation (.) or string at /usr/bin/inxi line 5766.
Use of uninitialized value $val2 in concatenation (.) or string at /usr/bin/inxi line 5767.
Use of uninitialized value $val2 in concatenation (.) or string at /usr/bin/inxi line 5768.
           Fan Speeds (RPM): N/A gpu: fan: 688 
Info:      Processes: 322 Uptime: 4h 29m Memory: 15.59 GiB used: 4.46 GiB (28.6%) Init: systemd runlevel: 5 
           Compilers: gcc: 7.5.0 Shell: bash v: 4.4.20 inxi: 3.0.32 

I also looked at /var/log/kern.log and found the following 8 second gap. Could this be related?

Code: Select all

Nov 28 10:28:30 lich-MS-7850 kernel: [    0.209741] NET: Registered protocol family 1
Nov 28 10:28:30 lich-MS-7850 kernel: [    0.209746] NET: Registered protocol family 44
Nov 28 10:28:30 lich-MS-7850 kernel: [    8.667070] pci 0000:00:14.0: quirk_usb_early_handoff+0x0/0x6b0 took 8259096 usecs
Nov 28 10:28:30 lich-MS-7850 kernel: [    8.667297] pci 0000:01:00.0: Video device with shadowed ROM at [mem 0x000c0000-0x000dffff]
Nov 28 10:28:30 lich-MS-7850 kernel: [    8.667303] pci 0000:01:00.1: D0 power state depends on 0000:01:00.0
Nov 28 10:28:30 lich-MS-7850 kernel: [    8.667313] pci 0000:04:00.0: Disabling ASPM L0s/L1
Nov 28 10:28:30 lich-MS-7850 kernel: [    8.667314] pci 0000:04:00.0: can't disable ASPM; OS doesn't have ASPM control

Thanks in advance, and please let me know if I need to provide any other info.

[t42]

look up in lspci output for 00:14.0

[caranthir]

Code: Select all

~ $ lspci | grep 00:14.0
00:14.0 USB controller: Intel Corporation 9 Series Chipset Family USB xHCI Controller

[senjoz]

Partition: ID-1: / size: 456.95 GiB used: 426.90 GiB (93.4%) fs: ext4 dev: /dev/sda5

That is not good. You should clean your root partition.

Regards, Jože

[t42]

Partition: ID-1: / size: 456.95 GiB used: 426.90 GiB (93.4%) fs: ext4 dev: /dev/sda5

That is not good. You should clean your root partition.

How this could be connected with the startup issue - 30 GB of free space on the root partition??

[t42]

a Windows 10 update ruined my bootloader and I had to reinstall grub. I was never able to get the same speed ever since.

It can't be unless you had some specific kernel option in /etc/default/grub in lines
GRUB_CMDLINE_LINUX_DEFAULT=""
GRUB_CMDLINE_LINUX=""

Do you have some devices connected to USB3 ports during boot time - if so, test boot time disconnecting them.
You may find (or not) a BIOS setting to switch off the USB3 controller to test boot time as well.

[senjoz]

Partition: ID-1: / size: 456.95 GiB used: 426.90 GiB (93.4%) fs: ext4 dev: /dev/sda5

That is not good. You should clean your root partition.

How this could be connected with the startup issue - 30 GB of free space on the root partition??

Maybe that is not directly related to the startup time. 5 % of ext4 partition is reserved for the root user. Soon the problem will not be slow boot but impossible boot.

Regards, Jože

[t42]

5 % of ext4 partition is reserved for the root user. Soon the problem will not be slow boot but impossible boot.

Not exactly.Root has 139GB reserved, it is enough to solve all system problems, boot including. It is a user will get no space soon for their needs.
The OP may consider to decrease reserved space to 1 (or 2) per cent, setting root with 28GB of reserved space.

Code: Select all

sudo tune2fs -m 1 /dev/sdX

[senjoz]

Not exactly.Root has 139GB reserved, it is enough to solve all system problems, boot including. It is a user will get no space soon for their needs.

5 % of 457 GiB is 23 GiB. How did you get 139 GB?

I am correcting my statement: Soon the main problem will not be slow boot but difficulties for non-privileged users to log in.

I remember quite a few posts in the forum regarding login difficulties because of not enough space in the root partition.

Regards, Jože

[t42]

How did you get 139 GB?

It's obviously wrong, sorry. Thanks for spotting a mistake.

[Aztaroth]

Hi,
senjoz made a valuable point by suggesting an almost full disk could be the problem. Even during the boot, temp files and journal logs are written on the disk and take some space.

Another direction to look at is systemd-analyze with a bit more 'fun' than basics :

Code: Select all

systemd-analyze blame

to see the time each process takes

Code: Select all

systemd-analyze critical-chain

informs about time a process needs to be active (after the @ symbol) and the time it has to sit and wait because other processes must be completed first (after the + symbol).

Just coming in mind, Timeshift snaps are also invasive with default settings (hourly, daily, monthly) on system disk.

[t42]

...an almost full disk could be the problem. Even during the boot, temp files and journal logs are written on the disk and take some space.

can you explain how it may be a problem while having 30 GB of free space on root partition (and + 23 GB reserved as senjoz pointed out) ?
The OP indicated the problem specifically, and obviously knows systemd-analyze options, maybe let's wait for more information asked for from him...

[caranthir]

Thank you all!

a Windows 10 update ruined my bootloader and I had to reinstall grub. I was never able to get the same speed ever since.

It can't be unless you had some specific kernel option in /etc/default/grub in lines
GRUB_CMDLINE_LINUX_DEFAULT=""
GRUB_CMDLINE_LINUX="ipv6.disable=1"

Do you have some devices connected to USB3 ports during boot time - if so, test boot time disconnecting them.
You may find (or not) a BIOS setting to switch off the USB3 controller to test boot time as well.

This is all I have in my /etc/default/grub:

Code: Select all

GRUB_DEFAULT=0
GRUB_TIMEOUT_STYLE=menu
GRUB_TIMEOUT=3
GRUB_DISTRIBUTOR=`lsb_release -i -s 2> /dev/null || echo Debian`
GRUB_CMDLINE_LINUX_DEFAULT="quiet splash"
GRUB_CMDLINE_LINUX=""

I had one device connected to a USB3 port. I've moved it to a USB2 port but no significant improvement.

Here is the output of systemd-analyze blame:

Code: Select all

1.641s mysql.service
          1.588s php7.4-fpm.service
          1.232s docker.service
          1.147s containerd.service
           701ms lm-sensors.service
           570ms tor@default.service
           503ms lightdm.service
           459ms udisks2.service
           427ms apache2.service
           369ms dev-sda5.device
           364ms networkd-dispatcher.service
           269ms mono-xsp4.service
           268ms grub-common.service
           266ms ModemManager.service
           264ms accounts-daemon.service
           260ms systemd-logind.service
           250ms ubuntu-system-adjustments.service
           240ms NetworkManager.service
           208ms avahi-daemon.service
           181ms systemd-journal-flush.service
           174ms tor.service
           171ms vboxautostart-service.service
           163ms vboxballoonctrl-service.service
           162ms pppd-dns.service
           153ms networking.service
           149ms gpu-manager.service
           143ms systemd-modules-load.service
           136ms nginx.service
           132ms wpa_supplicant.service
           116ms upower.service
           113ms alsa-restore.service
           109ms apparmor.service
           102ms redis-server.service
            96ms systemd-udev-trigger.service
            85ms thermald.service
            79ms dnsmasq.service
            79ms colord.service
            72ms lvm2-monitor.service
            72ms systemd-rfkill.service
            69ms keyboard-setup.service
            66ms swapfile.swap
            64ms systemd-journald.service
            62ms systemd-tmpfiles-setup.service
            57ms systemd-udevd.service
            57ms rsyslog.service
            53ms kmod-static-nodes.service
            51ms dev-hugepages.mount
            49ms sys-kernel-debug.mount
            49ms dev-mqueue.mount
            49ms ufw.service
            48ms virtualbox.service
            47ms systemd-remount-fs.service
            44ms speech-dispatcher.service
            41ms blk-availability.service
            39ms hddtemp.service
            39ms systemd-hostnamed.service

Here is the output of systemd-analyze critical-chain

Code: Select all

The time after the unit is active or started is printed after the "@" character.
The time the unit takes to start is printed after the "+" character.

graphical.target @3.520s
└─multi-user.target @3.520s
  └─docker.service @2.287s +1.232s
    └─containerd.service @1.138s +1.147s
      └─network.target @1.113s
        └─NetworkManager.service @872ms +240ms
          └─dbus.service @771ms
            └─basic.target @705ms
              └─sockets.target @704ms
                └─docker.socket @694ms +8ms
                  └─sysinit.target @679ms
                    └─systemd-timesyncd.service @640ms +37ms
                      └─systemd-tmpfiles-setup.service @567ms +62ms
                        └─systemd-journal-flush.service @383ms +181ms
                          └─systemd-journald.service @304ms +64ms
                            └─syslog.socket @302ms
                              └─system.slice @252ms
                                └─-.slice @248ms

And yeah I doubted the free space is the issue but just in case I cleared some more.

Code: Select all

Partition: ID-1: / size: 456.95 GiB used: 402.69 GiB (88.1%) fs: ext4 dev: /dev/sda5 

[t42]

"This is all I have in my /etc/default/grub:" -Of course. You said the problem appeared after grub reinstallation, probably there were no inserted by you kernel switches previously.

As you've found, you have the controller locked up for 8.25 seconds during boot. Look up journal messages around that time journalctl -b. You can limit an output with journalctl -b --since=07:41:05 --until=07:41:06 , changing times accordingly. Also look in dmesg output: dmesg , dmesg -l err and dmesg |grep -iE "usb|error|fail"
Also, with regard to issue it makes sense to install newer 5.13 kernel provided in the Update Manager Kernels module.

[Aztaroth]

can you explain how it may be a problem while having 30 GB of free space on root partition (and + 23 GB reserved as senjoz pointed out) ?

Easily. It's not a problem of space in GB value but in percentage. Most of what we may call senior advisers here agree that starting from a 85% full, system performances decrease until total freeze at some point. And 93,4 is a real high percentage.

The OP indicated the problem specifically, and obviously knows systemd-analyze options, maybe let's wait for more information asked for from him...

You have your way of helping the OP and I respect that. Give me the same respect back : if he doesn't like my suggestions, he's absolutely free (and grown-up I guess) to ignore them.

[Aztaroth]

Also, with regard to issue it makes sense to install newer 5.13 kernel provided in the Update Manager Kernels module.

The OP's distro is LM 19.3 Tricia. There's no 5.13 kernel available there (I would know of - see my signature) Yesterday, 5.4.0-91-generic x86_64 has been made available. That's the best he can expect if he wants to stay with Tricia's Kernel Management.
Even if available, I wouldn't install such a recent kernel on a 2015 machine. 5.4 is probably fine.

[Aztaroth]

@caranthir
Checking your system vs mine almost similar :

Code: Select all

System:
  Host: xxx-hp4770 Kernel: 5.4.0-91-generic x86_64 bits: 64 
  Desktop: Cinnamon 4.4.8 Distro: Linux Mint 19.3 Tricia 
CPU:
  Topology: Quad Core model: Intel Core i7-4770 bits: 64 type: MT MCP 
  L2 cache: 8192 KiB 
  Speed: 2485 MHz min/max: 800/3900 MHz Core speeds (MHz): 1: 2714 2: 2880 
  3: 2892 4: 2888 5: 2716 6: 2787 7: 2775 8: 2890 
Drives:
  Local Storage: total: 5.00 TiB used: 3.51 TiB (70.2%) 
  ID-1: /dev/sda vendor: Seagate model: ST2000DM001-1CH164 size: 1.82 TiB 
  ID-2: /dev/sdb vendor: Western Digital model: WD30EZRX-00DC0B0 
  size: 2.73 TiB 
  ID-3: /dev/sdc vendor: Crucial model: CT500MX500SSD4 size: 465.76 GiB 

I can say :
- I have almost the same /etc/default/grub, just a 5s TIMEOUT because I'm surely slower on the keyboard than you are.
- the systemd-analyze outputs are equivalent to mine too (my boot sequence is 18s because ID1 and ID2 are mounted at startup)
So, you may certainly be able to grab some milliseconds somewhere, but nothing that can be linked to an issue or failure. And the 'tweaks' you'll find to do that may compromise tasks the boot sequence has to perform.
However, as I mostly end, it's your computer and you're the boss.

[caranthir]

"This is all I have in my /etc/default/grub:" -Of course. You said the problem appeared after grub reinstallation, probably there were no inserted by you kernel switches previously.

As you've found, you have the controller locked up for 8.25 seconds during boot. Look up journal messages around that time journalctl -b. You can limit an output with journalctl -b --since=07:41:05 --until=07:41:06 , changing times accordingly. Also look in dmesg output: dmesg , dmesg -l err and dmesg |grep -iE "usb|error|fail"
Also, with regard to issue it makes sense to install newer 5.13 kernel provided in the Update Manager Kernels module.

Thanks, I tried to look in journalctl and dmesg as suggested but could not find any obvious USB related errors or failures.

I tried one other thing which was to disconnect my USB KVM switch from the PC and then reboot. Maybe I should have mentioned this earlier but I have a USB mouse, USB keyboard, USB adapter for wireless headset, and monitor (HDMI) hooked up to the computer via KVM switch.

The result is that I gain a significant boost:

Code: Select all

Startup finished in 6.100s (kernel) + 2.768s (userspace) = 8.869s
graphical.target reached after 2.761s in userspace

Previously:

Code: Select all

Startup finished in 15.034s (kernel) + 3.760s (userspace) = 18.795s
graphical.target reached after 3.751s in userspace

AND when I look at dmesg again there is no longer the 8s gap!
So what does this mean?

@caranthir
Checking your system vs mine almost similar :

Code: Select all

System:
  Host: xxx-hp4770 Kernel: 5.4.0-91-generic x86_64 bits: 64 
  Desktop: Cinnamon 4.4.8 Distro: Linux Mint 19.3 Tricia 
CPU:
  Topology: Quad Core model: Intel Core i7-4770 bits: 64 type: MT MCP 
  L2 cache: 8192 KiB 
  Speed: 2485 MHz min/max: 800/3900 MHz Core speeds (MHz): 1: 2714 2: 2880 
  3: 2892 4: 2888 5: 2716 6: 2787 7: 2775 8: 2890 
Drives:
  Local Storage: total: 5.00 TiB used: 3.51 TiB (70.2%) 
  ID-1: /dev/sda vendor: Seagate model: ST2000DM001-1CH164 size: 1.82 TiB 
  ID-2: /dev/sdb vendor: Western Digital model: WD30EZRX-00DC0B0 
  size: 2.73 TiB 
  ID-3: /dev/sdc vendor: Crucial model: CT500MX500SSD4 size: 465.76 GiB 

I can say :
- I have almost the same /etc/default/grub, just a 5s TIMEOUT because I'm surely slower on the keyboard than you are.
- the systemd-analyze outputs are equivalent to mine too (my boot sequence is 18s because ID1 and ID2 are mounted at startup)
So, you may certainly be able to grab some milliseconds somewhere, but nothing that can be linked to an issue or failure. And the 'tweaks' you'll find to do that may compromise tasks the boot sequence has to perform.
However, as I mostly end, it's your computer and you're the boss.

Appreciate your effort helping me look into this! I realize that the boot speed isn't bad but I'd like to get it faster if it doesn't compromise stability.

[t42]

I tried one other thing which was to disconnect my USB KVM switch from the PC and then reboot. Maybe I should have mentioned this earlier but I have a USB mouse, USB keyboard, USB adapter for wireless headset, and monitor (HDMI) hooked up to the computer via KVM switch.
The result is that I gain a significant boost

That was the right way to proceed - to disconnect as many USB devices as possible in order to find the one at fault. It may be that bad connector contact was excluded after reconnection.

[caranthir]

I tried one other thing which was to disconnect my USB KVM switch from the PC and then reboot. Maybe I should have mentioned this earlier but I have a USB mouse, USB keyboard, USB adapter for wireless headset, and monitor (HDMI) hooked up to the computer via KVM switch.
The result is that I gain a significant boost

That was the right way to proceed - to disconnect as many USB devices as possible in order to find the one at fault. It may be that bad connector contact was excluded after reconnection.

What should I look into next if the issue occurs regardless of whether I have the KVM plugged into a USB3.0 or 2.0 port?