[prev in list] [next in list] [prev in thread] [next in thread]
List: systemd-devel
Subject: Re: [systemd-devel] How to debug why a unit is started when?
From: Paul Menzel <pmenzel+systemd-devel () molgen ! mpg ! de>
Date: 2018-03-19 10:29:40
Message-ID: d04b566d-6ff4-c01f-dfd8-7cd196fbbb6b () molgen ! mpg ! de
[Download RAW message or body]
Dear Colin,
On 03/19/2018 07:31 AM, Colin Guthrie wrote:
> Paul Menzel wrote on 17/03/18 17:50:
> > On 03/16/2018 05:04 PM, Andrei Borzenkov wrote:
> > > 16.03.2018 18:49, Paul Menzel пишет:
> >
> > > > I am trying to get the GDM login screen started earlier on a Dell XPS 13
> > > > 9370 with Debian Sid/unstable system with systemd 238. Currently, after
> > > > selecting the Linux kernel in GRUB it’s only displayed after roughly
> > > > eight to ten seconds while Linux takes around two seconds [1].
> > > >
> > > > Using systemd-bootchart I see that GDM is started quite late [1], and I
> > > > wondering if there is an option to find out why.
> > > >
> > > > GDM’s service unit [2] has the “dependencies” below.
> > > >
> > > > After=rc-local.service plymouth-start.service
> > > > systemd-user-sessions.service
> > > >
> > > > Is there a debug option, where systemd says, why a certain unit is
> > > > started? For example, reached target X and therefore starting Y.
> > >
> > > systemctl --after (--recursive) --list-dependencies gdm.service
> > >
> > > may be the first step. Or use systemd-analyze chart to see full picture
> > > of what was started when.
> >
> > I didn’t know about `systemd-analyze plot`. Please find the SVG file
> > attached.
> >
> > Looking at the log messages, I kind of think it’s related to the
> > NetworkManager, but I do not see the dependency. Is it
> > `rc-local.service`? It seems to depend on the `network.target`.
>
> I didn't look too hard at the data, but from experience,
> systemd-user-sessions often has to start after the network is online as
> user accounts may be defined in e.g. LDAP etc.
>
> This is the likely chain you need to break and configure accordingly.
>
> e.g. if you have no network filesystems (defined without noauto or
> nofail) and no LDAP/NIS users etc., then you may not need
> networkmanager-wait-online.service and if you disable this, things might
> go a lot faster.
>
> Be careful however, as some old network-listening services may still
> need this dodgy delay service to function properly.
Thank you for pointing this out. I actually knew this from the past, but
forgot about it. I didn’t look further into it though, as I had removed
the `After=` line (including `systemd-user-sessions.service`). I changed
more things too though by deinstalling the package *ifupdown*.
```
$ systemctl cat gdm
# /lib/systemd/system/gdm.service
[Unit]
Description=GNOME Display Manager
# replaces the getty
Conflicts=getty@tty1.service
After=getty@tty1.service
# replaces plymouth-quit since it quits plymouth on its own
# Needs all the dependencies of the services it's replacing
# pulled from getty@.service and plymouth-quit.service
# (except for plymouth-quit-wait.service since it waits until
# plymouth is quit, which we do)
# GDM takes responsibility for stopping plymouth, so if it fails
# for any reason, make sure plymouth still stops
OnFailure=plymouth-quit.service
[Service]
ExecStartPre=/usr/share/gdm/generate-config
ExecStart=/usr/sbin/gdm3
KillMode=mixed
Restart=always
RestartSec=1s
IgnoreSIGPIPE=no
BusName=org.gnome.DisplayManager
StandardOutput=syslog
StandardError=inherit
EnvironmentFile=-/etc/default/locale
ExecReload=/usr/share/gdm/generate-config
ExecReload=/bin/kill -SIGHUP $MAINPID
```
But `sudo systemctl disable NetworkManager-wait-online.service` indeed
changed something, and the GDM service is now started at the same time
as NetworkManager.
Unfortunately, the GDM session worker is only started after 1.6 seconds
according to the chart – the updated chart is attached. That is a likely
a GDM problem though.
> ```
> […]
> Mar 19 10:14:30.440112 xps139370 systemd[1]: Starting GNOME Display Manager...
> […]
> Mar 19 10:14:30.475575 xps139370 systemd[1]: Started GNOME Display Manager.
> Mar 19 10:14:30.475764 xps139370 gdm3[523]: Successfully connected to D-Bus
> […]
> Mar 19 10:14:32.022907 xps139370 gdm3[523]: GdmLocalDisplayFactory: Adding display \
> on seat seat0 Mar 19 10:14:32.023006 xps139370 gdm3[523]: GdmDisplay: id: (null)
> Mar 19 10:14:32.023011 xps139370 gdm3[523]: GdmDisplay: seat id: (null)
> Mar 19 10:14:32.023014 xps139370 gdm3[523]: GdmDisplay: session class: greeter
> Mar 19 10:14:32.023017 xps139370 gdm3[523]: GdmDisplay: initial: no
> Mar 19 10:14:32.023019 xps139370 gdm3[523]: GdmDisplay: allow timed login: yes
> Mar 19 10:14:32.023022 xps139370 gdm3[523]: GdmDisplay: local: yes
> Mar 19 10:14:32.023109 xps139370 gdm3[523]: GdmDisplay: session type: wayland
> Mar 19 10:14:32.023113 xps139370 gdm3[523]: GdmDisplay: seat id: seat0
> Mar 19 10:14:32.023117 xps139370 gdm3[523]: GdmDisplay: initial: yes
> Mar 19 10:14:32.023121 xps139370 gdm3[523]: GdmDisplayStore: Adding display \
> /org/gnome/DisplayManager/Displays/94611499688528 to store Mar 19 10:14:32.023234 \
> xps139370 gdm3[523]: GdmDisplay: Managing display: \
> /org/gnome/DisplayManager/Displays/94611499688528 Mar 19 10:14:32.023236 xps139370 \
> gdm3[523]: GdmDisplay: Preparing display: \
> /org/gnome/DisplayManager/Displays/94611499688528 Mar 19 10:14:32.024422 xps139370 \
> kernel: ath10k_pci 0000:02:00.0: Unknown eventid: 118809 Mar 19 10:14:32.025099 \
> xps139370 gdm3[523]: GdmDisplay: Checking kernel command buffer \
> BOOT_IMAGE=/boot/vmlinuz-4.16.0-rc5+ root=UUID=44442f3b-df1e-41fc-8004-f2fb30debee9 \
> ro quiet init=/lib/systemd/systemd-bootchart initcall_debug \
> btusb.enable_autosuspend=y cryptomgr.notests Mar 19 10:14:32.025951 xps139370 \
> gdm3[523]: GdmDisplay: Failed to read kernel commandline: Could not match \
> gnome.initial-setup= in kernel cmdline Mar 19 10:14:32.025959 xps139370 gdm3[523]: \
> doing initial setup? no Mar 19 10:14:32.026019 xps139370 gdm3[523]: GdmDisplay: \
> prepare display Mar 19 10:14:32.026032 xps139370 gdm3[523]: GdmDisplay: Got \
> automatic login details for display: 0 Mar 19 10:14:32.026160 xps139370 gdm3[523]: \
> GdmSession: Creating D-Bus server for worker for session Mar 19 10:14:32.026288 \
> xps139370 gdm3[523]: GdmSession: D-Bus server for workers listening on \
> unix:abstract=/tmp/dbus-S3QKeBMV Mar 19 10:14:32.026290 xps139370 gdm3[523]: \
> GdmSession: Creating D-Bus server for greeters and such Mar 19 10:14:32.026327 \
> xps139370 gdm3[523]: GdmSession: D-Bus server for greeters listening on \
> unix:abstract=/tmp/dbus-5qHLJXry Mar 19 10:14:32.026333 xps139370 gdm3[523]: \
> GdmSession: Setting display device: (null) Mar 19 10:14:32.026353 xps139370 \
> gdm3[523]: GdmDisplay: Running greeter Mar 19 10:14:32.026356 xps139370 gdm3[523]: \
> GdmDisplay: Creating greeter for (null) (null) Mar 19 10:14:32.026363 xps139370 \
> gdm3[523]: GdmLaunchEnvironment: Starting... Mar 19 10:14:32.026386 xps139370 \
> gdm3[523]: GdmLaunchEnvironment: Setting up run time dir /var/run/gdm3/greeter Mar \
> 19 10:14:32.026433 xps139370 gdm3[523]: GdmSession: Creating D-Bus server for \
> worker for session Mar 19 10:14:32.026473 xps139370 gdm3[523]: GdmSession: D-Bus \
> server for workers listening on unix:abstract=/tmp/dbus-4SmwHAlc Mar 19 \
> 10:14:32.026475 xps139370 gdm3[523]: GdmSession: Creating D-Bus server for greeters \
> and such Mar 19 10:14:32.026511 xps139370 gdm3[523]: GdmSession: D-Bus server for \
> greeters listening on unix:abstract=/tmp/dbus-gQt2eHyy Mar 19 10:14:32.026516 \
> xps139370 gdm3[523]: GdmSession: Setting display device: (null) Mar 19 \
> 10:14:32.026533 xps139370 gdm3[523]: GdmSession: starting conversation \
> gdm-launch-environment Mar 19 10:14:32.027424 xps139370 kernel: ath10k_pci \
> 0000:02:00.0: Unknown eventid: 90118 Mar 19 10:14:32.026555 xps139370 gdm3[523]: \
> GdmSessionWorkerJob: Starting worker... Mar 19 10:14:32.026558 xps139370 gdm3[523]: \
> GdmSessionWorkerJob: Running session_worker_job process: gdm-session-worker \
> [pam/gdm-launch-environment] /usr/lib/gdm3/gdm-session-worker Mar 19 \
> 10:14:32.027686 xps139370 gdm3[523]: GdmSessionWorkerJob: : SessionWorkerJob on pid \
> 678 Mar 19 10:14:32.027713 xps139370 gdm3[523]: GdmSession: setting session to type \
> 'wayland' Mar 19 10:14:32.027727 xps139370 gdm3[523]: GdmLocalDisplayFactory: \
> display status changed: 1 Mar 19 10:14:32.029994 xps139370 \
> gdm-launch-environment][678]: Enabling debugging […]
> $ systemd-analyze
> Startup finished in 8.844s (firmware) + 1.993s (loader) + 1.782s (kernel) + 1.724s \
> (userspace) = 14.345s graphical.target reached after 1.714s in userspace
> ```
Then GNOME Shell needs another 1.6 seconds [1] but only later GSD stuff
is started, and there is a vertical line at 7.8 seconds.
Stopping the actual time with a stop watch from pressing enter in the
GRUB menu to having the login screen ready/loaded it takes ten seconds.
But maybe the 2.2 seconds are from GRUB loading the Linux kernel image
and the initramfs image.
```
$ ls -lh /boot/*rc5*
-rw-r--r-- 1 root root 195K Mar 18 11:18 /boot/config-4.16.0-rc5+
-rw-r--r-- 1 root root 24M Mar 18 15:05 /boot/initrd.img-4.16.0-rc5+
-rw-r--r-- 1 root root 3.0M Mar 18 11:18 /boot/System.map-4.16.0-rc5+
-rw-r--r-- 1 root root 4.8M Mar 18 11:18 /boot/vmlinuz-4.16.0-rc5+
```
Kind regards,
Paul
[1] https://gitlab.gnome.org/GNOME/gnome-shell/issues/126
["=?UTF-8?Q?20180319=e2=80=93bootchart-201080319-1014.svg.7z?=" (application/x-7z-compressed)]
[Attachment #4 (text/plain)]
_______________________________________________
systemd-devel mailing list
systemd-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/systemd-devel
[prev in list] [next in list] [prev in thread] [next in thread]
Configure |
About |
News |
Add a list |
Sponsored by KoreLogic