Bug 210917

Summary: 120 s delay during boot with smaller initrd
Product: Other Reporter: Paul Menzel (pmenzel+bugzilla.kernel.org)
Component: OtherAssignee: other_other
Status: NEW ---    
Severity: normal CC: jtmettala, pmenzel+bugzilla.kernel.org
Priority: P1    
Hardware: All   
OS: Linux   
Kernel Version: Subsystem:
Regression: No Bisected commit-id:
Attachments: Linux 5.9.15 messages (output of `dmesg`), tiny-initramfs
Linux 5.9.15 messages (output of `dmesg`), initramfs-tools

Description Paul Menzel 2020-12-27 12:03:08 UTC
Created attachment 294359 [details]
Linux 5.9.15 messages (output of `dmesg`), tiny-initramfs

On an Acer TravelMate 5735Z/BA51_MV, BIOS V1.14 07/26/2011, with Debian sid/unstable with an F2FS formatted root partition, creating the initrd with tiny-initramfs [1], there is a delay of 120 seconds during boot.

```
[    0.000000] microcode: microcode updated early to revision 0xa0b, date = 2010-09-28
[    0.000000] Linux version 5.9.0-5-amd64 (debian-kernel@lists.debian.org) (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
[…]
```

I have no idea, what could cause this, as it works with the initrd created with initramfs-tools. In a virtual machine, I also do not see this.
Comment 1 Paul Menzel 2020-12-27 12:59:34 UTC
Created attachment 294361 [details]
Linux 5.9.15 messages (output of `dmesg`), initramfs-tools

Here are the Linux messages with the initrd created by initramfs-tools.

```
[    0.000000] microcode: microcode updated early to revision 0xa0b, date = 2010-09-28
[    0.000000] Linux version 5.9.0-5-amd64 (debian-kernel@lists.debian.org) (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.648778] Trying to unpack rootfs image as initramfs...
[    0.697937] Freeing initrd memory: 7492K
[…]
[    6.725125] 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)
[…]
[   10.094074] initcall fuse_init+0x0/0x142 [fuse] returned 0 after 42105 usecs
[   10.102654] calling  pkcs8_key_init+0x0/0x1000 [pkcs8_key_parser] @ 207
[   10.120974] calling  drm_core_init+0x0/0x1000 [drm] @ 204
[   10.132562] Asymmetric key parser 'pkcs8' registered
[   10.140480] initcall pkcs8_key_init+0x0/0x1000 [pkcs8_key_parser] returned 0 after 11616 usecs
[   10.154979] initcall drm_core_init+0x0/0x1000 [drm] returned 0 after 25715 usecs
[   10.382179] audit: type=1400 audit(1609065082.072:2): apparmor="STATUS" operation="profile_load" profile="unconfined" name="nvidia_modprobe" pid=230 comm="apparmor_parser"
[   10.442826] audit: type=1400 audit(1609065082.072:3): apparmor="STATUS" operation="profile_load" profile="unconfined" name="nvidia_modprobe//kmod" pid=230 comm="apparmor_parser"
[   10.464922] audit: type=1400 audit(1609065082.124:4): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/bin/man" pid=246 comm="apparmor_parser"
[   10.486888] audit: type=1400 audit(1609065082.124:5): apparmor="STATUS" operation="profile_load" profile="unconfined" name="man_filter" pid=246 comm="apparmor_parser"
[   10.511956] audit: type=1400 audit(1609065082.124:6): apparmor="STATUS" operation="profile_load" profile="unconfined" name="man_groff" pid=246 comm="apparmor_parser"
[   10.536767] audit: type=1400 audit(1609065082.128:7): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/lib/cups/backend/cups-pdf" pid=229 comm="apparmor_parser"
[   10.568193] audit: type=1400 audit(1609065082.128:8): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/sbin/cupsd" pid=229 comm="apparmor_parser"
[   10.603329] audit: type=1400 audit(1609065082.128:9): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/sbin/cupsd//third_party" pid=229 comm="apparmor_parser"
[   10.635454] audit: type=1400 audit(1609065082.292:10): apparmor="STATUS" operation="profile_load" profile="unconfined" name="libreoffice-senddoc" pid=255 comm="apparmor_parser"
[   10.786382] audit: type=1400 audit(1609065082.476:11): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/bin/evince" pid=254 comm="apparmor_parser"
[   10.836873] calling  acpi_button_driver_init+0x0/0x1000 [button] @ 241
[   10.840596] calling  acpi_cpufreq_init+0x0/0x1000 [acpi_cpufreq] @ 238
[   10.872841] initcall acpi_cpufreq_init+0x0/0x1000 [acpi_cpufreq] returned 0 after 4638 usecs
[   10.889143] input: Power Button as /devices/LNXSYSTM:00/LNXSYBUS:00/PNP0A08:00/device:0b/PNP0C0C:00/input/input3
[   10.915164] ACPI: Power Button [PWRB]
[   10.931691] calling  acpi_ac_init+0x0/0xfdc [ac] @ 248
[   10.948211] calling  acpi_video_init+0x0/0x1000 [video] @ 244
[…]
```
Comment 2 Jouni Mettälä 2020-12-27 14:05:09 UTC
This sounds like waiting for network.
Comment 3 Paul Menzel 2021-12-24 22:24:34 UTC
Jouni, what makes you think that?

    [   12.060811] random: 7 urandom warning(s) missed due to ratelimiting
    [  135.871988] perf: interrupt took too long (2509 > 2500), lowering