How to make sure what is causing slow boot time on Lubuntu?
https://askubuntu.com/questions/816006/how-to-make-sure-what-is-causing-slow-boot-time-on-lubuntu
I'm not sure what counts slow or fast boot in the Linux world, but it seems like the Lubuntu machine that I have here (specs here), seems to be booting somewhat slow (around 50 seconds). My parents started complaining to me about slow boot and I thought I'll look into it.
The LXSession configuration wizard did not show anything that should slow the boot down. It showed the following services will start when computer is starting (computer is not in English, so I'm not sure if I'm translating correctly): power management, software updater, networking service, Screen Locker, user folder updates, AT-SPI D-Bus Bus.
Then I looked into dmesg, I suppose it's showing the boot time in the beginning of the line and saw some strange behaviours:
[ 21.827368] audit: type=1400 audit(1471992144.548:9): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/sbin/tcpdump" pid=1854 comm="apparmor_parser"
[ 21.944457] audit: type=1400 audit(1471992144.668:10): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/bin/evince" pid=1850 comm="apparmor_parser"
[ 21.944478] audit: type=1400 audit(1471992144.668:11): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/bin/evince//sanitized_helper" pid=1850 comm="apparmor_parser"
[ 32.425176] IPv6: ADDRCONF(NETDEV_UP): enp0s25: link is not ready
[ 32.892255] IPv6: ADDRCONF(NETDEV_UP): enp0s25: link is not ready
[ 34.236909] e1000e: enp0s25 NIC Link is Up 100 Mbps Full Duplex, Flow Control: Rx/Tx
[ 34.237022] e1000e 0000:00:19.0 enp0s25: 10/100 speed: disabling TSO
[ 34.237060] IPv6: ADDRCONF(NETDEV_CHANGE): enp0s25: link becomes ready
[ 42.868183] ata1.00: configured for UDMA/100
[ 42.868192] ata1: EH complete
So for some reason on the 21st second it just hangs and starts loading IPv6 service that I have nothing to do with. Could it be the reason behind slow boot? And if yes, how could I troubleshoot it?
I've been googling around for some time, but haven't really found good advice that would help me. The things I've tried haven't resolved the issue.
I'd be grateful if someone would help me investigate what's causing slow boot on this Lubuntu machine.
Thanks!
edit: A user called eridani suggested me to take a look in a tool called systemd-analyze, which may help me discover what slows down the boot time.
Here's the output of a command systemd-analyze plot > ~/Desktop/systemd.html: link to download (couldn't find a better way to share it).
Another command that was suggested in the Arch Linux blog was systemd-analyze critical-chain and here's the output of it:
~$ 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 @38.425s
└─multi-user.target @38.425s
└─teamviewerd.service @36.611s +1.812s (displayed in red color)
└─network-online.target @36.598s
└─NetworkManager-wait-online.service @24.297s +12.301s (displayed in red color)
└─NetworkManager.service @19.493s +4.785s (displayed in red color)
└─dbus.service @15.022s
└─basic.target @14.901s
└─paths.target @14.901s
└─systemd-networkd-resolvconf-update.path @14.901s
└─sysinit.target @14.869s
└─apparmor.service @6.651s +8.167s (displayed in red color)
└─local-fs.target @6.646s
└─run-user-1000.mount @34.907s
└─local-fs-pre.target @6.646s
└─systemd-remount-fs.service @6.533s +100ms (displayed in red color)
└─system.slice @1.934s
└─-.slice @1.851s
NetworkManager and apparmor.service seem to take quite a bit to load. Could I tweak something so that these would load faster?
Then again, is 44 seconds a good boot-up time given my specs? Could I somehow get it down a bit, using some even more lightweight distro (then again, I don't want to lose that much usability too, given it's my parents' computer, current Lubuntu GUI is good enough, I may try Xubuntu too).
Thanks for the help.
edit2: Apparently the disable command did not actually disable the NetworkManager-wait-online.service, so I used the following commands:
systemctl disable NetworkManager-wait-online.service
systemctl mask NetworkManager-wait-online.service
And got the system boot time from this: Startup finished in 5.647s (kernel) + 38.452s (userspace) = 44.100s to this: Startup finished in 5.487s (kernel) + 26.994s (userspace) = 32.481s. Though from a psychological perspective, it doesn't seem like, it's 12 seconds faster, but if the numbers say so, then I've got nothing to argue.
And now we have the apparmor.service left, which takes ~10 seconds to load. Here's the updated command of systemd-analyze critical-chain:
:~$ 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 @26.958s
└─multi-user.target @26.958s
└─ntp.service @26.590s +368ms (displayed in red)
└─network-online.target @26.569s
└─network.target @26.569s
└─NetworkManager.service @23.537s +3.032s (displayed in red)
└─dbus.service @16.973s
└─basic.target @16.896s
└─sockets.target @16.896s
└─pcscd.socket @16.896s
└─sysinit.target @16.895s
└─apparmor.service @6.518s +10.348s (displayed in red)
└─local-fs.target @6.513s
└─local-fs-pre.target @6.456s
└─systemd-remount-fs.service @6.353s +88ms (displayed in red)
└─systemd-journald.socket @1.901s
└─-.mount @1.826s
└─system.slice @1.901s
└─-.slice @1.826s
And the output of systemd-analyze blame | head:
:~$ systemd-analyze blame | head
10.348s apparmor.service
9.634s dev-sda1.device
7.510s ModemManager.service
7.449s grub-common.service
6.908s networking.service
6.898s apport.service
6.879s irqbalance.service
6.791s systemd-logind.service
6.724s ondemand.service
6.595s alsa-restore.service
Helpful user, eridani, asked for output of two commands, which might help me troubleshoot the slowness of apparmor.service and here they are:
~$ systemctl status apparmor
● apparmor.service - LSB: AppArmor initialization
Loaded: loaded (/etc/init.d/apparmor; bad; vendor preset: enabled)
Active: active (exited) since P 2016-08-28 20:00:10 EEST; 31min ago
Docs: man:systemd-sysv-generator(8)
Process: 785 ExecStart=/etc/init.d/apparmor start (code=exited, status=0/SUCCESS)
aug 28 19:59:59 dc7800 systemd[1]: Starting LSB: AppArmor initialization...
aug 28 20:00:08 dc7800 apparmor[785]: * Starting AppArmor profiles
aug 28 20:00:09 dc7800 apparmor[785]: Skipping profile in /etc/apparmor.d/disable: usr.bin.firefox
aug 28 20:00:09 dc7800 apparmor[785]: Skipping profile in /etc/apparmor.d/disable: usr.sbin.rsyslogd
aug 28 20:00:10 dc7800 apparmor[785]: ...done.
aug 28 20:00:10 dc7800 systemd[1]: Started LSB: AppArmor initialization.
And another one:
:~$ journalctl |grep apparmor
aug 28 20:00:08 dc7800 apparmor[785]: * Starting AppArmor profiles
aug 28 20:00:09 dc7800 audit[1849]: AVC apparmor="STATUS" operation="profile_load" profile="unconfined" name="/sbin/dhclient" pid=1849 comm="apparmor_parser"
aug 28 20:00:09 dc7800 audit[1849]: AVC apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/lib/NetworkManager/nm-dhcp-client.action" pid=1849 comm="apparmor_parser"
aug 28 20:00:09 dc7800 audit[1849]: AVC apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/lib/NetworkManager/nm-dhcp-helper" pid=1849 comm="apparmor_parser"
aug 28 20:00:09 dc7800 audit[1849]: AVC apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/lib/connman/scripts/dhclient-script" pid=1849 comm="apparmor_parser"
aug 28 20:00:09 dc7800 kernel: audit: type=1400 audit(1472403609.772:2): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/sbin/dhclient" pid=1849 comm="apparmor_parser"
aug 28 20:00:09 dc7800 kernel: audit: type=1400 audit(1472403609.772:3): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/lib/NetworkManager/nm-dhcp-client.action" pid=1849 comm="apparmor_parser"
aug 28 20:00:09 dc7800 kernel: audit: type=1400 audit(1472403609.772:4): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/lib/NetworkManager/nm-dhcp-helper" pid=1849 comm="apparmor_parser"
aug 28 20:00:09 dc7800 kernel: audit: type=1400 audit(1472403609.772:5): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/lib/connman/scripts/dhclient-script" pid=1849 comm="apparmor_parser"
aug 28 20:00:09 dc7800 audit[1848]: AVC apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/lib/lightdm/lightdm-guest-session" pid=1848 comm="apparmor_parser"
aug 28 20:00:09 dc7800 audit[1848]: AVC apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/lib/lightdm/lightdm-guest-session//chromium" pid=1848 comm="apparmor_parser"
aug 28 20:00:09 dc7800 apparmor[785]: Skipping profile in /etc/apparmor.d/disable: usr.bin.firefox
aug 28 20:00:09 dc7800 kernel: audit: type=1400 audit(1472403609.852:6): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/lib/lightdm/lightdm-guest-session" pid=1848 comm="apparmor_parser"
aug 28 20:00:09 dc7800 kernel: audit: type=1400 audit(1472403609.852:7): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/lib/lightdm/lightdm-guest-session//chromium" pid=1848 comm="apparmor_parser"
aug 28 20:00:09 dc7800 audit[1852]: AVC apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/sbin/ntpd" pid=1852 comm="apparmor_parser"
aug 28 20:00:09 dc7800 apparmor[785]: Skipping profile in /etc/apparmor.d/disable: usr.sbin.rsyslogd
aug 28 20:00:09 dc7800 kernel: audit: type=1400 audit(1472403609.920:8): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/sbin/ntpd" pid=1852 comm="apparmor_parser"
aug 28 20:00:09 dc7800 audit[1854]: AVC apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/sbin/tcpdump" pid=1854 comm="apparmor_parser"
aug 28 20:00:10 dc7800 kernel: audit: type=1400 audit(1472403609.996:9): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/sbin/tcpdump" pid=1854 comm="apparmor_parser"
aug 28 20:00:10 dc7800 audit[1850]: AVC apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/bin/evince" pid=1850 comm="apparmor_parser"
aug 28 20:00:10 dc7800 audit[1850]: AVC apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/bin/evince//sanitized_helper" pid=1850 comm="apparmor_parser"
aug 28 20:00:10 dc7800 audit[1850]: AVC apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/bin/evince-previewer" pid=1850 comm="apparmor_parser"
aug 28 20:00:10 dc7800 audit[1850]: AVC apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/bin/evince-previewer//sanitized_helper" pid=1850 comm="apparmor_parser"
aug 28 20:00:10 dc7800 audit[1850]: AVC apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/bin/evince-thumbnailer" pid=1850 comm="apparmor_parser"
aug 28 20:00:10 dc7800 audit[1850]: AVC apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/bin/evince-thumbnailer//sanitized_helper" pid=1850 comm="apparmor_parser"
aug 28 20:00:10 dc7800 kernel: audit: type=1400 audit(1472403610.068:10): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/bin/evince" pid=1850 comm="apparmor_parser"
aug 28 20:00:10 dc7800 kernel: audit: type=1400 audit(1472403610.072:11): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/bin/evince//sanitized_helper" pid=1850 comm="apparmor_parser"
aug 28 20:00:10 dc7800 apparmor[785]: ...done.
I'm trying to Google too in the meantime, but I'd appreciate good thoughts from here too :) Thanks for all the help, especially eridani!