Long kernel load time

Question

Running Ubuntu 18.04 on a Dell XPS 9370, I'm getting kernel load times of over 30 seconds.

systemd-analyze output:

Startup finished in 12.834s (firmware) + 1.331s (loader) + 33.643s (kernel) + 11.692s (userspace) = 59.502s

systemd-analyze blame only shows userspace load times, so I wont include it here.

Relevant dmesg output:

[    5.154052] pcieport 0000:04:00.0: Refused to change power state, currently in D3
[    5.155956] pci_bus 0000:05: busn_res: [bus 05] is released
[    5.156127] pci_bus 0000:06: busn_res: [bus 06-38] is released
[    5.156235] pci_bus 0000:39: busn_res: [bus 39] is released
[    5.156300] pci_bus 0000:3a: busn_res: [bus 3a-6d] is released
[    5.156352] pci_bus 0000:04: busn_res: [bus 04-6d] is released
[   33.556238] EXT4-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null)

Full dmesg output: https://pastebin.com/0JmWuLtZ

I've tried editing /etc/initramfs-tools/conf.d/resume as described here and adding noresume to my GRUB_CMDLINE_LINUX_DEFAULT.

How can I troubleshoot this?

BTW there are tricks to reducing Firmware time too. – WinEunuuchs2Unix Aug 10 '19 at 04:08 — WinEunuuchs2Unix, Aug 10 '19 at 04:08
@WinEunuuchs2Unix Ooh, I'll have a look. – Omegastick Aug 10 '19 at 04:13 — Omegastick, Aug 10 '19 at 04:13

WinEunuuchs2Unix · Accepted Answer · 2019-08-10T14:59:18.857

How can I troubleshoot this?

The first step is to find out what PCI device is generating the error:

pcieport 0000:04:00.0: Refused to change power state, currently in D3

My system doesn't have a 0000:04:00.0 but it does have 0000:03:00.0 so I would use:

$ cd /sys/bus/pci/devices/0000:03:00.0

$ ls -la
total 0
drwxr-xr-x 5 root root    0 Aug  8 17:15 .
drwxr-xr-x 8 root root    0 Aug  8 17:15 ..
drwxr-xr-x 3 root root    0 Aug  9 17:53 0000:03:00.0:pcie208
-rw-r--r-- 1 root root 4096 Aug  9 17:53 broken_parity_status
-r--r--r-- 1 root root 4096 Aug  8 17:15 class
-rw-r--r-- 1 root root 4096 Aug  8 17:15 config
-r--r--r-- 1 root root 4096 Aug  9 17:53 consistent_dma_mask_bits
-r--r--r-- 1 root root 4096 Aug  9 17:53 current_link_speed
-r--r--r-- 1 root root 4096 Aug  9 17:53 current_link_width
-rw-r--r-- 1 root root 4096 Aug  9 17:53 d3cold_allowed
-r--r--r-- 1 root root 4096 Aug  8 17:15 device
-r--r--r-- 1 root root 4096 Aug  9 17:53 dma_mask_bits
lrwxrwxrwx 1 root root    0 Aug  8 17:15 driver -> ../../../../../bus/pci/drivers/pcieport
-rw-r--r-- 1 root root 4096 Aug  9 17:53 driver_override
-rw-r--r-- 1 root root 4096 Aug  9 17:53 enable
-r--r--r-- 1 root root 4096 Aug  8 17:15 irq
-r--r--r-- 1 root root 4096 Aug  9 17:53 local_cpulist
-r--r--r-- 1 root root 4096 Aug  9 17:53 local_cpus
-r--r--r-- 1 root root 4096 Aug  9 17:53 max_link_speed
-r--r--r-- 1 root root 4096 Aug  9 17:53 max_link_width
-r--r--r-- 1 root root 4096 Aug  9 17:53 modalias
-rw-r--r-- 1 root root 4096 Aug  9 17:53 msi_bus
-rw-r--r-- 1 root root 4096 Aug  9 17:53 numa_node
drwxr-xr-x 3 root root    0 Aug  9 17:53 pci_bus
drwxr-xr-x 2 root root    0 Aug  8 17:15 power
--w--w---- 1 root root 4096 Aug  9 17:53 remove
--w--w---- 1 root root 4096 Aug  9 17:53 rescan
-r--r--r-- 1 root root 4096 Aug  8 17:15 resource
-r--r--r-- 1 root root 4096 Aug  9 17:53 revision
-r--r--r-- 1 root root 4096 Aug  9 17:53 secondary_bus_number
-r--r--r-- 1 root root 4096 Aug  9 17:53 subordinate_bus_number
lrwxrwxrwx 1 root root    0 Aug  9 17:53 subsystem -> ../../../../../bus/pci
-r--r--r-- 1 root root 4096 Aug  9 17:53 subsystem_device
-r--r--r-- 1 root root 4096 Aug  9 17:53 subsystem_vendor
-rw-r--r-- 1 root root 4096 Aug  9 17:53 uevent
-r--r--r-- 1 root root 4096 Aug  8 17:15 vendor

$ cat vendor
0x8086

$ cat device
0x1576

$ cat class
0x060400

$ cat max_link_speed
2.5 GT/s

$ cat max_link_width
4

$ lspci -n | tail -8
03:00.0 0604: 8086:1576
03:01.0 0604: 8086:1576
03:02.0 0604: 8086:1576
39:00.0 0c03: 8086:15b5
3b:00.0 0200: 1969:e0a1 (rev 10)
3c:00.0 0280: 168c:003e (rev 32)
3d:00.0 ff00: 10ec:5227 (rev 01)
3e:00.0 0108: 144d:a804

$ lspci | tail -8
03:00.0 PCI bridge: Intel Corporation DSL6340 Thunderbolt 3 Bridge [Alpine Ridge 2C 2015]
03:01.0 PCI bridge: Intel Corporation DSL6340 Thunderbolt 3 Bridge [Alpine Ridge 2C 2015]
03:02.0 PCI bridge: Intel Corporation DSL6340 Thunderbolt 3 Bridge [Alpine Ridge 2C 2015]
39:00.0 USB controller: Intel Corporation DSL6340 USB 3.1 Controller [Alpine Ridge]
3b:00.0 Ethernet controller: Qualcomm Atheros Killer E2400 Gigabit Ethernet Controller (rev 10)
3c:00.0 Network controller: Qualcomm Atheros QCA6174 802.11ac Wireless Network Adapter (rev 32)
3d:00.0 Unassigned class [ff00]: Realtek Semiconductor Co., Ltd. RTS5227 PCI Express Card Reader (rev 01)
3e:00.0 Non-Volatile memory controller: Samsung Electronics Co Ltd NVMe SSD Controller SM961/PM961

If my system had the error then it would be caused by the Thunderbolt subsystem and I might just start by unplugging my Thunderbolt DPI to HDMI adapter.

In your case replace 0000:03:00.0 with 0000:04:00.0 above. Adjust tail number of lines as necessary.

This is the first step in trouble shooting.

Credit: - Decoding PCI data and lspci output on Linux hosts

Solution: It was Intel SpeedStep located at 0000:04:00.0 and enabling it in BIOS removes 30 second boot delay.

This helped me find the problem. I've posted the root cause as a separate answer. — Omegastick, Aug 10 '19 at 03:50
@Omegastick Awesome! I upvoted your answer. I don't have Intel SpeedStep® Technology on my system which explains how you have a 0000:04:00.0 where my PCI ends at 0000:03:00.0 — WinEunuuchs2Unix, Aug 10 '19 at 04:03
@Omegastick I did a quick edit. Changed "disabling" to "enabling" — WinEunuuchs2Unix, Aug 10 '19 at 14:59

score 2 · Answer 2 · answered Aug 10 '19 at 03:49

2

I had disabled Intel SpeedStep® Technology in the BIOS, which was preventing the CPU from switching power states. Enabling it brought the kernel load time to about 3 seconds.

answered Aug 10 '19 at 03:49

Omegastick

175

Long kernel load time

2 Answers2

Linked