Improving boot time of systemd based initrd?

[Mikko Rapeli <mikko.rapeli@xxxxxxxxxx>]

Hi,

I'm trying to create a simple systemd based initrd with yocto
tooling. Main rootfs runs systemd too. The initrd should only
measure boot to TPM device and then detect rootfs from
mass storage on a number of boards. No graphics or other use cases
are needed at the moment. The initrd is created at cross compile time
and it does not know what kind of system it will run on so it needs
to be generic, not machine or board specific.

The test system boots u-boot based UEFI firmware which loads
secure boot signed UKI binary which includes the kernel and initrd.
The kernel command line has the end rootfs configured with label.

With shell script based initrd on qemu, the mass storage kernel module
loading and rootfs detection and mount happens in a few seconds.
With systemd this seems to take a lot longer, about 30 seconds.

Boot time to main rootfs is also around 30 seconds so it feels like
both rootfs and initrd are doing similar things, or possibly waiting
for udev etc probing a lot longer that would be needed.

Any ideas how to debug the root causes?

Any ideas how to improve the systemd based initrd boot time?

The TPM measurements done by systemd-boot already took a long time
due to UKI and initrd being way too big, over 200Mb, and I reduced the initrd
side of that to 56 Mb by dropping unnecessary userspace libraries and binaries
and kernel modules. So it looks like the size of UKI binary or rootfs are not
the root cause for slow initrd boot though.

Kernel is also not very optimized and a lot of drivers including TPM are currently
compiled into the kernel. Would be better to have a lot more modules but I need a way
to move them to initrd and they also need to improve the boot times then.

At the moment I'm constructing the initrd using same binary packages as rootfs.
It could be possible to use alternative tooling based on main rootfs for this but
they would need to work in cross compile environment outside of the target machine.

Some debug snippets below but full boot log and initrd packages and files are here:

https://people.linaro.org/~mikko.rapeli/systemd_initrd_slow_boot.txt
https://people.linaro.org/~mikko.rapeli/systemd_initrd_slow_boot_packages.txt
https://people.linaro.org/~mikko.rapeli/systemd_initrd_slow_boot_files.txt

Cheers,

-Mikko

# systemd-analyze
Startup finished in 8.315s (firmware) + 12.508s (loader) + 4.330s (kernel) + 27.660s (initrd) + 29.582s (userspace) = 1min 22.397s 
multi-user.target reached after 29.566s in userspace.

# systemd-analyze  blame
36.781s sys-module-fuse.device
36.697s sys-module-configfs.device
32.571s sys-devices-virtual-misc-rfkill.device
32.571s dev-rfkill.device
32.435s sys-devices-platform-platform\x2dbus\x40c000000-c000000.tpm_tis-tpm-tpm0.device
32.435s dev-tpm0.device
30.798s dev-ram0.device
30.798s sys-devices-virtual-block-ram0.device
30.729s dev-ram10.device
30.729s sys-devices-virtual-block-ram10.device
30.649s sys-devices-virtual-block-ram1.device
30.649s dev-ram1.device
30.646s dev-ram12.device
30.646s sys-devices-virtual-block-ram12.device
30.636s sys-devices-virtual-block-ram14.device
30.635s dev-ram14.device
30.557s dev-ram11.device
...

# 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.

multi-user.target @29.566s
`-ESC[0;1;31msystemd-logind.service @28.007s +1.548sESC[0m
  `-basic.target @27.288s
    `-ESC[0;1;31msystemd-pcrphase-sysinit.service @26.840s +431msESC[0m
      `-sysinit.target @26.640s
        `-ESC[0;1;31msystemd-update-done.service @26.298s +327msESC[0m
          `-ESC[0;1;31msystemd-journal-catalog-update.service @24.383s +1.843sESC[0m
            `-ESC[0;1;31msystemd-tmpfiles-setup.service @21.555s +2.312sESC[0m
              `-local-fs.target @20.995s
                `-ESC[0;1;31mboot.mount @20.642s +330msESC[0m
                  `-dev-vda1.device

# dmesg
...
[    4.526213] systemd[1]: System time advanced to built-in epoch: Thu 2024-12-19 21:25:48 UTC
[    4.801964] systemd[1]: Successfully made /usr/ read-only.
[    4.822912] systemd[1]: systemd 257.1 running in system mode (+PAM -AUDIT -SELINUX -APPARMOR +IMA +IPE -SMACK +SECCOMP -GCRYPT -GNUTLS +OPENSSL
 +ACL +BLKID -CURL -ELFUTILS -FIDO2 -IDN2 -IDN -IPTC +KMOD +LIBCRYPTSETUP +LIBCRYPTSETUP_PLUGINS +LIBFDISK -PCRE2 -PWQUALITY -P11KIT -QRENCODE +TP
M2 -BZIP2 -LZ4 -XZ -ZLIB +ZSTD -BPF_FRAMEWORK -BTF +XKBCOMMON +UTMP -SYSVINIT -LIBARCHIVE)
[    4.824136] systemd[1]: Detected virtualization qemu.
[    4.824793] systemd[1]: Detected architecture arm64.
[    4.825182] systemd[1]: Running in initrd.
[    4.847147] systemd[1]: Hostname set to <genericarm64>.
[    4.853025] systemd[1]: Initializing machine ID from random generator.
[    7.319963] systemd[1]: Queued start job for default target Initrd Default Target.
[    7.448059] systemd[1]: Created slice Slice /system/modprobe.
[    7.462036] systemd[1]: Started Dispatch Password Requests to Console Directory Watch.
[    7.465976] systemd[1]: Expecting device /dev/disk/by-label/root...
[    7.468692] systemd[1]: Reached target Initrd /usr File System.
[    7.471330] systemd[1]: Reached target Local Integrity Protected Volumes.
[    7.473868] systemd[1]: Reached target Path Units.
[    7.475937] systemd[1]: Reached target Remote Encrypted Volumes.
[    7.478360] systemd[1]: Reached target Remote Verity Protected Volumes.
[    7.480501] systemd[1]: Reached target Slice Units.
[    7.482884] systemd[1]: Reached target Swaps.
[    7.485000] systemd[1]: Reached target Local Verity Protected Volumes.
[    7.507968] systemd[1]: Listening on Credential Encryption/Decryption.
[    7.578926] systemd[1]: Journal Audit Socket was skipped because of an unmet condition check (ConditionSecurity=audit).
[    7.587701] systemd[1]: Listening on Journal Socket (/dev/log).
[    7.594422] systemd[1]: Listening on Journal Sockets.
[    7.620835] systemd[1]: Listening on TPM PCR Measurements.
[    7.643542] systemd[1]: Listening on Make TPM PCR Policy.
[    7.650550] systemd[1]: Listening on udev Control Socket.
[    7.655194] systemd[1]: Listening on udev Kernel Socket.
[    7.660355] systemd[1]: Listening on User Database Manager Socket.
[    7.727910] systemd[1]: Mounting Huge Pages File System...
[    7.771140] systemd[1]: Mounting POSIX Message Queue File System...
[    7.828934] systemd[1]: Mounting Kernel Debug File System...
[    7.881113] systemd[1]: Mounting Kernel Trace File System...
[    7.980366] systemd[1]: Mounting Temporary Directory /tmp...
[    8.077759] systemd[1]: Starting Create List of Static Device Nodes...
[    8.169881] systemd[1]: Starting Load Kernel Module configfs...
[    8.257899] systemd[1]: Starting Load Kernel Module dm_mod...
[    8.338270] systemd[1]: Starting Load Kernel Module fuse...
[    8.426323] systemd[1]: Starting Load Kernel Module loop...
[    8.434212] systemd[1]: Check battery level during early boot was skipped because of an unmet condition check (ConditionDirectoryNotEmpty=/sys/class/power_supply).
[    8.435793] systemd[1]: Clear Stale Hibernate Storage Info was skipped because of an unmet condition check (ConditionPathExists=!/etc/initrd-re
lease).
[    8.442043] systemd[1]: Rebuild Hardware Database was skipped because of an unmet condition check (ConditionNeedsUpdate=/etc).
[    8.603563] systemd[1]: Starting Journal Service...
[    8.615730] systemd[1]: Load Kernel Modules was skipped because no trigger condition checks were met.
[    8.695610] fuse: init (API version 7.41)
[    8.702234] systemd[1]: Starting Generate network units from Kernel command line...
[    8.719607] systemd[1]: TPM PCR Machine ID Measurement was skipped because of an unmet condition check (ConditionPathExists=!/etc/initrd-releas
e).
[    8.775964] systemd[1]: Starting TPM PCR Barrier (initrd)...
[    8.835777] systemd[1]: Starting Apply Kernel Variables...
[    8.959378] systemd[1]: Starting Load udev Rules from Credentials...
[    9.019475] systemd[1]: Starting Coldplug All udev Devices...
[    9.330155] systemd[1]: Mounted Huge Pages File System.
[    9.358111] systemd[1]: Mounted POSIX Message Queue File System.
[    9.365808] systemd[1]: Mounted Kernel Debug File System.
[    9.373663] systemd[1]: Mounted Kernel Trace File System.
[    9.430938] systemd[1]: Mounted Temporary Directory /tmp.
[    9.514663] systemd[1]: Finished Create List of Static Device Nodes.
[    9.551894] systemd[1]: modprobe@configfs.service: Deactivated successfully.
[    9.564350] systemd[1]: Finished Load Kernel Module configfs.
[    9.606657] systemd[1]: modprobe@dm_mod.service: Deactivated successfully.
[    9.619620] systemd-journald[108]: Collecting audit messages is disabled.
[    9.622701] systemd[1]: Finished Load Kernel Module dm_mod.
[    9.663572] systemd[1]: modprobe@fuse.service: Deactivated successfully.
[    9.674173] systemd[1]: Finished Load Kernel Module fuse.
[    9.697998] systemd[1]: modprobe@loop.service: Deactivated successfully.
[    9.709562] systemd[1]: Finished Load Kernel Module loop.
[    9.740235] systemd[1]: Finished Generate network units from Kernel command line.
[    9.760350] systemd[1]: Finished TPM PCR Barrier (initrd).
[    9.780836] systemd[1]: Finished Apply Kernel Variables.
[    9.811013] systemd[1]: Finished Load udev Rules from Credentials.
[    9.838295] systemd[1]: Reached target Local Encrypted Volumes.
[    9.840577] systemd[1]: Reached target Preparation for Network.
[    9.883287] systemd[1]: Mounting FUSE Control File System...
[    9.924704] systemd[1]: Mounting Kernel Configuration File System...
[   10.030383] systemd[1]: Starting Create Static Device Nodes in /dev gracefully...
[   10.131206] systemd[1]: Starting Early TPM SRK Setup...
[   10.244065] systemd[1]: Started Journal Service.
[   23.196772] pci-host-generic 4010000000.pcie: host bridge /pcie@10000000 ranges:
[   23.199735] pci-host-generic 4010000000.pcie:       IO 0x003eff0000..0x003effffff -> 0x0000000000
[   23.200966] pci-host-generic 4010000000.pcie:      MEM 0x0010000000..0x003efeffff -> 0x0010000000
[   23.205028] pci-host-generic 4010000000.pcie:      MEM 0x8000000000..0xffffffffff -> 0x8000000000
[   23.207056] pci-host-generic 4010000000.pcie: Memory resource size exceeds max for 32 bits
[   23.208781] pci-host-generic 4010000000.pcie: ECAM at [mem 0x4010000000-0x401fffffff] for [bus 00-ff]
[   23.212859] pci-host-generic 4010000000.pcie: PCI host bridge to bus 0000:00
[   23.214100] pci_bus 0000:00: root bus resource [bus 00-ff]
[   23.214465] pci_bus 0000:00: root bus resource [io  0x0000-0xffff]
[   23.214781] pci_bus 0000:00: root bus resource [mem 0x10000000-0x3efeffff]
[   23.215031] pci_bus 0000:00: root bus resource [mem 0x8000000000-0xffffffffff]
[   23.222081] pci 0000:00:00.0: [1b36:0008] type 00 class 0x060000 conventional PCI endpoint
[   23.238573] pci 0000:00:01.0: [1af4:1000] type 00 class 0x020000 conventional PCI endpoint
[   23.242790] pci 0000:00:01.0: BAR 0 [io  0x1000-0x101f]
[   23.245680] pci 0000:00:01.0: BAR 1 [mem 0x10000000-0x10000fff]
[   23.256313] pci 0000:00:01.0: BAR 4 [mem 0x10004000-0x10007fff 64bit pref]
[   23.259398] pci 0000:00:01.0: ROM [mem 0x10040000-0x1007ffff pref]
[   23.260851] pci 0000:00:02.0: [1af4:1005] type 00 class 0x00ff00 conventional PCI endpoint
[   23.264607] pci 0000:00:02.0: BAR 0 [io  0x1020-0x103f]
[   23.268050] pci 0000:00:02.0: BAR 1 [mem 0x10080000-0x10080fff]
[   23.279850] pci 0000:00:02.0: BAR 4 [mem 0x10084000-0x10087fff 64bit pref]
[   23.284583] pci 0000:00:03.0: [1af4:1001] type 00 class 0x010000 conventional PCI endpoint
[   23.292815] pci 0000:00:03.0: BAR 0 [io  0x1080-0x10ff]
[   23.299011] pci 0000:00:03.0: BAR 1 [mem 0x10088000-0x10088fff]
[   23.308052] pci 0000:00:03.0: BAR 4 [mem 0x1008c000-0x1008ffff 64bit pref]
[   23.350080] pci 0000:00:01.0: ROM [mem 0x10000000-0x1003ffff pref]: assigned
[   23.352101] pci 0000:00:01.0: BAR 4 [mem 0x8000000000-0x8000003fff 64bit pref]: assigned
[   23.366523] pci 0000:00:02.0: BAR 4 [mem 0x8000004000-0x8000007fff 64bit pref]: assigned
[   23.368187] pci 0000:00:03.0: BAR 4 [mem 0x8000008000-0x800000bfff 64bit pref]: assigned
[   23.382116] pci 0000:00:01.0: BAR 1 [mem 0x10040000-0x10040fff]: assigned
[   23.382983] pci 0000:00:02.0: BAR 1 [mem 0x10041000-0x10041fff]: assigned
[   23.383798] pci 0000:00:03.0: BAR 1 [mem 0x10042000-0x10042fff]: assigned
[   23.384692] pci 0000:00:03.0: BAR 0 [io  0x1000-0x107f]: assigned
[   23.394866] pci 0000:00:01.0: BAR 0 [io  0x1080-0x109f]: assigned
[   23.396522] pci 0000:00:02.0: BAR 0 [io  0x10a0-0x10bf]: assigned
[   23.400124] pci_bus 0000:00: resource 4 [io  0x0000-0xffff]
[   23.400441] pci_bus 0000:00: resource 5 [mem 0x10000000-0x3efeffff]
[   23.406036] pci_bus 0000:00: resource 6 [mem 0x8000000000-0xffffffffff]
[   23.571117] virtio_blk virtio2: 4/0/0 default/read/poll queues
[   23.633699] virtio_blk virtio2: [vda] 1920534 512-byte logical blocks (983 MB/938 MiB)
[   23.722722]  vda: vda1 vda2
[   26.437000] EXT4-fs (vda2): orphan cleanup on readonly fs
[   26.440484] EXT4-fs (vda2): mounted filesystem 8ee137f6-c962-4b01-9cb1-84e8a9751f8f ro with ordered data mode. Quota mode: disabled.
[   30.617995] systemd-journald[108]: Received SIGTERM from PID 1 (systemd).
[   32.434443] systemd[1]: systemd 257.1 running in system mode (+PAM -AUDIT -SELINUX -APPARMOR +IMA +IPE -SMACK +SECCOMP -GCRYPT -GNUTLS +OPENSSL
 +ACL +BLKID -CURL -ELFUTILS -FIDO2 -IDN2 -IDN -IPTC +KMOD +LIBCRYPTSETUP +LIBCRYPTSETUP_PLUGINS +LIBFDISK -PCRE2 -PWQUALITY -P11KIT -QRENCODE +TPM2 -BZIP2 -LZ4 -XZ -ZLIB +ZSTD -BPF_FRAMEWORK -BTF +XKBCOMMON +UTMP -SYSVINIT -LIBARCHIVE)
[   32.435848] systemd[1]: Detected virtualization qemu.
[   32.436510] systemd[1]: Detected architecture arm64.
[   32.472447] systemd[1]: Initializing machine ID from random generator.
[   32.476457] systemd[1]: Installed transient /etc/machine-id file.
[   37.433172] systemd[1]: initrd-switch-root.service: Deactivated successfully.
[   37.443351] systemd[1]: Stopped Switch Root.
[   37.487787] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1.
[   37.519910] systemd[1]: Created slice Slice /system/getty.
[   37.539922] systemd[1]: Created slice Slice /system/serial-getty.
[   37.559060] systemd[1]: Created slice User and Session Slice.
[   37.571458] systemd[1]: Started Dispatch Password Requests to Console Directory Watch.
[   37.577890] systemd[1]: Started Forward Password Requests to Wall Directory Watch.
[   37.581123] systemd[1]: Expecting device /dev/disk/by-uuid/B54F-CE02...
[   37.583910] systemd[1]: Expecting device /dev/ttyAMA0...
[   37.586578] systemd[1]: Reached target Local Encrypted Volumes.
[   37.589675] systemd[1]: Stopped target Switch Root.
[   37.592119] systemd[1]: Stopped target Initrd File Systems.
[   37.594705] systemd[1]: Stopped target Initrd Root File System.
[   37.596875] systemd[1]: Reached target Local Integrity Protected Volumes.
[   37.599931] systemd[1]: Reached target Path Units.
[   37.602520] systemd[1]: Reached target Remote Encrypted Volumes.
[   37.604844] systemd[1]: Reached target Remote File Systems.
[   37.607388] systemd[1]: Reached target Slice Units.
[   37.609905] systemd[1]: Reached target Swaps.
[   37.612303] systemd[1]: Reached target Local Verity Protected Volumes.
[   37.854439] systemd[1]: Listening on RPCbind Server Activation Socket.
[   37.859630] systemd[1]: Reached target RPC Port Mapper.
[   37.866337] systemd[1]: Listening on Syslog Socket.
[   37.897601] systemd[1]: Listening on Credential Encryption/Decryption.
[   37.991765] systemd[1]: Journal Audit Socket was skipped because of an unmet condition check (ConditionSecurity=audit).
[   38.002907] systemd[1]: Listening on Network Service Netlink Socket.
[   38.028507] systemd[1]: Listening on TPM PCR Measurements.
[   38.053985] systemd[1]: Listening on Make TPM PCR Policy.
[   38.059606] systemd[1]: Listening on udev Control Socket.
[   38.064294] systemd[1]: Listening on udev Kernel Socket.
[   38.071909] systemd[1]: Listening on User Database Manager Socket.
[   38.128929] systemd[1]: Mounting Temporary Directory /tmp...
[   38.182807] systemd[1]: Starting Create List of Static Device Nodes...
[   38.246390] systemd[1]: Starting Load Kernel Module configfs...
[   38.316315] systemd[1]: Starting Load Kernel Module dm_mod...
[   38.425351] systemd[1]: Starting Load Kernel Module drm...
[   38.566721] systemd[1]: Starting Load Kernel Module fuse...
[   38.656085] systemd[1]: Starting Load Kernel Module loop...
[   38.660358] systemd[1]: Clear Stale Hibernate Storage Info was skipped because of an unmet condition check (ConditionPathExists=/sys/firmware/efi/efivars/HibernateLocation-8cf2644b-4b0b-428f-9387-6d876050dc67).
[   38.806620] systemd[1]: Starting Journal Service...
[   38.822324] systemd[1]: Load Kernel Modules was skipped because no trigger condition checks were met.
[   38.875860] systemd[1]: Starting Generate network units from Kernel command line...
[   38.955244] systemd[1]: Starting TPM PCR Machine ID Measurement...
[   39.045116] systemd[1]: Starting Remount Root and Kernel File Systems...
[   39.151645] systemd[1]: Starting Apply Kernel Variables...
[   39.158767] systemd[1]: Early TPM SRK Setup was skipped because of an unmet condition check (ConditionPathExists=!/run/systemd/tpm2-srk-public-key.pem).
[   39.300077] systemd[1]: Starting Load udev Rules from Credentials...
[   39.453919] systemd[1]: Starting Coldplug All udev Devices...
[   39.730938] EXT4-fs (vda2): re-mounted 8ee137f6-c962-4b01-9cb1-84e8a9751f8f r/w. Quota mode: disabled.
[   39.909102] systemd[1]: Mounted Temporary Directory /tmp.
[   39.939935] systemd[1]: Finished Create List of Static Device Nodes.
[   39.968917] systemd[1]: modprobe@configfs.service: Deactivated successfully.
[   39.987649] systemd[1]: Finished Load Kernel Module configfs.
[   40.003033] systemd-journald[253]: Collecting audit messages is disabled.
[   40.015758] systemd[1]: modprobe@dm_mod.service: Deactivated successfully.
[   40.026072] systemd[1]: Finished Load Kernel Module dm_mod.
[   40.051110] systemd[1]: modprobe@drm.service: Deactivated successfully.
[   40.067039] systemd[1]: Finished Load Kernel Module drm.
[   40.086304] systemd[1]: modprobe@fuse.service: Deactivated successfully.
[   40.094834] systemd[1]: Finished Load Kernel Module fuse.
[   40.111459] systemd[1]: modprobe@loop.service: Deactivated successfully.
[   40.120288] systemd[1]: Finished Load Kernel Module loop.
[   40.140654] systemd[1]: Finished Generate network units from Kernel command line.
[   40.181684] systemd[1]: Finished TPM PCR Machine ID Measurement.
[   40.196347] systemd[1]: Finished Remount Root and Kernel File Systems.
[   40.220426] systemd[1]: Finished Apply Kernel Variables.
[   40.242444] systemd[1]: Finished Load udev Rules from Credentials.
[   40.251554] systemd[1]: Started Journal Service.
[   40.991343] systemd-journald[253]: Received client request to flush runtime journal.
[   47.562595] cfg80211: Loading compiled-in X.509 certificates for regulatory database
[   47.709831] Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'
[   47.711243] Loaded X.509 cert 'wens: 61c038651aabdcf94bd0ac7ff06c7248db18c600'