Dtyjlui

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!

Well to put a couple things in perspective, I have a relatively fast system (using Ubuntu) and it boots in around 8 seconds (i7 @ 3.6GHz, 16GB Ram @ 1866MHz, and a M.2 drive housing the root partition).

The desktop specs look relatively low (1.8 GHz, 1 GB Ram installed @ 667MHz, and a slower than average HDD at 3GBps). You aren't going to get fantastic loading times with this system. Now lubuntu is more lightweight than Ubuntu, so it should help, but you still have quite a bit loading at the startup.

From inspection, looks like your ram could be a bottleneck, that with the speed of your HDD. I'm imagining that your HDD access indicator is flashing a lot at T: 21sec?

You seem to think it hasn't always been this slow though. The more services you add, the slower the load times. Especially, also, if your HDD is full, it will take more time to seek and find the information.

Although this doesn't really solve your problem, it helped put it in perspective and shows some potential issues at your loading times.

I have this result of the commnad 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 @1min 41.706s

└─multi-user.target @1min 41.703s

  └─smbd.service @1min 41.278s +423ms

    └─nmbd.service @39.182s +1min 2.092s

      └─network-online.target @39.165s

        └─systemd-resolved.service @36.838s +156ms

          └─network.target @36.827s

            └─wpa_supplicant.service @38.285s +224ms

              └─basic.target @29.932s

                └─sockets.target @29.929s

                  └─snapd.socket @29.897s +28ms

                    └─sysinit.target @29.136s

                      └─systemd-timesyncd.service @27.747s +1.384s

                        └─systemd-tmpfiles-setup.service @26.585s +1.147s

                          └─systemd-journal-flush.service @7.366s +19.214s

                            └─systemd-remount-fs.service @7.094s +267ms

                              └─system.slice @3.316s

                                └─-.slice @3.240s

If anyone can help me to get possible faster boot time.

Laptop config is: 1.6 GHZ, 2GB Ram, Ubuntu Core + LXDE-Openbox