Arch Linux

rubenvb

Member

Registered: 2011-01-14

Posts: 104

SDDM startup slowed by entropy generation?

I was looking for reasons why SDDM was slow to start and only started if I pressed buttons on my keyboard.

Much to my surprise I found this forum post:
https://bbs.archlinux.org/viewtopic.php?id=243743

which suggests this is caused by slow entropy generation. There seems to be a kernel parameter (that I can't enable because "lscpu | grep rdrand" returns nada) to help the issue, and the suggested alternative ,haveged, seems to lack in quality and be possible dangerous (I'm aware this might be hyperbole).

How come a desktop window manager such as SDDM is blocked by random number entropy, and why does it only occur since "recently" (as in: 6 months ago this wasn't an issue at all).

More importantly: how can this be fixed without generating bad random numbers which could be used for anything on my system?

As far as system information goes:

# cat /proc/sys/kernel/random/entropy_avail
3981

This increases just a little as time goes by and I press buttons and stuff, but not fast at all.

Architecture:        x86_64
CPU op-mode(s):      32-bit, 64-bit
Byte Order:          Little Endian
Address sizes:       36 bits physical, 48 bits virtual
CPU(s):              4
On-line CPU(s) list: 0-3
Thread(s) per core:  2
Core(s) per socket:  2
Socket(s):           1
NUMA node(s):        1
Vendor ID:           GenuineIntel
CPU family:          6
Model:               37
Model name:          Intel(R) Core(TM) i5 CPU       M 460  @ 2.53GHz
Stepping:            5
CPU MHz:             1224.249
CPU max MHz:         2534.0000
CPU min MHz:         1199.0000
BogoMIPS:            5055.42
Virtualization:      VT-x
L1d cache:           32K
L1i cache:           32K
L2 cache:            256K
L3 cache:            3072K
NUMA node0 CPU(s):   0-3
Flags:               fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx rdtscp lm constant_tsc arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc cpuid aperfmperf pni dtes64 monitor ds_cpl vmx est tm2 ssse3 cx16 xtpr pdcm pcid sse4_1 sse4_2 popcnt lahf_lm pti ssbd ibrs ibpb stibp tpr_shadow vnmi flexpriority ept vpid dtherm ida arat flush_l1d

Yes, first generation i5 mobile. Welcome to the past

Last edited by rubenvb (2019-02-05 18:58:48)

frostschutz

Member

Registered: 2013-11-15

Posts: 1,653

Re: SDDM startup slowed by entropy generation?

Are you running in a VM? Is your rng initialization unusually late? dmesg | grep random?

[    0.167661] random: get_random_bytes called from start_kernel+0x95/0x548 with crng_init=0
[    2.276474] random: fast init done
[    3.737765] random: crng init done
[   27.285293] audit: type=1130 audit(1549387853.954:2): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-random-seed comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'

the suggested alternative, haveged, seems to lack in quality

even if it did, it shouldn't matter

you can not tamper with the random driver (from userspace... VM is a different can of worms). you can only mix in more data. if it was random before it will still be random after.

the cpu rdrand was similarly suspected to be not reliable at all. as long as its not the only random source, it makes no difference; and the kernel's random implementation has completely changed, so even if haveged or rdrand were somehow ingeniously designed to mess with the kernel, it no longer works the same as before.

Last edited by frostschutz (2019-02-05 19:39:39)

rubenvb

Member

Registered: 2011-01-14

Posts: 104

Re: SDDM startup slowed by entropy generation?

This is a native install, no VM. Although I do enable and use libvirtd as a system daemon.
This is the output of dmesg | grep random:

[    0.279472] random: get_random_bytes called from start_kernel+0x95/0x548 with crng_init=0
[    2.700836] random: fast init done
[    3.412775] random: systemd: uninitialized urandom read (16 bytes read)
[    3.449435] random: systemd: uninitialized urandom read (16 bytes read)
[    3.449910] random: systemd: uninitialized urandom read (16 bytes read)
[    3.519183] audit: type=1130 audit(1549347531.242:3): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-random-seed comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[   47.413277] random: crng init done
[   47.413305] random: 7 urandom warning(s) missed due to ratelimiting

No idea what this means though.

Maybe the only possible solution for me is indeed installing haveged.

I still wonder why this became a problem where it wasn't before.

loqs

Member

Registered: 2014-03-06

Posts: 19,062

Re: SDDM startup slowed by entropy generation?

I still wonder why this became a problem where it wasn't before.

With what package updates did the problem first occur?

frostschutz

Member

Registered: 2013-11-15

Posts: 1,653

Re: SDDM startup slowed by entropy generation?

47s is definitely rather late for the crng init. (even the above 4s is already a bit slow)

I still wonder why this became a problem where it wasn't before.

you could go through old system logs to see if crng init has always been this late

not sure what sddm does specifically

rubenvb

Member

Registered: 2011-01-14

Posts: 104

Re: SDDM startup slowed by entropy generation?

With what package updates did the problem first occur?

That's a very good question. It's been a while.
I usually just close my laptop lid and suspend to disk, bypassing this problem entirely for weeks on end.

The output of journalctl | grep crng is

Feb 03 22:41:58 arch-vaio kernel: random: get_random_bytes called from start_kernel+0x95/0x548 with crng_init=0
Feb 03 22:42:15 arch-vaio kernel: random: crng init done
Feb 03 22:43:54 arch-vaio kernel: random: get_random_bytes called from start_kernel+0x95/0x548 with crng_init=0
Feb 03 22:44:23 arch-vaio kernel: random: crng init done
Feb 03 22:46:54 arch-vaio kernel: random: get_random_bytes called from start_kernel+0x95/0x548 with crng_init=0
Feb 03 22:47:27 arch-vaio kernel: random: crng init done
Feb 03 22:51:44 arch-vaio kernel: random: get_random_bytes called from start_kernel+0x95/0x548 with crng_init=0
Feb 03 22:52:22 arch-vaio kernel: random: crng init done
Feb 03 22:56:52 arch-vaio kernel: random: get_random_bytes called from start_kernel+0x95/0x548 with crng_init=0
Feb 03 22:57:15 arch-vaio kernel: random: crng init done
Feb 03 23:01:36 arch-vaio kernel: random: get_random_bytes called from start_kernel+0x95/0x548 with crng_init=0
Feb 03 23:01:47 arch-vaio kernel: random: crng init done
Feb 03 23:07:59 arch-vaio kernel: random: get_random_bytes called from start_kernel+0x95/0x548 with crng_init=0
Feb 03 23:08:35 arch-vaio kernel: random: crng init done
Feb 05 07:13:44 arch-vaio kernel: random: get_random_bytes called from start_kernel+0x95/0x548 with crng_init=0
Feb 05 07:13:57 arch-vaio kernel: random: crng init done
Feb 05 07:18:51 arch-vaio kernel: random: get_random_bytes called from start_kernel+0x95/0x548 with crng_init=0
Feb 05 07:19:35 arch-vaio kernel: random: crng init done

Unfortunately that's an embarrassingly short timeframe, so no package updates I can blame for a change.
I guess the 47 seconds here was because I didn't ram random keys at boot this time.

chris.m

Member

Registered: 2014-04-06

Posts: 24

Re: SDDM startup slowed by entropy generation?

I have the same issue as OP on a headless server. I can't say when it started for me, as this is a new install. However, I'm fairly sure my old retired system had the same issue ...

$ dmesg | grep random
[    0.000000] random: get_random_u32 called from bsp_init_amd+0x1f9/0x290 with crng_init=0
[    1.919935] random: fast init done
[    2.335921] random: systemd: uninitialized urandom read (16 bytes read)
[    2.379395] random: systemd: uninitialized urandom read (16 bytes read)
[    2.387126] random: systemd: uninitialized urandom read (16 bytes read)
[   46.543114] random: crng init done
[   46.543120] random: 7 urandom warning(s) missed due to ratelimiting

I noticed this mainly as it takes an age for ssh start and accept connections.

loqs

Member

Registered: 2014-03-06

Posts: 19,062

Re: SDDM startup slowed by entropy generation?

Possibly sddm is triggering it by doing this
https://github.com/sddm/sddm/blob/c8867 … er.cpp#L54
https://github.com/qt/qtbase/blob/5733d … m.cpp#L149

frostschutz

Member

Registered: 2013-11-15

Posts: 1,653

Re: SDDM startup slowed by entropy generation?

The journalctl output is not helpful (absolute date instead of seconds since boot).

Perhaps the short-monotonic format will be better.

journalctl -o short-monotonic --grep='crng init'

Going through my own logs I found some very late init occurences too, the first few boots after doing a clean reinstall of ArchLinux this year:

[   33.419182] ALU kernel: random: crng init done
-- Reboot --
[  112.366278] ALU kernel: random: crng init done
-- Reboot --
[   20.303777] ALU kernel: random: crng init done
-- Reboot --
[   18.952419] ALU kernel: random: crng init done
-- Reboot --
[   33.389437] ALU kernel: random: crng init done
-- Reboot --
[   18.284476] ALU kernel: random: crng init done
-- Reboot --
[   17.749362] ALU kernel: random: crng init done
-- Reboot --
[   47.229639] ALU kernel: random: crng init done
-- Reboot --
[   12.475382] ALU kernel: random: crng init done
-- Reboot --
[  209.502112] ALU kernel: random: crng init done
-- Reboot --
[    3.093296] ALU kernel: random: crng init done
-- Reboot --
[    3.314664] ALU kernel: random: crng init done
-- Reboot --
[    3.265564] ALU kernel: random: crng init done
-- Reboot --
[    3.599648] ALU kernel: random: crng init done
...

So, *something* on my system also caused crng init to be late (up to 200 seconds, wow), until it kicked into fast mode.

Not sure what exactly is the cause... I did not do anything specific to make crng init faster/slower.

I do have an encrypted system though so I'm typing in a passphrase in initramfs. Even if all other ways of initializing random failed, that alone should be enough to do it...

However the crng init time is too uniform, sometimes I type the passphrase late, so that can't be it either.

rubenvb

Member

Registered: 2011-01-14

Posts: 104

Re: SDDM startup slowed by entropy generation?

Ah well, I thought since the start_kernel thing was near 0 seconds after boot the output would be sufficient.

Here's what you suggested:

-- Reboot --
[   21.316086] arch-vaio kernel: random: crng init done
-- Reboot --
[   33.187899] arch-vaio kernel: random: crng init done
-- Reboot --
[   37.205018] arch-vaio kernel: random: crng init done
-- Reboot --
[   42.151419] arch-vaio kernel: random: crng init done
-- Reboot --
[   26.537719] arch-vaio kernel: random: crng init done
-- Reboot --
[   14.303927] arch-vaio kernel: random: crng init done
-- Reboot --
[   40.701436] arch-vaio kernel: random: crng init done
-- Reboot --
[   17.130402] arch-vaio kernel: random: crng init done
-- Reboot --
[   47.413277] arch-vaio kernel: random: crng init done

Which pretty much confirms what I thought: the time diff between the start_kernel entries and init done entries is pretty much the absolute monotonic timestamp as you get above. I do have an Arch HTPC, I'll see if there are any older logs to be found there.