Bug#925160: systemd: user session slow to start (11 seconds)

[Laurent Bonnaud]

Package: systemd
Version: 241-2
Severity: important


Dear Maintainer,

on this system, an initial ssh connection needs 11 seconds to complete (as root or any other user).  Further connections are fast.
This is not a slow boot problem because it occurs even when the machine has been booted for days.

It comes from a slow start of the user's session as can be seen in this log:

Mar 20 15:06:27 hostname sshd[172771]: Accepted publickey for root from 193.55.51.153 port 53702 ssh2: RSA SHA256:wmFQ70BsRjT4uCWua2ddnbfFv7kiMecLHVNtZMw0KMk
Mar 20 15:06:27 hostname sshd[172771]: pam_unix(sshd:session): session opened for user root by (uid=0)
Mar 20 15:06:27 hostname systemd-logind[743]: New session 3373 of user root.
Mar 20 15:06:27 hostname systemd[1]: Starting User Manager for UID 0...
Mar 20 15:06:27 hostname systemd[172774]: pam_unix(systemd-user:session): session opened for user root by (uid=0)
[11 seconds gap]
Mar 20 15:06:38 hostname systemd[172774]: Listening on GnuPG network certificate management daemon.
Mar 20 15:06:38 hostname systemd[172774]: Reached target Timers.
Mar 20 15:06:38 hostname systemd[172774]: Listening on GnuPG cryptographic agent and passphrase cache.
Mar 20 15:06:38 hostname systemd[172774]: Reached target Paths.
Mar 20 15:06:38 hostname systemd[172774]: Listening on GnuPG cryptographic agent and passphrase cache (access for web browsers).
Mar 20 15:06:38 hostname systemd[172774]: Listening on GnuPG cryptographic agent and passphrase cache (restricted).
Mar 20 15:06:38 hostname systemd[172774]: Listening on Multimedia System.
Mar 20 15:06:38 hostname systemd[172774]: Listening on GnuPG cryptographic agent (ssh-agent emulation).
Mar 20 15:06:38 hostname systemd[172774]: Condition check resulted in Sound System being skipped.
Mar 20 15:06:38 hostname systemd[172774]: Starting D-Bus User Message Bus Socket.
Mar 20 15:06:38 hostname systemd[172774]: Listening on D-Bus User Message Bus Socket.
Mar 20 15:06:38 hostname systemd[172774]: Reached target Sockets.
Mar 20 15:06:38 hostname systemd[172774]: Reached target Basic System.
Mar 20 15:06:38 hostname systemd[172774]: Reached target Default.
Mar 20 15:06:38 hostname systemd[172774]: Startup finished in 11.151s.
Mar 20 15:06:38 hostname systemd[1]: Started User Manager for UID 0.
Mar 20 15:06:38 hostname systemd[1]: Started Session 3373 of user root.

The problem can also be seen here:

# systemd-analyze --user
Startup finished in 11.151s (userspace) 
default.target reached after 11.151s in userspace

# systemd-analyze --user blame
             7ms dbus.socket

# systemd-analyze --user 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.

default.target @11.151s
└─basic.target @11.150s
  └─sockets.target @11.150s
    └─dbus.socket @11.143s +7ms
      └─run-user-0.mount @11.137s
        └─-.mount @11.137s
          └─-.slice @11.137s

In a further e-mail I will send the output of this command:

# systemd-analyze --user dump


-- Package-specific info:

-- System Information:
Debian Release: buster/sid
  APT prefers unstable-debug
  APT policy: (500, 'unstable-debug'), (500, 'unstable'), (1, 'experimental-debug'), (1, 'experimental')
Architecture: amd64 (x86_64)

Kernel: Linux 4.19.0-4-amd64 (SMP w/2 CPU cores)
Locale: LANG=en_US.UTF-8, LC_CTYPE=en_US.UTF-8 (charmap=UTF-8) (ignored: LC_ALL set to en_US.UTF-8), LANGUAGE=en_US.
UTF-8 (charmap=UTF-8) (ignored: LC_ALL set to en_US.UTF-8)
Shell: /bin/sh linked to /usr/bin/dash
Init: systemd (via /run/systemd/system)
LSM: AppArmor: enabled

Versions of packages systemd depends on:
ii  adduser          3.118
ii  libacl1          2.2.53-4
ii  libapparmor1     2.13.2-9
ii  libaudit1        1:2.8.4-2
ii  libblkid1        2.33.1-0.1
ii  libc6            2.28-8
ii  libcap2          1:2.25-2
ii  libcryptsetup12  2:2.1.0-2
ii  libgcrypt20      1.8.4-5
ii  libgnutls30      3.6.6-3
ii  libgpg-error0    1.36-1
ii  libidn11         1.33-2.2
ii  libip4tc0        1.8.2-4
ii  libkmod2         26-1
ii  liblz4-1         1.8.3-1
ii  liblzma5         5.2.4-1
ii  libmount1        2.33.1-0.1
ii  libpam0g         1.3.1-5
ii  libseccomp2      2.3.3-4
ii  libselinux1      2.9-1
ii  libsystemd0      241-2
ii  mount            2.33.1-0.1
ii  util-linux       2.33.1-0.1

Versions of packages systemd recommends:
ii  dbus            1.13.8-1
ii  libpam-systemd  241-2

Versions of packages systemd suggests:
ii  policykit-1        0.115-3
ii  systemd-container  241-2

Versions of packages systemd is related to:
pn  dracut           <none>
ii  initramfs-tools  0.133
ii  udev             241-2

-- no debconf information

-- 
Laurent.