bottlerocket-os / bottlerocket-os/bottlerocket
Possible Containerd Startup Latency Increase
- Dominant language
- Rust
- Stars
- 9.7k
- Forks
- 586
- Avg merge
- 1d 11h
- Merged PRs (30d)
- 11
Description
**Image I'm using:**
`aws-dev` variant using core kit v2.3.5. Built using the following commands:
**What I expected to happen:**
I expect containerd to start up in ~1.5s after running `/bin/systemctl try-restart containerd.service`.
**What actually happened:**
It takes roughly ~6s for containerd to start.
**How to reproduce the problem:**
1. Build the AMI:
~~~
$ git clone https://github.com/bottlerocket-os/bottlerocket
$ cd bottlerocket
$ cargo make -e ARCH="x86_64" -e VARIANT="aws-dev" -e PUBLISH_REGIONS="us-west-2" build
$ cargo make -e ARCH="x86_64" -e PUBLISH_AMI_NAME="my-dev-ami" -e VARIANT="aws-dev" -e PUBLISH_REGIONS="us-west-2" ami
~~~
2. Start an EC2 Instance
3. Run `systemd-analyze blame`
~~~
bash-5.2# systemd-analyze
Startup finished in 3.277s (kernel) + 29.099s (userspace) = 32.376s
multi-user.target reached after 29.098s in userspace.
bash-5.2# systemd-analyze blame
5.670s host-containerd.service
4.083s docker.service
3.706s soci-snapshotter.service
2.220s sundog.service
1.976s early-boot-config.service
1.455s settings-applier.service
1.129s dev-nvme0n1p3.device
998ms dev-dm\x2d0.device
~~~
4. When looking at the journal logs, there seems to be a 6s delay between when containerd.service is started and when the daemon itself starts. I'll included the relevant journal logs below. Note that containerd only takes 60ms to load, which is expected.
~~~
Aug 23 20:20:24 localhost thar-be-settings[1063]: 20:20:24 [INFO] restart commands ["/bin/systemctl try-restart host-containerd.service"]
Aug 23 20:20:24 localhost thar-be-settings[1063]: 20:20:24 [INFO] restart commands ["/bin/systemctl try-restart containerd.service"]
Aug 23 20:20:24 localhost thar-be-settings[1063]: 20:20:24 [INFO] restart commands ["/usr/bin/systemctl try-restart systemd-modules-load"]
Aug 23 20:20:24 localhost systemd[1]: systemd-modules-load.service: Deactivated successfully.
Aug 23 20:20:24 localhost systemd[1]: Stopped Load Kernel Modules.
Aug 23 20:20:24 localhost systemd[1]: Stopping Load Kernel Modules...
Aug 23 20:20:25 localhost systemd[1]: Starting Load Kernel Modules...
Aug 23 20:20:25 localhost systemd[1]: Finished Load Kernel Modules.
Aug 23 20:20:25 localhost thar-be-settings[1063]: 20:20:25 [INFO] restart commands ["/usr/bin/corndog lockdown"]
Aug 23 20:20:25 localhost thar-be-settings[1063]: 20:20:25 [INFO] restart commands ["netdog write-resolv-conf"]
Aug 23 20:20:25 localhost systemd[1]: Reloading Network Configuration...
Aug 23 20:20:25 localhost systemd[1]: Stopping Network Name Resolution...
Aug 23 20:20:25 localhost systemd[1]: Finished Applies settings to create config files.
Aug 23 20:20:25 localhost systemd[1]: Started Send signal to CloudFormation Stack.
Aug 23 20:20:25 localhost systemd[1]: Starting Sets the hostname...
Aug 23 20:20:25 ip-10-192-0-240.us-west-2.compute.internal systemd[1]: Finished Sets the hostname.
Aug 23 20:20:25 ip-10-192-0-240.us-west-2.compute.internal systemd[1]: Reached target Bottlerocket initial configuration complete.
Aug 23 20:20:25 ip-10-192-0-240.us-west-2.compute.internal systemd[1]: Starting Isolates configured.target...
Aug 23 20:20:25 ip-10-192-0-240.us-west-2.compute.internal systemctl[1100]: Created symlink /etc/systemd/system/default.target → /x86_64-bottlerocket-linux-gnu/sys-root/usr/lib/systemd/system/configured.target.
Aug 23 20:20:25 ip-10-192-0-240.us-west-2.compute.internal systemd[1]: Reloading.
Aug 23 20:20:25 ip-10-192-0-240.us-west-2.compute.internal systemd-networkd[985]: eth0: found matching network '/etc/systemd/network/10-eth0.network', based on potentially unpredictable interface name.
Aug 23 20:20:25 ip-10-192-0-240.us-west-2.compute.internal systemd-networkd[985]: eth0: Reconfiguring with /etc/systemd/network/10-eth0.network.
Aug 23 20:20:25 ip-10-192-0-240.us-west-2.compute.internal systemd-networkd[985]: eth0: DHCPv4 connection considered critical, ignoring request to reconfigure it.
Aug 23 20:20:25 ip-10-192-0-240.us-west-2.compute.internal systemd-networkd[985]: eth0: DHCPv6 lease lost
Aug 23 20:20:25 ip-10-192-0-240.us-west-2.compute.internal systemd-networkd[985]: eth0: DHCPv4 address 10.192.0.240/24, gateway 10.192.0.1 acquired from 10.192.0.1
Aug 23 20:20:25 ip-10-192-0-240.us-west-2.compute.internal systemd[1]: systemd-resolved.service: Deactivated successfully.
Aug 23 20:20:25 ip-10-192-0-240.us-west-2.compute.internal systemd[1]: Stopped Network Name Resolution.
Aug 23 20:20:25 ip-10-192-0-240.us-west-2.compute.internal systemd[1]: Reloaded Network Configuration.
Aug 23 20:20:25 ip-10-192-0-240.us-west-2.compute.internal systemd[1]: Starting Network Name Resolution...
Aug 23 20:20:25 ip-10-192-0-240.us-west-2.compute.internal systemd[1]: Started A versatile implementation of the Network Time Protocol.
Aug 23 20:20:25 ip-10-192-0-240.us-west-2.compute.internal systemd[1]: Disables UDP offload was skipped because of an unmet condition check (ConditionVirtualization=vmware).
Aug 23 20:20:25 ip-10-192-0-240.us-west-2.compute.internal systemd[1]: Starting containerd runtime for host containers...
Aug 23 20:20:25 ip-10-192-0-240.us-west-2.compute.internal systemd[1]: Platform Persistent Storage Archival was skipped because of an unmet condition check (ConditionDirectoryNotEmpty=/sys/fs/pstore).
Aug 23 20:20:25 ip-10-192-0-240.us-west-2.compute.internal systemd[1]: Finished Isolates configured.target.
Aug 23 20:20:25 ip-10-192-0-240.us-west-2.compute.internal chronyd[1111]: 2024-08-23T20:20:25Z chronyd version 4.5 starting (+CMDMON +NTP +REFCLOCK +RTC +PRIVDROP +SCFILTER -SIGND +ASYNCDNS -NTS -SECHASH +IPV6 -DEBUG)
Aug 23 20:20:25 ip-10-192-0-240.us-west-2.compute.internal chronyd[1111]: 2024-08-23T20:20:25Z Loaded seccomp filter (level 1)
Aug 23 20:20:25 ip-10-192-0-240.us-west-2.compute.internal systemd-resolved[1109]: Positive Trust Anchors:
Aug 23 20:20:25 ip-10-192-0-240.us-west-2.compute.internal systemd-resolved[1109]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d
Aug 23 20:20:25 ip-10-192-0-240.us-west-2.compute.internal systemd-resolved[1109]: Negative trust anchors: home.arpa 10.in-addr.arpa 16.172.in-addr.arpa 17.172.in-addr.arpa 18.172.in-addr.arpa 19.172.in-addr.arpa 20.172.in-addr.arpa 21.172.in-addr.arpa 22.172.in-addr.arpa 23.172.in-addr.arpa 24.172.in-addr.arpa 25.172.in-addr.arpa 26.172.in-addr.arpa 27.172.in-addr.arpa 28.172.in-addr.arpa 29.172.in-addr.arpa 30.172.in-addr.arpa 31.172.in-addr.arpa 168.192.in-addr.arpa d.f.ip6.arpa corp home internal intranet lan local private test
Aug 23 20:20:25 ip-10-192-0-240.us-west-2.compute.internal systemd-resolved[1109]: Using system hostname 'ip-10-192-0-240.us-west-2.compute.internal'.
Aug 23 20:20:25 ip-10-192-0-240.us-west-2.compute.internal systemd[1]: Started Network Name Resolution.
Aug 23 20:20:29 ip-10-192-0-240.us-west-2.compute.internal chronyd[1111]: 2024-08-23T20:20:29Z Selected source 169.254.169.123
Aug 23 20:20:31 ip-10-192-0-240.us-west-2.compute.internal containerd[1112]: time="2024-08-23T20:20:31.046799766Z" level=info msg="starting containerd" revision=8fc6bcff51318944179630522a095cc9dbf9f353 version=1.7.20+bottlerocket
[...]
Aug 23 20:20:31 ip-10-192-0-240.us-west-2.compute.internal containerd[1112]: time="2024-08-23T20:20:31.105048029Z" level=info msg="containerd successfully booted in 0.060867s"
~~~
Contributor guide
Assessment
This issue has not been assessed yet.