[Solved] Slow boot - 22 minutes!

[MintyFresh22]

Hi all,

Can anyone provide any assistance getting this down to sane levels?

Code: Select all

systemd-analyze
Startup finished in 22min 29.741s (kernel) + 8.691s (userspace) = 22min 38.432s
graphical.target reached after 8.683s in userspace

Code: Select all

systemd-analyze blame
          6.184s NetworkManager-wait-online.service
          1.030s systemd-cryptsetup@cryptswap1.service
           976ms dev-md0.device
           883ms keyboard-setup.service
           844ms apt-daily.service
           780ms apt-daily-upgrade.service
           634ms udisks2.service
           593ms systemd-resolved.service
           537ms systemd-journal-flush.service
           499ms systemd-timesyncd.service
           397ms NetworkManager.service
           345ms systemd-logind.service
           260ms networkd-dispatcher.service
           232ms upower.service
           227ms ubuntu-system-adjustments.service
           204ms virtualbox.service
           204ms systemd-journald.service
           179ms ModemManager.service
           149ms grub-common.service
           146ms lvm2-monitor.service
           141ms accounts-daemon.service
           140ms systemd-modules-load.service
           129ms systemd-tmpfiles-setup.service
           125ms apparmor.service
           120ms systemd-udev-trigger.service
           110ms thermald.service
           100ms packagekit.service
            99ms gpu-manager.service
            82ms alsa-restore.service
            71ms networking.service
            70ms lightdm.service
            68ms rsyslog.service
            64ms user@1000.service
            63ms run-rpc_pipefs.mount
            59ms systemd-tmpfiles-setup-dev.service
            54ms lm-sensors.service
            54ms systemd-udevd.service
            53ms mdmon@md127.service
            51ms polkit.service
            51ms avahi-daemon.service
            49ms wpa_supplicant.service
            48ms mono-xsp4.service
            48ms apport.service
            48ms systemd-fsck@dev-disk-by\x2duuid-9545835a\x2d3325\x2d4cb5\x2da949\x2da03564abb27a.service
            46ms dns-clean.service
            40ms systemd-remount-fs.service
            36ms hddtemp.service
            34ms pppd-dns.service
            34ms speech-dispatcher.service
            25ms colord.service
            22ms blk-availability.service
            21ms ufw.service
            20ms systemd-sysctl.service
            18ms plymouth-read-write.service
            18ms kerneloops.service
            17ms systemd-random-seed.service
            16ms ntp.service
            15ms rtkit-daemon.service
            14ms systemd-user-sessions.service
            14ms dev-hugepages.mount
            13ms nfs-config.service
            13ms sys-fs-fuse-connections.mount
            13ms kmod-static-nodes.service
            12ms rpcbind.service
             9ms sys-kernel-debug.mount
             9ms console-setup.service
             8ms systemd-tmpfiles-clean.service
             8ms systemd-update-utmp.service
             8ms boot.mount
             8ms dev-mqueue.mount
             7ms ureadahead-stop.service
             7ms dev-mapper-cryptswap1.swap
             6ms sys-kernel-config.mount
             5ms systemd-update-utmp-runlevel.service
             4ms nvidia-persistenced.service
             4ms swapfile.swap
             4ms openvpn.service
             3ms setvtrgb.service
             2ms plymouth-quit-wait.service
             2ms motd-news.service

Code: Select all

inxi -Fzx
System:    Host: JohnnyBravo Kernel: 4.15.0-72-generic x86_64 bits: 64 compiler: gcc v: 7.4.0 Desktop: MATE 1.20.1 
           Distro: Linux Mint 19.1 Tessa base: Ubuntu 18.04 bionic 
Machine:   Type: Desktop Mobo: Gigabyte model: EP45T-DS3R v: x.x serial: <filter> BIOS: Award v: F1 date: 06/11/2008 
CPU:       Topology: Quad Core model: Intel Core2 Quad Q9550 bits: 64 type: MCP arch: Penryn rev: 7 
           L2 cache: 6144 KiB 
           flags: lm nx pae sse sse2 sse3 sse4_1 ssse3 vmx bogomips: 22662 
           Speed: 2000 MHz min/max: 2000/2834 MHz Core speeds (MHz): 1: 2000 2: 2002 3: 2001 4: 2000 
Graphics:  Device-1: NVIDIA GP106 [GeForce GTX 1060 6GB] vendor: Gigabyte driver: nvidia v: 435.21 bus ID: 01:00.0 
           Display: x11 server: X.Org 1.19.6 driver: nvidia unloaded: fbdev,modesetting,nouveau,vesa 
           resolution: 3840x1600~60Hz 
           OpenGL: renderer: GeForce GTX 1060 6GB/PCIe/SSE2 v: 4.6.0 NVIDIA 435.21 direct render: Yes 
Audio:     Device-1: Intel 82801JI HD Audio vendor: Gigabyte GA-EP45-DS5/GA-EG45M-DS2H driver: snd_hda_intel 
           v: kernel bus ID: 00:1b.0 
           Device-2: NVIDIA GP106 High Definition Audio vendor: Gigabyte driver: snd_hda_intel v: kernel 
           bus ID: 01:00.1 
           Sound Server: ALSA v: k4.15.0-72-generic 
Network:   Device-1: Realtek RTL8111/8168/8411 PCI Express Gigabit Ethernet vendor: Gigabyte driver: r8169 
           v: 2.3LK-NAPI port: c000 bus ID: 05:00.0 
           IF: enp5s0 state: up speed: 1000 Mbps duplex: full mac: <filter> 
           Device-2: Realtek RTL8111/8168/8411 PCI Express Gigabit Ethernet vendor: Gigabyte driver: r8169 
           v: 2.3LK-NAPI port: d000 bus ID: 06:00.0 
           IF: enp6s0 state: down mac: <filter> 
Drives:    Local Storage: total: 1.82 TiB used: 216.36 GiB (11.6%) 
           ID-1: /dev/sda vendor: Seagate model: ST500LM000-1EJ162 size: 465.76 GiB 
           ID-2: /dev/sdb vendor: Seagate model: ST500LM000-1EJ162 size: 465.76 GiB 
           ID-3: /dev/sdg vendor: Western Digital model: WDS500G2B0A-00SM50 size: 465.76 GiB 
           ID-4: /dev/sdh vendor: Western Digital model: WDS500G2B0A-00SM50 size: 465.76 GiB 
RAID:      Hardware-1: Intel SATA Controller [RAID mode] driver: ahci v: 3.0 bus ID: 00:1f.2 
           Hardware-2: Adaptec Series 6 - 6G SAS/PCIe 2 driver: aacraid v: 1.2.1[50877]-custom bus ID: 02:00.0 
           Device-1: md126 type: mdraid status: active Components: online: sda~c1 sdb~c0 
           Info: raid: mirror blocks: 488383488 report: 2/2 UU chunk size: N/A 
           Device-2: md127 type: mdraid status: inactive Components: online: N/A spare: sdb~c0 
           Info: raid: sda[1](S) blocks: 6192 report: N/A chunk size: N/A 
           Device-3: md0 type: mdraid status: active Components: online: sdg2~c0 sdh2~c1 
           Info: raid: mirror blocks: 486157312 report: 2/2 UU chunk size: N/A 
Partition: ID-1: / size: 455.36 GiB used: 14.98 GiB (3.3%) fs: ext4 dev: /dev/md0 
           ID-2: /boot size: 1.91 GiB used: 283.6 MiB (14.5%) fs: ext4 dev: /dev/sdg1 
           ID-3: swap-1 size: 2.00 GiB used: 0 KiB (0.0%) fs: swap dev: /dev/dm-0 
Sensors:   System Temperatures: cpu: 55.0 C mobo: N/A gpu: nvidia temp: 39 C 
           Fan Speeds (RPM): N/A gpu: nvidia fan: 0% 
Info:      Processes: 250 Uptime: 2d 13h 15m Memory: 15.66 GiB used: 2.47 GiB (15.7%) Init: systemd runlevel: 5 
           Compilers: gcc: 7.4.0 Shell: bash v: 4.4.20 inxi: 3.0.27

The biggest delay seems to be the kernel waiting for a floppy drive which does not exist. Extract from kern.log below (he whole log puts me way over the 60000 char limit)

Code: Select all

Jan 15 21:25:40 JohnnyBravo kernel: [   61.656339] print_req_error: I/O error, dev fd0, sector 0
Jan 15 21:25:40 JohnnyBravo kernel: [   61.656383] floppy: error 10 while reading block 0
<snip>
Jan 15 21:25:40 JohnnyBravo kernel: [ 1349.368383] print_req_error: I/O error, dev fd0, sector 0
Jan 15 21:25:40 JohnnyBravo kernel: [ 1349.368424] floppy: error 10 while reading block 0
Jan 15 21:25:40 JohnnyBravo kernel: [ 1349.552495] EXT4-fs (md0): mounted filesystem with ordered data mode. Opts: (null)

After md0 is mounted the boot completes quickly. So I tried blacklisting floppy in the kernel with:

Code: Select all

$ echo "blacklist floppy" | sudo tee /etc/modprobe.d/blacklist-floppy.conf
$ sudo rmmod floppy
$ sudo update-initramfs -u

The blacklist file exists and the floppy is removed by the rmmod command but boot is unchanged and the floppy is back after login.
Does update-initramfs -u put the blacklist onto the boot volume (sdg1)? If so how do I check what the kernel is reading? /etc/modprobe.d is on md0 so not available until after the delay.

Cheers
'22

[Moonstone Man]

Code: Select all

date: 06/11/2008

The best course of action is to organise a funeral.

[JerryF]

Code: Select all

date: 06/11/2008

The best course of action is to organise a funeral.

This is the second post I've seen from you that hasn't been helpful.

So, I got a new (second-hand) laptop...

I made various attempts using both operating systems, all failed...

Any solutions for my problem?

Give it back.

[Moonstone Man]

This is the second post I've seen from you that hasn't been helpful.

It's very old hardware. There's not much more that can be said. In the other thread, the poster states that the problem also occurs on Windows. So again...

[rene]

The biggest delay seems to be the kernel waiting for a floppy drive which does not exist.

Although I'm unsure of why your own blacklisting wouldn't have worked (it should have; the update-initramfs should've put the rule in the initramfs, i.e., no need for /etc/modprobe.d/ itself at boot time) one being detected at all supposedly means you have it configured in the BIOS. What happens if you disable (change the type to "None") there?

[MintyFresh22]

Thanks rene,

I've figured out why the blacklist didn't work - sort of!
I have two SSDs in a RAID1 but mdraid doesn't work at boot. To get round that the first 2Gb of each disk is my boot partition. They are not in any way RAID, they are normal bootable partitions and they are supposed to be identical and interchangeable. One is used, the other is just standby in case the in-use disk fails. Key word - supposed. sdd1 is monunted as /boot and contains

Code: Select all

drwxr-xr-x  4 root root     4096 Jan 19 11:39 .
drwxr-xr-x 25 root root     4096 Jan 19 11:57 ..
-rw-r--r--  1 root root  1536934 Apr 24  2018 abi-4.15.0-20-generic
-rw-r--r--  1 root root   216807 Apr 24  2018 config-4.15.0-20-generic
-rw-r--r--  1 root root   217278 Jul  2  2019 config-4.15.0-55-generic
-rw-r--r--  1 root root   217495 Dec 18 22:20 config-4.15.0-74-generic
drwxr-xr-x  5 root root     4096 Jan  6 19:28 grub
-rw-r--r--  1 root root 60908166 Aug  9 11:22 initrd.img-4.15.0-20-generic
-rw-r--r--  1 root root 61069988 Aug  9 11:23 initrd.img-4.15.0-51-generic
-rw-r--r--  1 root root 61074477 Aug  9 11:25 initrd.img-4.15.0-55-generic
-rw-r--r--  1 root root 60761542 Jan 19 11:39 initrd.img-4.15.0-74-generic
drwx------  2 root root    16384 Jun  7  2019 lost+found
-rw-r--r--  1 root root   182704 Jan 28  2016 memtest86+.bin
-rw-r--r--  1 root root   184380 Jan 28  2016 memtest86+.elf
-rw-r--r--  1 root root   184840 Jan 28  2016 memtest86+_multiboot.bin
-rw-r--r--  1 root root        0 Apr 24  2018 retpoline-4.15.0-20-generic
-rw-------  1 root root  4038188 Apr 24  2018 System.map-4.15.0-20-generic
-rw-------  1 root root  4051807 Jul  2  2019 System.map-4.15.0-55-generic
-rw-------  1 root root  4068355 Dec 18 22:20 System.map-4.15.0-74-generic
-rw-r--r--  1 root root  8249080 Dec 17  2018 vmlinuz-4.15.0-20-generic
-rw-------  1 root root  8294136 Jul  2  2019 vmlinuz-4.15.0-55-generic
-rw-------  1 root root  8367768 Dec 18 22:46 vmlinuz-4.15.0-74-generic

using lsinitramfs I verified that blacklist-floppy.conf has been put into initrd.img-4.15.0-74-generic. However I noticed that in my inxi -Fzx in my OP my kernel is 4.15.0-72-generic. Smelling a rat I mounted sdc1 as /bootmirror and that contains:

Code: Select all

drwxr-xr-x  4 root root     4096 Jan 19 10:36 .
drwxr-xr-x 25 root root     4096 Jan 19 11:57 ..
-rw-r--r--  1 root root  1536934 Apr 24  2018 abi-4.15.0-20-generic
-rw-r--r--  1 root root   216807 Apr 24  2018 config-4.15.0-20-generic
-rw-r--r--  1 root root   217460 Nov 26 11:18 config-4.15.0-72-generic
drwxr-xr-x  6 root root     4096 Jan 19 10:36 grub
-rw-r--r--  1 root root 61456947 Jan  4 14:59 initrd.img-4.15.0-20-generic
-rw-r--r--  1 root root 60745932 Jan  4 15:14 initrd.img-4.15.0-72-generic
-rw-r--r--  1 root root 60759986 Jan 13 11:15 initrd.img-4.15.0-74-generic
drwx------  2 root root    16384 Jun  7  2019 lost+found
-rw-r--r--  1 root root   182704 Jan 28  2016 memtest86+.bin
-rw-r--r--  1 root root   184380 Jan 28  2016 memtest86+.elf
-rw-r--r--  1 root root   184840 Jan 28  2016 memtest86+_multiboot.bin
-rw-r--r--  1 root root        0 Apr 24  2018 retpoline-4.15.0-20-generic
-rw-------  1 root root  4038188 Apr 24  2018 System.map-4.15.0-20-generic
-rw-------  1 root root  4066550 Nov 26 11:18 System.map-4.15.0-72-generic
-rw-r--r--  1 root root  8249080 Dec 17  2018 vmlinuz-4.15.0-20-generic
-rw-------  1 root root  8367768 Nov 26 11:28 vmlinuz-4.15.0-72-generic

Somehow I've ended up with sdc1 booted but sdd1 mounted as /boot. This initrd.img-4.15.0-74-generic also contains blacklist-floppy.conf, initrd.img-4.15.0-72-generic does not.
I can partially explain how the mess has come about. I've been playing about with my drives recently trying to connect them to a RAID card. It is perfectly feasible that I either swapped the disks between SATA ports or when attempting a boot with one drive on the RAID card the bios switched boot priority. kernel 74 was installed on Jan 06 which is before I got the RAID card.
I can also explain why the old versions differ. I run purge-old-kernels whenever there is a kernel update, that only sees the mounted /boot.

I cannot explain why I have a initrd.img-4.15.0-74-generic on both disks, I've only used initramfs-update since I gave up on the RAID card.

Most importantly - I'm note sure what to do to get everything back in sync Worryingly initrd.img and vmlinuz in / point to 72 versions which do not exist in the mounted /boot.

Time to go out for a walk and a long think.

'22

[rene]

Somehow I've ended up with sdc1 booted but sdd1 mounted as /boot.

Well, certainly that part should be easy to fix it seems; sudo umount /boot, change the device for /boot in /etc/fstab to /dev/sdc1 or whatever UUID or Label you identify the filesystem it contains with, sudo mount /boot; sudo update-grub.

In any case though, while all that may be semi-fascinating, with the legacy floppy a decidedly non-PnP device it is generally/historically still the case that the module load would not trigger if the BIOS did not advertise presence of a floppy drive; if it had it configured to "None". I.e., as to the specific/original issue it seems you still want to do that.

[MintyFresh22]

Hi again rene,

I looked at changing the partition mounted as /boot as you suggested but both partitions have the same uuid:

Code: Select all

/dev/sdc1: UUID="9545835a-3325-4cb5-a949-a03564abb27a" TYPE="ext4" PARTUUID="48303152-01"
/dev/sdc2: UUID="72486d35-f7f9-b8d2-ae7f-e6b1369059de" UUID_SUB="be4061b1-eaca-6858-5e02-105a35a9a6f1" LABEL="mint:0" TYPE="linux_raid_member" PARTUUID="48303152-02"
/dev/sdd1: UUID="9545835a-3325-4cb5-a949-a03564abb27a" TYPE="ext4" PARTUUID="48303152-01"
/dev/sdd2: UUID="72486d35-f7f9-b8d2-ae7f-e6b1369059de" UUID_SUB="0997627b-918a-8305-3b78-9102d007cc3b" LABEL="mint:0" TYPE="linux_raid_member" PARTUUID="48303152-02"

So instead I tried two things and both worked. Booting the 72 kernel with the floppy disabled in the bios (also as suggested by you) gave this:

Code: Select all

startup finished in 44.315s (kernel) + 9.193s (userspace) = 53.509s
graphical.target reached after 9.185s in userspace

Alternatively switching the bios boot priority to the partition containing the 74 kernel with floppy blacklisted gives this:

Code: Select all

Startup finished in 42.885s (kernel) + 9.686s (userspace) = 52.571s
graphical.target reached after 8.563s in userspace

For completeness I enabled the floppy just to check the blacklisting had worked, it did:

Code: Select all

Startup finished in 42.707s (kernel) + 8.495s (userspace) = 51.202s
graphical.target reached after 8.487s in userspace

That gave an apparent difference of 1.5s between the kernel versions. However, the 72 kernel was showing all boot messages whereas 74 was showing the mint logo, could that be making a difference? All I needed to do was run update-grub to get 74 showing boot messages and reboot:

Code: Select all

Startup finished in 44.236s (kernel) + 9.309s (userspace) = 53.546s
graphical.target reached after 9.300s in userspace

So yes, showing boot progress costs 1.5 seconds. Can't say I'm worried about that!

Thank you for your help with this rene.

Oh and Kadaitcha Man, do you think replacing my motherboard, CPU and RAM would have resulted in a 97% reduction in boot time? Finding and fixing the configuration error did

[rene]

Good that things are working, but:

I looked at changing the partition mounted as /boot as you suggested but both partitions have the same uuid:

... that should not be. You appearently cloned /dev/sdc1 to /dev/sdd1 at some point but this shouldn't be. You can give the filesystem on /dev/sdd1 a new UUID with

Code: Select all

$ sudo tune2fs -U random /dev/sdd1

There'd then no longer be confusion as to which one gets mounted. Of course, arrange for the "right" one to be said one, but, well, yes, that's the point; this confusion shouldn't have existed