Bugzilla – Bug 1110199
Plymouth takes too long to react to quit command
Last modified: 2018-12-13 11:13:25 UTC
Several openSUSE Forum users have noticed that Leap 15.0 running on non-UEFI platforms suddenly began to take about a minute to boot -- 20 to 40 seconds due to the Display Manager service … **************************************** Analysis: The openSUSE /usr/lib/systemd/system/display-manager.service file calls "ExecStart=/usr/lib/X11/display-manager start" (openSUSE/SUSE) /usr/lib/X11/display-manager has not only a "plymouth quit" statement but also a "plymouth --wait" statement. The /usr/lib/systemd/system/display-manager.service has a "Conflicts=" statement for "plymouth-quit.service" but, not for "plymouth-quit-wait.service" … Adding a "plymouth-quit-wait.service" conflict reduces the userspace boot time of the non-UEFI system under test to about 20 seconds -- like it was a few months ago …
Bug 1110364 offers an alternative solution.
Hi Donald, Does this still happen now? Could you please attach the output of 'systemd-analyze critical-chain' and 'systemd-analyze blame'? Thanks a lot.
Non-UEFI system: AMD FX(tm)-4100 Quad-Core Processor. Restored Plymouth -- reversed all the file changes -- re-installed sddm, xdm and plymouth -- applied today's kernel update … Kernel command line (/proc/cmdline): BOOT_IMAGE=/boot/vmlinuz-4.12.14-lp150.12.22-default root=UUID=1ebd0398-732c-469a-9df5-af28273f743f resume=/dev/disk/by-id/ata-OCZ-VERTEX2_OCZ-HC8068405854W13J-part2 splash=silent quiet showopts elevator=cfq # 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 @39.346s └─display-manager.service @13.109s +26.236s └─apache2.service @12.748s +359ms └─time-sync.target @12.747s └─ntpd.service @12.565s +181ms └─network.target @12.542s └─wicked.service @3.586s +8.955s └─network-pre.target @3.585s └─firewalld.service @2.858s +726ms └─polkit.service @4.309s +108ms └─basic.target @2.681s └─sockets.target @2.681s └─iscsid.socket @2.681s └─sysinit.target @2.677s └─apparmor.service @930ms +1.746s └─var.mount @783ms +82ms └─systemd-fsck@dev-disk-by\x2did-ata\x2dWDC_WD10EZEX\x2d60M2NA0_WD\x2dWCC3F5AYCJL7\x2dpar> └─local-fs-pre.target @699ms └─lvm2-monitor.service @204ms +494ms └─lvm2-lvmetad.service @242ms └─lvm2-lvmetad.socket @202ms └─-.mount └─system.slice └─-.slice # # systemd-analyze blame | head 26.236s display-manager.service 26.151s plymouth-quit-wait.service 8.955s wicked.service 1.746s apparmor.service 1.413s dev-sda1.device 1.299s mariadb.service 1.225s systemd-journal-flush.service 734ms home01.mount 726ms firewalld.service 658ms ca-certificates.service # # systemd-analyze blame | grep -iE 'display|plymouth' 26.236s display-manager.service 26.151s plymouth-quit-wait.service 109ms plymouth-read-write.service 23ms plymouth-start.service 12ms plymouth-switch-root.service # # journalctl --this-boot | grep -iE 'plymouth|display' Okt 16 12:09:17 xxx systemd[1]: Starting Show Plymouth Boot Screen... Okt 16 12:09:17 xxx systemd[1]: Started Show Plymouth Boot Screen. Okt 16 12:09:17 xxx systemd[1]: Started Forward Password Requests to Plymouth Directory Watch. Okt 16 12:09:18 xxx systemd[1]: Starting Plymouth switch root service... Okt 16 12:09:18 xxx systemd[1]: Started Plymouth switch root service. Okt 16 12:09:19 xxx kernel: [drm] Radeon Display Connectors Okt 16 12:09:20 xxx systemd[1]: Starting Show Plymouth Boot Screen... Okt 16 12:09:20 xxx systemd[1]: Started Show Plymouth Boot Screen. Okt 16 12:09:20 xxx systemd[1]: Starting Tell Plymouth To Write Out Runtime Data... Okt 16 12:09:20 xxx systemd[1]: Started Tell Plymouth To Write Out Runtime Data. Okt 16 12:09:23 xxx systemd[1]: Received SIGRTMIN+20 from PID 276 (plymouthd). Okt 16 12:09:32 xxx systemd[1]: Starting X Display Manager... Okt 16 12:09:32 xxx display-manager[2354]: /etc/vconsole.conf available Okt 16 12:09:32 xxx display-manager[2354]: KEYMAP: de-latin1-nodeadkeys Okt 16 12:09:32 xxx display-manager[2354]: Command: localectl set-keymap de-latin1-nodeadkeys Okt 16 12:09:32 xxx display-manager[2354]: I: Using systemd /usr/share/systemd/kbd-model-map mapping Okt 16 12:09:32 xxx systemd[1]: Received SIGRTMIN+21 from PID 276 (plymouthd). Okt 16 12:09:58 xxx sddm[2398]: Adding new display on vt 7 ... Okt 16 12:09:58 xxx sddm[2398]: Display server starting... Okt 16 12:09:58 xxx sddm[2398]: Running: /usr/bin/X -nolisten tcp -auth /run/sddm/{05c13821-947a-4108-8d8a-fea9dd49ae68} -background none -noreset -displayfd 18 -seat seat0 vt7 Okt 16 12:09:59 xxx display-manager[2354]: Starting service sddm..done Okt 16 12:09:59 xxx systemd[1]: Started X Display Manager. Okt 16 12:10:00 xxx sddm[2398]: Running display setup script "/etc/X11/xdm/Xsetup" Okt 16 12:10:00 xxx sddm[2398]: Display server started. # # systemctl status display-manager.service ● display-manager.service - X Display Manager Loaded: loaded (/usr/lib/systemd/system/display-manager.service; enabled; vendor preset: enabled) Active: active (running) since Tue 2018-10-16 12:09:59 CEST; 40min ago Process: 2354 ExecStart=/usr/lib/X11/display-manager start (code=exited, status=0/SUCCESS) Main PID: 2398 (sddm) Tasks: 12 (limit: 4915) CGroup: /system.slice/display-manager.service ├─2398 /usr/bin/sddm └─2400 /usr/bin/X -nolisten tcp -auth /run/sddm/{05c13821-947a-4108-8d8a-fea9dd49ae68} -background none -nor> Okt 16 12:10:07 xxx sddm[2398]: Session "/usr/share/xsessions/xsession.desktop" selected, command: "default" Okt 16 12:10:07 xxx sddm-helper[2484]: [PAM] Starting... Okt 16 12:10:07 xxx sddm-helper[2484]: [PAM] Authenticating... Okt 16 12:10:07 xxx sddm-helper[2484]: [PAM] Preparing to converse... Okt 16 12:10:07 xxx sddm-helper[2484]: [PAM] Conversation with 1 messages Okt 16 12:10:07 xxx sddm-helper[2484]: [PAM] returning. Okt 16 12:10:07 xxx sddm[2398]: Authenticated successfully Okt 16 12:10:07 xxx sddm[2398]: Auth: sddm-helper exited successfully Okt 16 12:10:07 xxx sddm[2398]: Greeter stopped. Okt 16 12:10:07 xxx sddm[2398]: Session started #
*** Bug 1110364 has been marked as a duplicate of this bug. ***
plymouth-quit.service/lymouth-quit-wait.service are completely news to me. Policy was, that displaymanagers take care of terminating plymouth theirselves via the appropriate scripts in /usr/lib/X11/displaymanagers. See /usr/lib/X11/displaymanagers/xdm for an example.
(In reply to Stefan Dirsch from comment #8) > plymouth-quit.service/lymouth-quit-wait.service are completely news to me. > Policy was, that displaymanagers take care of terminating plymouth > theirselves via the appropriate scripts in /usr/lib/X11/displaymanagers. See > /usr/lib/X11/displaymanagers/xdm for an example. If this is so, why are there symbolic links to 'plymouth-quit.service' and 'plymouth-quit-wait.service' in the directory "/usr/lib/systemd/system/multi-user.target.wants/"? * These symbolic links will "enable" the static systemd services 'plymouth-quit.service' and 'plymouth-quit-wait.service' …
Whatever. Added the needed bits. https://build.opensuse.org/request/show/642936 Fixed for TW.
Sorry for commenting here late, but I am not sure if this is the right solution. The plymouth-quit-wait service is meant to intentionally hold boot until plymouth exits. Plymouth should exit once its told by the display manager. The other services that are configured to run after plymouth-quit-wait expect that plymouth will be gone when they run. Adding the Conflict=plymouth-quit-wait to display-manager will just stop plymouth-quit-wait prematurely even if plymouth is still running, won't it? So this is rather covering up the real problem. That said, I was not able to reproduce the issue on my Leap 15 system. Donald, did you try if it happens with other display managers, such as GDM or XDM?
Ok. SR revoked ...
PS: If I understand it correctly, the plymouth-quit service is meant to stop plymouth in case there is no display-manager. It is not run if display-manager is run.
FWIW, the reporter apparently is using sddm, which does a sddm_start_proc () { if [ -x /usr/bin/plymouth ]; then /usr/bin/plymouth quit fi return 0 } i.e. no "plymouth --wait" in contrast to xdm. Not sure what gdm is doing internally (as usual hardcoded).
My view is: 1. "/usr/lib/systemd/system/display-manager.service" calls "/usr/lib/X11/display-manager start" with an 'ExecStart='. 2. "/usr/lib/X11/display-manager" has a Bash function "plymouth_quit()" which calls "plymouth quit" and then "plymouth --wait" 3. The Bash function "plymouth_quit" is called only by lightdm and xdm. 4. In the directory "/usr/lib/systemd/system/multi-user.target.wants/" there are symbolic links to plymouth-quit.service and plymouth-quit-wait.service. 5. Therefore, both systemd services are enabled and triggered by the systemd Multi-User target … 6. Unless they're "Conflicted" … 7. And, "sddm_start_proc ()" calls "plymouth quit", which will collide with any "plymouth quit" called by a systemd service triggered by the Multi-User target … -------------------------------------------------------------------- Bottom line: * The SUSE/openSUSE policy decision to have the display managers stop/quit Plymouth seems to be colliding with the systemd Multi-User target "wants" … -------------------------------------------------------------------- Given the policy decision, would it not be better to unlink the plymouth-quit.service and plymouth-quit-wait.service from the Multi-User target?
(In reply to Donald Curtis from comment #15) > * The SUSE/openSUSE policy decision to have the display managers stop/quit > Plymouth seems to be colliding with the systemd Multi-User target "wants" … There is technical reason for this - the display manager tells plymouth to quit so it can choose when and how to do so. For example GDM will call "plymouth quit --retain-splash" to allow smooth transition. SDDM, LightDM or XDM for example only call "plymouth quit". > Given the policy decision, would it not be better to unlink the > plymouth-quit.service and plymouth-quit-wait.service from the Multi-User > target? IMHO no. Multi-user target should not be considered reached if plymouth is still running. So we should try to figure out the real problem - why does it take 20 seconds to start display manager or to quit plymouth (we still don't know which one actually). A first and easiest step would be to try if it works any better with different display managers. You are using SDDM now, right? Can you please test with GDM?
(In reply to Donald Curtis from comment #15) > > Bottom line: > > * The SUSE/openSUSE policy decision to have the display managers stop/quit > Plymouth seems to be colliding with the systemd Multi-User target "wants" … IIRC plymouth-quit-wait.service and plymouth-quit.service used to conflict with the "graphical" target so this should not happen.
(In reply to Michal Srb from comment #16) > Can you please test with GDM? OK, but, possibly, later today -- this (non-UEFI) machine is my default Desktop -- my (UEFI) Laptop is normally my "preferred" test platform but, because it's UEFI, it won't help us here … I have absolutely no idea if simply installing GDM without installing GNOME will work -- searching "The Net" doesn't look promising but, maybe /etc/gdm/Sessions will be correctly populated for the Plasma Frameworks 5 case …
(In reply to Franck Bui from comment #17) > IIRC plymouth-quit-wait.service and plymouth-quit.service used to conflict > with the "graphical" target so this should not happen. Could it be that, serial-console-interface only servers using systemd for the system initialisation, need/want "Plymouth quit" and "Plymouth quit wait" for the Multi-User target? * For this case the "default" target …
(In reply to Michal Srb from comment #16) > IMHO no. Multi-user target should not be considered reached if plymouth is > still running. AFAICS, assuming a "default" Graphical target, the Multi-User target is pulled in by the Graphical target … Meaning that, you're right! ** The systemd Multi-User target will have more than a few "wants" dependency issues around Display Managers calling "plymouth quit" and "plymouth --wait" outside of the systemd framework …
Created attachment 786533 [details] systemd-analyze Plot - GDM Display Manager is GDM -- GNOME is not installed …
FWIW, can anybody explain to me why this happens only on non-UEFI systems, but not on UEFI systems?
(In reply to Donald Curtis from comment #21) > Created attachment 786533 [details] > systemd-analyze Plot - GDM > > Display Manager is GDM -- GNOME is not installed … So do you see the same problem with GDM or not?
(In reply to Michal Srb from comment #16) > Can you please test with GDM? I've attached the systemd-analyze Plot. GDM is installed without any GNOME components -- black-listed … Changed the Display Manager with 'update-alternatives' and updated the sysconfig setting as well. GDM crashed -- possibly due to "no GNOME" … ● display-manager.service - X Display Manager Loaded: loaded (/usr/lib/systemd/system/display-manager.service; enabled; vendor preset: enabled) Active: active (running) since Fri 2018-10-19 12:28:43 CEST; 9min ago Process: 2366 ExecStart=/usr/lib/X11/display-manager start (code=exited, status=0/SUCCESS) Main PID: 2386 (gdm) Tasks: 3 (limit: 4915) CGroup: /system.slice/display-manager.service └─2386 /usr/sbin/gdm Okt 19 12:29:53 xxx gdm[2386]: Child process 9954 was already dead. Okt 19 12:29:53 xxx gdm[2386]: Unable to kill session worker process Okt 19 12:29:53 xxx gdm[2386]: Child process -9979 was already dead. Okt 19 12:29:53 xxx gdm[2386]: Child process 9969 was already dead. Okt 19 12:29:53 xxx gdm[2386]: Unable to kill session worker process Okt 19 12:29:53 xxx gdm[2386]: Could not start command '/usr/lib/gdm/gdm-session-worker': Too many open files Okt 19 12:29:53 xxx gdm[2386]: GLib: g_child_watch_add_full: assertion 'pid > 0' failed Okt 19 12:29:53 xxx gdm[2386]: Child process -9994 was already dead. Okt 19 12:29:53 xxx gdm[2386]: Child process 9984 was already dead. Okt 19 12:29:53 xxx gdm[2386]: Unable to kill session worker process # systemd-analyze blame | grep -iE 'displa|plymo': 576ms display-manager.service 56ms plymouth-read-write.service 20ms plymouth-start.service 12ms plymouth-switch-root.service # systemd-analyze blame | head 9.771s wicked.service 2.107s mariadb.service 1.719s apparmor.service 1.446s dev-sda1.device 1.110s systemd-journal-flush.service 758ms ca-certificates.service 741ms firewalld.service 728ms lvm2-monitor.service 577ms home01.mount 576ms display-manager.service # systemd-analyze critical-chain graphical.target @15.843s └─multi-user.target @15.843s └─mariadb.service @13.735s +2.107s └─network.target @13.721s └─wicked.service @3.949s +9.771s └─network-pre.target @3.948s └─firewalld.service @3.206s +741ms └─polkit.service @4.686s +105ms └─basic.target @3.021s └─sockets.target @3.021s └─iscsid.socket @3.021s └─sysinit.target @3.018s └─apparmor.service @1.298s +1.719s └─var.mount @1.272s +21ms └─systemd-fsck@dev-disk-by\x2did-ata\x2dWDC_WD10EZEX\x2d60M2NA0_WD\x2dWCC3F5AYCJL7\x2dpart1.service @942ms +327ms └─local-fs-pre.target @941ms └─lvm2-monitor.service @212ms +728ms └─lvm2-lvmetad.service @239ms └─lvm2-lvmetad.socket @201ms └─-.slice # journalctl --this-boot | grep -iE 'plymou|displa' Okt 19 12:28:26 xxx systemd[1]: Starting Show Plymouth Boot Screen... Okt 19 12:28:26 xxx systemd[1]: Started Show Plymouth Boot Screen. Okt 19 12:28:26 xxx systemd[1]: Started Forward Password Requests to Plymouth Directory Watch. Okt 19 12:28:27 xxx systemd[1]: Starting Plymouth switch root service... Okt 19 12:28:27 xxx systemd[1]: Started Plymouth switch root service. Okt 19 12:28:28 xxx kernel: [drm] Radeon Display Connectors Okt 19 12:28:29 xxx systemd[1]: Starting Show Plymouth Boot Screen... Okt 19 12:28:29 xxx systemd[1]: Started Show Plymouth Boot Screen. Okt 19 12:28:30 xxx systemd[1]: Starting Tell Plymouth To Write Out Runtime Data... Okt 19 12:28:30 xxx systemd[1]: Started Tell Plymouth To Write Out Runtime Data. Okt 19 12:28:32 xxx systemd[1]: Received SIGRTMIN+20 from PID 279 (plymouthd). Okt 19 12:28:32 xxx systemd[1]: Received SIGRTMIN+20 from PID 279 (plymouthd). Okt 19 12:28:42 xxx systemd[1]: Starting X Display Manager... Okt 19 12:28:42 xxx display-manager[2366]: /etc/vconsole.conf available Okt 19 12:28:42 xxx display-manager[2366]: KEYMAP: de-latin1-nodeadkeys Okt 19 12:28:42 xxx display-manager[2366]: Command: localectl set-keymap de-latin1-nodeadkeys Okt 19 12:28:42 xxx display-manager[2366]: I: Using systemd /usr/share/systemd/kbd-model-map mapping Okt 19 12:28:43 xxx systemd[1]: Received SIGRTMIN+21 from PID 279 (plymouthd). Okt 19 12:28:43 xxx display-manager[2366]: Starting service gdm..done Okt 19 12:28:43 xxx systemd[1]: Started X Display Manager.
(In reply to Stefan Dirsch from comment #23) > So do you see the same problem with GDM or not? Without the GNOME dependencies installed, GDM crashes. Therefore, I suspect that the 576 ms reported by systemd for the (GDM) Display Manager service is possibly not representative but, it's comparable to the time required for a SDDM Display Manager running on an UEFI system …
(In reply to Donald Curtis from comment #24) > GDM crashed -- possibly due to "no GNOME" … Then that was useless test. Are you willing to install the required packages? Or you can try with LightDM or XDM. Also I don't see the "plymouth-quit-wait.service" in the plot at all. Please make sure you have removed the additional Conflicts you described in comment 0 before testing with other display manager.
(In reply to Stefan Dirsch from comment #22) > FWIW, can anybody explain to me why this happens only on non-UEFI systems, > but not on UEFI systems? What I haven't tried, is a fresh install of this (main/prime) Desktop system -- it's suffered upgrades from 13.2 through the Leap 42.x series to Leap 15.0 -- no idea if there're any pre-Leap relicts in the system -- 'rpmconfigcheck', 'rpm --verify --all' and 'zypper packages --orphaned' have been regularly executed … The output of ' zypper packages --unneeded' is also regularly inspected …
(In reply to Michal Srb from comment #26) > Then that was useless test. Are you willing to install the required > packages? Or you can try with LightDM or XDM. > > Also I don't see the "plymouth-quit-wait.service" in the plot at all. Please > make sure you have removed the additional Conflicts you described in comment > 0 before testing with other display manager. Will do -- will be back later …
Created attachment 786560 [details] systemd-analyze Plot XDM In Display Manager service, "Plymouth quit wait" conflict removed.
Values for the Xdm case: # systemd-analyze blame | head 11.609s wicked.service 5.073s plymouth-quit-wait.service 4.694s display-manager.service 1.649s apparmor.service 1.321s dev-sda1.device 1.244s mariadb.service 1.155s systemd-journal-flush.service 973ms firewalld.service 913ms ca-certificates.service 626ms lvm2-monitor.service # # systemd-analyze blame | grep -iE 'plymo|displa' 5.073s plymouth-quit-wait.service 4.694s display-manager.service 102ms plymouth-read-write.service 23ms plymouth-switch-root.service 17ms plymouth-start.service # # systemd-analyze critical-chain graphical.target @20.780s └─display-manager.service @16.086s +4.694s └─apache2.service @15.713s +372ms └─time-sync.target @15.709s └─ntpd.service @15.534s +174ms └─network.target @15.500s └─wicked.service @3.890s +11.609s └─network-pre.target @3.888s └─firewalld.service @2.914s +973ms └─polkit.service @4.597s +103ms └─basic.target @2.853s └─sockets.target @2.853s └─pcscd.socket @2.853s └─sysinit.target @2.849s └─apparmor.service @1.200s +1.649s └─var.mount @1.036s +130ms └─systemd-fsck@dev-disk-by\x2did-ata\x2dWDC_WD10EZEX\x2d60M2NA0_WD\x2dWCC3F5AYCJL7\x2dpar> └─local-fs-pre.target @832ms └─lvm2-monitor.service @206ms +626ms └─lvm2-lvmetad.service @232ms └─lvm2-lvmetad.socket @191ms └─-.slice # # journalctl --this-boot | grep -iE 'plymou|displa' Okt 19 15:10:12 eck001 systemd[1]: Starting Show Plymouth Boot Screen... Okt 19 15:10:12 eck001 systemd[1]: Started Show Plymouth Boot Screen. Okt 19 15:10:12 eck001 systemd[1]: Started Forward Password Requests to Plymouth Directory Watch. Okt 19 15:10:13 eck001 systemd[1]: Starting Plymouth switch root service... Okt 19 15:10:13 eck001 systemd[1]: Started Plymouth switch root service. Okt 19 15:10:14 eck001 kernel: [drm] Radeon Display Connectors Okt 19 15:10:15 eck001 systemd[1]: Starting Show Plymouth Boot Screen... Okt 19 15:10:15 eck001 systemd[1]: Started Show Plymouth Boot Screen. Okt 19 15:10:15 eck001 systemd[1]: Starting Tell Plymouth To Write Out Runtime Data... Okt 19 15:10:15 eck001 systemd[1]: Started Tell Plymouth To Write Out Runtime Data. Okt 19 15:10:18 eck001 systemd[1]: Received SIGRTMIN+20 from PID 264 (plymouthd). Okt 19 15:10:30 eck001 systemd[1]: Starting X Display Manager... Okt 19 15:10:30 eck001 display-manager[2374]: /etc/vconsole.conf available Okt 19 15:10:30 eck001 display-manager[2374]: KEYMAP: de-latin1-nodeadkeys Okt 19 15:10:30 eck001 display-manager[2374]: Command: localectl set-keymap de-latin1-nodeadkeys Okt 19 15:10:30 eck001 display-manager[2374]: I: Using systemd /usr/share/systemd/kbd-model-map mapping Okt 19 15:10:30 eck001 systemd[1]: Received SIGRTMIN+21 from PID 264 (plymouthd). Okt 19 15:10:35 eck001 display-manager[2374]: Starting service xdm..done Okt 19 15:10:35 eck001 systemd[1]: Started X Display Manager. Okt 19 15:10:52 eck001 kapplymousetheme[2565]: kcm_input: Using X11 backend #
Thank you for the test. The plot shows that there was about 4.5 seconds between the start of display-manager.service and the end of plymouth-quit-wait.service. That is less than 20 seconds, but still more than I would expect. Since it is happening with two different display managers, I suspect the problem is at plymouth side. Maybe the "plymouth quit" command has trouble getting to the daemon, or the plymouth daemon is taking too long to react to the quit command... I will do some testing and come back.
Created attachment 786562 [details] systemd-analyze Plot LightDM Needs more time than that what SDDM usually needs …
Values for the LightDM case: # systemd-analyze blame | head 44.665s display-manager.service 44.556s plymouth-quit-wait.service 8.313s wicked.service 1.662s apparmor.service 1.267s mariadb.service 1.162s systemd-journal-flush.service 1.094s dev-sda1.device 851ms firewalld.service 809ms ca-certificates.service 586ms lvm2-monitor.service # # systemd-analyze blame | grep -iE 'plymo|displa' 44.665s display-manager.service 44.556s plymouth-quit-wait.service 96ms plymouth-read-write.service 22ms plymouth-start.service 17ms plymouth-switch-root.service # # systemd-analyze critical-chain graphical.target @57.312s └─display-manager.service @12.646s +44.665s └─apache2.service @12.278s +365ms └─time-sync.target @12.276s └─ntpd.service @12.087s +188ms └─network.target @12.076s └─wicked.service @3.762s +8.313s └─network-pre.target @3.761s └─firewalld.service @2.910s +851ms └─polkit.service @4.464s +107ms └─basic.target @2.834s └─sockets.target @2.834s └─pcscd.socket @2.834s └─sysinit.target @2.831s └─apparmor.service @1.168s +1.662s └─var.mount @1.002s +133ms └─systemd-fsck@dev-disk-by\x2did-ata\x2dWDC_WD10EZEX\x2d60M2NA0_WD\x2dWCC3F5AYCJL7\x2dpar> └─local-fs-pre.target @803ms └─lvm2-monitor.service @217ms +586ms └─lvm2-lvmetad.service @245ms └─lvm2-lvmetad.socket @203ms └─-.slice # # journalctl --this-boot | grep -iE 'plymou|displa' Okt 19 15:51:19 xxx systemd[1]: Starting Show Plymouth Boot Screen... Okt 19 15:51:19 xxx systemd[1]: Started Show Plymouth Boot Screen. Okt 19 15:51:19 xxx systemd[1]: Started Forward Password Requests to Plymouth Directory Watch. Okt 19 15:51:21 xxx systemd[1]: Starting Plymouth switch root service... Okt 19 15:51:21 xxx systemd[1]: Started Plymouth switch root service. Okt 19 15:51:21 xxx kernel: [drm] Radeon Display Connectors Okt 19 15:51:22 xxx systemd[1]: Starting Show Plymouth Boot Screen... Okt 19 15:51:22 xxx systemd[1]: Started Show Plymouth Boot Screen. Okt 19 15:51:22 xxx systemd[1]: Starting Tell Plymouth To Write Out Runtime Data... Okt 19 15:51:22 xxx systemd[1]: Started Tell Plymouth To Write Out Runtime Data. Okt 19 15:51:25 xxx systemd[1]: Received SIGRTMIN+20 from PID 300 (plymouthd). Okt 19 15:51:34 xxx systemd[1]: Starting X Display Manager... Okt 19 15:51:34 xxx display-manager[2373]: /etc/vconsole.conf available Okt 19 15:51:34 xxx display-manager[2373]: KEYMAP: de-latin1-nodeadkeys Okt 19 15:51:34 xxx display-manager[2373]: Command: localectl set-keymap de-latin1-nodeadkeys Okt 19 15:51:34 xxx display-manager[2373]: I: Using systemd /usr/share/systemd/kbd-model-map mapping Okt 19 15:51:34 xxx systemd[1]: Received SIGRTMIN+21 from PID 300 (plymouthd). Okt 19 15:52:19 xxx display-manager[2373]: Starting service lightdm..done Okt 19 15:52:19 xxx systemd[1]: Started X Display Manager. Okt 19 15:52:31 xxx kapplymousetheme[2638]: kcm_input: Using X11 backend #
Which plymouth theme do you use? Do you use the default "openSUSE" one? (It uses the Leap logo in white color, the top shape is moving up and down during boot and it stops moving and turns green at the end.) What do you see on the screen during the final 20 seconds before it finally switches to the display manager? Do you see the plymouth splash? Is it moving or not, white or green? (Based on that we can know if plymouth received the quit command or not.)
(In reply to Michal Srb from comment #34) > Which plymouth theme do you use? Do you use the default "openSUSE" one? (It > uses the Leap logo in white color, the top shape is moving up and down > during boot and it stops moving and turns green at the end.) default openSUSE -- animated Leap logo -- monochrome and then finally green … > > What do you see on the screen during the final 20 seconds before it finally > switches to the display manager? Do you see the plymouth splash? Is it > moving or not, white or green? (Based on that we can know if plymouth > received the quit command or not.) After the Plymouth Leap "green phase", the screen is black, then, after a while, the mouse cursor appears, and then, after some time, the openSUSE SDDM splash appears -- the one with the floor plan of the Prague office on the right hand side of the screen … -------------------------------------------------------------- BTW: I'll post the GDM case before the evening is out -- need to install and log the missing GNOME bits and pieces …
(In reply to Michal Srb from comment #34) > What do you see on the screen during the final 20 seconds before it finally > switches to the display manager? Do you see the plymouth splash? Is it > moving or not, white or green? Update for GDM: 1. Plymouth Leap logo green -- possibly still … 2. After a while the mouse cursor appears in the green Leap logo … 3. Screen becomes grey, with the mouse cursor visible … 4. GDM login screen appears, with the mouse cursor …
Created attachment 786582 [details] systemd-analyze Plot -- GDM Fast Display Manager: ~600 ms. Plymouth Quit Wait a 45 s issue …
Values for the GDM Case: # systemd-analyze blame | head 45.571s plymouth-quit-wait.service 10.134s wicked.service 2.000s apparmor.service 1.495s systemd-journal-flush.service 1.244s mariadb.service 1.135s dev-sda1.device 865ms ca-certificates.service 747ms firewalld.service 690ms lvm2-monitor.service 587ms display-manager.service # # systemd-analyze blame | grep -iE 'plymo|displa' 45.571s plymouth-quit-wait.service 587ms display-manager.service 121ms plymouth-read-write.service 17ms plymouth-switch-root.service 16ms plymouth-start.service # # systemd-analyze critical-chain graphical.target @59.688s └─multi-user.target @59.687s └─getty.target @59.687s └─getty@tty1.service @59.687s └─apache2.service @14.220s +373ms └─time-sync.target @14.214s └─ntpd.service @14.064s +149ms └─network.target @14.062s └─wpa_supplicant.service @58.072s +43ms └─dbus.service @3.025s └─basic.target @3.011s └─sockets.target @3.011s └─avahi-daemon.socket @3.011s └─sysinit.target @3.007s └─apparmor.service @1.007s +2.000s └─var.mount @991ms +13ms └─systemd-fsck@dev-disk-by\x2did-ata\x2dWDC_WD10EZEX\x2d60M2NA0_WD\x2dWCC3F5AYCJL7\x2dpart1.service @893ms +96ms └─local-fs-pre.target @891ms └─lvm2-monitor.service @201ms +690ms └─lvm2-lvmetad.service @235ms └─lvm2-lvmetad.socket @196ms └─-.slice # # journalctl --this-boot | grep -iE 'plymou|displa' Okt 19 18:15:06 xxx systemd[1]: Starting Show Plymouth Boot Screen... Okt 19 18:15:06 xxx systemd[1]: Started Show Plymouth Boot Screen. Okt 19 18:15:06 xxx systemd[1]: Started Forward Password Requests to Plymouth Directory Watch. Okt 19 18:15:08 xxx systemd[1]: Starting Plymouth switch root service... Okt 19 18:15:08 xxx systemd[1]: Started Plymouth switch root service. Okt 19 18:15:08 xxx kernel: [drm] Radeon Display Connectors Okt 19 18:15:09 xxx systemd[1]: Starting Show Plymouth Boot Screen... Okt 19 18:15:09 xxx systemd[1]: Started Show Plymouth Boot Screen. Okt 19 18:15:09 xxx systemd[1]: Starting Tell Plymouth To Write Out Runtime Data... Okt 19 18:15:09 xxx systemd[1]: Started Tell Plymouth To Write Out Runtime Data. Okt 19 18:15:12 xxx systemd[1]: Received SIGRTMIN+20 from PID 278 (plymouthd). Okt 19 18:15:23 xxx systemd[1]: Starting X Display Manager... Okt 19 18:15:23 xxx display-manager[2350]: /etc/vconsole.conf available Okt 19 18:15:23 xxx display-manager[2350]: KEYMAP: de-latin1-nodeadkeys Okt 19 18:15:23 xxx display-manager[2350]: Command: localectl set-keymap de-latin1-nodeadkeys Okt 19 18:15:23 xxx display-manager[2350]: I: Using systemd /usr/share/systemd/kbd-model-map mapping Okt 19 18:15:23 xxx display-manager[2350]: Starting service gdm..done Okt 19 18:15:23 xxx systemd[1]: Started X Display Manager. Okt 19 18:16:06 xxx gnome-shell[2422]: JS WARNING: [resource:///org/gnome/shell/ui/osdMonitorLabeler.js 59]: reference to undefined property "MetaDBusDisplayConfigSkeleton" Okt 19 18:16:08 xxx systemd[1]: Received SIGRTMIN+21 from PID 278 (plymouthd).
And now, to remove the 200 packages installed due the GDM dependencies …
I was able to reproduce it now on Leap 15.1 system. But I believe it can happen on 15.0 too. The issue really is plymouthd that is taking long time to react to the quit command. I debugged it, this is happening: * plymouthd receives the "quit" command immediately * it sets a flag that it should play the last iteration of the current animation (white throbber) and switch to the next animation (turning green) * when that flag is set and the animation frame equals to the last frame, switch to the next animation But! The frames are not played one by one - it chooses the next frame based on the time elapsed since the last frame and the desired animation speed. Plymouth is trying to play at 30 FPS, the animation loop has 2 seconds and there are 73 frames. This means that some frames will be skipped, quite often also the last frame! So the animation keeps looping for long time, until you are lucky that the last frame is actually hit. The machine is usually busy during boot, which brings some randomness into it. I will prepare patch tomorrow...
Created attachment 786816 [details] throbber: Don't skip last frame when waiting for end. The attached patch fixes the issue for me. I have built test package in this OBS project: https://build.opensuse.org/package/show/home:michalsrb:bug1110199:Base:System/plymouth Here is repository for Leap 15.0: https://download.opensuse.org/repositories/home:/michalsrb:/bug1110199:/Base:/System/openSUSE_Leap_15.0/ Donald, can you please install plymouth from that repository and test if it fixes the delay? It is enough to install just the "libply-splash-graphics4" package, but updating all packages to the ones from that repository is also fine. Please make sure you don't have any of the changes to the systemd unit files in place. I have also created separate bug 1112849 to request re-rendering the throbber animation into exactly 60 frames (30 FPS * 2 seconds). Because even with this bug fixed, the current 73 frames (and 48 frames on Tumbleweed) are causing unnecessary jitter in the animation.
Installed "libply-splash-graphics4" from <https://download.opensuse.org/repositories/home:/michalsrb:/bug1110199:/Base:/System/openSUSE_Leap_15.0/>; following packages were also installed from the 'bug1110199' repository due to dependencies: libply4; libply-boot-client4; libply-splash-core4; plymouth-plugin-script; plymouth-plugin-label-ft; plymouth-plugin-label; plymouth-plugin-two-step. Display Manager now needs 2.988 seconds to start; * "Plymouth quit wait" now takes 2.953 seconds to complete. systemd Journal entries at Display/SDDM start time for this boot: Okt 23 10:12:21 xxx systemd[1]: Started The Apache Webserver. Okt 23 10:12:21 xxx systemd[1]: Starting X Display Manager... Okt 23 10:12:21 xxx display-manager[2371]: /etc/vconsole.conf available Okt 23 10:12:21 xxx display-manager[2371]: KEYMAP: de-latin1-nodeadkeys Okt 23 10:12:21 xxx display-manager[2371]: Command: localectl set-keymap de-latin1-nodeadkeys Okt 23 10:12:21 xxx display-manager[2371]: I: Using systemd /usr/share/systemd/kbd-model-map mapping Okt 23 10:12:21 xxx dbus-daemon[1044]: [system] Activating via systemd: service name='org.freedesktop.locale1' unit='dbus-org.freedesktop.locale1.service' requested by ':1.18' (uid=0 pid=2394 comm="localectl set-keymap de-latin1-node> Okt 23 10:12:21 xxx systemd[1]: Starting Locale Service... Okt 23 10:12:21 xxx dbus-daemon[1044]: [system] Successfully activated service 'org.freedesktop.locale1' Okt 23 10:12:21 xxx systemd[1]: Started Locale Service. Okt 23 10:12:21 xxx systemd[1]: Received SIGRTMIN+21 from PID 266 (plymouthd). Okt 23 10:12:22 xxx systemd[1]: Started MySQL server. Okt 23 10:12:24 xxx systemd[1]: Started Hold until boot process finishes up. Okt 23 10:12:24 xxx systemd[1]: Started Getty on tty1. Okt 23 10:12:24 xxx systemd[1]: Reached target Login Prompts. Okt 23 10:12:24 xxx systemd[1]: Reached target Multi-User System. Okt 23 10:12:24 xxx sddm[2415]: Initializing... Okt 23 10:12:24 xxx sddm[2415]: Logind interface found Okt 23 10:12:24 xxx sddm[2415]: Starting... Okt 23 10:12:24 xxx sddm[2415]: Adding new display on vt 7 ... Okt 23 10:12:24 xxx sddm[2415]: Loading theme configuration from "" Okt 23 10:12:24 xxx sddm[2415]: Display server starting... Okt 23 10:12:24 xxx sddm[2415]: Running: /usr/bin/X -nolisten tcp -auth /run/sddm/{7b1fe41e-f535-435c-8459-7944c19c80b4} -background none -noreset -displayfd 18 -seat seat0 vt7 Okt 23 10:12:24 xxx display-manager[2371]: Starting service sddm..done Okt 23 10:12:24 xxx systemd[1]: Started X Display Manager. Okt 23 10:12:24 xxx systemd[1]: Reached target Graphical Interface. Okt 23 10:12:24 xxx systemd[1]: Starting Update UTMP about System Runlevel Changes... Okt 23 10:12:24 xxx systemd[1]: Started Update UTMP about System Runlevel Changes. Okt 23 10:12:24 xxx systemd[1]: Startup finished in 2.549s (kernel) + 1.849s (initrd) + 19.324s (userspace) = 23.723s. Okt 23 10:12:25 xxx sddm[2415]: Setting default cursor Okt 23 10:12:25 xxx sddm[2415]: Running display setup script "/etc/X11/xdm/Xsetup" Okt 23 10:12:25 xxx sddm[2415]: Display server started. Okt 23 10:12:25 xxx sddm[2415]: Socket server starting... Okt 23 10:12:25 xxx sddm[2415]: Socket server started. Okt 23 10:12:25 xxx sddm[2415]: Loading theme configuration from "/usr/share/sddm/themes/breeze-openSUSE/theme.conf" Okt 23 10:12:25 xxx sddm[2415]: Greeter starting... Okt 23 10:12:25 xxx sddm[2415]: Adding cookie to "/run/sddm/{7b1fe41e-f535-435c-8459-7944c19c80b4}"
(In reply to Donald Curtis from comment #42) > Display Manager now needs 2.988 seconds to start; > * "Plymouth quit wait" now takes 2.953 seconds to complete. Perfect! Thank you for testing. The actual time to quit plymouth is the time from the start of display-manager to the end of plymouth-quit-wait, so even bit shorter than these times. Note that it takes anything between 0 to 2 seconds to finish the throbber animation and then the end animation lasts additional 1.03 seconds. So this is within the expected time. I have updated the Summary to reflect the actual nature of the bug. I will submit the patched plymouth now.
The patch was now accepted upstream and I submitted update for Factory/Tumbleweed and SLE15/Leap15. Closing as fixed.
*** Bug 1114248 has been marked as a duplicate of this bug. ***
SUSE-RU-2018:4096-1: An update that has one recommended fix can now be installed. Category: recommended (moderate) Bug References: 1110199 CVE References: Sources used: SUSE Linux Enterprise Module for Packagehub Subpackages 15 (src): plymouth-0.9.4+git20181111.118c5ca-4.12.1 SUSE Linux Enterprise Module for Open Buildservice Development Tools 15 (src): plymouth-0.9.4+git20181111.118c5ca-4.12.1 SUSE Linux Enterprise Module for Basesystem 15 (src): plymouth-0.9.4+git20181111.118c5ca-4.12.1
openSUSE-RU-2018:4115-1: An update that has one recommended fix can now be installed. Category: recommended (moderate) Bug References: 1110199 CVE References: Sources used: openSUSE Leap 15.0 (src): plymouth-0.9.4+git20181111.118c5ca-lp150.3.6.1