SOLVED: Boot time increased to 1800s(!)

Markismus · 2018-01-14 11:12:49

The last three days I have seen my boot times increase drastically. In the boot messages I saw a sudden jump of 300s and tried to fix it. To no avail. Today the system booted in 1800s (I was drinking coffee, otherwise, I wouldn't have noticed it: I thought it had crashed...)

What can I do to analyze and solve this, apart from reinstalling arch?

There are three time 'jumps' in the dmesg output:

[    0.941557] ohci-pci 0000:00:12.1: irq 16, io mem 0xfe02d000
[    0.963829] firewire_ohci 0000:04:0e.0: added OHCI v1.10 device as card 1, 4 IR + 8 IT contexts, quirks 0x2
[  600.963958] hub 4-0:1.0: USB hub found
[ 600.963965] hub 4-0:1.0: 3 ports detected
[  600.964276] ohci-pci 0000:00:13.0: OHCI PCI host controller
[  600.964281] ohci-pci 0000:00:13.0: new USB bus registered, assigned bus number 5
[  600.964312] ohci-pci 0000:00:13.0: irq 18, io mem 0xfe02b000
[  900.988409] ata3.00: HPA detected: current 625134191, native 625142448
[ 900.988411] ata3.00: ATA-6: WDC WD3200JB-00KFA0, 08.05J08, max UDMA/100
...
...
[  901.180194]  sda: sda1 sda2
[  901.186613] usb-storage 2-2:1.0: USB Mass Storage device detected
[  901.186787] scsi host12: usb-storage 2-2:1.0
[  901.186849] usbcore: registered new interface driver usb-storage
[  901.187225] usbcore: registered new interface driver uas
[  901.196223] sd 2:0:0:0: [sda] Attached SCSI disk
[ 1801.241364] ata7: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
[ 1801.244693] ata5: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
[ 1801.244722] ata9: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
[ 1801.244746] ata12: SATA link up 1.5 Gbps (SStatus 113 SControl 300)

At the same time the systemd-analyse commands only claim to take seconds to start up.

$ systemd-analyze
Startup finished in 4.205s (kernel) + 19.319s (userspace) = 23.524s
$ systemd-analyze critical-chain
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 @14.879s
└─multi-user.target @14.877s
  └─smbd.service @14.746s +131ms
    └─nmbd.service @14.516s +227ms
      └─network.target @14.505s
        └─dhcpcd@enp3s0.service @2.457s +12.047s
          └─basic.target @2.369s
            └─tmp.mount @2.357s +11ms
              └─mnt-Striped.mount @2.147s +207ms
                └─local-fs-pre.target @2.145s
                  └─lvm2-monitor.service @470ms +1.674s
                    └─lvm2-lvmetad.service @503ms
                      └─systemd-journald.socket @462ms
                        └─system.slice @455ms
                          └─-.slice @406ms

The 900s time jump corresponds to these lines generated with the command `journalctl -xb`(full journalctl log):

jan 14 10:30:42 debiel kernel: usb 1-5: new high-speed USB device number 3 using ehci-pci
jan 14 10:30:42 debiel kernel: scsi 12:0:0:0: Direct-Access     USB Mass  Storage Device  1.00 PQ: 0 ANSI: 0
jan 14 10:30:42 debiel kernel: sd 12:0:0:0: [sdh] 7761920 512-byte logical blocks: (3.97 GB/3.70 GiB)
jan 14 10:30:42 debiel kernel: sd 12:0:0:0: [sdh] Write Protect is off
jan 14 10:30:42 debiel kernel: sd 12:0:0:0: [sdh] Mode Sense: 03 00 00 00
jan 14 10:30:42 debiel kernel: sd 12:0:0:0: [sdh] No Caching mode page found
jan 14 10:30:42 debiel kernel: sd 12:0:0:0: [sdh] Assuming drive cache: write through
jan 14 10:30:42 debiel kernel:  sdh: sdh1
jan 14 10:30:42 debiel kernel: sd 12:0:0:0: [sdh] Attached SCSI removable disk
jan 14 10:30:42 debiel kernel: ata7: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
jan 14 10:30:42 debiel kernel: ata7.00: n_sectors mismatch 3907020911 != 3907029168
jan 14 10:30:42 debiel kernel: ata7.00: new n_sectors matches native, probably late HPA unlock, n_sectors updated
jan 14 10:30:42 debiel kernel: ata7.00: configured for UDMA/133
jan 14 10:30:42 debiel kernel: ata7: EH complete

The two 300s jumps correspond to these lines:

jan 14 10:30:42 debiel kernel: ohci-pci 0000:00:12.1: OHCI PCI host controller
jan 14 10:30:42 debiel kernel: ohci-pci 0000:00:12.1: new USB bus registered, assigned bus number 4
jan 14 10:30:42 debiel kernel: ohci-pci 0000:00:12.1: irq 16, io mem 0xfe02d000
jan 14 10:30:42 debiel kernel: firewire_ohci 0000:04:0e.0: added OHCI v1.10 device as card 1, 4 IR + 8 IT contexts, quirks 0x2
jan 14 10:30:42 debiel kernel: hub 4-0:1.0: USB hub found
jan 14 10:30:42 debiel kernel: hub 4-0:1.0: 3 ports detected
jan 14 10:30:42 debiel kernel: ohci-pci 0000:00:13.0: OHCI PCI host controller
jan 14 10:30:42 debiel kernel: ohci-pci 0000:00:13.0: new USB bus registered, assigned bus number 5
jan 14 10:30:42 debiel kernel: ohci-pci 0000:00:13.0: irq 18, io mem 0xfe02b000
jan 14 10:30:42 debiel kernel: ata3.00: HPA detected: current 625134191, native 625142448
jan 14 10:30:42 debiel kernel: ata3.00: ATA-6: WDC WD3200JB-00KFA0, 08.05J08, max UDMA/100
jan 14 10:30:42 debiel kernel: ata3.00: 625134191 sectors, multi 16: LBA48 
jan 14 10:30:42 debiel kernel: ata3.01: ATAPI: HL-DT-ST DVD+/-RW GWA4164B, E111, max UDMA/33
jan 14 10:30:42 debiel kernel: ata3.00: configured for UDMA/100
jan 14 10:30:42 debiel kernel: ata3.01: configured for UDMA/33
jan 14 10:30:42 debiel kernel: hub 5-0:1.0: USB hub found
jan 14 10:30:42 debiel kernel: hub 5-0:1.0: 3 ports detected

Last edited by Markismus (2018-01-14 15:29:58)

Trilby · 2018-01-14 12:30:38

Well the obvious starting point: what's the usb device that ends up recognized as sdh? Do you have the same problem booting without it plugged in?

Markismus · 2018-01-14 12:35:51

Thanks for the reply Trilby! It's a 4GB corrupted mSDcard, fom which I had to rescue foto's. That would explain the change from 300s to 1800s! I'll reboot!

Last edited by Markismus (2018-01-14 13:56:16)

Markismus · 2018-01-14 13:11:41

It didn't do the trick. I removed the kernel parameter spl.spl_hostid=0x78303078, which didn't do anything special.

However, adding the kernel parameter "acpi=off" did do the trick!

Why would this start to cause problems now? Hardware has not been recently changed. Have there been kernel changes that would cause this? However, an older kernel 3.xxx that I booted with grub, ran into the same stalled boot. Is my motherboard dying?

What are the consequences of disabling acpi in the kernel? Should I worry about suspending? Can I work around it? Ubuntu users are advised to just do it.

Is this only the start of the debugging Reading here they seem to suggest, that I could further narrow down the issue. Is this prudent?

(Nice list of ACPI kernel parameters)

Last edited by Markismus (2018-01-14 13:56:34)

Markismus · 2018-01-14 15:29:34

Yep. Auto-suspend now freezes the PC.

seth · 2018-01-14 15:34:40

Just to be sure: the first delay occurs when dealing with some USB hub which might be an external cardreader (holding the corrupted SD card) and seems attached via firewire - removing card (and reader?) didn't impact boot times at all??

Markismus · 2018-01-14 15:44:06

@seth In journalctl I get identical times for all the lines during boot. So I can't assess whether there were large time differences between consecutive lines.

Booting took longer than 6 minutes, so I tried changing the kernel parameters. Worked for booting, not so much for suspending.
The card reader is connected to the motherboard via an USB-header. No firewire involved anywhere. I just ejected the mSD-card, left the cardreader in place.

seth · 2018-01-14 15:49:40

No ACPI will break interaction with the BIOS what means suspending, hibernating and likely even rebooting will fail just as much as (typically) power saving, fan and backlight control.
There is definitively firewire in action

[    0.906722] firewire_ohci 0000:04:07.2: added OHCI v1.10 device as card 0, 4 IR + 8 IT contexts, quirks 0x2
[    0.941292] hub 3-0:1.0: USB hub found
[    0.941299] hub 3-0:1.0: 3 ports detected
[    0.941535] ohci-pci 0000:00:12.1: OHCI PCI host controller
[    0.941540] ohci-pci 0000:00:12.1: new USB bus registered, assigned bus number 4
[    0.941557] ohci-pci 0000:00:12.1: irq 16, io mem 0xfe02d000
[    0.963829] firewire_ohci 0000:04:0e.0: added OHCI v1.10 device as card 1, 4 IR + 8 IT contexts, quirks 0x2
[  600.963958] hub 4-0:1.0: USB hub found
[  600.963965] hub 4-0:1.0: 3 ports detected

Try to blacklist firewire_ohci, ensure it's not loaded and watch the impact.

Markismus · 2018-01-14 16:38:22

Blacklisting and turning firewire off in CMOS didn't work.

However, reloading optimized settings in the CMOS (and changing bootorder and setting drives to AHCI and turning firewire off), did! Suspend works again.

The only thing I see that has changed in CMOS was Clock settings to auto instead of off.

Last edited by Markismus (2018-01-14 16:39:37)

Markismus · 2018-01-16 09:35:14

@seth and @Trilby After 2 days the PC is still running without a hitch. Couldn't get it to work on my own. Thanks for helping me!

Arch Linux

#1 2018-01-14 11:12:49

SOLVED: Boot time increased to 1800s(!)

#2 2018-01-14 12:30:38

Re: SOLVED: Boot time increased to 1800s(!)

#3 2018-01-14 12:35:51

Re: SOLVED: Boot time increased to 1800s(!)

#4 2018-01-14 13:11:41

Re: SOLVED: Boot time increased to 1800s(!)

#5 2018-01-14 15:29:34

Re: SOLVED: Boot time increased to 1800s(!)

#6 2018-01-14 15:34:40

Re: SOLVED: Boot time increased to 1800s(!)

#7 2018-01-14 15:44:06

Re: SOLVED: Boot time increased to 1800s(!)

#8 2018-01-14 15:49:40

Re: SOLVED: Boot time increased to 1800s(!)

#9 2018-01-14 16:38:22

Re: SOLVED: Boot time increased to 1800s(!)

#10 2018-01-16 09:35:14

Re: SOLVED: Boot time increased to 1800s(!)

Board footer