systemd-analyze issues

yzb3 · 2013-10-31 17:18:38

I noticed that my boot has become a bit slower than before, so I decided to follow the steps described in the Improve Boot Performance Wiki page. However, I was not happy with the outcome of my research, especially with pure systemd-analyze, which yields crazy results.

systemd-analyze (the loader value is plain silly, but the whole process does take around 25 seconds):

Startup finished in 584542y 2w 2d 20h 1min 42.881s (loader) + 1.881s (kernel) + 24.379s (userspace) = 26.260s

systemd-analyze critical-chain:

graphical.target @24.379s
└─multi-user.target @24.378s
  └─systemd-logind.service @24.186s +192ms
    └─basic.target @24.185s
      └─timers.target @24.184s
        └─systemd-tmpfiles-clean.timer @24.183s
          └─sysinit.target @3.612s
            └─systemd-update-utmp.service @3.466s +146ms
              └─systemd-tmpfiles-setup.service @3.378s +87ms
                └─local-fs.target @3.378s
                  └─home.mount @3.298s +79ms
                    └─dev-disk-by\x2duuid-c26e6d9a\x2d0bbb\x2d436a\x2da217\x2d95c738b5b9c6.device @3.297s

systemd-analyze blame:

          1.144s systemd-remount-fs.service
           882ms systemd-tmpfiles-setup-dev.service
           529ms systemd-udev-trigger.service
           468ms systemd-sysctl.service
           468ms systemd-vconsole-setup.service
           467ms sys-kernel-debug.mount
           414ms kmod-static-nodes.service
           192ms systemd-logind.service
           182ms dev-mqueue.mount
           182ms sys-kernel-config.mount
           181ms dev-hugepages.mount
           180ms tmp.mount
           146ms systemd-update-utmp.service
           128ms user@1000.service
           106ms systemd-udevd.service
            89ms systemd-random-seed.service
            87ms systemd-tmpfiles-setup.service
            79ms home.mount
            52ms systemd-journal-flush.service
            38ms systemd-user-sessions.service
            32ms systemd-backlight@acpi_video0.service
             5ms alsa-restore.service
             2ms systemd-tmpfiles-clean.service

systemd-analyze plot > plot.svg (http://s7.postimg.org/iztmz5ep5/plot.png):

Can someone help me interpret these results? I am pretty sure I have not cluttered the startup process on my own.

clfarron4 · 2013-10-31 19:39:39

Also got this with one of my fresh installs, set-up to run Cinnamon. I've just ignore it for the time being, but if there anything that goes majorly wrong, I would look into it.

qinohe · 2013-10-31 19:45:51

Hi welcome Arch, not much to say but

graphical.target @24.379s
└─multi-user.target @24.378s

I think you should you run one, or graphical or multi-user, not both.

yzb3 · 2013-10-31 20:03:27

Also got this with one of my fresh installs, set-up to run Cinnamon.

You mean the funky time value or the slowdown? I don't mind silly stats, but slow boot is irritating.

graphical.target @24.379s
└─multi-user.target @24.378s

I think you should you run one, or graphical or multi-user, not both.

I didn't setup anything to launch. This is what bothers me most: I don't even turn anything on during boot; no network, no xorg, no autologin - hardly anything. There are no external devices (except for input and the monitor) and there is only 1 HDD.

Last edited by yzb3 (2013-10-31 20:05:12)

qinohe · 2013-10-31 20:14:00

Here is your target, https://wiki.archlinux.org/index.php/Systemd#Targets

yzb3 · 2013-10-31 20:28:13

Ok, but the wiki says that

The standard target is default.target, which is aliased by default to graphical.target

which is described as

Multi-user, graphical. Usually has all the services of runlevel 3 (multi-user.target) plus a graphical login.

This would mean this is the standard behavior. Do you suggest that I add a kernel boot parameter changing the default target from graphical.target to multi-user.target? Will this speed things up noticeably?

I don't want anything turned on by default - nothing else than a raw boot to the console. I thought that this was already my case, but the slow boot would indicate otherwise.

Last edited by yzb3 (2013-10-31 20:30:11)

qinohe · 2013-10-31 20:33:53

yzb3 wrote:

Do you suggest that I add a kernel boot parameter changing the default target from graphical.target to multi-user.target? Will this speed things up noticeably?

I suggested nothing, I only suggest you choose which one to use and follow instructions how to do that in the wiki. I don't know about speed, might make a difference, maybe not.

yzb3 · 2013-10-31 20:51:41

Well, that sounded like the only option anyway. I changed the default target to multi-user and it looks like it has sped things up a bit.

systemd-analyze:

Startup finished in 584542y 2w 2d 20h 1min 44.615s (loader) + 1.956s (kernel) + 20.987s (userspace) = 22.944s

systemd-analyze critical-chain:

multi-user.target @20.987s
└─systemd-logind.service @20.793s +193ms
  └─basic.target @20.792s
    └─timers.target @20.791s
      └─systemd-tmpfiles-clean.timer @5.724s
        └─sysinit.target @5.724s
          └─systemd-update-utmp.service @5.608s +116ms
            └─systemd-tmpfiles-setup.service @5.554s +52ms
              └─local-fs.target @5.554s
                └─home.mount @5.443s +111ms
                  └─local-fs-pre.target @5.443s
                    └─systemd-remount-fs.service @689ms +4.753s
                      └─systemd-journald.socket @394ms
                        └─-.mount @394ms
                          └─system.slice @690ms
                            └─-.slice @689ms

Since systemd itself might be the main reason for the slowdown, I will investigate in this direction.

qinohe · 2013-10-31 20:56:07

That looks better, I you are satisfied with the answer and think it's solved, please edit the title in your first post by adding [solved] thanks.

clfarron4 · 2013-10-31 21:40:41

yzb3 wrote:

Also got this with one of my fresh installs, set-up to run Cinnamon.
You mean the funky time value or the slowdown? I don't mind silly stats, but slow boot is irritating.

I mean the funky time values, which we will want to look at.

yzb3 · 2013-10-31 22:05:56

qinohe wrote:

if you are satisfied with the answer and think it's solved, please edit the title in your first post by adding [solved] thanks.

Nah, in my case 22s is still at least 3 times too slow. I will investigate further; maybe it's because I'm using btrfs? Then again, I have been using it for a long time, and the boot used to be at least twice as fast.

I'm thinking about disabling systemd services that I don't need and modifying the kernel boot parameters. For now I managed to add the

raid=noautodetect

parameter, but it didn't change anthing.

qinohe · 2013-10-31 22:17:23

Then I guess you run of SSD cause if these times are HDD then there still very nice, goodluck.

mrunion · 2013-11-01 01:37:42

qinohe wrote:

Hi welcome Arch, not much to say but
graphical.target @24.379s
└─multi-user.target @24.378s
I think you should you run one, or graphical or multi-user, not both.

Please pardon my ignorance, but my system starts VERY slow -- over 1 minute to boot to GDM!

Anyway, I have mine set to boot to the graphical.target, but it simply loads the multi-user.target first, then the additional graphical stuff. Am I missing something? Running:

systemctl enable graphic.target

Still causes the:

graphical.target @29.452s
└─multi-user.target @29.451s

Have I compeltely lost my mind?

WonderWoofy · 2013-11-01 02:41:18

multi-user.target is a dependency of the graphical.target. That is to say that if you enable the multi-user.target, obviously it will start, but enabling the graphical.target will also start the multi-user.target before it is able to start the things there.

Take a look at the multi-user.target.wants and the graphical.target.wants and you will see that there is a reason why it needs to start the multi-user.target before the graphical.target. The multi-user.target is where the user services get pulled in.

yzb3 · 2013-11-01 06:38:10

I tried changing my kernel boot parameters so that initrd could be bypassed (following http://freedesktop.org/wiki/Software/sy … mizations/), but no luck there; changing

linux   /boot/vmlinuz-linux root=UUID=c21e3a5a-0bac-216a-a201-95c768b5a9c6 rw quiet

to

linux   /boot/vmlinuz-linux rootfs=btrfs root=/dev/sda2 rw quiet

and commenting out the initrd line only resulted in a kernel panic right after choosing that boot option.

I also tried slimming my kernel image (http://blog.falconindy.com/articles/opt … tcpio.html), but even though the system did boot successfully, there was no difference in terms of speed.

Last edited by yzb3 (2013-11-01 07:01:51)

qinohe · 2013-11-01 08:06:31

mrunion wrote:

Please pardon my ignorance, but my system starts VERY slow -- over 1 minute to boot to GDM!
[...]
Have I compeltely lost my mind?

I stand corrected, you didn't lose your mind, I did.

WonderWoofy is totally right, I tried it, it's true they're both started, I feel like an a..
Never in my life I booted into runlevel 5, I always used runlevel 3 on Arch and BSD systems.

yzb3 · 2013-11-03 13:08:58

I read that a proper kernel boot parameter allows to omit mounting root at fstab level. I tried that, but it doesn't seem to have improved my boot speed noticeably.

systemd-analyze critical-chain:

multi-user.target @23.604s
└─systemd-logind.service @23.378s +225ms
  └─basic.target @23.377s
    └─timers.target @23.376s
      └─systemd-tmpfiles-clean.timer @23.376s
        └─sysinit.target @2.419s
          └─systemd-update-utmp.service @2.344s +75ms
            └─systemd-tmpfiles-setup.service @2.122s +221ms
              └─local-fs.target @2.121s
                └─home.mount @2.013s +107ms
                  └─dev-disk-by\x2duuid-c26e6d9a\x2d0bbb\x2d436a\x2da217\x2d95c738b5b9c6.device @2.013s

systemd-blame:

           501ms systemd-vconsole-setup.service
           429ms sys-kernel-debug.mount
           405ms kmod-static-nodes.service
           349ms systemd-udev-trigger.service
           300ms systemd-sysctl.service
           225ms systemd-logind.service
           221ms systemd-tmpfiles-setup.service
           126ms dev-hugepages.mount
           123ms tmp.mount
           121ms sys-kernel-config.mount
           119ms dev-mqueue.mount
           107ms home.mount
            89ms systemd-tmpfiles-setup-dev.service
            75ms systemd-update-utmp.service
            71ms systemd-user-sessions.service
            66ms systemd-remount-fs.service
            66ms systemd-journal-flush.service
            39ms systemd-backlight@acpi_video0.service
            36ms user@1000.service
            17ms systemd-udevd.service
            10ms systemd-random-seed.service
             4ms alsa-restore.service

I analyzed the journal and it would seem that the slowest stage is the following:

13:37:27 arch systemd[1]: Reached target System Initialization.
13:37:48 arch systemd[1]: Starting D-Bus System Message Bus Socket.

It looks like it corresponds to the sysinit.target visible in the output of the systemd-analyze critial-chain command. Is there any way I can speed this stage up?

Edit: after several reboots I was displeased to notice that the ~20s pause occurred at different targets; at firtst it was sysinit.target, then timers.target, after that basic.target... I removed quiet from the kernel parameters in hopes of pinpointing the actual culprit and then it stopped at "Starting sockets". It doesn't look like I'm getting anywhere with this.

Any ideas?

Last edited by yzb3 (2013-11-03 15:26:56)

WonderWoofy · 2013-11-03 17:59:12

yzb3 wrote:

I read that a proper kernel boot parameter allows to omit mounting root at fstab level.
...
Any ideas?

So are you saying that you have added all the proper mount options to the kernel command line itself? If so, then that is not the only thing you need to do. If you take a look at your systemd-analyze blame output, you'll see that the systemd-remount-fs.service is still run, and taking 66ms. So if it is mounted to your satisfaction initially (by the kernel command line), then it is then coming back and remounting that partition with the same options, which are likely still set in your fstab.

You may also need to actually mask the systemd-remount-fs.service in order to have it totally stop running. But in reality, saving 66ms is not really worth the hassle to me. I have also in the past, moved all fstab entries to native systemd units, which did save a few ms, but ultimately, I decided that having all the mount configuration in a single centralized file (the fstab) was worth the extra few ms that it was taking to convert those via systemd-fstab-generator as well as remount the rootfs.

If you still want to go this route though, first try simply commenting the entry in fstab. If that doesn't fully work (systemd-remount-fs.service still runs), then mask the offending service. But keep in mind that normal boot time fluctuation is likely going to be >66ms.

yzb3 · 2013-11-03 19:47:12

WonderWoofy wrote:

So are you saying that you have added all the proper mount options to the kernel command line itself? If so, then that is not the only thing you need to do. If you take a look at your systemd-analyze blame output, you'll see that the systemd-remount-fs.service is still run, and taking 66ms. So if it is mounted to your satisfaction initially (by the kernel command line), then it is then coming back and remounting that partition with the same options, which are likely still set in your fstab.

I was also surprised to see this, since the root entry is in fact commented out in fstab . However, since it was only 66ms, I decided to ignore this.

WonderWoofy wrote:

You may also need to actually mask the systemd-remount-fs.service in order to have it totally stop running. But in reality, saving 66ms is not really worth the hassle to me.

Exactly.

The issue here is that I see nothing that would be even close to amounting to the ~20s lag that I am having at boot. What is more, my boot time fluctuation is ~5s, which is also confusing.

Edit:

I filed a bug with systemd bugzilla: https://bugs.freedesktop.org/show_bug.cgi?id=71277. The randomness of the boot lags makes it impossible for me to investigate further.

Edit:

In the meantime I rolled back to a fresh image of my root subvolume (aww yiss, btrfs) and the boot time has improved nicely. It is now 6.374s. Seriously, why would I be using Arch if I were OK with a 30 second boot ? I will leave the topic as unresolved for the time being - maybe some systemd developer will investigate my ticket and I will resolve the issue on the original subvolume.

Edit (and possible resolution):

The reason for the boot lags might be related to btrfs after all - after a few reboots my new subvolume became laggy as well (10s?! unacceptable). I thought I might give the clear_cache boot option a try (unfortunately I begun with nospace_cache, which borked things up a little bit and temporarily rendered the subvolume ro) and it sped boot up again. I will bring this up to btrfs devs, but I still think that systemd should have properly indicated the point at which the lag occurs.

Edit:

After a second clear_cache I started seeing btrfs-related errors and I received no answers on the btrfs mailing list regarding their resolution. I decided to reformat to ext4 and now my boot time takes a much more appropriate 3.472s.

Last edited by yzb3 (2013-11-22 17:30:47)

Arch Linux

#1 2013-10-31 17:18:38

systemd-analyze issues

#2 2013-10-31 19:39:39

Re: systemd-analyze issues

#3 2013-10-31 19:45:51

Re: systemd-analyze issues

#4 2013-10-31 20:03:27

Re: systemd-analyze issues

#5 2013-10-31 20:14:00

Re: systemd-analyze issues

#6 2013-10-31 20:28:13

Re: systemd-analyze issues

#7 2013-10-31 20:33:53

Re: systemd-analyze issues

#8 2013-10-31 20:51:41

Re: systemd-analyze issues

#9 2013-10-31 20:56:07

Re: systemd-analyze issues

#10 2013-10-31 21:40:41

Re: systemd-analyze issues

#11 2013-10-31 22:05:56

Re: systemd-analyze issues

#12 2013-10-31 22:17:23

Re: systemd-analyze issues

#13 2013-11-01 01:37:42

Re: systemd-analyze issues

#14 2013-11-01 02:41:18

Re: systemd-analyze issues

#15 2013-11-01 06:38:10

Re: systemd-analyze issues

#16 2013-11-01 08:06:31

Re: systemd-analyze issues

#17 2013-11-03 13:08:58

Re: systemd-analyze issues

#18 2013-11-03 17:59:12

Re: systemd-analyze issues

#19 2013-11-03 19:47:12

Re: systemd-analyze issues

Board footer