[SOLVED] systemd-analyze plot failure

[GreyGeek]

I was curious about how long each systemd service took to become active. My bootup takes 19 secs from the grub bell to the password prompt, and just a second to display the desktop after entering my password. That is the fastest bootup time I've ever had, due primarily to the SSD on which Bionic sets.

So, I did:
systemd-analyze plot > plot.svg

Firefox could not read plot.svg. It was only 129 bytes long, not the 300Kb I was expecting. I put a sudo infront of the command and it, too, failed with a tiny plot.svg file. Systemd is v237 on my BIonic. I did a bug hunt and found:
https://github.com/systemd/systemd/issues/7667
which showed that on Dec 15, 2017, this bug was present in v235 and v236 as well. Unlike the bug report, using the plot command didn't give an error message, it just wouldn't product a valid svg file. A proposed patch, https://github.com/LibreELEC/LibreELEC.tv/pull/2364, if it came down the pipe, didn't work on my installation. It's been ten months since the patch was merged. A regression

systemd-analyze blame worked OK in a Konsole. I wondered if I could print out the plot data to a text file.
systemd-analyze plot > plot.txt

Sure enough, it worked. Futhermore, the contents of plot.txt looked like a valid svg file, so I renamed it to plot.svg and then Firefox opened it just fine. So, I will be using this workaround till the REAL patch shows up.

[vinnywright]

strange , works just fine @hear on the new Kubuntu-1804 install in the new SSD

VINNY

[GreyGeek]

What version of systemd are you running? Mine is v237 And also the kernel? Mine is 4.15.0-34-generic

[mr_raider]

Chrome just opened my plot file fine.

[Thomas00]

Never a dull day :-)
This is brilliant, first time I hear of this feature, and it comes just in time as for a couple of days my machine all of a sudden takes ages to boot and I couldn't find out what was going on.
Do I read this chart correctly that the services are listed top down as they get started, with the red bar showing that they are running. Those with a short red bar are ones which started and quickly finished.

Which means that the last process under the circle is the one causing my delay?


nss-lookup.target is the last one before the gap, then there is nothing for 90 seconds and then sysinit.target starts
Has anyone got an idea what those two do?

By the way, systemd-analyze plot > plot.svg worked for me without the need for renaming.

[SpecialEd]

You maybe better off running systemd-analyze and systemd-analyze blame. Your results will be more obvious.

[vinnywright]

What version of systemd are you running? Mine is v237 And also the kernel? Mine is 4.15.0-34-generic

same as you ?

VINNY

[GreyGeek]

One day later and the plot command works for me too.

In looking over the plot I noticed that apt-daily.service timer was taking 1 min and 9 seconds to activate (dark red bar). This must be in the background because I am still booting from the grub bell to my login screen in 23 seconds and from there to a functional desktop in about two seconds. I remember when running my 16.04 system on a spinning disk my bootup times were 3 minutes. Using the plot function I noticed that most of that time was using activating (dark red bar), followed by 2.8 seconds of apt-daily-upgrade.service activating. I also remembered that there was a change to the timer script which would make those services run randomly 15 to 30 minutes AFTER the boot up as a background service.

The solution was to create or change the script at /etc/systemd/system/apt-update.serviceapt-daily.timer and make it read as follows:

# apt-daily timer configuration override
[Timer]
OnBootSec=15min
OnUnitActiveSec=1d
AccuracySec=1h
RandomizedDelaySec=30min

That knocked over 2 minutes off my bootup time when I was using a spinning HD.

So, I checked for the existence of that file in my Bionic installation and found a subdirectory called /etc/systemd/system/apt-daily.timer.d
Inside of it was a file titled "override.conf". In that file was the exact code above. BUT, Bionic was ignoring it. I created the apt-daily.serviceapt-daily.timer file under /etc/systemd/system and put that same code in it and rebooted.

Before the code change plot showed:

Startup finished in 5.556s (kernel) + 1min 20.427s (userspace) = 1min 25.983s graphical.target reached after 8.918s in userspace

After the code change and a reboot plot showed:

Startup finished in 5.170s (kernel) + 8.284s (userspace) = 13.455s graphical.target reached after 7.615s in userspace

The odd thing is that before and after that code change my MEASURED time to the login screen from the grub beep was 24 seconds. From the moment I hit the enter key on my password till I had a working desktop was under three seconds. Sort of like what VINNY says, "it just fades in within a second or two".

The plot.svg before the change showed 86 seconds of graph. After the change just 13 seconds.

[Thomas00]

You maybe better off running systemd-analyze and systemd-analyze blame. Your results will be more obvious.

Thanks for the suggestions!
Well, it shows that 3 minutes are somehow spent in userspace, but this is not reflected in the "blame" list? The one which takes longest is the 6 second NetworkManager one below.

thomas@hermes:~$ systemd-analyze
Startup finished in 23.098s (firmware) + 8.326s (loader) + 12.706s (kernel) + 3min 632ms (userspace) = 3min 44.763s
graphical.target reached after 1min 37.266s in userspace
thomas@hermes:~$ systemd-analyze blame
6.411s NetworkManager-wait-online.service
1.372s dev-mapper-nvme0n1p3_crypt.device
771ms keyboard-setup.service
607ms udisks2.service
...

The nss-lookup.target / sysinit.target item from systemd-analyze plot don't show at all.

[GreyGeek]

...
The nss-lookup.target / sysinit.target item from systemd-analyze plot don't show at all.

That's why, IMO, plot.svg is a better tool. It shows ever thing, beginning with the kernel and everything that uses the kernel on the way to the desktop. If you view the plot.svg of your system you'll see LONG dark red bars extending horizontally. They are the ones consuming your boot time. My culprit was apt-daily.service, which I modified as shown above.

[Snowhog]

Not suggesting that the Q&A in this is, or will be helpful, but it might point you in the general direction.

[vinnywright]

Thanks for the suggestions!
Well, it shows that 3 minutes are somehow spent in userspace, but this is not reflected in the "blame" list? The one which takes longest is the 6 second NetworkManager one below.

The nss-lookup.target / sysinit.target item from systemd-analyze plot don't show at all.

NetworkManager-wate-online.service can be disabled safely to save that time .

sudo apt install kde-config-systemd

after installing you will find it at the bottom of the list in system settings , open it and sort by "services" find it and right click on it's line , then "mask" it .
reboot and it will not run and eat up that amount of time

VINNY

[Thomas00]

That's why, IMO, plot.svg is a better tool. It shows ever thing, beginning with the kernel and everything that uses the kernel on the way to the desktop. If you view the plot.svg of your system you'll see LONG dark red bars extending horizontally. They are the ones consuming your boot time. My culprit was apt-daily.service, which I modified as shown above.

Thanks GreyGeek, the chart in post 5 shows my plot.svg. I actually only learned about this chart through this thread and have read up about it since. Wouldn't say I have fully understood things though, especially regarding the *.target entries.
My understanding is that top down I see the services as systemd launches them, left to right shows when a service gets started and for how long it ran. *.targets are like milestones to make sure starting services have all the requirements in place, e.g network active, before they get launched.

Now, in my case things look normal until nss-lookup.target is reached, then there doesn't seem to be any activity for 1:30 minutes which is when sysinit.target is listed and things continue as normal.
If my assumptions are correct I need to find out which services need to be complete/initialized to declare sysinit.target, one of those takes the 1:30 minutes
Is there a way to find out what a .target is dependent on?

@Vinny, thanks a lot. The kde-config.systemd thing is now on my list of post-install configs, I managed to eliminate the 6s wait for NetworkManager like you suggested.
Unfortunately the huge 1:30 minute delay between nss-lookup.target and sysinit.target is still there.

@Snowhog, thanks for the link, good suggestions but so far no success I am afraid.

[mr_raider]

Run

systemd-analyze critical-chain

To see what's holding up boot

Sent from my ONEPLUS A5010 using Tapatalk

[Thomas00]

Thanks mr_raider, here's what I got:

thomas@hermes:~$ sudo systemd-analyze critical-chain
[sudo] password for thomas:
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 @1min 31.185s
└─multi-user.target @1min 31.185s
└─postfix.service @1min 31.183s +1ms
└─postfix@-.service @1min 30.497s +684ms
└─network-online.target @1min 30.496s
└─network.target @1min 30.496s
└─NetworkManager.service @1min 30.337s +158ms
└─dbus.service @1min 30.326s
└─basic.target @1min 30.304s
└─sockets.target @1min 30.304s
└─snapd.socket @1min 30.300s +3ms
└─sysinit.target @1min 30.291s
└─systemd-timesyncd.service @1.737s +212ms
└─systemd-tmpfiles-setup.service @1.722s +11ms
└─local-fs.target @1.716s
└─run-user-1000-gvfs.mount @1min 56.974s
└─run-user-1000.mount @1min 54.169s
└─local-fs-pre.target @598ms
└─keyboard-setup.service @158ms +438ms
└─systemd-journald.socket @157ms
└─system.slice @154ms
└─-.slice @154ms

If I read this correctly it took almost 2 minutes to start/complete run-user-1000.mount

This, Snowhog's link higher up, and bit of more poking around finally led me to this post https://www.dedoimedo.com/computers/...slow-boot.html which covers my exact problem
It mentioned to check the boot log /var/log/boot.log file and there was my error message:

[  OK  ] Started Authorization Manager.
[ TIME ] Timed out waiting for device dev-disk-by\x2duuid-cd17d3f6\x2df424\x2d4a2f\x2d97f5\x2d5435238caeb2.device.
[DEPEND] Dependency failed for Cryptography Setup for data_crypt.
[DEPEND] Dependency failed for Local Encrypted Volumes.
[  OK  ] Reached target System Initialization.

So over to /etc/crypttab and there was my faulty entry. This may have been a leftover from a previous issue where I all of a sudden lost the dev/mapper entry for an encrypted drive and had to recreate. In any case, after removing that device from crypttab what took 1.30 minutes before is now down to 2.8 seconds.
Case closed and thanks a lot for all your help!

thomas@hermes:~$ sudo systemd-analyze
[sudo] password for thomas:
Startup finished in 13.563s (firmware) + 8.438s (loader) + 20.196s (kernel) + 2.860s (userspace) = 45.059s
graphical.target reached after 2.853s in userspace
thomas@hermes:~$