Slow boot, yet fast systemd-analyze time

SaltyBarcode · 2017-03-14 14:23:24

From pressing the power button, my computer takes 29 seconds to get to the desktop. I use GRUB as I'm dual booting with Windows 10 but I have it set to auto select Arch Linux. I use getty to auto-login, and startx automatically starts upon login. Running systemd-analyze time shows me that the kernel and userspace startup takes 2.57 seconds. I've tried to find anything that can help me analyze or solve the slow start-up prior to the kernel and userspace startup but no luck so far. Does anyone have any solutions/advice?

Slithery · 2017-03-14 14:29:42

Can you post the output of the following so we can take a look...

systemd-analyze
systemd-analyze blame
systemd-analyze critical-chain

You may just have a very slow BIOS/UEFI implementation, this isn't uncommon and there's nothing you can do about it.

Last edited by Slithery (2017-03-14 14:30:59)

ewaller · 2017-03-14 14:31:28

Maybe systemd-analyze blame
or perhaps systemd-analyze critical-chain
?

Edit: Snaked by Slithery

Edit 2: Oh, BTW, Welcome the Arch Linux Forums

Last edited by ewaller (2017-03-14 14:32:40)

SaltyBarcode · 2017-03-14 14:37:29

Thanks for the welcome and quick reply! I've tried using these commands and I'm getting similarly fast times:

systemd-analyze
Startup finished in 1.668s (kernel) + 599ms (userspace) = 2.268s

systemd-analyze blame
221ms systemd-journald.service
142ms dev-sda3.device
131ms systemd-resolved.service
61ms lm_sensors.service
51ms polkit.service
36ms systemd-udevd.service
31ms systemd-tmpfiles-setup.service
28ms systemd-tmpfiles-setup-dev.service
23ms systemd-udev-trigger.service
16ms user@1000.service
15ms sys-kernel-debug.mount
15ms dev-mqueue.mount
14ms dev-hugepages.mount
13ms systemd-networkd.service
13ms systemd-tmpfiles-clean.service
9ms systemd-logind.service
9ms systemd-sysctl.service
9ms systemd-random-seed.service
6ms sys-kernel-config.mount
6ms kmod-static-nodes.service
6ms systemd-remount-fs.service
5ms systemd-journal-flush.service
5ms systemd-update-utmp.service
2ms alsa-restore.service
2ms systemd-user-sessions.service
2ms rtkit-daemon.service
1ms tmp.mount
947us sys-fs-fuse-connections.mount

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 @599ms
└─multi-user.target @599ms
└─systemd-resolved.service @467ms +131ms
└─network.target @464ms
└─systemd-networkd.service @450ms +13ms
└─dbus.service @402ms
└─basic.target @398ms
└─sockets.target @398ms
└─dbus.socket @398ms
└─sysinit.target @397ms
└─systemd-update-utmp.service @392ms +5ms
└─systemd-tmpfiles-setup.service @361ms +31ms
└─systemd-journal-flush.service @355ms +5ms
└─systemd-journald.service @133ms +221ms
└─systemd-journald-dev-log.socket @132ms
└─-.slice @116ms

Last edited by SaltyBarcode (2017-03-14 14:38:37)

ewaller · 2017-03-14 14:46:02

So, it appears that you reach the graphical target at just under 0.6 seconds. Pretty darn good. You spend about a second waiting for a fuse file system to mount, but it is not in the critical path.
What desktop environment are you using? Is your hostname set correctly? Anything of interest in the journal? perhaps if you rebooted , waited until you are in the GUI, then post the output of journalctl -b

SaltyBarcode · 2017-03-14 15:02:28

I use i3-gaps. I set the hostname as set out in the beginner's guide in the wiki, so I assume it's set correctly. Here's my journalctl -b after a reboot, I'd be impressed if you can make heads or tails of anything here:

(note - PS1Hagrid is the hostname, just some stupid running joke)

journalctl -b
-- Logs begin at Thu 2017-02-23 18:02:10 GMT, end at Tue 2017-03-14 14:54:59 GMT. --
Mar 14 14:54:38 PS1Hagrid systemd-journald[206]: Time spent on flushing to /var is 810us for
Mar 14 14:54:38 PS1Hagrid kernel: PCCT header not found.
Mar 14 14:54:38 PS1Hagrid kernel: pmd_set_huge: Cannot satisfy [mem 0xf8000000-0xf8200000] w
Mar 14 14:54:38 PS1Hagrid kernel: (NULL device *): hwmon_device_register() is deprecated. Pl
Mar 14 14:54:38 PS1Hagrid kernel: ACPI Warning: SystemIO range 0x0000000000001828-0x00000000
Mar 14 14:54:38 PS1Hagrid kernel: ACPI Warning: SystemIO range 0x0000000000001C40-0x00000000
Mar 14 14:54:38 PS1Hagrid kernel: ACPI Warning: SystemIO range 0x0000000000001C30-0x00000000
Mar 14 14:54:38 PS1Hagrid kernel: ACPI Warning: SystemIO range 0x0000000000001C30-0x00000000
Mar 14 14:54:38 PS1Hagrid kernel: ACPI Warning: SystemIO range 0x0000000000001C00-0x00000000
Mar 14 14:54:38 PS1Hagrid kernel: ACPI Warning: SystemIO range 0x0000000000001C00-0x00000000
Mar 14 14:54:38 PS1Hagrid kernel: lpc_ich: Resource conflict(s) found affecting gpio_ich
Mar 14 14:54:38 PS1Hagrid kernel: r8169 0000:03:00.0: can't disable ASPM; OS doesn't have AS
Mar 14 14:54:38 PS1Hagrid systemd-journald[206]: Journal started
Mar 14 14:54:38 PS1Hagrid systemd-journald[206]: System journal (/var/log/journal/5c7cada7de
Mar 14 14:54:38 PS1Hagrid systemd-journald[206]: System journal (/var/log/journal/5c7cada7de
Mar 14 14:54:38 PS1Hagrid systemd-tmpfiles[306]: Cannot set file attribute for '/var/log/jou
Mar 14 14:54:38 PS1Hagrid kernel: snd_hda_intel 0000:00:1b.0: control 2:0:0:PCM Playback Vol
Mar 14 14:54:38 PS1Hagrid systemd-tmpfiles[306]: Cannot set file attribute for '/var/log/jou
Mar 14 14:54:38 PS1Hagrid systemd-tmpfiles[306]: Cannot set file attribute for '/var/log/jou
Mar 14 14:54:38 PS1Hagrid systemd-udevd[253]: Process '/usr/bin/alsactl restore 0' failed wi
Mar 14 14:54:38 PS1Hagrid kernel: nvidia: loading out-of-tree module taints kernel.
Mar 14 14:54:38 PS1Hagrid kernel: nvidia: module license 'NVIDIA' taints kernel.
Mar 14 14:54:38 PS1Hagrid kernel: Disabling lock debugging due to kernel taint
Mar 14 14:54:38 PS1Hagrid kernel: NVRM: loading NVIDIA UNIX x86_64 Kernel Module  378.13  Tu
Mar 14 14:54:38 PS1Hagrid kernel:  (using threaded interrupts)
Mar 14 14:54:38 PS1Hagrid kernel: 
Mar 14 14:54:59 PS1Hagrid systemd-resolved[330]: Using degraded feature set (UDP) for DNS se
Mar 14 14:54:59 PS1Hagrid systemd-resolved[330]: Using degraded feature set (UDP) for DNS se
lines 1-29/29 (END)...skipping...
-- Logs begin at Thu 2017-02-23 18:02:10 GMT, end at Tue 2017-03-14 14:54:59 GMT. --
Mar 14 14:54:38 PS1Hagrid systemd-journald[206]: Time spent on flushing to /var is 810us for 0 entries.
Mar 14 14:54:38 PS1Hagrid kernel: PCCT header not found.
Mar 14 14:54:38 PS1Hagrid kernel: pmd_set_huge: Cannot satisfy [mem 0xf8000000-0xf8200000] with a huge-page mapping due to MTRR override.
Mar 14 14:54:38 PS1Hagrid kernel: (NULL device *): hwmon_device_register() is deprecated. Please convert the driver to use hwmon_device_register_with_info().
Mar 14 14:54:38 PS1Hagrid kernel: ACPI Warning: SystemIO range 0x0000000000001828-0x000000000000182F conflicts with OpRegion 0x0000000000001800-0x000000000000187F (\PMIO) (20160930/utaddress-
Mar 14 14:54:38 PS1Hagrid kernel: ACPI Warning: SystemIO range 0x0000000000001C40-0x0000000000001C4F conflicts with OpRegion 0x0000000000001C00-0x0000000000001FFF (\GPR) (20160930/utaddress-2
Mar 14 14:54:38 PS1Hagrid kernel: ACPI Warning: SystemIO range 0x0000000000001C30-0x0000000000001C3F conflicts with OpRegion 0x0000000000001C00-0x0000000000001C3F (\GPRL) (20160930/utaddress-
Mar 14 14:54:38 PS1Hagrid kernel: ACPI Warning: SystemIO range 0x0000000000001C30-0x0000000000001C3F conflicts with OpRegion 0x0000000000001C00-0x0000000000001FFF (\GPR) (20160930/utaddress-2
Mar 14 14:54:38 PS1Hagrid kernel: ACPI Warning: SystemIO range 0x0000000000001C00-0x0000000000001C2F conflicts with OpRegion 0x0000000000001C00-0x0000000000001C3F (\GPRL) (20160930/utaddress-
Mar 14 14:54:38 PS1Hagrid kernel: ACPI Warning: SystemIO range 0x0000000000001C00-0x0000000000001C2F conflicts with OpRegion 0x0000000000001C00-0x0000000000001FFF (\GPR) (20160930/utaddress-2
-- Logs begin at Thu 2017-02-23 18:02:10 GMT, end at Tue 2017-03-14 14:54:59 GMT. --
Mar 14 14:54:38 PS1Hagrid systemd-journald[206]: Time spent on flushing to /var is 810us for 0 entries.
Mar 14 14:54:38 PS1Hagrid kernel: PCCT header not found.
Mar 14 14:54:38 PS1Hagrid kernel: pmd_set_huge: Cannot satisfy [mem 0xf8000000-0xf8200000] with a huge-page mapping due to MTRR override.
Mar 14 14:54:38 PS1Hagrid kernel: (NULL device *): hwmon_device_register() is deprecated. Please convert the driver to use hwmon_device_register_with_info().
Mar 14 14:54:38 PS1Hagrid kernel: ACPI Warning: SystemIO range 0x0000000000001828-0x000000000000182F conflicts with OpRegion 0x0000000000001800-0x000000000000187F (\PMIO) (20160930/utaddress-
Mar 14 14:54:38 PS1Hagrid kernel: ACPI Warning: SystemIO range 0x0000000000001C40-0x0000000000001C4F conflicts with OpRegion 0x0000000000001C00-0x0000000000001FFF (\GPR) (20160930/utaddress-2
Mar 14 14:54:38 PS1Hagrid kernel: ACPI Warning: SystemIO range 0x0000000000001C30-0x0000000000001C3F conflicts with OpRegion 0x0000000000001C00-0x0000000000001C3F (\GPRL) (20160930/utaddress-
Mar 14 14:54:38 PS1Hagrid kernel: ACPI Warning: SystemIO range 0x0000000000001C30-0x0000000000001C3F conflicts with OpRegion 0x0000000000001C00-0x0000000000001FFF (\GPR) (20160930/utaddress-2
Mar 14 14:54:38 PS1Hagrid kernel: ACPI Warning: SystemIO range 0x0000000000001C00-0x0000000000001C2F conflicts with OpRegion 0x0000000000001C00-0x0000000000001C3F (\GPRL) (20160930/utaddress-
Mar 14 14:54:38 PS1Hagrid kernel: ACPI Warning: SystemIO range 0x0000000000001C00-0x0000000000001C2F conflicts with OpRegion 0x0000000000001C00-0x0000000000001FFF (\GPR) (20160930/utaddress-2
Mar 14 14:54:38 PS1Hagrid kernel: lpc_ich: Resource conflict(s) found affecting gpio_ich
Mar 14 14:54:38 PS1Hagrid kernel: r8169 0000:03:00.0: can't disable ASPM; OS doesn't have ASPM control
Mar 14 14:54:38 PS1Hagrid systemd-journald[206]: Journal started
Mar 14 14:54:38 PS1Hagrid systemd-journald[206]: System journal (/var/log/journal/5c7cada7debf436a8d6a9e4d7ab763e4) is 104.0M, max 80.0M, 0B free.
Mar 14 14:54:38 PS1Hagrid systemd-journald[206]: System journal (/var/log/journal/5c7cada7debf436a8d6a9e4d7ab763e4) is 104.0M, max 80.0M, 0B free.
Mar 14 14:54:38 PS1Hagrid systemd-tmpfiles[306]: Cannot set file attribute for '/var/log/journal', value=0x00800000, mask=0x00800000: Operation not supported
Mar 14 14:54:38 PS1Hagrid kernel: snd_hda_intel 0000:00:1b.0: control 2:0:0:PCM Playback Volume:0 is already present
Mar 14 14:54:38 PS1Hagrid systemd-tmpfiles[306]: Cannot set file attribute for '/var/log/journal/5c7cada7debf436a8d6a9e4d7ab763e4', value=0x00800000, mask=0x00800000: Operation not supported
Mar 14 14:54:38 PS1Hagrid systemd-tmpfiles[306]: Cannot set file attribute for '/var/log/journal/remote', value=0x00800000, mask=0x00800000: Operation not supported
Mar 14 14:54:38 PS1Hagrid systemd-udevd[253]: Process '/usr/bin/alsactl restore 0' failed with exit code 99.
Mar 14 14:54:38 PS1Hagrid kernel: nvidia: loading out-of-tree module taints kernel.
Mar 14 14:54:38 PS1Hagrid kernel: nvidia: module license 'NVIDIA' taints kernel.
Mar 14 14:54:38 PS1Hagrid kernel: Disabling lock debugging due to kernel taint
Mar 14 14:54:38 PS1Hagrid kernel: NVRM: loading NVIDIA UNIX x86_64 Kernel Module  378.13  Tue Feb  7 20:10:06 PST 2017
Mar 14 14:54:38 PS1Hagrid kernel:  (using threaded interrupts)
Mar 14 14:54:38 PS1Hagrid kernel: 
Mar 14 14:54:59 PS1Hagrid systemd-resolved[330]: Using degraded feature set (UDP) for DNS server 192.168.1.254.
Mar 14 14:54:59 PS1Hagrid systemd-resolved[330]: Using degraded feature set (UDP) for DNS server 192.168.1.254.
~

Thanks for all the help, I'd heard the community here can be a little harsh to newcomers but it seems great.

My main concern is with everything before systemd-analyze stuff. Alhough it would still be useful, I'm less interested in trimming down 2.5 seconds to 2.2 seconds in the userspace and more interested in trimming all the stuff before it from 27 seconds to e.g. 17 seconds.

Last edited by ewaller (2017-03-14 15:15:23)

Scimmia · 2017-03-14 15:06:08

SaltyBarcode wrote:

My main concern is with everything before systemd-analyze stuff. Alhough it would still be useful, I'm less interested in trimming down 2.5 seconds to 2.2 seconds in the userspace and more interested in trimming all the stuff before it from 27 seconds to e.g. 17 seconds.

So is all that time before it says "Starting Version 232"? If so, that's all prior to Arch.

Last edited by Scimmia (2017-03-14 15:14:00)

ewaller · 2017-03-14 15:18:19

I took the liberty of adding code tags to your post; you should use them around program output and file contents : https://bbs.archlinux.org/help.php#bbcode

I see what happened, run that command again without a pager; we only got the first bit. journalctl -b --no-pager should give a lot more output.
Sorry about that.

SaltyBarcode · 2017-03-14 15:33:35

Scimmia wrote:

SaltyBarcode wrote:
My main concern is with everything before systemd-analyze stuff. Alhough it would still be useful, I'm less interested in trimming down 2.5 seconds to 2.2 seconds in the userspace and more interested in trimming all the stuff before it from 27 seconds to e.g. 17 seconds.
So is all that time before it says "Starting Version 232"? If so, that's all prior to Arch.

Yes, it's before that, but it's still Kernel & hardware related, right? I think GRUB might at be fault here, though I have no categorical proof.

ewaller wrote:

I see what happened, run that command again without a pager; we only got the first bit. journalctl -b --no-pager should give a lot more output.
Sorry about that.

Here's journalctl -b --no-pager, though it's not much more clear.

journalctl -b --no-pager
-- Logs begin at Thu 2017-02-23 18:02:10 GMT, end at Tue 2017-03-14 15:06:41 GMT. --
Mar 14 14:54:38 PS1Hagrid systemd-journald[206]: Time spent on flushing to /var is 810us for 0 entries.
Mar 14 14:54:38 PS1Hagrid kernel: PCCT header not found.
Mar 14 14:54:38 PS1Hagrid kernel: pmd_set_huge: Cannot satisfy [mem 0xf8000000-0xf8200000] with a huge-page mapping due to MTRR override.
Mar 14 14:54:38 PS1Hagrid kernel: (NULL device *): hwmon_device_register() is deprecated. Please convert the driver to use hwmon_device_register_with_info().
Mar 14 14:54:38 PS1Hagrid kernel: ACPI Warning: SystemIO range 0x0000000000001828-0x000000000000182F conflicts with OpRegion 0x0000000000001800-0x000000000000187F (\PMIO) (20160930/utaddress-247)
Mar 14 14:54:38 PS1Hagrid kernel: ACPI Warning: SystemIO range 0x0000000000001C40-0x0000000000001C4F conflicts with OpRegion 0x0000000000001C00-0x0000000000001FFF (\GPR) (20160930/utaddress-247)
Mar 14 14:54:38 PS1Hagrid kernel: ACPI Warning: SystemIO range 0x0000000000001C30-0x0000000000001C3F conflicts with OpRegion 0x0000000000001C00-0x0000000000001C3F (\GPRL) (20160930/utaddress-247)
Mar 14 14:54:38 PS1Hagrid kernel: ACPI Warning: SystemIO range 0x0000000000001C30-0x0000000000001C3F conflicts with OpRegion 0x0000000000001C00-0x0000000000001FFF (\GPR) (20160930/utaddress-247)
Mar 14 14:54:38 PS1Hagrid kernel: ACPI Warning: SystemIO range 0x0000000000001C00-0x0000000000001C2F conflicts with OpRegion 0x0000000000001C00-0x0000000000001C3F (\GPRL) (20160930/utaddress-247)
Mar 14 14:54:38 PS1Hagrid kernel: ACPI Warning: SystemIO range 0x0000000000001C00-0x0000000000001C2F conflicts with OpRegion 0x0000000000001C00-0x0000000000001FFF (\GPR) (20160930/utaddress-247)
Mar 14 14:54:38 PS1Hagrid kernel: lpc_ich: Resource conflict(s) found affecting gpio_ich
Mar 14 14:54:38 PS1Hagrid kernel: r8169 0000:03:00.0: can't disable ASPM; OS doesn't have ASPM control
Mar 14 14:54:38 PS1Hagrid systemd-journald[206]: Journal started
Mar 14 14:54:38 PS1Hagrid systemd-journald[206]: System journal (/var/log/journal/5c7cada7debf436a8d6a9e4d7ab763e4) is 104.0M, max 80.0M, 0B free.
Mar 14 14:54:38 PS1Hagrid systemd-journald[206]: System journal (/var/log/journal/5c7cada7debf436a8d6a9e4d7ab763e4) is 104.0M, max 80.0M, 0B free.
Mar 14 14:54:38 PS1Hagrid systemd-tmpfiles[306]: Cannot set file attribute for '/var/log/journal', value=0x00800000, mask=0x00800000: Operation not supported
Mar 14 14:54:38 PS1Hagrid kernel: snd_hda_intel 0000:00:1b.0: control 2:0:0:PCM Playback Volume:0 is already present
Mar 14 14:54:38 PS1Hagrid systemd-tmpfiles[306]: Cannot set file attribute for '/var/log/journal/5c7cada7debf436a8d6a9e4d7ab763e4', value=0x00800000, mask=0x00800000: Operation not supported
Mar 14 14:54:38 PS1Hagrid systemd-tmpfiles[306]: Cannot set file attribute for '/var/log/journal/remote', value=0x00800000, mask=0x00800000: Operation not supported
Mar 14 14:54:38 PS1Hagrid systemd-udevd[253]: Process '/usr/bin/alsactl restore 0' failed with exit code 99.
Mar 14 14:54:38 PS1Hagrid kernel: nvidia: loading out-of-tree module taints kernel.
Mar 14 14:54:38 PS1Hagrid kernel: nvidia: module license 'NVIDIA' taints kernel.
Mar 14 14:54:38 PS1Hagrid kernel: Disabling lock debugging due to kernel taint
Mar 14 14:54:38 PS1Hagrid kernel: NVRM: loading NVIDIA UNIX x86_64 Kernel Module  378.13  Tue Feb  7 20:10:06 PST 2017
Mar 14 14:54:38 PS1Hagrid kernel:  (using threaded interrupts)
Mar 14 14:54:38 PS1Hagrid kernel: 
Mar 14 14:54:59 PS1Hagrid systemd-resolved[330]: Using degraded feature set (UDP) for DNS server 192.168.1.254.
Mar 14 14:54:59 PS1Hagrid systemd-resolved[330]: Using degraded feature set (UDP) for DNS server 192.168.1.254.
Mar 14 15:06:41 PS1Hagrid systemd-resolved[330]: Using degraded feature set (UDP) for DNS server 192.168.1.254.

I did change some settings in /etc/systemd/journald.conf recently, including MaxLevelStore/Syslog/Console/Wall levels, would that affect the output of this?

Last edited by SaltyBarcode (2017-03-14 15:36:04)

Scimmia · 2017-03-14 15:57:31

SaltyBarcode wrote:

Scimmia wrote:
SaltyBarcode wrote:
My main concern is with everything before systemd-analyze stuff. Alhough it would still be useful, I'm less interested in trimming down 2.5 seconds to 2.2 seconds in the userspace and more interested in trimming all the stuff before it from 27 seconds to e.g. 17 seconds.
So is all that time before it says "Starting Version 232"? If so, that's all prior to Arch.
Yes, it's before that, but it's still Kernel & hardware related, right? I think GRUB might at be fault here, though I have no categorical proof.

Very unlikely to be kernel related. Could be grub, but it's much more likely just your system's firmware. Set grub not to automatically load anything, see how long it takes to get that far.

SaltyBarcode · 2017-03-14 16:05:05

Scimmia wrote:

SaltyBarcode wrote:
Scimmia wrote:
So is all that time before it says "Starting Version 232"? If so, that's all prior to Arch.
Yes, it's before that, but it's still Kernel & hardware related, right? I think GRUB might at be fault here, though I have no categorical proof.
Very unlikely to be kernel related. Could be grub, but it's much more likely just your system's firmware. Set grub not to automatically load anything, see how long it takes to get that far.

I set the timeout to be 5 instead of 0 for grub, and it took ~13 seconds to get there. After I select arch linux, there's a flashing cursor for around 5 seconds before the "Starting Version..." screen, so something is holding it up. Could it be to do with os-prober, or would that happen before grub?

Scimmia · 2017-03-15 14:32:18

That does sound like either grub or the kernel, then. Not sure how to take it further

Arch Linux

#1 2017-03-14 14:23:24

Slow boot, yet fast systemd-analyze time

#2 2017-03-14 14:29:42

Re: Slow boot, yet fast systemd-analyze time

#3 2017-03-14 14:31:28

Re: Slow boot, yet fast systemd-analyze time

#4 2017-03-14 14:37:29

Re: Slow boot, yet fast systemd-analyze time

#5 2017-03-14 14:46:02

Re: Slow boot, yet fast systemd-analyze time

#6 2017-03-14 15:02:28

Re: Slow boot, yet fast systemd-analyze time

#7 2017-03-14 15:06:08

Re: Slow boot, yet fast systemd-analyze time

#8 2017-03-14 15:18:19

Re: Slow boot, yet fast systemd-analyze time

#9 2017-03-14 15:33:35

Re: Slow boot, yet fast systemd-analyze time

#10 2017-03-14 15:57:31

Re: Slow boot, yet fast systemd-analyze time

#11 2017-03-14 16:05:05

Re: Slow boot, yet fast systemd-analyze time

#12 2017-03-15 14:32:18

Re: Slow boot, yet fast systemd-analyze time

Board footer