Bug 1795021 - plymouth-quit-wait.service increases boot time by ~8 seconds
Summary: plymouth-quit-wait.service increases boot time by ~8 seconds
Keywords:
Status: CLOSED NOTABUG
Alias: None
Product: Fedora
Classification: Fedora
Component: plymouth
Version: rawhide
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
Assignee: Ray Strode [halfline]
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2020-01-26 13:12 UTC by Chris Murphy
Modified: 2020-02-29 22:03 UTC (History)
4 users (show)

Fixed In Version:
Clone Of:
Environment:
Last Closed: 2020-01-26 13:58:15 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)
unmasked plymouth-quit-wait, systemd-analyze plot (111.79 KB, image/svg+xml)
2020-01-27 05:53 UTC, Chris Murphy
no flags Details
masked plymouth-quit-wait, systemd-analyze plot (106.43 KB, image/svg+xml)
2020-01-27 05:53 UTC, Chris Murphy
no flags Details
debug log quit-wait masked (110.86 KB, text/plain)
2020-01-28 18:00 UTC, Chris Murphy
no flags Details
debug log quit-wait unmasked (110.87 KB, text/plain)
2020-01-28 18:07 UTC, Chris Murphy
no flags Details

Description Chris Murphy 2020-01-26 13:12:48 UTC
Description of problem:

plymouth-quit-wait.service seems to add significant time to boot for no reason.


Version-Release number of selected component (if applicable):
plymouth-0.9.4-11.20191022git32c097c.fc32.x86_64

How reproducible:
Always, every boot


Steps to Reproduce:
1. Clean install Fedora Workstation 32/Rawhide, reboot
2.
3.

Actual results:

plymouth-quit-wait.service unmasked

Startup finished in 1.887s (kernel) + 2.593s (initrd) + 10.872s (userspace) = 15.353s 

plymouth-quit-wait.service masked

Startup finished in 1.846s (kernel) + 2.445s (initrd) + 3.868s (userspace) = 8.160s 

$ systemd-analyze blame
8.328s plymouth-quit-wait.service 


Expected results:

I expect it shouldn't increase boot time.

Additional info:

Comment 1 Hans de Goede 2020-01-26 13:58:15 UTC
plymouth-quit-wait.service does not increase boot time, it waits for plymouth to be told by gdm to quit, so it runs beyond when gdm starts and once gdm starts you get your login screen, so although systemd-analyze counts plymouth-quit-wait.service as part of boot time, you win nothing by masking it, except that it drops from the statistics.

Try using a stopwatch to time the time from say pressing enter in the grub menu till the login screen shows and you will see that masking plymouth-quit-wait.service does not change a thing.

Comment 2 Chris Murphy 2020-01-27 05:52:40 UTC
Using the stopwatch method, unmasked plymouth-quit-wait.service boots ~3.5s faster. Sample size is 3 boots each.

Comment 3 Chris Murphy 2020-01-27 05:53:36 UTC
Created attachment 1655588 [details]
unmasked plymouth-quit-wait, systemd-analyze plot

Comment 4 Chris Murphy 2020-01-27 05:53:52 UTC
Created attachment 1655589 [details]
masked plymouth-quit-wait, systemd-analyze plot

Comment 5 Chris Murphy 2020-01-27 05:55:28 UTC
>unmasked plymouth-quit-wait.service boots ~3.5s faster

s/unmasked/masked

Comment 6 Hans de Goede 2020-01-27 14:21:23 UTC
(In reply to Chris Murphy from comment #2)
> Using the stopwatch method, unmasked plymouth-quit-wait.service boots ~3.5s
> faster. Sample size is 3 boots each.

Thank you for testing that, that is really weird though, looking at the systemd-analyze outputs in both cases gdm starts at around the 9.5 second mark and there really is no reason why it showing the login screen should wait for plymouth-quit-wait.service.

I guess that gdm is waiting for login's to be ok according to account-manager or some such and that that only happens once systemd believes the graphical target has been reached...

Comment 7 Chris Murphy 2020-01-28 01:58:50 UTC
I coincidentally ran into a related user report. They're disabling plymouth by boot parameter, not merely the wait systemd service unit. They found a significant delay with systemd-analyze, but I followed up with a request that they use a stop watch. They reported back finding a 3s delay with and without plymouth.

https://ask.fedoraproject.org/t/disabling-plymouth-reduces-boot-time-by-50-percent/5160/4?u=chrismurphy

Comment 8 Hans de Goede 2020-01-28 09:22:52 UTC
Thank you for pointing out the other bug / https://ask.fedoraproject.org/t/disabling-plymouth-reduces-boot-time-by-50-percent/5160/ to me.

I've been investigating why plymouth-quit-wait.service might be making the login screen showing take 3 seconds longer for you, but I've been unable to reproduce this.

gdm will tell plymouth to quit when it gets a connection from the greeter, iow when the login screen shows. So theoretically the systemd-analyze time with plymouth-quit-wait.service included should be a good indication of the boot time, but clearly it isn't.

What might be interesting is if you can add "plymouth.debug=stream:/dev/null" to your kernel commandline, this will make plymouth write out a debug log to /var/log/plymouth-debug.log including timestamps. plymouth will quit when told to by gdm independent of the masking of plymouth-quit-wait.service, so it would be interesting to see if masking / unmasking it results in a significantly different end-time in the  /var/log/plymouth-debug.log .

Comment 9 Chris Murphy 2020-01-28 18:00:49 UTC
Created attachment 1656074 [details]
debug log quit-wait masked

stopwatch 18s

Comment 10 Chris Murphy 2020-01-28 18:07:32 UTC
Created attachment 1656076 [details]
debug log quit-wait unmasked

stopwatch 19s

Comment 11 Hans de Goede 2020-02-02 08:59:12 UTC
Thanks, so in both cases plymouth gets told to deactivate at 10.5 seconds or to be precise at 00:00:10.496 to the millisecond exactly on both cases (coincidence much?).

And in both cases plymouth gets told to quit around the same time, at 00:00:16.779 (unmasked) resp. 00:00:16.543 (masked) and then actually quits at 00:00:16.790 (masked) resp. 00:00:16.554 (masked).

So I do not really see much if any difference between the two.

Comment 12 Hans de Goede 2020-02-19 18:02:25 UTC
While working on another bug (bug 1794333) I did notice that plymouth does cause a boot delay, unrelated to plymouth-quit-wait.service. When asked by gdm to deactivate gdm finishes the current throbber animation which is on a cycle of 2 seconds; and then also plays an end animation which takes 1 second.

Plymouth tries to predict the boot time using a measurement of the previous boot and then starts the end-sequence described above at 90%, but that is not reliable and with modern boot times of say 5 seconds, the 10% used as margin is only 0.5 seconds where as the end sequence may last up to 3 seconds (if we are unlucky).

I've prepared a plymouth patch which adds an option to immediately deactivate when requested to deactivate, skipping the wait (which may last up to 3 seconds), this comes at the cost of the transition to gdm being somewhat more abrupt (no more one last fading out circling round of the spinner).

I've done a scratch-build of plymouth with this patch added, please give it a try and:
a) Check if it reduces boot time
b) Let me know what you think of the new transition to gdm vs the old transition.

You can find the scratch-build here:
https://koji.fedoraproject.org/koji/taskinfo?taskID=41654795

Comment 13 Hans de Goede 2020-02-19 18:06:56 UTC
p.s. To install the plymouth from koji do the following:

1) Run "rpm -qa | grep plymouth | sort"
2) Download the rpms from the link for the plymouth (sub)packages which you have installed
3) In a folder with the downloaded rpms run: "sudo rpm -Uvh plymouth*"
4) Run "sudo dracut -f" to regenerate the initrd for your currently running kernel so that the new plymouth gets added to it
5) Run "uname -a" note the kernel version
6) reboot
7) Run "uname -a" again, if the kernel version is different the kernel was upgraded since you last rebooted, go to step 4.

Comment 14 Chris Murphy 2020-02-28 22:46:57 UTC
plymouth-0.9.4-12.20191022git32c097c.fc32.x86_64

$ systemd-analyze 
Startup finished in 1.453s (kernel) + 2.806s (initrd) + 8.411s (userspace) = 12.671s 
graphical.target reached after 8.401s in userspace

stop watch: grub press enter, to appearance of gdm (gray)
13.69s


plymouth-0.9.4-13.20191224gitd7c737d.fc31.x86_64

$ systemd-analyze 
Startup finished in 1.425s (kernel) + 2.923s (initrd) + 7.940s (userspace) = 12.288s 
graphical.target reached after 7.924s in userspace

stop watch: grub press enter, to appearance of gdm (gray)
13.22s


I'm offhand not noticing a difference in time or the transition. But I applied that update to an f32 laptop. I did do 'dracut -f' and it's a one kernel system so, I'm not sure.

Comment 15 Chris Murphy 2020-02-29 07:32:09 UTC
(different laptop, running f31)

plymouth-0.9.4-11.20191022git32c097c.fc31.x86_64
$ systemd-analyze 
Startup finished in 1.212s (kernel) + 1.380s (initrd) + 3.819s (userspace) = 6.412s 
graphical.target reached after 3.810s in userspace

stop watch: grub press enter, to appearance of gdm (gray)
11.73s

plymouth-0.9.4-13.20191224gitd7c737d.fc31.x86_64
$ systemd-analyze 
Startup finished in 1.204s (kernel) + 1.350s (initrd) + 4.115s (userspace) = 6.670s 
graphical.target reached after 3.935s in userspace

stop watch: grub press enter, to appearance of gdm (gray)
11.03

Comment 16 Hans de Goede 2020-02-29 19:06:30 UTC
Chris, thank you for testing I guess you are not using full disk encryption ?

That (fd encryption) causes us to get the boot time estimate significantly wrong which causes the biggest delay. Note that the max theoretical improvement from the patches is 3 seconds, so seeing you get 0.5 seconds improvement on the stopwatch times is ok, even though that is somewhat in the error margin of how accurate our measurements are... Anyways I'm happy to see that at least there are no regressions for you and that you do not notice any change in then transation.

My biggest worry with this change is that people would find the new faster transition ugkly.

Comment 17 Chris Murphy 2020-02-29 22:03:16 UTC
(In reply to Hans de Goede from comment #16)
> Chris, thank you for testing I guess you are not using full disk encryption ?

No encryption. However, sysroot is btrfs with zstd compression.

> My biggest worry with this change is that people would find the new faster
> transition ugkly.

I'm not seeing a difference so I can't assess.


Note You need to log in before you can comment on or make changes to this bug.