Page 1 of 1
Boot "hanging" a couple of times
Posted: Mon Nov 20, 2017 5:05 pm
by 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!
Re: Boot "hanging" a couple of times
Posted: Mon Nov 20, 2017 10:40 pm
by 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.
Re: Boot "hanging" a couple of times
Posted: Tue Nov 21, 2017 5:02 am
by LnX
Mute Ant wrote:"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.
Re: Boot "hanging" a couple of times
Posted: Tue Nov 21, 2017 5:49 am
by rene
LnX wrote: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.
Re: Boot "hanging" a couple of times
Posted: Tue Nov 21, 2017 7:15 am
by LnX
rene wrote:LnX wrote: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.
Re: Boot "hanging" a couple of times
Posted: Tue Nov 21, 2017 9:07 am
by rene
LnX wrote: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/.
Re: Boot "hanging" a couple of times
Posted: Wed Nov 22, 2017 6:53 am
by LnX
rene wrote:LnX wrote: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