[Solved] Slow loading of GDM - Random Number Generation?

hoschi · 2019-07-28 09:55:15

Hello!

Since the last upgrades, the login screen of GDM needs about 20 seconds to load. I suspect linux >= 5.2 is responsible for this or something required by the graphical.target, which consumes a lot of random numbers. I think so, because booting to th multi-user.target is as fast as usual and systemd-analyze and systemd-analyze blame are not showing anything unexpected:

# systemd-analyze

Startup finished in 4.652s (kernel) + 2.401s (userspace) = 7.054s 
graphical.target reached after 2.401s in userspace

# systemd-analyze critical-chain

The time when unit became active or started is printed after the "@" character.
The time the unit took to start is printed after the "+" character.

graphical.target @2.401s
└─multi-user.target @2.401s
  └─systemd-logind.service @1.695s +705ms
    └─basic.target @1.693s
      └─sockets.target @1.693s
        └─dbus.socket @1.693s
          └─sysinit.target @1.690s
            └─systemd-update-done.service @1.682s +7ms
              └─ldconfig.service @1.469s +210ms
                └─local-fs.target @1.467s
                  └─home.mount @1.441s +26ms
                    └─systemd-fsck@dev-sda3.service @1.374s +65ms
                      └─local-fs-pre.target @1.372s
                        └─lvm2-monitor.service @278ms +1.084s
                          └─lvm2-lvmetad.service @301ms
                            └─systemd-journald.socket @267ms
                              └─-.mount @242ms
                                └─systemd-journald.socket @267ms
                                  └─...

# journalctl -rb

Jul 27 19:25:30 cupcake systemd[1]: Started WPA supplicant.
Jul 27 19:25:30 cupcake audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=wpa_supplicant comm="systemd" exe="/usr/lib/systemd/systemd" hostnam>
Jul 27 19:25:30 cupcake NetworkManager[474]: <info>  [1564248330.4294] supplicant: wpa_supplicant running
Jul 27 19:25:30 cupcake NetworkManager[474]: <info>  [1564248330.4295] device (wlp3s0): supplicant interface state: init -> starting
Jul 27 19:25:30 cupcake kernel: audit: type=1130 audit(1564248330.421:30): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=wpa_supplicant comm="systemd" exe="/usr/l>
Jul 27 19:25:30 cupcake kernel: input: TPPS/2 IBM TrackPoint as /devices/platform/i8042/serio1/serio2/input/input17
Jul 27 19:25:33 cupcake systemd[1]: systemd-rfkill.service: Succeeded.
Jul 27 19:25:33 cupcake audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-rfkill comm="systemd" exe="/usr/lib/systemd/systemd" hostname>
Jul 27 19:25:33 cupcake kernel: audit: type=1131 audit(1564248333.901:31): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-rfkill comm="systemd" exe="/usr/l>
Jul 27 19:25:55 cupcake NetworkManager[474]: <error> [1564248355.4418] sup-iface[0x5589f51e80b0,wlp3s0]: error adding interface: Timeout was reached
Jul 27 19:25:55 cupcake NetworkManager[474]: <info>  [1564248355.4420] device (wlp3s0): supplicant interface state: starting -> down
Jul 27 19:25:55 cupcake NetworkManager[474]: <info>  [1564248355.4422] manager: startup complete
Jul 27 19:25:59 cupcake systemd[1]: systemd-hostnamed.service: Succeeded.
Jul 27 19:25:59 cupcake audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-hostnamed comm="systemd" exe="/usr/lib/systemd/systemd" hostn>
Jul 27 19:25:59 cupcake kernel: audit: type=1131 audit(1564248359.345:32): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-hostnamed comm="systemd" exe="/us>
Jul 27 19:26:05 cupcake NetworkManager[474]: <warn>  [1564248365.7717] device (wlp3s0): re-acquiring supplicant interface (#1).
Jul 27 19:26:30 cupcake NetworkManager[474]: <error> [1564248390.8002] sup-iface[0x5589f51e8190,wlp3s0]: error adding interface: Timeout was reached
Jul 27 19:26:30 cupcake NetworkManager[474]: <info>  [1564248390.8003] device (wlp3s0): supplicant interface state: starting -> down
Jul 27 19:26:31 cupcake kernel: random: crng init done
Jul 27 19:26:31 cupcake kernel: random: 7 urandom warning(s) missed due to ratelimiting
Jul 27 19:26:32 cupcake org.gnome.Shell.desktop[536]: glamor: No eglstream capable devices found

As you can see, the system is literally waiting a half minute for something - up until crng init is done. I know about havegd, just never need it and therefore hesitate do install a daemon which I don't actually require. My system is a ThinkPad X220 with a SandyBridge CPU, it should be therefore able to provide enough entropy by itself from the CPU. As a workaround I type some "random" keys on my keboard

Questions:
Has anyone else seen similar delays with recent upgrades?
Any guess whether this is bug or "feature"? I know about, that the kernel folks reverted changes which lead to delays through rng problems.

I don't have anything against haveged, I just want keep the system small&simple and want to understand why I got a RNG problem?

// edit
Aha! Haveged (use internal hardware states) is more a kind of daemon for headless servers, like I assumed. I will take now a look at rng-tools (uses hardware rng in processor).

Last edited by hoschi (2019-07-29 08:17:20)

loqs · 2019-07-28 10:22:32

Sandybridge lacks RDRAND meaning there is no hardware RNG on the CPU for rng-tools to use.
The kernel would use RDRAND if available but by default will not initialize the CSRNG without other entropy sources to prevent solely trusting RDRAND.

frostschutz · 2019-07-28 11:27:30

I use haveged everywhere. It's quick to install, try and see if it helps, and ifn it doesn't just as quick to uninstall.

You can also check systemd settings regarding randomness (it should save and restore a seed each reboot, for one thing). https://www.freedesktop.org/software/sy … rvice.html

hoschi · 2019-07-28 12:03:08

Good hint. I've read 'man 4 random':

If a seed file is saved across reboots as recommended below (all major Linux distributions have done this since 2000 at least)

It's a 'static' service in Systemd and in usage, the 'sysinit.target' seems to require it.

loqs wrote:

Sandybridge lacks RDRAND meaning there is no hardware RNG on the CPU for rng-tools to use.
The kernel would use RDRAND if available but by default will not initialize the CSRNG without other entropy sources to prevent solely trusting RDRAND.

Yep. I've opted for rng-tools:
# rngd -f

Initalizing available sources

Failed to init entropy source hwrng

Failed to init entropy source rdrand

Initalizing AES buffer

Enabling JITTER rng support

Initalizing entropy source jitter

PKCS11 Engine /usr/lib64/opensc-pkcs11.so Error: No such file or directory

Failed to init entropy source pkcs11

HWRNG: TPM, which is turned OFF deliberately by me
RDRAND: As you said, not available in SandyBridge
Other stuff: Works

systemctl enable rngd.service

GDM now loads quickly

TPM is OFF, while I have to trust my CPU and mainboard, I don't see a reason to trust and use TPM. Okay, it's kind of pointless, because I've to trust everything in the laptop.

What remains is, why my system now has not enough entropy or what consumes more of it.

Last edited by hoschi (2019-07-28 12:46:56)

loqs · 2019-07-28 14:42:47

The random seed is not currently credited with any entropy so does not progress initializing the CSRNG. See https://github.com/systemd/systemd/pull/13137 not present in systemd 242.

hoschi · 2019-07-28 21:42:04

Sounds interesting! They label it as fix for rather longstanding problems

Last edited by hoschi (2019-07-28 21:54:47)

hoschi · 2019-08-01 13:32:03

https://www.reddit.com/r/archlinux/comm … ew_laptop/

More people affected?

Arch Linux

#1 2019-07-28 09:55:15

[Solved] Slow loading of GDM - Random Number Generation?

#2 2019-07-28 10:22:32

Re: [Solved] Slow loading of GDM - Random Number Generation?

#3 2019-07-28 11:27:30

Re: [Solved] Slow loading of GDM - Random Number Generation?

#4 2019-07-28 12:03:08

Re: [Solved] Slow loading of GDM - Random Number Generation?

#5 2019-07-28 14:42:47

Re: [Solved] Slow loading of GDM - Random Number Generation?

#6 2019-07-28 21:42:04

Re: [Solved] Slow loading of GDM - Random Number Generation?

#7 2019-08-01 13:32:03

Re: [Solved] Slow loading of GDM - Random Number Generation?

Board footer