[Solved] Very slow initial loading on Stretch, not on Jessie

[thatguychuck]

I'm attempting to diagnose a boot problem I'm having on Stretch that isn't present on Jessie. I have a Fujitsu Lifebook T5010 with Stretch (XFCE, SSH, standard system utilities) that appears to boot normally, right up to the point where I would expect lightdm to show. Instead, I have a black screen that has a non blinking cursor on the upper left. If I let this sit, eventually (I haven't timed, but +5minutes) lightdm will appear and I can login. After that everything appears to load at normal speed. During these black screens, I can still SSH into the machine (over wifi, which was a little unexpected.)

I have installed firmware-linux-free and non-free, as well as intel-microcode (with and without the blacklist) thinking it might help, but it did not. Switched from Stretch to SID to see if some updated packages would help, but they did not. Edited lightdm for autologin, no change (other than skipping lightdm.) I re installed Jessie just to make sure I wasn't having some sort of hardware fluke, and Jessie worked just fine. At the moment I'm back to a fresh Stretch install (XFCE, SSH, standard system utilities, firmware-linux-free and nonfree, and intel-microcode.) I've found a few similar threads but nothing that quite matches up to what I have, and to be honest I'm not exactly sure what I'm looking at, or for. I've used some of the commands from those other threads to give the information listed below. These were ran after finally getting to the desktop, any and all ideas appreciated.

systemd-analyze blame

Code: Select all

root@lifebook:/# systemd-analyze blame
          8.670s NetworkManager-wait-online.service
          3.309s dev-mapper-lifebook\x2d\x2dvg\x2droot.device
          2.472s ModemManager.service
          1.696s NetworkManager.service
          1.588s home.mount
          1.462s systemd-rfkill.service
          1.453s networking.service
          1.332s keyboard-setup.service
          1.322s lvm2-monitor.service
          1.196s speech-dispatcher.service
          1.074s systemd-logind.service
          1.062s pppd-dns.service
          1.061s alsa-restore.service
          1.061s rsyslog.service
          1.058s avahi-daemon.service
          1.032s exim4.service
           956ms rtkit-daemon.service
           926ms ssh.service
           920ms systemd-fsck@dev-disk-by\x2duuid-93f617af\x2dd38a\x2d440f\x2da0c2\x2dd4d6fba9a27c.service
           876ms systemd-cryptsetup@sda5_crypt.service
           808ms systemd-tmpfiles-setup-dev.service
           721ms systemd-fsck@dev-mapper-lifebook\x2d\x2dvg\x2dhome.service
           632ms upower.service
           623ms lm-sensors.service
           604ms systemd-udevd.service
           536ms bluetooth.service
           504ms polkit.service
           498ms systemd-remount-fs.service
           479ms dev-hugepages.mount
           461ms dev-mqueue.mount
           459ms sys-kernel-debug.mount
           430ms lightdm.service
           303ms systemd-udev-trigger.service
           214ms kmod-static-nodes.service
           214ms wpa_supplicant.service
           199ms systemd-random-seed.service
           190ms systemd-tmpfiles-setup.service
           189ms systemd-journald.service
           164ms systemd-journal-flush.service
           151ms systemd-timesyncd.service
           141ms boot.mount
           141ms systemd-modules-load.service
           123ms console-setup.service
           123ms udisks2.service
           104ms systemd-backlight@backlight:intel_backlight.service
           104ms systemd-backlight@backlight:acpi_video0.service
           100ms systemd-user-sessions.service
            84ms systemd-sysctl.service
            74ms dev-mapper-lifebook\x2d\x2dvg\x2dswap_1.swap
            64ms hddtemp.service
            60ms systemd-update-utmp.service
            33ms user@1000.service
             7ms systemd-update-utmp-runlevel.service]

systemd-analyze critical-chain

Code: Select all

root@lifebook:/# 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 @21.298s
└─multi-user.target @21.298s
  └─exim4.service @20.265s +1.032s
    └─network-online.target @20.264s
      └─NetworkManager-wait-online.service @11.593s +8.670s
        └─NetworkManager.service @9.865s +1.696s
          └─dbus.service @8.908s
            └─basic.target @8.805s
              └─sockets.target @8.805s
                └─avahi-daemon.socket @8.805s
                  └─sysinit.target @8.805s
                    └─systemd-timesyncd.service @8.653s +151ms
                      └─systemd-tmpfiles-setup.service @8.445s +190ms
                        └─local-fs.target @8.377s
                          └─boot.mount @8.235s +141ms
                            └─systemd-fsck@dev-disk-by\x2duuid-93f617af\x2dd38a\x2d440f\x2da0c2\x2dd4d6fba9a27c.service @7.253s +920ms
                              └─dev-disk-by\x2duuid-93f617af\x2dd38a\x2d440f\x2da0c2\x2dd4d6fba9a27c.device @7.253s

journalctl -b -p 3

Code: Select all

root@lifebook:/# journalctl -b -p 3
-- Logs begin at Tue 2017-07-04 17:56:32 MDT, end at Tue 2017-07-04 18:02:22 MDT. --
Jul 04 17:56:32 lifebook kernel: acpi LNXCPU:00: Invalid PBLK length [8]
Jul 04 17:56:32 lifebook kernel: acpi LNXCPU:01: Invalid PBLK length [8]
Jul 04 17:56:42 lifebook bluetoothd[569]: Failed to obtain handles for "Service Changed" characteristic
Jul 04 17:56:42 lifebook bluetoothd[569]: Sap driver initialization failed.
Jul 04 17:56:42 lifebook bluetoothd[569]: sap-server: Operation not permitted (1)

dmesg -tail

Code: Select all

root@lifebook:/# dmesg | tail
[   33.844949] wlp24s0: RX AssocResp from 2c:30:33:48:27:94 (capab=0x11 status=0 aid=3)
[   33.845044] wlp24s0: associated
[   33.845075] IPv6: ADDRCONF(NETDEV_CHANGE): wlp24s0: link becomes ready
[   33.850633] ath: EEPROM regdomain: 0x8348
[   33.850634] ath: EEPROM indicates we should expect a country code
[   33.850635] ath: doing EEPROM country->regdmn map search
[   33.850636] ath: country maps to regdmn code: 0x3a
[   33.850637] ath: Country alpha2 being used: US
[   33.850637] ath: Regpair used: 0x3a
[   33.850638] ath: regdomain 0x8348 dynamically updated by country IE

[thatguychuck]

A reddit post pointed me towards my Xorg.0.log, and a possible cause of the delay.

Code: Select all

[   367.872] (II) Serial Wacom Tablet FUJ02e5: other types will be automatically added.
[   617.953] (II) Serial Wacom Tablet FUJ02e5 stylus: serial tablet id 0x90.

Removing xserver-xorg-input-wacom gets me back to a normal boot (without the stylus support of course, thankfully that is not a show stopper for me.) While not ideal, I now have a package to file a bug report against.

Edit: Things have come full circle now, the bug was not in xserver-xorg-input-wacom, but a patch needed in Xorg. There was a change where microseconds were taken as milliseconds and some things are taking much longer than they should.

https://bugs.debian.org/cgi-bin/bugrepo ... bug=863532