Boot "hanging" a couple of times

[LnX]

Hi!

I have a little issue with my boot. I found it a bit slower than my previous Arch install so I checked with dmesg. I found two larger time jumps:

Code: Select all

[    6.400146] systemd[1]: Created slice System Slice.
[    6.400161] systemd[1]: Reached target Encrypted Volumes.
[    7.653624] lp: driver loaded but no devices found
[    7.759281] ppdev: user-space parallel port driver
[   17.526337] EXT4-fs (sda2): re-mounted. Opts: errors=remount-ro
[   17.555907] systemd-journald[418]: Received request to flush runtime journal from PID 1
[   17.625513] wmi: Mapper loaded

Code: Select all

[   25.609337] wlp5s0: authenticate with a4:2b:8c:a3:82:14
[   25.612203] wlp5s0: send auth to a4:2b:8c:a3:82:14 (try 1/3)
[   25.614323] wlp5s0: authenticated
[   25.615592] wlp5s0: associate with a4:2b:8c:a3:82:14 (try 1/3)
[   25.619695] wlp5s0: RX AssocResp from a4:2b:8c:a3:82:14 (capab=0x1411 status=0 aid=3)
[   25.623551] wlp5s0: associated
[   25.623589] IPv6: ADDRCONF(NETDEV_CHANGE): wlp5s0: link becomes ready
[   62.417066] Bluetooth: BNEP (Ethernet Emulation) ver 1.3
[   62.417067] Bluetooth: BNEP filters: protocol multicast
[   62.417071] Bluetooth: BNEP socket layer initialized

With the first one, I got no idea what is going on. My filesystem is being remounted?
The second one seems to be the Bluetooth hogging time. Haven't managed to find any info on how to disable this. Don't really use bluetooth on my laptop, so can manually activate it when I need it.

Any tips will be appriciated!

[Mute Ant]

"With the first one, I got no idea what is going on. My filesystem is being remounted?" It looks like Linux found something that needed read-only access to the OS file system, which it fixed, then remounted it read-write. Ten seconds is about right for a fsck when there's nothing seriously wrong, just a not-marked-as-empty journal after the last shutdown is my guess.

[LnX]

"With the first one, I got no idea what is going on. My filesystem is being remounted?" It looks like Linux found something that needed read-only access to the OS file system, which it fixed, then remounted it read-write. Ten seconds is about right for a fsck when there's nothing seriously wrong, just a not-marked-as-empty journal after the last shutdown is my guess.

It happens one very boot though. Even after normal shutdown.

[rene]

It happens [on every] boot though. Even after normal shutdown.

It is is normal; the root fs is being remounted from its initial mount so as to apply whichever options you've set for it in your /etc/fstab. I.e.,

Code: Select all

$ dmesg | grep EXT4-fs
[    3.120609] EXT4-fs (sda2): mounted filesystem with ordered data mode. Opts: (null)
[    3.455465] EXT4-fs (sda2): re-mounted. Opts: errors=remount-ro

Those times are from a Core 2 Duo 3GHz with a 64G SSD. I don't myself have a pause after either; can't verify behaviour on HDD at the moment.

[LnX]

It happens [on every] boot though. Even after normal shutdown.

It is is normal; the root fs is being remounted from its initial mount so as to apply whichever options you've set for it in your /etc/fstab. I.e.,

Code: Select all

$ dmesg | grep EXT4-fs
[    3.120609] EXT4-fs (sda2): mounted filesystem with ordered data mode. Opts: (null)
[    3.455465] EXT4-fs (sda2): re-mounted. Opts: errors=remount-ro

Those times are from a Core 2 Duo 3GHz with a 64G SSD. I don't myself have a pause after either; can't verify behaviour on HDD at the moment.

Code: Select all

[    7.653624] lp: driver loaded but no devices found
[    7.759281] ppdev: user-space parallel port driver
[   17.526337] EXT4-fs (sda2): re-mounted. Opts: errors=remount-ro
[   17.555907] systemd-journald[418]: Received request to flush runtime journal from PID 1

My gap is actually before, so is it the driver being loaded that hangs? I.e is the log written at begining of action or after action?
I have a quad core i7 (i7-4702MQ @ 2.2GHz) and 8GB ram, but regular HDD. This is why I am concerned about my almost 1 minute long boot time.

[rene]

My gap is actually before, so is it the driver being loaded that hangs? I.e is the log written at begining of action or after action?

It says re-mountED so in this case and in theory, after. Not sure you should place complete faith in the remount being fully synchronous anyway though (i.e., necessary completed before the message appears in the kernel message buffer).

I expected the HDD to be enough explanation but must say I just booted up an old P4 which is still using an HDD and only find a 4 second pause shortly after the root remount (it's running Debian 9). So, frankly, "dunno". It won't be the ppdev driver if that's the driver you were referring to. Your later pause I expect to related to IPv6 rather than Bluetooth. Is this Mint 18.x? If so, systemd-analyze blame could be semi-useful for the userspace part at least.

"Semi" since I do wonder a bit why you're concerned. 1 minute is faster than what I used to have on my (first gen) Core i7 2.8GHz, 8GiB when it was still running on HDD; a spiffy WD Black one, even. It seems you have little to be concerned about, certainly after disabling IPv6 if you don't use it. In your router would be most effective, alternatively supposedly see "the right fix" subheader at https://www.techrepublic.com/article/ho ... -machines/.

[LnX]

My gap is actually before, so is it the driver being loaded that hangs? I.e is the log written at begining of action or after action?

It says re-mountED so in this case and in theory, after. Not sure you should place complete faith in the remount being fully synchronous anyway though (i.e., necessary completed before the message appears in the kernel message buffer).

I expected the HDD to be enough explanation but must say I just booted up an old P4 which is still using an HDD and only find a 4 second pause shortly after the root remount (it's running Debian 9). So, frankly, "dunno". It won't be the ppdev driver if that's the driver you were referring to. Your later pause I expect to related to IPv6 rather than Bluetooth. Is this Mint 18.x? If so, systemd-analyze blame could be semi-useful for the userspace part at least.

"Semi" since I do wonder a bit why you're concerned. 1 minute is faster than what I used to have on my (first gen) Core i7 2.8GHz, 8GiB when it was still running on HDD; a spiffy WD Black one, even. It seems you have little to be concerned about, certainly after disabling IPv6 if you don't use it. In your router would be most effective, alternatively supposedly see "the right fix" subheader at https://www.techrepublic.com/article/ho ... -machines/.

Turned off IPv6 according to you link, but it is still active it seems. I am on a school network most of the time with the laptop, so I can't really turn off IPv6 on the router.

Code: Select all

[lnx@Archer ~]$ dmesg | grep IPv6
[    2.451153] Segment Routing with IPv6
[   25.340270] IPv6: ADDRCONF(NETDEV_UP): wlp5s0: link is not ready
[   25.556043] IPv6: ADDRCONF(NETDEV_UP): wlp5s0: link is not ready
[   25.559515] IPv6: ADDRCONF(NETDEV_UP): enp4s0: link is not ready
[   25.783261] IPv6: ADDRCONF(NETDEV_UP): enp4s0: link is not ready
[   26.697627] IPv6: ADDRCONF(NETDEV_UP): wlp5s0: link is not ready
[   27.681097] IPv6: ADDRCONF(NETDEV_CHANGE): wlp5s0: link becomes ready

Here is the output of systemd-analyze blame:

Code: Select all

[lnx@Archer ~]$ systemd-analyze blame
         12.838s dev-sda2.device
         10.933s lvm2-monitor.service
         10.889s keyboard-setup.service
          9.391s systemd-udevd.service
          8.992s ntp.service
          7.259s NetworkManager-wait-online.service
          4.603s preload.service
          2.564s grub-common.service
          1.465s virtualbox-guest-utils.service
          1.460s ModemManager.service
          1.391s sys-kernel-debug.mount
          1.390s dev-hugepages.mount
          1.308s NetworkManager.service
          1.186s accounts-daemon.service
           994ms systemd-tmpfiles-setup-dev.service
           915ms dev-mqueue.mount
           805ms irqbalance.service
           789ms systemd-rfkill.service
           773ms wpa_supplicant.service
           753ms systemd-modules-load.service
           704ms dev-disk-by\x2duuid-88dc32dc\x2d2177\x2d4944\x2d9a36\x2d64fa3d18eba9.swap
           680ms polkitd.service
           549ms systemd-journald.service
           503ms systemd-logind.service
           501ms loadcpufreq.service
           477ms ufw.service
           453ms apparmor.service
           448ms ondemand.service
           442ms lm-sensors.service
           441ms console-kit-log-system-start.service
           439ms alsa-restore.service
           437ms iio-sensor-proxy.service
           434ms pppd-dns.service
           433ms systemd-user-sessions.service
           433ms rsyslog.service
           429ms gpu-manager.service
           406ms avahi-daemon.service
           404ms thermald.service
           379ms networking.service
           366ms console-setup.service
           256ms kmod-static-nodes.service
           246ms systemd-update-utmp.service
           234ms lightdm.service
           223ms colord.service
           206ms systemd-fsck@dev-disk-by\x2duuid-4709\x2d09DD.service
           187ms binfmt-support.service
           185ms nvidia-persistenced.service
           161ms sys-fs-fuse-connections.mount
           153ms udisks2.service
           142ms systemd-random-seed.service
           125ms systemd-sysctl.service
           104ms rc-local.service
           100ms systemd-tmpfiles-setup.service
            92ms systemd-remount-fs.service
            76ms plymouth-read-write.service
            76ms upower.service
            74ms hddtemp.service
            63ms speech-dispatcher.service
            49ms systemd-udev-trigger.service
            49ms setvtrgb.service
            41ms boot-efi.mount
            14ms user@1000.service
            13ms plymouth-start.service
             8ms ureadahead-stop.service
             6ms cpufrequtils.service
             4ms dns-clean.service
             3ms proc-sys-fs-binfmt_misc.mount
             3ms resolvconf.service
             3ms rtkit-daemon.service
             2ms systemd-journal-flush.service
             2ms systemd-update-utmp-runlevel.service
             1ms systemd-backlight@backlight:intel_backlight.service
             1ms plymouth-quit-wait.service
           849us openvpn.service

The critical chain seems to indicate that networking takes a lot of time. Do I really need it during boot? How would I set it up to start after boot?

Code: Select all

[lnx@Archer ~]$ 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 @34.674s
└─multi-user.target @34.674s
  └─ntp.service @25.681s +8.992s
    └─network-online.target @25.681s
      └─NetworkManager-wait-online.service @18.421s +7.259s
        └─NetworkManager.service @17.112s +1.308s
          └─dbus.service @16.707s
            └─basic.target @16.697s
              └─paths.target @16.697s
                └─cups.path @16.697s
                  └─sysinit.target @16.693s
                    └─apparmor.service @16.239s +453ms
                      └─local-fs.target @16.237s
                        └─run-user-1000-gvfs.mount @32.618s
                          └─run-user-1000.mount @31.808s
                            └─local-fs-pre.target @13.955s
                              └─lvm2-monitor.service @3.021s +10.933s
                                └─lvm2-lvmetad.service @4.201s
                                  └─systemd-journald.socket @2.543s
                                    └─-.mount @2.496s
                                      └─system.slice @2.543s
                                        └─-.slice @2.496s