[SOLVED] Kernel 3.17: Timeout on hotplug command 0x00000000

Trilby · 2014-10-23 03:09:29

After upgrading to the 3.17 kernel I've noticed much slower boot times. The lag is before any fsck result is displayed, and as the 'parsing ELF' message shows [1].

Typically my systemd-analyze times for 'kernel' have been in the range of hundreds of milliseconds (this is on an SSD). But after the upgrade to 3.17 it has consistently been well over 4 seconds just in the kernel stage (before initrd). I rebuilt the initramfs to ensure it wasn't an error there making it slower to even start loading, but there was no change. I further confirmed that it was the 3.17 kernel by downgrading to 3.16.4 after which systemd-analyze again shows a 'kernel' time of 344ms.

I've also just cleared my cache, redownloaded and reinstalled 3.17 and confirmed that the lag returned.

As this all takes place before any journals are started, I don't know how to find any relevant logs. Any suggestions on troubleshooting would be appreciated.

edit:
[1] The exact message is as follows:

Decompressing Linux ... Parsing ELF.  Done
Booting the kernel.

There is a hang here for about 4 seconds with 3.17, but not with 3.16. Both versions then next output an fsck message and continue - there is no difference in output in the boot process between the two version. 3.17 just hangs there for 4 seconds.

Last edited by Trilby (2014-10-24 17:38:48)

mauritiusdadd · 2014-10-23 15:38:55

Hi Trilby,
I'm not a kernel expert but if systemd-analyze can see the delay then you could use systemd-bootchart to compare the boot sequence of the two kernels.

Trilby · 2014-10-23 16:09:17

Thanks for the suggestion. I'm not sure if that'd be expected to work as the hang is in the kernel loading before init is loaded anyways. But I gave it a shot. It failed miserably when I added it to the kernel line as recommended in the wiki [1], but I was able to run it from a booted system, and it starts far too late in the boot process. Among the first things listed (within the first second) are xinit and Xorg.bin.

Based on an email from another archer about this thread, I also tried adding "init=/usr/bin/bash" to the kernel line. This (I believe) should eliminate any fsck and systemd processes. I do get to a shell prompt right after the kernel loads, but the ~4 second lag remains. So this does definitely seem to be the kernel itself hanging for 4 seconds.

[1] error in svg.c, then hangs on 'stop job running for ...' after 90 seconds the process is killed then restarted and the 90s cylce starts again).

Trilby · 2014-10-24 17:32:17

I've received a couple more tips via email. One suggesting this might be related to TSC (which I'm pretty ignorant of). If this is the case this other thread may be related. But the emailed suggestion also pointed me to dmesg which is proving useful. There seems to be a large lag in this sequence:

[    1.450034] tsc: Refined TSC clocksource calibration: 2526.999 MHz      
[    1.790033] pciehp 0000:00:1c.0:pcie04: Timeout on hotplug command 0x00000000 (issued 1333 msec ago)
[    1.790050] pciehp 0000:00:1c.0:pcie04: service driver pciehp loaded    
[    1.790084] pciehp 0000:00:1c.1:pcie04: Slot #1 AttnBtn- AttnInd- PwrInd- PwrCtrl- MRL- Interlock- NoCompl- LLActRep+
[    2.450119] Switched to clocksource tsc                                 
[    3.123356] pciehp 0000:00:1c.1:pcie04: Timeout on hotplug command 0x00000000 (issued 1333 msec ago)
[    3.123372] pciehp 0000:00:1c.1:pcie04: service driver pciehp loaded    
[    3.123404] pciehp 0000:00:1c.3:pcie04: Slot #3 AttnBtn- AttnInd- PwrInd- PwrCtrl- MRL- Interlock- NoCompl- LLActRep+
[    4.460023] pciehp 0000:00:1c.3:pcie04: Timeout on hotplug command 0x00000000 (issued 1336 msec ago)
[    4.460039] pciehp 0000:00:1c.3:pcie04: service driver pciehp loaded                                                                                        
[    4.460060] pciehp: PCI Express Hot Plug Controller Driver version: 0.4 
[    4.460186] intel_idle: does not run on family 6 model 23

I'm about to downgrade to compare dmesg output from the 'good' and 'bad' versions and will edit this post momentarily.

---

I just rebooted with the 'fast' 3.16.4 kernel and noticed two things. First, the fast kernel reports "Fast TSC Failed" while booting, the slow 3.17 does not (so TSC did not fail in the 3.17 kernel?). But also the dmesg output of the 3.16.4 kernel lacks any of the "Timeout on hotplug command" lines that are scattered throughout the 3.17 kernel dmesg and seem to be responsible for the lag.

I'll append part of this dmesg line to the title of this thread - does anyone know what these null (0x0000000) hotplug commands are? The three failed commands each using 1.33333 seconds would exactly account for the seeming 4 second lag.

---

For anyone who may be able to make more sense of this than I can, I just googled the dmesg line I'm getting, and I see it in a report of an issue with a 'Thunderbolt' driver here

I'm going to look into the kernel configs and see if this Thunderbolt driver was a new addition to 3.17 - if anyone can beat me to that and has any knowledge of this, that'd be appreciated.

edit: It seems the Thunderbolt driver is likely a red-herring: this did not change between 3.16.4 and 3.17.1 (at least according to the kernel configs both having CONFIG_HOTPLUG_PCI_PCIE=y).

Last edited by Trilby (2014-10-24 17:38:12)

yaroslav · 2014-12-10 21:28:24

I have the same issue on Fedora 21. The kernel is 3.17.4. Shutdown also lags for ~5 seconds after printing "Restarting system"

Trilby · 2014-12-10 22:03:18

Yaroslav, have you checked dmesg? Do you have the same 1.33 second lag on several hotplug timeouts?

I have not made any progress with this yet, but the problem remains in all minor version updates of the 3.17 kernel.

OB4Life · 2014-12-17 16:17:22

Post grub there is an approximately 8 second hang before init begins for me. Just a blank screen.

Downgrading to 3.16 reduces the time between Grub and init to around 2 seconds. Which still seems rather long to me, given i have an SSD and fairly powerful machine. I have emptied /var/log/journal and limited it's size, is it worth adding root partition to the kernel command line, or are we talking mere millisecond savings there? Anyway, that's offtopic.

Have reinstalled the kernel and rerun mkinitcpio -p linux to no avail. Here's hoping 3.18 brings a fix.

Trilby · 2014-12-17 16:24:59

Please check your dmesg output for the above mentioned lines to get an idea whether this is a similar issue.

ix7 · 2014-12-17 19:17:22

I have the same issue on a Thinkpad T400

[    0.395612] io scheduler cfq registered (default)
[    0.395824] pcieport 0000:00:1c.0: irq 24 for MSI/MSI-X
[    0.396032] pcieport 0000:00:1c.1: irq 25 for MSI/MSI-X
[    0.396223] pcieport 0000:00:1c.4: irq 26 for MSI/MSI-X
[    0.396380] pcieport 0000:00:1c.0: Signaling PME through PCIe PME interrupt
[    0.396386] pcie_pme 0000:00:1c.0:pcie01: service driver pcie_pme loaded
[    0.396408] pcieport 0000:00:1c.1: Signaling PME through PCIe PME interrupt
[    0.396410] pci 0000:03:00.0: Signaling PME through PCIe PME interrupt
[    0.396415] pcie_pme 0000:00:1c.1:pcie01: service driver pcie_pme loaded
[    0.396436] pcieport 0000:00:1c.4: Signaling PME through PCIe PME interrupt
[    0.396441] pcie_pme 0000:00:1c.4:pcie01: service driver pcie_pme loaded
[    0.396461] pci_hotplug: PCI Hot Plug PCI Core version: 0.5
[    0.396512] pciehp 0000:00:1c.0:pcie04: Slot #0 AttnBtn- AttnInd- PwrInd- PwrCtrl- MRL- Interlock- NoCompl- LLActRep+
[    1.393352] tsc: Refined TSC clocksource calibration: 2260.999 MHz
[    1.726684] pciehp 0000:00:1c.0:pcie04: Timeout on hotplug command 0x00000000 (issued 1333 msec ago)
[    1.726692] pciehp 0000:00:1c.0:pcie04: service driver pciehp loaded
[    1.726708] pciehp 0000:00:1c.1:pcie04: Slot #1 AttnBtn- AttnInd- PwrInd- PwrCtrl- MRL- Interlock- NoCompl- LLActRep+
[    2.393397] Switched to clocksource tsc
[    3.060008] pciehp 0000:00:1c.1:pcie04: Timeout on hotplug command 0x00000000 (issued 1333 msec ago)
[    3.060016] pciehp 0000:00:1c.1:pcie04: service driver pciehp loaded
[    3.060031] pciehp 0000:00:1c.4:pcie04: Slot #4 AttnBtn- AttnInd- PwrInd- PwrCtrl- MRL- Interlock- NoCompl- LLActRep+
[    4.393343] pciehp 0000:00:1c.4:pcie04: Timeout on hotplug command 0x00000000 (issued 1333 msec ago)
[    4.393351] pciehp 0000:00:1c.4:pcie04: service driver pciehp loaded
[    4.393362] pciehp: PCI Express Hot Plug Controller Driver version: 0.4
[    4.393406] vesafb: mode is 1440x900x32, linelength=5760, pages=0

on my Thinkpad T410 it works fine

[    0.544815] io scheduler cfq registered (default)
[    0.545341] pci_hotplug: PCI Hot Plug PCI Core version: 0.5
[    0.545356] pciehp: PCI Express Hot Plug Controller Driver version: 0.4
[    0.545388] vesafb: mode is 1280x800x32, linelength=5120, pages=0

both notebooks are on linux 3.17.6-1

OB4Life · 2014-12-17 21:03:21

I am on an Thinkpad R400 (very similar to T400).

dmesg seems no record slow progress after TSC calibration.

[    0.383184] pciehp 0000:00:1c.0:pcie04: Slot #0 AttnBtn- AttnInd- PwrInd- PwrCtrl- MRL- Interlock- NoCompl- LLActRep+
[    1.380914] tsc: Refined TSC clocksource calibration: 3058.999 MHz
[    1.841639] pciehp 0000:00:1c.0:pcie04: Timeout on hotplug command 0x00000000 (issued 1460 msec ago)
[    1.841646] pciehp 0000:00:1c.0:pcie04: service driver pciehp loaded
[    1.841659] pciehp 0000:00:1c.1:pcie04: Slot #1 AttnBtn- AttnInd- PwrInd- PwrCtrl- MRL- Interlock- NoCompl- LLActRep+
[    2.386163] Switched to clocksource tsc
[    3.260008] pciehp 0000:00:1c.1:pcie04: Timeout on hotplug command 0x00000000 (issued 1420 msec ago)
[    3.260023] pciehp 0000:00:1c.1:pcie04: service driver pciehp loaded
[    3.260046] pciehp 0000:00:1c.3:pcie04: Slot #3 AttnBtn- AttnInd- PwrInd- PwrCtrl- MRL- Interlock- NoCompl- LLActRep+
[    4.593340] pciehp 0000:00:1c.3:pcie04: Timeout on hotplug command 0x00000000 (issued 1333 msec ago)
[    4.593355] pciehp 0000:00:1c.3:pcie04: service driver pciehp loaded
[    4.593380] pciehp 0000:00:1c.4:pcie04: Slot #4 AttnBtn- AttnInd- PwrInd- PwrCtrl- MRL- Interlock- NoCompl- LLActRep+
[    5.936672] pciehp 0000:00:1c.4:pcie04: Timeout on hotplug command 0x00000000 (issued 1343 msec ago)
[    5.936679] pciehp 0000:00:1c.4:pcie04: service driver pciehp loaded
[    5.936684] pciehp: PCI Express Hot Plug Controller Driver version: 0.4
[    5.936716] vesafb: mode is 1440x900x8, linelength=1472, pages=0
[    5.936718] vesafb: scrolling: redraw
[    5.936719] vesafb: Pseudocolor: size=0:6:6:6, shift=0:0:0:0
[    5.936731] vesafb: framebuffer at 0xd0000000, mapped to 0xffffc90004e80000, using 1344k, total 1344k
[    5.947081] Console: switching to colour frame buffer device 180x56
[    5.957310] fb0: VESA VGA frame buffer device
[    5.957325] intel_idle: does not run on family 6 model 23

OB4Life · 2014-12-18 00:57:07

I installed linux-mainline kernel, which is a 3.18 release, and the problem is resolved. I am still not happy with the time it takes between grub and systemd starting, it is around 2.5 seconds, but mere milliseconds for others. This is a separate issue of mine, but out of interest, what time would you expect, or what times are you getting, with 3.16?*

Anyway, here is systemd-analyze plot with 3.18:

http://imgur.com/IJtfMdy

and dmesg:

http://pastebin.com/T13e5tvJ

*that is, the time before systemd starts and after the kernel has finished, as seen in the output from systemd-analyze plot.

Last edited by OB4Life (2014-12-18 01:07:13)

OB4Life · 2014-12-18 01:02:35

By the way, i get TSC fast calibration failed, or something approximating that, printed to screen first thing with the new kernel.

[edit] I am no longer getting TSC fast calibration failed, at least i am not seeing it printed any more (three boots). I have posted another dmesg here:

http://pastebin.com/BX3ynvgT

Last edited by OB4Life (2014-12-18 01:26:49)

Trilby · 2014-12-18 02:27:05

While I admit almost complete ignorance of what the TSC failed message means, I do know that it has been around for a while and is generally regarded as harmless. It seems to show up on some boots for me and not on others, and based on all my experiences it is in no way correlated with the null hotplug command timeout several of us are dealing with in this thread.

OB4Life, many thanks for trying out 3.18 - that gives me hope. I thought about doing this as well, but compiling a kernel not in the repos is quite an ordeal on my hardware.

Also thanks to all who've posted dmesg replicates. When 3.18 hits the main repos we can try that out. I'll then either mark this as solved, or if it fails I'll see if I can make a well formed bug report for this issue.

EDIT: sorry I missed a question above about expected boot times on an SSD. While it can vary widely based on many factors (hardware, services started, desktops/DEs, etc) I think order-of-magnitude style comparisons can be made on the "kernel" section of systemd-analyze. As indicated in a early post in the thread, with 3.16 and earlier kernels, kernel time was consistently between 300-400ms. Now with 3.17 it's consistently 4 seconds longer (3 x 1.333333):

systemd-analyze
Startup finished in 4.368s (kernel) + 998ms (initrd) + 5.204s (userspace) = 10.570s

Last edited by Trilby (2014-12-18 02:37:31)

ix7 · 2014-12-18 10:35:36

I tried the 3.18.1-1 kernel from the testing repo.
It is fine now.

systemd-analyze
Startup finished in 1.585s (kernel) + 1.674s (userspace) = 3.259s

OB4Life · 2014-12-18 21:46:22

Hi, Trilby. I notice that you have kernel and initrd times separate in the output of systemd-analyze. Are you using the "systemd" hook in /etc/mkinitcpio.conf instead of "base"? If so why, as a believe "base" is the default.
If i add the "systemd" hook i get kernel times in the hundreds milliseconds, but with the separate initrd measurement, it averages out similarly to the combined total recorded with the "base" hook.
What hardware do you have, if i may ask?

Trilby · 2014-12-18 22:09:19

$ cat /etc/mkinitcpio.conf 
MODULES="ahci sd_mod ext4"
BINARIES="fsck fsck.ext4"
FILES=""
HOOKS="base systemd"
COMPRESSION=cat

I like having the two separate times - it made narrowing this down a bit easier.

I have a Lenovo X200 (Intel Core 2 Duo CPU P8700 @ 2.53GHz).

OB4Life · 2014-12-18 22:36:47

So we all three have Lenovo machines. I have an R400 with a T9900 @ 3.06GHz.

I have got my kernel time down to 1.324s, including initrd. I have decided to be happy with this. I uninstalled a few items as per https://lizards.opensuse.org/2012/07/26 … cond-boot/ and added modules to /etc/mkinitcpio.conf and removed hooks as per http://blog.falconindy.com/articles/opt … tcpio.html.

Are you aware that, according to https://wiki.archlinux.org/index.php/mkinitcpio#HOOKS, the "systemd" hook is meant to replace "base"?

OB4Life · 2014-12-19 00:42:59

Hey, ix7, if you are still around, I have no video playback with 3.18 in VLC or Mplayer. Flash on the web still works though. Thought the recent ffmpeg update might have been to blame, but no. And booting from the older kernel provides working video.

How about for you?

Trilby · 2014-12-19 00:44:40

Please open another thread for unrelated issues.

OB4Life · 2014-12-19 01:00:21

Ok. I will wait and see if the issue is present on the regular 3.18 kernel when it hits, and do that if it does.

kjell · 2014-12-25 13:59:34

had major issues as well with 3.17 and lvm ..could not boot at all. Revering to 3.16 and it's fine. Waiting for 3.18 instead of growing more greys.

Trilby · 2014-12-25 14:05:37

This is not intended as a catch-all dumpster for any issue with linux 3.17:

Trilby wrote:

Please check your dmesg output for the above mentioned lines to get an idea whether this is a similar issue.

- and -

Trilby wrote:

Please open another thread for unrelated issues.

EDIT: as 3.18 just hit core, I can confirm this is solved with the new kernel. Sadly I know have issues with suspend (grr).

Last edited by Trilby (2015-01-15 15:58:06)

Arch Linux

#1 2014-10-23 03:09:29

[SOLVED] Kernel 3.17: Timeout on hotplug command 0x00000000

#2 2014-10-23 15:38:55

Re: [SOLVED] Kernel 3.17: Timeout on hotplug command 0x00000000

#3 2014-10-23 16:09:17

Re: [SOLVED] Kernel 3.17: Timeout on hotplug command 0x00000000

#4 2014-10-24 17:32:17

Re: [SOLVED] Kernel 3.17: Timeout on hotplug command 0x00000000

#5 2014-12-10 21:28:24

Re: [SOLVED] Kernel 3.17: Timeout on hotplug command 0x00000000

#6 2014-12-10 22:03:18

Re: [SOLVED] Kernel 3.17: Timeout on hotplug command 0x00000000

#7 2014-12-17 16:17:22

Re: [SOLVED] Kernel 3.17: Timeout on hotplug command 0x00000000

#8 2014-12-17 16:24:59

Re: [SOLVED] Kernel 3.17: Timeout on hotplug command 0x00000000

#9 2014-12-17 19:17:22

Re: [SOLVED] Kernel 3.17: Timeout on hotplug command 0x00000000

#10 2014-12-17 21:03:21

Re: [SOLVED] Kernel 3.17: Timeout on hotplug command 0x00000000

#11 2014-12-18 00:57:07

Re: [SOLVED] Kernel 3.17: Timeout on hotplug command 0x00000000

#12 2014-12-18 01:02:35

Re: [SOLVED] Kernel 3.17: Timeout on hotplug command 0x00000000

#13 2014-12-18 02:27:05

Re: [SOLVED] Kernel 3.17: Timeout on hotplug command 0x00000000

#14 2014-12-18 10:35:36

Re: [SOLVED] Kernel 3.17: Timeout on hotplug command 0x00000000

#15 2014-12-18 21:46:22

Re: [SOLVED] Kernel 3.17: Timeout on hotplug command 0x00000000

#16 2014-12-18 22:09:19

Re: [SOLVED] Kernel 3.17: Timeout on hotplug command 0x00000000

#17 2014-12-18 22:36:47

Re: [SOLVED] Kernel 3.17: Timeout on hotplug command 0x00000000

#18 2014-12-19 00:42:59

Re: [SOLVED] Kernel 3.17: Timeout on hotplug command 0x00000000

#19 2014-12-19 00:44:40

Re: [SOLVED] Kernel 3.17: Timeout on hotplug command 0x00000000

#20 2014-12-19 01:00:21

Re: [SOLVED] Kernel 3.17: Timeout on hotplug command 0x00000000

#21 2014-12-25 13:59:34

Re: [SOLVED] Kernel 3.17: Timeout on hotplug command 0x00000000

#22 2014-12-25 14:05:37

Re: [SOLVED] Kernel 3.17: Timeout on hotplug command 0x00000000

Board footer