[Solved] Improve Arch Boot(userspace)

saurabh · 2018-01-29 19:54:56

I have been using Arch(Or Linux) for two months now. And tried various desktop enviornments and window managers to settle with openbox in the end. The boottimes for my system are currently 15+ seconds. After seeing a few reddits and other posts online I have seen people achieving 5-7s boot time even with hdds. (Booting into GUI)
My setup is: Laptop(CPU: i5 6200U | RAM: 8 GB)

/etc/fstab
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
# <file system>					<dir>	<type>	<options>												<dump>	<pass>
PARTUUID=003482dc-8af2-4321-8d05-282d192b2b68	/esp	vfat	rw,relatime,fmask=0022,dmask=0022,codepage=437,iocharset=iso8859-1,shortname=mixed,errors=remount-ro	0	2
PARTUUID=a7cd2091-7d81-4719-b8ce-b7b8bbaa081d	none	swap	defaults												0	0
PARTUUID=2875dc0c-2845-4f9b-bb70-e346cb206fbf	/	ext4	rw,relatime,data=ordered										0	1
PARTUUID=f47f8b9b-3936-4b9c-97a2-8867f30318f8	/home	ext4	rw,relatime,data=ordered										0	2
/esp/EFI/arch					/boot	none	defaults,bind												0	0

Also I have:

disabled/masked lvm2-monitor.service
enabled quiet boot

The problem I am facing is that the userspace take a long time to load compared to firmware and kernal. Where as the results on reddit show a contrasting results where the user space loads faster than either of them.
Results:

systemd-analyze
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Startup finished in 2.690s (firmware) + 109ms (loader) + 3.464s (kernel) + 10.417s (userspace) = 16.681s
graphical.target reached after 10.417s in userspace

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 @10.417s
`-lightdm.service @10.189s +227ms
  `-systemd-user-sessions.service @10.160s +28ms
    `-network.target @10.159s
      `-NetworkManager.service @8.882s +1.275s
        `-dbus.service @8.523s
          `-basic.target @8.521s
            `-sockets.target @8.520s
              `-dbus.socket @8.520s
                `-sysinit.target @8.520s
                  `-systemd-update-utmp.service @8.475s +45ms
                    `-systemd-tmpfiles-setup.service @8.390s +83ms
                      `-local-fs.target @8.368s
                        `-home.mount @8.046s +321ms
                          `-systemd-fsck@dev-disk-by\x2dpartuuid-f47f8b9b\x2d3936\x2d4b9c\x2d97a2\x2d8867f30318f8.service @6.933s +1.111s
                            `-dev-disk-by\x2dpartuuid-f47f8b9b\x2d3936\x2d4b9c\x2d97a2\x2d8867f30318f8.device @6.933s

Plotted the same for detailed results - systemd-analyze plot
I have went through the Improving performance/Boot process on arch wiki but most of the tips revolve around kernel optimization. One of the settings that (according to me and may be wrong) could have affected the userspace boot time was quiet/silent boot. But it doesn't make any difference what so ever.
Can any of the following help me improve the userspace boot time?

Changing root partition type (Btrfs or something else. I know it seems foolish but mounting is taking 4 seconds, is it normal?)
Updating fstab
Anything else

Edit:
Added output for systemd-analyze critical-chain

Last edited by saurabh (2018-02-06 19:16:22)

Slithery · 2018-01-29 20:04:39

NetworkManager is blocking the boot for 1.275s, switching to a different method of managing your network will cut this.

Can you post the output of...

systemd-analyze critical-chain

Head_on_a_Stick · 2018-01-29 20:21:22

saurabh wrote:

mounting is taking 4 seconds, is it normal?

No, I wouldn't say so.

Does the journal say anything about it?

journalctl -u dev\-sda3.device

Speaking of which, the journal itself is taking almost 5 seconds to flush so perhaps try disabling persistent logging or reducing the maximum size of the log files on the disk, see journald.conf(5) for the method.

saurabh · 2018-01-29 20:25:28

slithery wrote:

NetworkManager is blocking the boot for 1.275s, switching to a different method of managing your network will cut this.
Can you post the output of...
systemd-analyze critical-chain

Yes even I observed the same but Network manager is taking up only 1 sec here. And I need wifi,(lightning killed my LAN card) so was using NetworkManager. Will surely look into other network utils that are available. Hoping that there is more to it than the network manager.
Here is the output, also added to main post:

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 @10.417s
`-lightdm.service @10.189s +227ms
  `-systemd-user-sessions.service @10.160s +28ms
    `-network.target @10.159s
      `-NetworkManager.service @8.882s +1.275s
        `-dbus.service @8.523s
          `-basic.target @8.521s
            `-sockets.target @8.520s
              `-dbus.socket @8.520s
                `-sysinit.target @8.520s
                  `-systemd-update-utmp.service @8.475s +45ms
                    `-systemd-tmpfiles-setup.service @8.390s +83ms
                      `-local-fs.target @8.368s
                        `-home.mount @8.046s +321ms
                          `-systemd-fsck@dev-disk-by\x2dpartuuid-f47f8b9b\x2d3936\x2d4b9c\x2d97a2\x2d8867f30318f8.service @6.933s +1.111s
                            `-dev-disk-by\x2dpartuuid-f47f8b9b\x2d3936\x2d4b9c\x2d97a2\x2d8867f30318f8.device @6.933s

Last edited by saurabh (2018-01-29 20:26:50)

saurabh · 2018-01-29 20:51:29

Head_on_a_Stick wrote:

Does the journal say anything about it?
journalctl -u dev\-sda3.device
Speaking of which, the journal itself is taking almost 5 seconds to flush so perhaps try disabling persistent logging or reducing the maximum size of the log files on the disk, see journald.conf(5) for the method.

The journalctl command returned -- No entries -- for sda3

journalctl -u dev\-sda3.device
--------------------------------------------------
-- Logs begin at Sun 2018-01-28 12:55:58 IST, end at Tue 2018-01-30 02:11:33 IST. 
-- No entries --

Also making the log volatile shaved 2 seconds off the boot time. So that is an improvement. Link
Something with the harddrive? May be this helps

lspci -v | grep SATA
--------------------------------------------------
00:1f.2 SATA controller: Intel Corporation Wildcat Point-LP SATA Controller [AHCI Mode] (rev 03) (prog-if 01 [AHCI 1.0])
	Subsystem: Hewlett-Packard Company Wildcat Point-LP SATA Controller [AHCI Mode]

Last edited by saurabh (2018-01-29 20:53:46)

Head_on_a_Stick · 2018-01-29 21:00:07

saurabh wrote:

The journalctl command returned -- No entries -- for sda3

journalctl -u dev\-sda3.device
--------------------------------------------------
-- Logs begin at Sun 2018-01-28 12:55:58 IST, end at Tue 2018-01-30 02:11:33 IST. 
-- No entries --

That's probably not the full name of the unit file, try this to find the full name:

systemctl --all | grep sda3

Or just go old-school:

journalctl -b | grep sda3

^ That's very hacky though, I'm sure there must be a more "proper" way of doing that

saurabh · 2018-01-29 21:28:02

Head_on_a_Stick wrote:

That's probably not the full name of the unit file, try this to find the full name:
systemctl --all | grep sda3

Ya that was not the unit name. The actual name was "dev-sda3.device". But still it gives -- No entries --. "-.mount" unit, also returns -- No entries --
Also tried

systemctl --state=failed
---------------------------------------------------------------
0 loaded units listed. Pass --all to see loaded but inactive units, too.
To show all installed unit files use 'systemctl list-unit-files'.

But this does return an error

journalctl -fp err
---------------------------------------------------------------
-- Logs begin at Sun 2018-01-28 12:55:58 IST. --
Jan 30 00:53:18 DevMachine kernel: [drm:intel_pipe_update_end [i915]] *ERROR* Atomic update failure on pipe B (start=167727 end=167728) time 1294 us, min 1073, max 1079, scanline start 1067, end 29
Jan 30 01:13:04 DevMachine kernel: [drm:intel_pipe_update_end [i915]] *ERROR* Atomic update failure on pipe B (start=238883 end=238884) time 1293 us, min 1073, max 1079, scanline start 1059, end 22
Jan 30 01:15:03 DevMachine kernel: [drm:intel_pipe_update_end [i915]] *ERROR* Atomic update failure on pipe A (start=246738 end=246739) time 649 us, min 1072, max 1079, scanline start 1070, end 1116
Jan 30 01:38:38 DevMachine kernel: [drm:intel_pipe_update_end [i915]] *ERROR* Atomic update failure on pipe A (start=331632 end=331633) time 486 us, min 1072, max 1079, scanline start 1048, end 1083
Jan 30 02:09:10 DevMachine kernel: watchdog: watchdog0: watchdog did not stop!
-- Reboot --
Jan 30 02:09:22 DevMachine kernel: [Firmware Bug]: TSC_DEADLINE disabled due to Errata; please update microcode to version: 0x25 (or later)
Jan 30 02:09:22 DevMachine kernel: Error parsing PCC subspaces from PCCT
Jan 30 02:09:26 DevMachine kernel: nouveau 0000:09:00.0: bus: MMIO read of 00000000 FAULT at 612004 [ IBUS ]
Jan 30 02:09:26 DevMachine kernel: nouveau 0000:09:00.0: bus: MMIO read of 00000000 FAULT at 10ac08 [ IBUS ]
Jan 30 02:09:27 DevMachine kernel: nouveau 0000:09:00.0: DRM: Pointer to TMDS table invalid

Does it mean I need to update microcode for my cpu?
Will look into it by tomorrow and then update if the boot issue is solved after this.

saurabh · 2018-01-29 21:47:14

ERR!! updated the intel microcode. Now nouveau is having issue. Is this standard or I need to clean install the system again?

Jan 30 00:06:44 DevMachine kernel: nouveau 0000:09:00.0: DRM: Pointer to TMDS table invalid
Jan 30 00:53:18 DevMachine kernel: [drm:intel_pipe_update_end [i915]] *ERROR* Atomic update failure on pipe B (start=167727 end=167728) time 1294 us, min 1073, max 1079, scanline start 1067, end 29
Jan 30 01:13:04 DevMachine kernel: [drm:intel_pipe_update_end [i915]] *ERROR* Atomic update failure on pipe B (start=238883 end=238884) time 1293 us, min 1073, max 1079, scanline start 1059, end 22
Jan 30 01:15:03 DevMachine kernel: [drm:intel_pipe_update_end [i915]] *ERROR* Atomic update failure on pipe A (start=246738 end=246739) time 649 us, min 1072, max 1079, scanline start 1070, end 1116
Jan 30 01:38:38 DevMachine kernel: [drm:intel_pipe_update_end [i915]] *ERROR* Atomic update failure on pipe A (start=331632 end=331633) time 486 us, min 1072, max 1079, scanline start 1048, end 1083
Jan 30 02:09:10 DevMachine kernel: watchdog: watchdog0: watchdog did not stop!
-- Reboot --
Jan 30 03:09:34 DevMachine kernel: Error parsing PCC subspaces from PCCT
Jan 30 03:09:37 DevMachine kernel: nouveau 0000:09:00.0: bus: MMIO read of 00000000 FAULT at 612004 [ IBUS ]
Jan 30 03:09:37 DevMachine kernel: nouveau 0000:09:00.0: bus: MMIO read of 00000000 FAULT at 10ac08 [ IBUS ]
Jan 30 03:09:37 DevMachine kernel: nouveau 0000:09:00.0: DRM: Pointer to TMDS table invalid

mrunion · 2018-01-30 13:02:38

Nouveau was having the same issue before you last post as well. If you updated the microcode between post 7 and 8, the microcode was not the cause of the Nouveau error.

saurabh · 2018-01-31 08:11:20

@mrunion - thanks for the information.

I have made few changes to the system now. I had xrandr command in my openbox startup script moved it to lightdm display script for smother login. Doesn't optimize the boot process but the things seem a lot smoother now. Next I am planning to setup display in kernel space.

After that I searched over for a few more methods that can help to make booting process faster and stumbled across e4rat. All the posts that I have found are atleast 3-4 years old. So wanted to ask if the method is still relevant with systemd boot? Anyone using this in todays date or are there better options available. If this or any other method is still relevant I will go ahead and try it.
Will continue my search for time being and post any updates that help.

Note: I am using HDD, no SSD in my system.

Thorsten Reinbold · 2018-01-31 13:17:10

e4rat is definitly worth a try with a hdd.

lo1 · 2018-01-31 19:21:50

As a learning experience, try e4rat (you have to build a kernel with AUDIT support, probably there's some kernel that enables it by default) but I'd stick with that boot time, is quite good. Have you already tried gopreload and systemd-readahead? (both from AUR)

saurabh · 2018-02-01 06:06:00

lo1 wrote:

As a learning experience, try e4rat (you have to build a kernel with AUDIT support, probably there's some kernel that enables it by default) but I'd stick with that boot time, is quite good. Have you already tried gopreload and systemd-readahead? (both from AUR)

Yes, waiting for the weekend to play around with e4rat. I am not much concerned with the boot time right now I am happy with them, just exploring things to know more about the linux system. Things are just getting more and more exciting as time goes by.
And nope I have not tried any of those two but just stumbled across systemd-readahead yesterday and had no idea about gopreload. Thanks for pointing those out, will try them this weekend hopefully without breaking the system .

saurabh · 2018-02-05 10:41:05

I setup e4rat on pc this weekend didnot improve the boot times so just turned it off and uninstalled it. Also I tried out gopreload which doesn't seem to improve the load time for my applications. Trying out several things has been a great learning experience and I have been able to get the total boot times from 20+ seconds to sub 15 seconds on my machine.

Slithery wrote:

NetworkManager is blocking the boot for 1.275s, switching to a different method of managing your network will cut this.

Thanks for the tip. I switched to using systemd-networkd and it is no longer blocking my boot now.

Also this helped Minimal initramfs. This shaved another 1-1.5 for the kernel.

I think this topic can be closed now.

Last edited by saurabh (2018-02-05 10:42:48)

Slithery · 2018-02-05 11:37:04

We don't close topics unless we have to, someone may well come along with more relevant information for you.

You can mark it as [SOLVED] if you want...
CoC - How to post

Arch Linux

#1 2018-01-29 19:54:56

[Solved] Improve Arch Boot(userspace)

#2 2018-01-29 20:04:39

Re: [Solved] Improve Arch Boot(userspace)

#3 2018-01-29 20:21:22

Re: [Solved] Improve Arch Boot(userspace)

#4 2018-01-29 20:25:28

Re: [Solved] Improve Arch Boot(userspace)

#5 2018-01-29 20:51:29

Re: [Solved] Improve Arch Boot(userspace)

#6 2018-01-29 21:00:07

Re: [Solved] Improve Arch Boot(userspace)

#7 2018-01-29 21:28:02

Re: [Solved] Improve Arch Boot(userspace)

#8 2018-01-29 21:47:14

Re: [Solved] Improve Arch Boot(userspace)

#9 2018-01-30 13:02:38

Re: [Solved] Improve Arch Boot(userspace)

#10 2018-01-31 08:11:20

Re: [Solved] Improve Arch Boot(userspace)

#11 2018-01-31 13:17:10

Re: [Solved] Improve Arch Boot(userspace)

#12 2018-01-31 19:21:50

Re: [Solved] Improve Arch Boot(userspace)

#13 2018-02-01 06:06:00

Re: [Solved] Improve Arch Boot(userspace)

#14 2018-02-05 10:41:05

Re: [Solved] Improve Arch Boot(userspace)

#15 2018-02-05 11:37:04

Re: [Solved] Improve Arch Boot(userspace)

Board footer