Slow boot time due to repeated system image loading

[janeczku]

RancherOS Version: (ros os version)
v1.4.0

Where are you running RancherOS? (docker-machine, AWS, GCE, baremetal, etc.)
vSphere
2 vCPU / 2048 MB

Expected:
Boot time ~ 60 seconds

Actual:
vmware ISO: 90 seconds boot time
vmware disk install: 70 seconds boot time

Most of the boot time is spent loading the system images from images.tar. This is done 3 times during bootstrapping, cloud-init, and init phase. When booting from vmware ISO a total of 50 seconds was spent loading the images (see below).

It looks like the first two boot phases require only 1 out of the 9 images included in images.tar.
To reduce boot time, we could split images.tar in multiple archives to only load those that are required in each phase.

--- dmesg ---

[Fri Sep  7 19:09:53 2018] Linux version 4.14.32-rancher2 (root@148079e86502) (gcc version 7.3.0 (GCC)) #1 SMP Fri May 11 11:30:31 UTC 2018
(...)
[    0.605837] Unpacking initramfs...
[   22.892150] Freeing initrd memory: 80672K
(...)
[   24.807893] ip_tables: (C) 2000-2006 Netfilter Core Team
[   44.501799] cgroup: system-docker-r (380) created nested cgroup for controller "memory" which has incomplete hierarchy support. Nested cgroups may change behavior in the future.
(...)
[   48.417880] EXT4-fs (sda): mounted filesystem with ordered data mode. Opts: (null)
[   60.508546] udevd[633]: starting version 3.2.5
(...)
[   65.731908] IPv6: ADDRCONF(NETDEV_UP): docker-sys: link is not ready
[   88.870509] udevd[20]: starting version 3.2.5
(...)
[Fri Sep  7 19:11:24 2018] vmxnet3 0000:0b:00.0 eth0: NIC Link is Up 10000 Mbps

--- init.log: 30 seconds spent loading images ---

(...)
time="2018-09-07T19:10:17Z" level=info msg="[1/2] Starting bootstrap loadImages"
time="2018-09-07T19:10:17Z" level=debug msg="Looking for images at /usr/share/ros"
time="2018-09-07T19:10:17Z" level=debug msg="Found images.tar"
time="2018-09-07T19:10:17Z" level=info msg="Waiting for Docker at unix:///var/run/system-docker.sock"
time="2018-09-07T19:10:18Z" level=info msg="Connected to Docker at unix:///var/run/system-docker.sock"
time="2018-09-07T19:10:18Z" level=info msg="Loading images from /usr/share/ros/images.tar"
time="2018-09-07T19:10:37Z" level=info msg="Done loading images from /usr/share/ros/images.tar"
(...)
time="2018-09-07T19:10:41Z" level=info msg="[1/2] Starting cloudinit loadImages"
time="2018-09-07T19:10:41Z" level=debug msg="Looking for images at /usr/share/ros"
time="2018-09-07T19:10:41Z" level=debug msg="Found images.tar"
time="2018-09-07T19:10:41Z" level=info msg="Waiting for Docker at unix:///var/run/system-docker.sock"
time="2018-09-07T19:10:43Z" level=info msg="Connected to Docker at unix:///var/run/system-docker.sock"
time="2018-09-07T19:10:43Z" level=info msg="Loading images from /usr/share/ros/images.tar"
time="2018-09-07T19:10:53Z" level=info msg="Done loading images from /usr/share/ros/images.tar"
(...)

--- ros-sysinit.log: 20 seconds spent loading images ---

(...)
time="2018-09-07T19:10:57Z" level=info msg="[1/4] Starting loadImages"
time="2018-09-07T19:10:57Z" level=debug msg="Looking for images at /usr/share/ros"
time="2018-09-07T19:10:57Z" level=debug msg="Found images.tar"
time="2018-09-07T19:10:59Z" level=info msg="Loading images from /usr/share/ros/images.tar"
time="2018-09-07T19:11:20Z" level=info msg="Done loading images from /usr/share/ros/images.tar"
(...)
time="2018-09-07T19:11:29Z" level=info msg="RancherOS 289ff05 started"

[niusmallnan]

Mitigated by #2474

[pwFoo]

Bare metal installed on ssd unpacking initramfs needs 39,1 seconds and I have to wait for a full boot 70 seconds.

Don't know how long that problem exists. It's for a long time... That's why I moved away.
Linuxkit docker boots really fast and that should be possible with RancherOS too...

If possible the preload images shouldn't included to the (installed version of) initramfs of RancherOS, because the images should be loaded from disk.

[niusmallnan]

Before we can officially release 1.5, anybody who hit this problem can try this iso.
http://releases.rancher.com/os/test/rancheros-master.iso

[pwFoo]

Bare metal install boot time reduced from 70 seconds to 28,5 seconds.

But maybe a new error appeared during boot (I see no problems after boot).

[28.044800] system-dockerd[1481]: segfault at 8 ip 0000000000542436 sp 000000c421587308 error 4 in system-dockerd[400000+1485000]

Maybe for installed version the image preload could be removed (overlay partition?) or moved out of the initrd to reduce the boot time again?

[niusmallnan]

@pwFoo Thanks for looking into this.
About that kernel segfault, I have been tracking, but no progress, but it seems to have no effect.

In the early versions, we didn't put the system image in the initrd, so it booted up very quickly, but if the user needs to use the full RancherOS, they still need to manually download the images and install them. Especially when the user boots up using iPXE mode, the built-in system images cannot be removed.
From the user experience, we have to put it in the initrd.

But there is indeed a point to improve, when the system-docker loads the image, different image compression methods may affect the load time. We also need to do a lot of testing.
Zstd may be one of the options.

[pwFoo]

As live cd / boot stick the images are needed, but during install maybe it could be used a smaller initrd file?
Would it possible to build

1. initrd-full (live, boot iso, recovery)
2. initrd (without preloaded images, used during install to reduce boot time)

Needed images could be downloaded during install I think.

[niusmallnan]

Created a new issue to track your idea.