петък, 14 февруари 2014 г.

System boots ridiculously slowly?

After I bough my new laptop (ASUS N550J), quite a decent machine, it turned out it booted very very slowly. Not that I restart that often, but when I do, it was simply ridiculous to watch the system struggle for a minute or so. Additionally my bluetooth didn't work which was quite odd and annoying. The strange part was that kinfo and lspci saw my usb device, it was just BlueDevil which told me "Adapter not found". I installed net-wireless/blueman - but it didn't help.
Anyway, after I reported it on the Sabayon forum, we came up with the following solution.
First, the symptoms (of the slow boot up):
localhost  # systemd-analyze
Startup finished in 4.962s (kernel) + 43.943s (userspace) = 48.906s
localhost # systemd-analyze blame
         32.071s systemd-udev-settle.service
          8.149s NetworkManager.service
          5.167s systemd-logind.service
          3.168s x-setup.service
          3.085s ufw.service
          2.962s systemd-user-sessions.service
          2.635s systemd-fsck-root.service
          2.620s plymouth-start.service
          2.563s avahi-daemon.service
          2.421s systemd-vconsole-setup.service
          2.203s plymouth-quit-wait.service
          2.203s plymouth-quit.service
          2.195s dev-mqueue.mount
          1.955s sys-kernel-debug.mount
          1.955s dev-hugepages.mount
          1.928s dev-disk-by\x2duuid-5de9b296\x2d1968\x2d4ce2\x2db745\x2d79782c4a3819.swap
          1.259s systemd-modules-load.service
          1.230s systemd-udev-trigger.service
           993ms systemd-udevd.service
           984ms var-lock.mount
           984ms var-run.mount
           955ms sys-fs-fuse-connections.mount
           785ms lvm2-activation-early.service
           541ms udisks2.service
           347ms rtkit-daemon.service
           274ms systemd-sysctl.service
           270ms polkit.service
           244ms systemd-tmpfiles-setup-dev.service
           210ms systemd-tmpfiles-setup.service
           182ms lvm2-activation-net.service
           145ms systemd-tmpfiles-clean.service
           121ms bluetooth.service
           116ms wpa_supplicant.service
           101ms systemd-journal-flush.service
            96ms systemd-remount-fs.service
            66ms plymouth-read-write.service
            63ms systemd-random-seed-load.service
            59ms vixie-cron.service
            56ms upower.service
            18ms alsa-restore.service
             5ms lvm2-activation.service
             1ms tmp.mount
localhost # 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 @43.943s
└─kdm.service @43.943s
  └─steambox.service @43.943s
    └─network.target @43.943s
      └─NetworkManager.service @35.793s +8.149s
        └─basic.target @35.775s
          └─timers.target @35.775s
            └─systemd-tmpfiles-clean.timer @35.775s
              └─sysinit.target @35.723s
                └─systemd-tmpfiles-setup.service @35.512s +210ms
                  └─local-fs.target @35.511s
                    └─tmp.mount @5.318s +1ms
                      └─local-fs-pre.target @4.150s
                        └─systemd-remount-fs.service @4.052s +96ms
                          └─systemd-journald.socket @1.354s
                            └─-.mount @1.353s

And in the dmesg I found:
[   16.991818] xhci_hcd 0000:00:14.0: Timeout while waiting for address device command
[   22.197007] xhci_hcd 0000:00:14.0: Timeout while waiting for address device command
[   22.398176] usb 1-5: device not accepting address 3, error -62

(and a lot more similar lines)

Here's what I did (and it worked):
1. Install "acpi". It turned out that merely by installing this package it decreased my boot up time from 48secs to 26 secs. And that is 22 secs difference - approximately 50% reduction!
2. Add to your kernel line in GRB pcie_hp=nomsi, i.e.:
linux   /kernel-genkernel-x86-3.12.0-sabayon root=/dev/sda3 ro splash vga=791 quiet dokeymap keymap=us  resume=/dev/sda5 pcie_hp=nomsi  
This reduces 4 more seconds to :
#systemd-analyze
Startup finished in 5.379s (kernel) + 16.956s (userspace) = 22.336s
3. You can also use this suggestion, though I still have to try it myself:
#systemctl enable systemd-readahead-collect systemd-readahead-replay
It make the system learn which disk sectors are read on boot up and read them ahead, so it should save time.

The best part is that as a side-result from the installation of "acpi", my bluetooth device started working. Well, at least it's on and visible from other devices. Last time I tried to send something, it failed but at least now I know it works.