[systemd-devel] How to debug why a unit is started when?

Mon Mar 19 10:29:40 UTC 2018

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 at tty1.service
After=getty at 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 at .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
-------------- next part --------------
A non-text attachment was scrubbed...
Name: 20180319?bootchart-201080319-1014.svg.7z
Type: application/x-7z-compressed
Size: 43180 bytes
Desc: not available
URL: <https://lists.freedesktop.org/archives/systemd-devel/attachments/20180319/a1e41c99/attachment-0001.7z>