rkt startup time analysis

startup_time.md

rkt start-up time analysis

rkt run a Docker nginx image, pre-fetched. size = 188MiB when unextracted.

command	time	strace -C
1st-time run, on ssd	real 0m8.927s, user 0m5.048s, sys 0m0.896s	rkt_run_1_ssd.txt
2nd-time run, on ssd	real 0m0.683s, user 0m0.052s, sys 0m0.044s	rkt_run_2_ssd.txt
1st-time prepare, on ssd	real 0m11.008s, user 0m6.716s, sys 0m0.956s	rkt_prepare_1_ssd.txt
2nd-time prepare, on ssd	real 0m1.713s, user 0m1.688s, sys 0m0.180s	rkt_prepare_2_ssd.txt
run-prepared, on ssd	real 0m0.432s, user 0m0.036s, sys 0m0.032s	rkt_run-prepared_1_ssd.txt

                      |                                              |

1st-time run, on ramfs | real 0m4.734s, user 0m5.044s, sys 0m0.616s | rkt_run_1_ram.txt 2nd-time run, on ramfs | real 0m0.305s, user 0m0.044s, sys 0m0.032s | rkt_run_2_ram.txt 1st-time prepare, on ramfs | real 0m5.698s, user 0m6.560s, sys 0m0.784s | rkt_prepare_1_ram.txt 2nd-time prepare, on ramfs | real 0m1.354s, user 0m1.752s, sys 0m0.116s | rkt_prepare_2_ram.txt run-prepared, on ramfs | real 0m0.293s, user 0m0.036s, sys 0m0.032s | rkt_run-prepared_1_ram.txt

Docker run nginx, pre-fetched

command	time	strace -C
1st-time docker run, on ssd	real 0m0.941s, user 0m0.020s, sys 0m0.008s	docker_run_1_ssd.txt
2nd-time docker run, on ssd	real 0m0.930s, user 0m0.028s, sys 0m0.000s	docker_run_2_ssd.txt
1st-time docker create, on ssd	real 0m0.233s, user 0m0.020s, sys 0m0.004s	docker_create_1_ssd.txt
2nd-time docker create, on ssd	real 0m0.268s, user 0m0.024s, sys 0m0.000s	docker_create_2_ssd.txt
docker start, on ssd	real 0m0.363s, user 0m0.024s, sys 0m0.000s	docker_start_1_ssd.txt

Compare rkt and Docker:

command	time (rkt)	time (Docker)
1st-time run	real 0m8.927s, user 0m5.048s, sys 0m0.896s	real 0m0.941s, user 0m0.020s, sys 0m0.008s
2nd-time run	real 0m0.683s, user 0m0.052s, sys 0m0.044s	real 0m0.930s, user 0m0.028s, sys 0m0.000s
1st-time prepare	real 0m11.008s, user 0m6.716s, sys 0m0.956s	real 0m0.233s, user 0m0.020s, sys 0m0.004s
2nd-time prepare	real 0m1.713s, user 0m1.688s, sys 0m0.180s	real 0m0.268s, user 0m0.024s, sys 0m0.000s
run-prepared	real 0m0.432s, user 0m0.036s, sys 0m0.032s	real 0m0.363s, user 0m0.024s, sys 0m0.000s

Pulling time comparison:

time (rkt)	time (Docker)
real 0m26.442s, user 0m9.496s, sys 0m1.220s	real 0m15.368s, user 0m0.060s, sys 0m0.008s

What version of docker was used?

@yujuhong Docker 1.9.1

Observations and thoughts:

• The 1st time of rkt run takes much longer than the 2nd time we do rkt run:
  • User space time difference is big. (5s vs 0.05s, >100 times)
  • 2 extra wait4 syscalls (waiting for tarball extraction process) takes 85% of the kernel space time (~0.5s) during the 1st rkt run
  • Disk I/O time difference is big. When running on ram instead of SSD, the total time decreased 45%~55%.
  • Theory: Due to the image extraction during the 1st time of running the pod
• For docker, most of the time are spent on I/O.
  • During docker pull, the images are downloaded, and extracted to /var/lib/docker/aufs
• Why prepare is slower than run??
  • Actually this is a bug, fixed by rkt/rkt#2376