120 s delay during boot with smaller initrd

[Paul Menzel]

Dear Linux folks,


Using an initrd created by tiny-initramfs [1], the boot stalls for two 
minutes *after* the initrd has run and systemd has already started. An 
F2FS root partition is used.

```
[    0.000000] microcode: microcode updated early to revision 0xa0b, 
date = 2010-09-28
[    0.000000] Linux version 5.9.0-5-amd64 
(debian-kernel@xxxxxxxxxxxxxxxx) (gcc-10 (Debian 10.2.1-1) 10.2.1 
20201207, GNU ld (GNU Binutils for Debian) 2.35.1) #1 SMP Debian 
5.9.15-1 (2020-12-17)
[    0.000000] Command line: BOOT_IMAGE=/boot/vmlinuz-5.9.0-5-amd64 
root=/dev/sda2 ro quiet noisapnp cryptomgr.notests random.trust_cpu=on 
tsc=unstable debug log_buf_len=2M initcall_debug
[…]
[    0.650168] Trying to unpack rootfs image as initramfs...
[    0.661343] Freeing initrd memory: 1024K
[…]
[    6.033044] systemd[1]: systemd 247.2-3 running in system mode. (+PAM 
+AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP 
+GCRYPT +GNUTLS +ACL +XZ +LZ4 +ZSTD +SECCOMP +BLKID +ELFUTILS +KMOD 
+IDN2 -IDN +PCRE2 default-hierarchy=unified)
[…]
[    9.372134] fuse: init (API version 7.31)
[    9.396990] calling  pkcs8_key_init+0x0/0x1000 [pkcs8_key_parser] @ 114
[    9.413956] Asymmetric key parser 'pkcs8' registered
[    9.421378] initcall pkcs8_key_init+0x0/0x1000 [pkcs8_key_parser] 
returned 0 after 15912 usecs
[    9.433989] initcall fuse_init+0x0/0x142 [fuse] returned 0 after 
28206 usecs
[    9.443229] calling  drm_core_init+0x0/0x1000 [drm] @ 110
[    9.480740] initcall drm_core_init+0x0/0x1000 [drm] returned 0 after 
28888 usecs
[   12.057456] random: crng init done
[   12.060811] random: 7 urandom warning(s) missed due to ratelimiting
[  135.871988] perf: interrupt took too long (2509 > 2500), lowering 
kernel.perf_event_max_sample_rate to 79500
[  140.286157] audit: type=1400 audit(1609064788.012:2): 
apparmor="STATUS" operation="profile_load" profile="unconfined" 
name="nvidia_modprobe" pid=142 comm="apparmor_parser"
[  140.315152] audit: type=1400 audit(1609064788.012:3): 
apparmor="STATUS" operation="profile_load" profile="unconfined" 
name="nvidia_modprobe//kmod" pid=142 comm="apparmor_parser"
[  140.348623] audit: type=1400 audit(1609064788.072:4): 
apparmor="STATUS" operation="profile_load" profile="unconfined" 
name="/usr/bin/man" pid=155 comm="apparmor_parser"
[  140.382744] audit: type=1400 audit(1609064788.072:5): 
apparmor="STATUS" operation="profile_load" profile="unconfined" 
name="man_filter" pid=155 comm="apparmor_parser"
[  140.408791] audit: type=1400 audit(1609064788.072:6): 
apparmor="STATUS" operation="profile_load" profile="unconfined" 
name="man_groff" pid=155 comm="apparmor_parser"
[  140.439860] audit: type=1400 audit(1609064788.072:7): 
apparmor="STATUS" operation="profile_load" profile="unconfined" 
name="/usr/lib/cups/backend/cups-pdf" pid=141 comm="apparmor_parser" 

[  140.481521] calling  acpi_cpufreq_init+0x0/0x1000 [acpi_cpufreq] @ 154
[…]
```

The userspace log during that time could be:

```
Dez 27 11:24:17 sitopanaki systemd[1]: Finished Coldplug All udev Devices.
Dez 27 11:24:17 sitopanaki systemd[1]: systemd-udev-trigger.service: 
Control group is empty.
Dez 27 11:24:17 sitopanaki systemd[1]: sysinit.target: starting held 
back, waiting for: systemd-hwdb-update.service
Dez 27 11:26:02 sitopanaki systemd[1]: systemd-journald.service: Got 
notification message from PID 113 (WATCHDOG=1)
Dez 27 11:26:27 sitopanaki systemd-fsck[119]: Info: Fix the reported 
corruption.
Dez 27 11:26:27 sitopanaki systemd-fsck[119]: Info: Mounted device!
Dez 27 11:26:27 sitopanaki systemd-fsck[119]: Info: Check FS only due to RO
```

As it does not happen with the initrd created by initramfs-tools, but 
the initrd was successfully run, I am quite confused. Could it be F2FS 
related? Please find the full logs of both starts attached to bug 
#210917 [2].


Kind regards,

Paul


[1]: https://github.com/chris-se/tiny-initramfs/
[2]: https://bugzilla.kernel.org/show_bug.cgi?id=210917