Dear Linux folks,
Looking at the timestamps I only just noticed a two second regression.
The line below
systemd[1]: Created slice Slice /system/getty.
is logged two seconds later. I haven’t debugged yet, and wanted to
report it early. (No idea if it’s even related to the random subsystem.)
### 5.17-rc8
```
[ 0.000000] Linux version 5.17.0-rc8-00254-g24544474c7a3
(root@45e877da5b3e) (gcc (Debian 11.2.0-12) 11.2.0, GNU ld (GNU Binutils
for Debian) 2.37) #292 SMP PREEMPT Sat Mar 19 17:58:03 UTC 2022
[ 0.000000] Command line:
BOOT_IMAGE=/boot/vmlinuz-5.17.0-rc8-00254-g24544474c7a3 root=/dev/sda3
rw quiet noisapnp cryptomgr.notests ipv6.disable_ipv6=1 selinux=0
apic=verbose
[…]
[ 0.495882] Run /sbin/init as init process
[ 0.495883] with arguments:
[ 0.495884] /sbin/init
[ 0.495885] noisapnp
[ 0.495886] with environment:
[ 0.495887] HOME=/
[ 0.495887] TERM=linux
[ 0.495888] BOOT_IMAGE=/boot/vmlinuz-5.17.0-rc8-00254-g24544474c7a3
[ 0.508902] random: random: 1
[ 0.508906] random: random: 2
[ 0.508906] random: random: 3
[ 0.508907] random: random: 4
[ 0.535152] random: random: 1
[ 0.535155] random: random: 2
[ 0.535156] random: random: 3
[ 0.535157] random: random: 4
[ 0.535158] random: fast init done
[ 0.656129] systemd[1]: Inserted module 'autofs4'
[ 0.670092] NET: Registered PF_INET6 protocol family
[ 0.670798] Segment Routing with IPv6
[ 0.670817] In-situ OAM (IOAM) with IPv6
[ 0.688171] systemd[1]: systemd 250.4-1 running in system mode (+PAM
+AUDIT +SELINUX +APPARMOR +IMA +SMACK +SECCOMP +GCRYPT +GNUTLS -OPENSSL
+ACL +BLKID +CURL +ELFUTILS +FIDO2 +IDN2 -IDN +IPTC +KMOD +LIBCRYPTSETUP
+LIBFDISK +PCRE2 -PWQUALITY -P11KIT -QRENCODE +BZIP2 +LZ4 +XZ +ZLIB
+ZSTD -BPF_FRAMEWORK -XKBCOMMON +UTMP +SYSVINIT default-hierarchy=unified)
[ 0.688462] systemd[1]: Detected architecture x86-64.
[ 0.689648] systemd[1]: Hostname set to <kodi>.
[ 0.882098] systemd[1]: Queued start job for default target Graphical
Interface.
[ 0.882399] random: systemd: uninitialized urandom read (16 bytes read)
[ 0.884599] systemd[1]: Created slice Slice /system/getty.
[…]
```
### 5.18-rc4+ (based on commit 38d741cb70b3 (Merge tag
'drm-fixes-2022-04-29' of git://anongit.freedesktop.org/drm/drm)
```
[ 0.000000] Linux version 5.18.0-rc4-00303-g7c523829a82e
(root@4beb429beb4a) (gcc (Debian 11.2.0-12) 11.2.0, GNU ld (GNU Binutils
for Debian) 2.37) #349 SMP PREEMPT_DYNAMIC Fri Apr 29 06:33:06 UTC 2022
[ 0.000000] Command line:
BOOT_IMAGE=/boot/vmlinuz-5.18.0-rc4-00303-g7c523829a82e root=/dev/sda3
rw quiet noisapnp cryptomgr.notests ipv6.disable_ipv6=1 selinux=0
[…]
[ 0.536857] Run /sbin/init as init process
[ 0.536859] with arguments:
[ 0.536860] /sbin/init
[ 0.536861] noisapnp
[ 0.536862] with environment:
[ 0.536862] HOME=/
[ 0.536863] TERM=linux
[ 0.536864] BOOT_IMAGE=/boot/vmlinuz-5.18.0-rc4-00303-g7c523829a82e
[ 0.592103] random: fast init done
[ 0.708529] systemd[1]: Inserted module 'autofs4'
[ 0.720889] NET: Registered PF_INET6 protocol family
[ 0.721601] Segment Routing with IPv6
[ 0.721619] In-situ OAM (IOAM) with IPv6
[ 0.737764] systemd[1]: systemd 250.4-1 running in system mode (+PAM
+AUDIT +SELINUX +APPARMOR +IMA +SMACK +SECCOMP +GCRYPT +GNUTLS -OPENSSL
+ACL +BLKID +CURL +ELFUTILS +FIDO2 +IDN2 -IDN +IPTC +KMOD +LIBCRYPTSETUP
+LIBFDISK +PCRE2 -PWQUALITY -P11KIT -QRENCODE +BZIP2 +LZ4 +XZ +ZLIB
+ZSTD -BPF_FRAMEWORK -XKBCOMMON +UTMP +SYSVINIT default-hierarchy=unified)
[ 0.738077] systemd[1]: Detected architecture x86-64.
[ 0.739470] systemd[1]: Hostname set to <kodi>.
[ 0.931002] systemd[1]: Queued start job for default target Graphical
Interface.
[ 1.434543] tsc: Refined TSC clocksource calibration: 3900.224 MHz
[ 1.434549] clocksource: tsc: mask: 0xffffffffffffffff max_cycles:
0x70705a6472c, max_idle_ns: 881590586812 ns
[ 1.434562] clocksource: Switched to clocksource tsc
[ 2.826543] random: crng init done
[ 2.828295] systemd[1]: Created slice Slice /system/getty.
[…]
```
I am going to be away from the system for a week, but maybe I find time
to try to reproduce it in QEMU.
Kind regards,
Paul
Hi Paul,
On Mon, May 16, 2022 at 12:09:20AM +0200, Paul Menzel wrote:
> Dear Linux folks,
>
>
> Looking at the timestamps I only just noticed a two second regression.
> The line below
>
> systemd[1]: Created slice Slice /system/getty.
>
Known thing, but not quite a regression, as it does unblock and continue
booting. IOW, there's no possibility it will hang forever. But that's
neither here nor there: your log says you're using systemd 250.4. This
was fixed and backported to 250.5 (and 251 of course), so try updating,
and the issue you're seeing will be gone. If not, do let me know.
Jason
Dear Jason,
Thank you for your quick reply.
Am 16.05.22 um 00:26 schrieb Jason A. Donenfeld:
> On Mon, May 16, 2022 at 12:09:20AM +0200, Paul Menzel wrote:
>> Looking at the timestamps I only just noticed a two second regression.
>> The line below
>>
>> systemd[1]: Created slice Slice /system/getty.
>
> Known thing, but not quite a regression, as it does unblock and continue
> booting. IOW, there's no possibility it will hang forever.
Depends on the definition of *regression*. If you have boottime
requirements, than it would be considered one, and would hold me back
from always updating the Linux kernel confidently as promised by Linux.
But in my case it’s not a product, so I do not care.
> But that's neither here nor there: your log says you're using systemd
> 250.4. This was fixed and backported to 250.5 (and 251 of course), so
> try updating, and the issue you're seeing will be gone. If not, do
> let me know.
systemd 251 was released last week, and entered Debian sid/unstable this
week, and I can confirm, the two second delay is gone with Linux 5.18.
```
[ 0.000000] Linux version 5.18.0-00107-geb50eb550f2c
(root@4beb429beb4a) (gcc (Debian 11.2.0-12) 11.2.0, GNU ld (GNU Binutils
for Debian) 2.37) #360 SMP PREEMPT_DYNAMIC Mon May 23 07:00:41 UTC 2022
[ 0.000000] Command line:
BOOT_IMAGE=/boot/vmlinuz-5.18.0-00107-geb50eb550f2c root=/dev/sda3 rw
quiet noisapnp cryptomgr.notests ipv6.disable_ipv6=1 selinux=0
[ 0.000000] random: get_random_u32 called from
bsp_init_amd+0x142/0x210 with crng_init=0
[…]
[ 0.000000] DMI: ASUS F2A85-M_PRO/F2A85-M_PRO, BIOS
4.16-1133-g923080d1e6 05/25/2022
[…]
[ 0.541486] Run /sbin/init as init process
[ 0.541487] with arguments:
[ 0.541488] /sbin/init
[ 0.541489] noisapnp
[ 0.541490] with environment:
[ 0.541491] HOME=/
[ 0.541491] TERM=linux
[ 0.541492] BOOT_IMAGE=/boot/vmlinuz-5.18.0-00107-geb50eb550f2c
[ 0.592867] random: fast init done
[ 0.711960] systemd[1]: Inserted module 'autofs4'
[ 0.725757] NET: Registered PF_INET6 protocol family
[ 0.726491] Segment Routing with IPv6
[ 0.726509] In-situ OAM (IOAM) with IPv6
[ 0.745301] systemd[1]: systemd 251-2 running in system mode (+PAM
+AUDIT +SELINUX +APPARMOR +IMA +SMACK +SECCOMP +GCRYPT +GNUTLS -OPENSSL
+ACL +BLKID +CURL +ELFUTILS +FIDO2 +IDN2 -IDN +IPTC +KMOD +LIBCRYPTSETUP
+LIBFDISK +PCRE2 -PWQUALITY -P11KIT -QRENCODE +TPM2 +BZIP2 +LZ4 +XZ
+ZLIB +ZSTD -BPF_FRAMEWORK -XKBCOMMON +UTMP +SYSVINIT
default-hierarchy=unified)
[ 0.745311] systemd[1]: Detected architecture x86-64.
[ 0.747380] systemd[1]: Hostname set to <kodi>.
[ 0.943692] systemd[1]: Queued start job for default target Graphical
Interface.
[ 0.946792] systemd[1]: Created slice Slice /system/getty.
[ 0.947738] systemd[1]: Created slice Slice /system/modprobe.
[ 0.948377] systemd[1]: Created slice User and Session Slice.
[ 0.948528] systemd[1]: Started Dispatch Password Requests to Console
Directory Watch.
[ 0.948636] systemd[1]: Started Forward Password Requests to Wall
Directory Watch.
[ 0.949036] systemd[1]: Set up automount Arbitrary Executable File
Formats File System Automount Point.
```
Kind regards,
Paul