30+ seconds kernel boot time

General system Kernel, boot, graphics & hardware
1

Hello. I’ve been using linux for a few years now and there is a bug i have on my laptop that until recently I’ve kept ignoring. Even though the laptop I have has a decent SSD and a good enough CPU(Intel i5-8250U) my boot sequence takes 43 seconds in total.
Running systemd-analyze results in:

Startup finished in 4.538s (firmware) + 2.774s (loader) + 31.544s (kernel) + 1.719s (initrd) + 3.333s (userspace) = 43.910s 
graphical.target reached after 3.226s in userspace.

And here is my systemd-analyze plot:
systemd-plot.pdf (27.1 KB)

So I don’t think It’s a userspace thing that I can optimize by disabling some services

After some more digging I came across these lines in my dmesg log:

...
[    0.126068] ... version:                4
[    0.126068] ... bit width:              48
[    0.126068] ... generic registers:      4
[    0.126068] ... value mask:             0000ffffffffffff
[    0.126068] ... max period:             00007fffffffffff
[    0.126068] ... fixed-purpose events:   3
[    0.126068] ... event mask:             000000070000000f
[    0.126068] Estimated ratio of average max frequency by base frequency (times 1024): 1934
[    0.126068] rcu: Hierarchical SRCU implementation.
[    0.126068] rcu: 	Max phase no-delay instances is 1000.
[    0.126068] smp: Bringing up secondary CPUs ...
[    0.126068] x86: Booting SMP configuration:
[    0.126068] .... node  #0, CPUs:      #1 #2 #3 #4
[    0.137820] MDS CPU bug present and SMT on, data leak possible. See https://www.kernel.org/doc/html/latest/admin-guide/hw-vuln/mds.html for more details.
[    0.137820] MMIO Stale Data CPU bug present and SMT on, data leak possible. See https://www.kernel.org/doc/html/latest/admin-guide/hw-vuln/processor_mmio_stale_data.html for more details.
[    0.137820]  #5 #6 #7
[    0.140235] smp: Brought up 1 node, 8 CPUs
[    0.140235] smpboot: Max logical packages: 1
[    0.140235] smpboot: Total of 8 processors activated (28811.00 BogoMIPS)
[    0.143190] devtmpfs: initialized
[    0.143190] x86/mm: Memory block size: 128MB
[    0.144069] ACPI: PM: Registering ACPI NVS region [mem 0x73de1000-0x73de1fff] (4096 bytes)
[    0.144069] ACPI: PM: Registering ACPI NVS region [mem 0x8c88e000-0x8cf7dfff] (7274496 bytes)
[    0.144069] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 6370867519511994 ns
[    0.144069] futex hash table entries: 2048 (order: 5, 131072 bytes, linear)
[    0.144069] pinctrl core: initialized pinctrl subsystem
[    0.144069] PM: RTC time: 10:41:01, date: 2023-01-27
[    0.146323] NET: Registered PF_NETLINK/PF_ROUTE protocol family
[    0.146693] DMA: preallocated 1024 KiB GFP_KERNEL pool for atomic allocations
[    0.146804] DMA: preallocated 1024 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations
[    0.146916] DMA: preallocated 1024 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations
[    0.146942] audit: initializing netlink subsys (disabled)
[    0.146956] audit: type=2000 audit(1674816061.023:1): state=initialized audit_enabled=0 res=1
[    0.146956] thermal_sys: Registered thermal governor 'fair_share'
[    0.146956] thermal_sys: Registered thermal governor 'bang_bang'
[    0.146956] thermal_sys: Registered thermal governor 'step_wise'
[    0.146956] thermal_sys: Registered thermal governor 'user_space'
[    0.146956] thermal_sys: Registered thermal governor 'power_allocator'
[    0.146956] cpuidle: using governor ladder
[    0.146956] cpuidle: using governor menu
[    0.146956] Simple Boot Flag at 0x44 set to 0x1
[    0.146956] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5
[    0.146956] PCI: MMCONFIG for domain 0000 [bus 00-ff] at [mem 0xe0000000-0xefffffff] (base 0xe0000000)
[    0.146956] PCI: MMCONFIG at [mem 0xe0000000-0xefffffff] reserved in E820
[    0.146956] PCI: Using configuration type 1 for base access
[    0.146956] ENERGY_PERF_BIAS: Set to 'normal', was 'performance'
[    0.149472] kprobes: kprobe jump-optimization is enabled. All kprobes are optimized if possible.
[    0.156080] HugeTLB: registered 1.00 GiB page size, pre-allocated 0 pages
[    0.156083] HugeTLB: 16380 KiB vmemmap can be freed for a 1.00 GiB page
[    0.156086] HugeTLB: registered 2.00 MiB page size, pre-allocated 0 pages
[    0.156088] HugeTLB: 28 KiB vmemmap can be freed for a 2.00 MiB page
[    0.156271] ACPI: Added _OSI(Module Device)
[    0.156274] ACPI: Added _OSI(Processor Device)
[    0.156276] ACPI: Added _OSI(3.0 _SCP Extensions)
[    0.156279] ACPI: Added _OSI(Processor Aggregator Device)
[    0.156282] ACPI: Added _OSI(Windows 2022)
[    0.270472] ACPI: 14 ACPI AML tables successfully acquired and loaded
[    0.274265] ACPI: EC: EC started
[    0.274267] ACPI: EC: interrupt blocked
[   30.299995] ACPI Error: Aborting method \_SB.PCI0.LPCB.H_EC.ECMD due to previous error (AE_AML_LOOP_TIMEOUT) (20220331/psparse-529)
[   30.300010] ACPI Error: Aborting method \_TZ.FNCL due to previous error (AE_AML_LOOP_TIMEOUT) (20220331/psparse-529)
[   30.300021] ACPI Error: Aborting method \_TZ.FN00._OFF due to previous error (AE_AML_LOOP_TIMEOUT) (20220331/psparse-529)
[   30.300031] ACPI Error: Aborting method \_SB.PCI0.LPCB.H_EC._REG due to previous error (AE_AML_LOOP_TIMEOUT) (20220331/psparse-529)
[   30.300062] ACPI: EC: EC_CMD/EC_SC=0x66, EC_DATA=0x62
[   30.300065] ACPI: EC: Boot ECDT EC used to handle transactions
[   30.302815] ACPI: [Firmware Bug]: BIOS _OSI(Linux) query ignored
[   30.496081] ACPI: Dynamic OEM Table Load:
[   30.496081] ACPI: SSDT 0xFFFF93ABC14B6800 00058B (v02 PmRef  Cpu0Ist  00003000 INTL 20160527)
[   30.497872] ACPI: \_PR_.CPU0: _OSC native thermal LVT Acked
[   30.502167] ACPI: Dynamic OEM Table Load:
[   30.502185] ACPI: SSDT 0xFFFF93ABC149F400 0003FF (v02 PmRef  Cpu0Cst  00003001 INTL 20160527)
[   30.506654] ACPI: Dynamic OEM Table Load:
[   30.506672] ACPI: SSDT 0xFFFF93ABC14B5800 00065C (v02 PmRef  ApIst    00003000 INTL 20160527)
[   30.510962] ACPI: Dynamic OEM Table Load:
[   30.510978] ACPI: SSDT 0xFFFF93ABC1411200 000197 (v02 PmRef  ApHwp    00003000 INTL 20160527)
[   30.514322] ACPI: Dynamic OEM Table Load:
[   30.514337] ACPI: SSDT 0xFFFF93ABC1410A00 00018A (v02 PmRef  ApCst    00003000 INTL 20160527)
[   30.525799] ACPI: Interpreter enabled
[   30.525900] ACPI: PM: (supports S0 S3 S4 S5)
[   30.525902] ACPI: Using IOAPIC for interrupt routing
[   30.525987] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug
[   30.525989] PCI: Using E820 reservations for host bridge windows
[   30.529088] ACPI: Enabled 8 GPEs in block 00 to 7F
[   30.558028] ACPI: PM: Power Resource [PC01]
[   30.559774] ACPI: PM: Power Resource [WRST]
[   30.560654] ACPI: PM: Power Resource [WRST]
[   30.561535] ACPI: PM: Power Resource [WRST]
[   30.562421] ACPI: PM: Power Resource [WRST]
[   30.563310] ACPI: PM: Power Resource [WRST]
[   30.564178] ACPI: PM: Power Resource [WRST]
[   30.565045] ACPI: PM: Power Resource [WRST]
[   30.565914] ACPI: PM: Power Resource [WRST]
[   30.566792] ACPI: PM: Power Resource [WRST]
[   30.567663] ACPI: PM: Power Resource [WRST]
[   30.568531] ACPI: PM: Power Resource [WRST]
[   30.569375] ACPI: PM: Power Resource [WRST]
[   30.570228] ACPI: PM: Power Resource [WRST]
[   30.571071] ACPI: PM: Power Resource [WRST]
[   30.571913] ACPI: PM: Power Resource [WRST]
[   30.572766] ACPI: PM: Power Resource [WRST]
[   30.573612] ACPI: PM: Power Resource [WRST]
[   30.574455] ACPI: PM: Power Resource [WRST]
[   30.575297] ACPI: PM: Power Resource [WRST]
[   30.593260] acpi ABCD0000:00: ACPI dock station (docks/bays count: 1)
[   30.600124] ACPI: PM: Power Resource [FN00]
[   30.600335] ACPI: PM: Power Resource [FN01]
[   30.600541] ACPI: PM: Power Resource [FN02]
[   30.600745] ACPI: PM: Power Resource [FN03]
[   30.600949] ACPI: PM: Power Resource [FN04]
[   30.604319] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-fe])
[   30.604332] acpi PNP0A08:00: _OSC: OS supports [ExtendedConfig ASPM ClockPM Segments EDR HPX-Type3]
[   30.604337] acpi PNP0A08:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI]
[   30.610492] PCI host bridge to bus 0000:00
...

I can post the rest of the log if needed but the fact that the time jumps from 0 to 30 seconds during some ACPI steps makes me think that this is a problem with ACPI

I tried the acpi=off kernel parameter but it just made the computer boot until the account service, throw up some IRQ error and fail to start X11. So that’s probably out.

Thanks in advance :slight_smile:

Edit: Here is the inxi -Fz and the dmesg output

2

Just for comparison with a more recent CPU (AMD 4800H), systemd-analyze returns:

Startup finished in 3.775s (firmware) + 21.094s (loader) + 1.798s (kernel) + 3.145s (userspace) = 29.813s 
graphical.target reached after 3.144s in userspace.

Much faster kernel, much slower loader: I don’t know what we should conclude…

3

Have you tried changing the default wait times in the systemd config file? “/etc/systemd/system.conf”

4

I’ve tried uncommenting these lines and setting them to 1s, same outcome

DefaultTimeoutStartSec=1s
DefaultTimeoutStopSec=1s
DefaultDeviceTimeoutSec=1s
1 Like
5

As far as I understand (loader) is the time that grub/systemd-boot takes so I’d guess that probably means either a long timeout, a very slow drive or just you entering into edit mode and spending some time there

6

see if you can update your EFI motherboard ( 2018 )

7

Have you tried

systemd-analyze blame

and

systemd-analyze critical-chain

?

Strangely, that’s neither of them for my long loading time (1s timeout in grub, nvme)… What else could it be?

What do you think about removing the “base” hook as advised in section 2 of https://wiki.archlinux.org/title/Improving_performance/Boot_process ? Is it safe? What do we lose?

8

systemd-analyze blame:
added to the gist

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 @2.910s
└─lightdm.service @2.850s +56ms
  └─systemd-user-sessions.service @2.759s +51ms
    └─nss-user-lookup.target @2.933s
9

I checked it and seems like my laptop’s manufacturer doesn’t list any bios updates on their site. I’ll try to get in contact with their support but unless it’s absolutely necessary I’d rather avoid taking any risks with a bios update.

10

Then you know who’s to blame.
First culprit, see for instance:

11

Are the additional/custom kernel parameters important/necessary for booting? For example "acpi_osi=Windows 2022", which AFAIK it should be formatted as acpi_osi='Windows 2022', but if it works :person_shrugging: …
Can you test with removing each of them ?

Have you ever installed a different Linux OS and had a different behavior on boot-up?

It seems there is a gap/step of pause at the kernel stage, as you mention, and it starts almost after reading kernel parameters. The rest of the time-consuming tasks look normal, even though some are unusual (to me).

It may not be relevant, but there is a suggestion message that you might want to test/try:

[ 30.525902] ACPI: Using IOAPIC for interrupt routing
[ 30.525987] PCI: Using host bridge windows from ACPI; if necessary, use “pci=nocrs” and report a bug

12

I added the acpi_osi argument via grub during boot selection. Sorry about the confusion, I don’t normally have them in the config.

I’ve used Manjaro and Mint on this laptop before and both of them had the same problem.

I also just tried the pci=nocrs option just now and got the same result with 31 seconds in kernel during boot time

13

I would look for any available settings in BIOS/UEFI and hope for a difference.
It really looks (to me) like a hardware/firmware/vendor issue. :person_shrugging:

14

After doing a full update a few days ago the issue stopped.
The sytemd-analize output is now
4.474s (firmware) + 3.532s (loader) + 1.217s (kernel) + 1.799s (initrd) + 3.328s (userspace) = 14.352s

Thanks to everyone who tried to help. I’ll be closing the thread now.

15

This topic was automatically closed 2 days after the last reply. New replies are no longer allowed.