slow boot: normal or configuration problem?

[GNUser]

Pure64 10.1 is my main OS and I love it, but it always boots much slower (~40 seconds) compared to my prior OS (Devuan ASCII, ~12 seconds).

It's no big deal if it's normal. I just want to make sure that there is no problem with my configuration. Some of the delay is due to all my extensions, so let's see what happens if I exclude the bulk of the extensions. I will use the printk.time=1 boot parameter for the two tests below.

Boot time is ~12 seconds (/var/log/messages here) when my onboot.lst contains this:

Code: [Select]

Xfbdev.tcz
aterm.tcz
fluxbox.tcz

Boot time jumps up to ~24 seconds (/var/log/messages here; note the ~10 second delay between lines 1037 and 1038) when my onboot.lst contains this:

Code: [Select]

Xorg-7.7.tcz
aterm.tcz
fluxbox.tcz
xf86-video-intel.tcz

Does any obvious pathology jump out at you in either log? I prefer using full-blown Xorg7.7--is there a reason it takes about twice as long to boot than Xfbdev?

P.S. This machine is a T400 ThinkPad with integrated Intel graphics. My harddrive is a nice and fast SSD. I'm using mount mode for the extensions (i.e., I don't use copy2fs.flg).

[Rich]

Hi GNUser
I'm guessing that's a 10 second timeout occurring due to the error. I see a similar error here:
https://bbs.archlinux.org/viewtopic.php?id=198157

[curaga]

Xorg has a lot of deps, but certainly shouldn't take 10 seconds. If you boot with "showapps" you can roughly see on screen what takes time.

The wiki has info on using bootchart too.

[Rich]

Hi GNUser
You  might want to take a peek at  Xorg.0.log  (it's timestamped too) for other errors. I wonder if you need  firmware-i915.tcz ?

[GNUser]

Thank you, Rich and curaga. When it comes to graphics, I'm in way over my head. So I really appreciate any help/suggestions. Here are some updates based on the above suggestions:

- showapps shows no big delays during extension loading. The delays happen later.

- installing firmware-i915.tcz makes no difference

- /var/log/Xorg.0.log does not seem to show anything to account for the delay

- The Libreboot FAQ specifically says that KMS is required for graphics, so I tried booting with the i915.modeset=1 boot parameter, but it makes no difference

Here is the hotspot of /var/log/messages where the two big delays happen (one between 15.2 and 24.6, the other between 24.6 and 37.0) (BTW, running filetool.sh -r once system is booted takes less than 2 seconds, so restoring mydata.tgz is not to blame for the second delay):

Code: [Select]

Nov 21 09:25:04 box user.debug kernel: [   14.370429] ath: Country alpha2 being used: 00
Nov 21 09:25:04 box user.debug kernel: [   14.370430] ath: Regpair used: 0x6a
Nov 21 09:25:04 box user.debug kernel: [   14.381012] ieee80211 phy0: Selected rate control algorithm 'minstrel_ht'
Nov 21 09:25:04 box user.info kernel: [   14.381264] ieee80211 phy0: Atheros AR9280 Rev:2 mem=0xffffc90000810000, irq=17
Nov 21 09:25:04 box user.info kernel: [   14.459799] [drm] Initialized i915 1.6.0 20180719 for 0000:00:02.0 on minor 0
Nov 21 09:25:04 box user.info kernel: [   14.644789] fbcon: inteldrmfb (fb0) is primary device
Nov 21 09:25:04 box user.info kernel: [   14.884996] Console: switching to colour frame buffer device 160x50
Nov 21 09:25:04 box user.info kernel: [   14.906011] i915 0000:00:02.0: fb0: inteldrmfb frame buffer device
Nov 21 09:25:05 box user.notice kernel: [   15.202172] random: fc-cache: uninitialized urandom read (8 bytes read)
Nov 21 09:25:05 box user.notice kernel: [   15.202708] random: fc-cache: uninitialized urandom read (8 bytes read)
Nov 21 09:25:05 box user.notice kernel: [   15.203109] random: fc-cache: uninitialized urandom read (8 bytes read)
Nov 21 09:25:14 box user.err kernel: [   24.601669] [drm:0xffffffffa031711f] *ERROR* CPU pipe A FIFO underrun
Nov 21 09:25:19 box authpriv.notice sudo:     root : TTY=console ; PWD=/ ; USER=root ; COMMAND=/bin/chown -R root.staff /usr/local/tce.installed
Nov 21 09:25:19 box authpriv.notice sudo:     root : TTY=console ; PWD=/ ; USER=root ; COMMAND=/bin/chmod -R 775 /usr/local/tce.installed
Nov 21 14:25:24 box daemon.err udevd[144]: unknown key 'RUN{program}' in /etc/udev/rules.d/73-seat-late.rules:17
Nov 21 14:25:24 box daemon.err udevd[144]: unknown key 'RUN{program}' in /etc/udev/rules.d/73-seat-late.rules:17
Nov 21 14:25:25 box daemon.err udevd[144]: unknown key 'RUN{program}' in /etc/udev/rules.d/73-seat-late.rules:17
Nov 21 14:25:25 box daemon.err udevd[144]: unknown key 'RUN{program}' in /etc/udev/rules.d/73-seat-late.rules:17
Nov 21 09:25:26 box daemon.notice haveged: haveged starting up
Nov 21 09:25:26 box authpriv.notice sudo:     root : TTY=console ; PWD=/ ; USER=root ; COMMAND=/bin/sh
Nov 21 09:25:26 box authpriv.notice sudo:     root : TTY=console ; PWD=/ ; USER=root ; COMMAND=/bin/cp /usr/local/share/wbar/dot.wbar /usr/local/tce
.icons
Nov 21 09:25:26 box authpriv.notice sudo:     root : TTY=console ; PWD=/ ; USER=root ; COMMAND=/bin/chown root.staff /usr/local/tce.icons
Nov 21 09:25:26 box authpriv.notice sudo:     root : TTY=console ; PWD=/ ; USER=root ; COMMAND=/bin/chmod g+w /usr/local/tce.icons
Nov 21 09:25:26 box authpriv.notice sudo:     root : TTY=console ; PWD=/ ; USER=root ; COMMAND=/bin/mv /tmp/wbar.7053 /usr/local/tce.icons
Nov 21 09:25:26 box authpriv.notice sudo:     root : TTY=console ; PWD=/ ; USER=root ; COMMAND=/bin/chmod g+w /usr/local/tce.icons
Nov 21 09:25:26 box authpriv.notice sudo:     root : TTY=console ; PWD=/ ; USER=root ; COMMAND=/bin/mv /tmp/wbar.7061 /usr/local/tce.icons
Nov 21 09:25:26 box authpriv.notice sudo:     root : TTY=console ; PWD=/ ; USER=root ; COMMAND=/bin/chmod g+w /usr/local/tce.icons
Nov 21 09:25:26 box authpriv.notice sudo:     root : TTY=console ; PWD=/ ; USER=root ; COMMAND=/bin/tar -C / -zxf /mnt/sda2/tce/mydata.tgz
Nov 21 09:25:27 box user.notice kernel: [   37.064760] random: crng init done
Nov 21 09:25:27 box user.notice kernel: [   37.064789] random: 6 urandom warning(s) missed due to ratelimiting
Nov 21 14:25:27 box daemon.info init: starting pid 7265, tty '/dev/tty1': '/sbin/getty -nl /sbin/autologin 38400 tty1'
Nov 21 14:25:27 box auth.info login[7265]: root login on 'tty1'
Nov 21 09:25:27 box daemon.notice haveged: haveged starting up

[GNUser]

The log in my prior post is from a boot where all my extensions are loaded. With minimal onboot.lst (with only Xorg-7.7.tcz, aterm.tcz, fluxbox.tcz and xf86-video-intel.tcz) the only unexplainable delay is between 7.06 and 16.7:

Code: [Select]

Nov 21 10:21:13 box user.info kernel: [    6.463944] Console: switching to colour dummy device 80x25
Nov 21 10:21:13 box user.info kernel: [    6.464048] [drm] Replacing VGA console driver
Nov 21 10:21:13 box user.info kernel: [    6.464123] [drm] Supports vblank timestamp caching Rev 2 (21.10.2013).
Nov 21 10:21:13 box user.info kernel: [    6.464127] [drm] Driver supports precise vblank timestamp query.
Nov 21 10:21:13 box user.warn kernel: [    6.464150] resource sanity check: requesting [mem 0x000c0000-0x000dffff], which spans more than PCI Bus 0000:00 [mem 0x000c0000-0x000c3fff window]
Nov 21 10:21:13 box user.warn kernel: [    6.464156] caller 0xffffffff812e3c22 mapping multiple BARs
Nov 21 10:21:13 box user.info kernel: [    6.464161] i915 0000:00:02.0: Invalid PCI ROM header signature: expecting 0xaa55, got 0x0000
Nov 21 10:21:13 box user.info kernel: [    6.464167] [drm] Failed to find VBIOS tables (VBT)
Nov 21 10:21:13 box user.info kernel: [    6.464477] i915 0000:00:02.0: vgaarb: changed VGA decodes: olddecodes=io+mem,decodes=io+mem:owns=io+mem
Nov 21 10:21:13 box user.info kernel: [    6.498300] [drm] RC6 disabled, disabling runtime PM support
Nov 21 10:21:13 box user.info kernel: [    6.579222] [drm] Initialized i915 1.6.0 20180719 for 0000:00:02.0 on minor 0
Nov 21 10:21:13 box user.info kernel: [    6.766074] fbcon: inteldrmfb (fb0) is primary device
Nov 21 10:21:13 box user.info kernel: [    7.038877] Console: switching to colour frame buffer device 160x50
Nov 21 10:21:14 box user.info kernel: [    7.064326] i915 0000:00:02.0: fb0: inteldrmfb frame buffer device
Nov 21 10:21:23 box user.err kernel: [   16.705496] [drm:0xffffffffa01c511f] *ERROR* CPU pipe A FIFO underrun

[Rich]

Hi GNUser
Did you try changing the drivers acceleration method as suggested here:
https://bbs.archlinux.org/viewtopic.php?id=198157

[GNUser]

Sorry, I had overlooked that. I just tried it and it made no difference

(Remember that I also have a Devuan partition on this laptop and, even though it's an elephant compared to TCL, its boot time is lightning fast. If you can think of a piece of data that would be helpful to compare between the two distros' boot process, let me know and I can go grab it.)

BTW, I'm a bit embarrassed to be taking up people's time because of 10 seconds. For the record, the delay itself doesn't matter to me; it's not understanding why there is a delay that bothers me.

[Rich]

Hi GNUser

... For the record, the delay itself doesn't matter to me; it's not understanding why there is a delay that bothers me.

I couldn't agree more. Maybe post the  dmesg  result from the Devuan install.

[GNUser]

Thank you, Rich.

Here you go: Devuan dmesg vs. TCL dmesg (the latter using the minimal onboot.lst as above).

[GNUser]

The "inteldrmfb" lines in the two dmesg outputs appear to be identical. Maybe this is not a graphics issue at all and the fact that the delay in TCL happens after that line is just a coincidence? Just playing devil's advocate.

Take a look at Reply #5 above. Is there a way to log more details regarding what's going on between timestamps 7.06 and 16.7?

[GNUser]

I found the same *ERROR* CPU pipe A FIFO underrun in Devuan's dmesg, so that error is probably not related to the cause of the delay.

The first difficulty here is that we don't know which warnings/errors are related to the delay and which ones are red herrings

[Rich]

Hi GNUser
Here's a long shot. I found references to the random number generator causing delays because it wasn't ready. Fontconfigs
fc-cache  command was listed as one of the culprits that triggered it. Unpack  fontconfig.tcz  and delete:

Code: [Select]

/usr/local/tce.installed/fontconfigRepack the extension and delete the  md5.txt  file. Create a file in your  ~/.X.d  directory containing:

Code: [Select]

fc-cache -sfv 1>/dev/null &

[GNUser]

You're on to something!

I did as you suggested and tried booting with the minimal onboot.lst...

...the boot completed very quickly (about 7 seconds), but it boots to a black screen (no panel, no cursor, no nothing). I need to switch to vt-1 in order to use the command prompt and reboot.

[Rich]

Hi GNUser
Maybe try placing:

Code: [Select]

fc-cache -sfv 1>/dev/nullin your  bootlocal.sh ?