[systemd-devel] Understanding systemd-analyze's plots

[Kay Sievers]

On Sun, Nov 27, 2011 at 13:42, Gustavo Sverzut Barbieri
<barbieri at profusion.mobi> wrote:
> On Sun, Nov 27, 2011 at 2:44 AM, Kay Sievers <kay.sievers at vrfy.org> wrote:
>> On Sat, Nov 26, 2011 at 22:52, Stefan Majewsky
>> <stefan.majewsky at googlemail.com> wrote:
>>> my openSUSE 12.1 system boots in about 30 seconds, and I wanted to cut
>>> that time down a bit, so I took a look at systemd-analyze's blame and
>>> plot output.
>>>
>>> But I do not really know how to interpret the results which I see in
>>> the plot [1]. The startup sequence takes 20.5 seconds in userspace, of
>>> which only the last 3 seconds seem to be spent on what I consider "the
>>> interesting stuff": starting all sorts of services and finally
>>> bringing up KDM.
>>>
>>> The rest of the time seems to be spent activating the hardware,
>>> various mounts and udev. (According to the LED on my notebook's case,
>>> the disk is busy all the time.) To put my confusion into questions:
>>>
>>> 1. Why does the system need 6 seconds (from t=6.3s to t=12.3s on the
>>> plot) to activate some tmpfs mounts?
>>>
>>> 2. Why is localnet.service activating for a whole 7 seconds? I looked
>>> into it, it's only a SysV init script that sets hostname and
>>> domainname from the config in /etc, yet it's number 1 in
>>> systemd-analyze blame.
>>>
>>> 3. Why does it look like about nothing happens between t=13s and t=22s?
>>>
>>> It might be that openSUSE's unit files (or SysV leftovers) are not yet
>>> optimized for the early boot: For example, I seem to have saved some
>>> seconds by masking lvm.service (I don't use LVM at all). But that
>>> won't explain why systemd is actually slower on this stage of boot vs.
>>> the old SysV init some distro versions ago.
>>>
>>> Can someone enlighten me?
>>
>> These numbers just look like a slower disk. The timing graph is not
>> really useful if things wait for I/O. The old SUSE boot was in some
>> cases better optimized for slower rotating media than systemd is. How
>> fast is the disk? Try hdparm -t /dev/sda
>>
>> The filesystem is ext4? This is an updated or newly installed system?
>> The filesystem is formatted a while back? We've seen strange ext4
>> performance numbers on older filesystems, that just went away after
>> reformatting. We have no real idea what's causing this, maybe some
>> weird fragmentation issue.
>
> Kay, do you really think slow media is the only reason?

Yes, we've seen that before.

> I could check
> the plot right now and there is a super-strange delay from t=4.5 to
> t=6.5 (before doing anything at all).

It should be the SUSE initramfs, which does not support profiling like
dracut does.

> Later on there is the delay for mounts, those I agree may be related
> to slow media.
>
> But again from 13 to 22 it's basically waiting udev events... which is too much!
>
> I'd check a fresh install to avoid problem with legacy udev rules... I
> recall when I moved my gentoo from openrc to systemd I had a "hotplug"
> package (http://linux-hotplug.sourceforge.net) doing nothing useful.

I was in charge of that until recently. They don't provide that mess
to their users. :)

> Then I went to notice my kernel was also configured to call
> /sbin/hotplug even tho it did not exist was raising pid count, etc.

SUSE kernels don't use that.

> Last but not least, Kay you could write an article similar to
> Lennart's blogs about the proper systemd+udev setup, like "systemd +
> udev for packagers". People are doing crazy things! :-(

There is not that much of the crazy stuff left. And if the filesystem
is not on LVM or BIOS raid, most of these packages can be removed.
Many of the other broken things like blkid's scanning of /dev are
avoided with systemd, because we never call 'mount -a' and things like
that, we only run these tools in a specific device context triggered
by udev.

The long delay in remount / looks suspiciously like a storage related
problem. The raw speed of the device should give some clue, otherwise
only a reformat would make sure it isn't the filesystem.
As mentioned, we've got quite some reports like that, and they all
stated it went away with a reformat of the ext4 partition, but nobody
really looked into or had an idea what the real reason for all that
was.

Kay