<div dir="ltr"><div>Hello,</div><div><br></div><div>I've been working on a tool[1] to help analyze cloud-init boot time</div><div>performance.  It's loosely based on systemd-analyze where we have two</div><div>main actions: show and blame.</div><div><br></div><div>The 'show' action is similar to 'systemd-analyze critical-chain' which</div><div>prints a list of units, the time they started and how long they took.</div><div>For cloud-init, we have four stages, and within each stage a number</div><div>of modules may run depending on configuration.  ‘cloudinit-analyze show’</div><div>will, for each boot, print this information and a summary total time,</div><div>per boot. [2]</div><div><br></div><div>The 'blame' action matches 'systemd-analyze blame' where it prints, in</div><div>descending order, the units that took the longest to run.  This output is</div><div>highly useful for examining where cloud-init is spending its time during</div><div>execution. [3]</div><div><br></div><div>Additional data may be needed to further understand why a particular module</div><div>takes as long as it does.  I've provided some tooling to help capture this</div><div>data.</div><div><br></div><div>What I’ve found most useful so far is dumping strace output from the exec</div><div>of each cloud-init stage (init-local, init-net, config-modules, config-final).</div><div>This is performed via the cloud-init.wrap shell script which I've integrated</div><div>to run when profiling is enabled (touch /etc/cloud/profiler-enable).  The resulting</div><div>strace data is made available in /var/run/cloud-{init-local,init,config,final}*.strace.PID</div><div><br></div><div>I've created a profiling "service" unit which when profiling is enabled will</div><div>run  just before cloud-init-local unit and stops at the end of</div><div>cloud-init-final unit.  The three hooks I've implemented so far are blktrace,</div><div>perf and dstat.  This units will start up the various profilers which</div><div>collect data during cloud-init run and will write out data to</div><div>/var/lib/cloud/data/ on a per-profiler, per-boot directory which is compressed</div><div>and can be post-processed at a later time.</div><div><br></div><div>cloudinit-analyze has a few requirements that must be met to be useful.</div><div>First, we require the event reporting infrastructure to be included in</div><div>cloud-init; this is first available in cloud-init 0.7.6 or newer.  Without the</div><div>event reporting infrastructure we don't have timestamps collected at the start</div><div>and finish of each event.  The second requirement is a subsecond timestamp</div><div>configuration.  Current cloud-init will merge with rsyslog configuration</div><div>during boot and at least in Ubuntu, the default rsyslog config does not use a</div><div>high resolution timestamp.  This is addressed by updating the cloud-init</div><div>logging configuration.</div><div><br></div><div>With these two requirements met cloudinit-analyze can process cloud-init.log</div><div>data to produce useful summaries.</div><div><br></div><div>The simplest way to try out cloudinit-analyze and collect your own data is to</div><div>use my modified version of cloud-init from this ppa:</div><div><br></div><div>ppa:raharper/cloud-init-dev</div><div><br></div><div>For existing Xenial or Yakkety Ubuntu instances, you can do the following:</div><div><br></div><div>sudo add-apt-repository -y ppa:raharper/cloud-init-dev</div><div>sudo apt update && sudo apt install --no-install-recommends cloud-init</div><div>sudo apt install --no-install-recommends linux-tools-virtual blktrace dstat</div><div>sudo rm -rf /var/log/cloud-init* /var/lib/cloud/data /var/lib/cloud/instance*</div><div># optionally enable profiling/tracing with:</div><div># sudo touch /etc/cloud/profiler-enable</div><div>sudo reboot</div><div><br></div><div># after logging into the instance</div><div>sudo cloudinit-analyze show</div><div>sudo cloudinit-analyze blame</div><div><br></div><div><br></div><div>If you're using LXD, you can do this locally:</div><div><br></div><div># install some deps (cloud-utils with lxd support, lxc1 for lxc-usernsexec)</div><div>sudo add-apt-repository -y ppa:raharper/cloud-init-dev</div><div>sudo apt update && sudo apt install --no-install-recommends cloud-utils lxc1</div><div>git clone <a href="https://git.launchpad.net/~raharper/+git/cloudinit-analyze">https://git.launchpad.net/~raharper/+git/cloudinit-analyze</a></div><div>cd cloudinit-analyze</div><div>lxc init ubuntu-daily:yakkety y1</div><div>./bin/inject-payload.sh lxd:y1 ppa</div><div>lxc start y1</div><div>lxc exec y1 -- systemctl is-active cloud-init.target</div><div><br></div><div>Once the is-active command returns 'active', then cloud-init has completed</div><div>and you can start processing cloud-init.log data:</div><div><br></div><div>Outside container:</div><div><br></div><div>lxc file pull y1/var/log/cloud-init.log - | ./bin/cloudinit-analyze show -i -</div><div><br></div><div>or from within:</div><div><br></div><div>lxc exec y1 -- cloudinit-analyze show</div><div><br></div><div>After looking at your output, if you have questions or would like to discuss</div><div>what you're seeing and how to improve boot time, please join us in #cloud-init</div><div>on FreeNode (<a href="http://irc.freenode.net">irc.freenode.net</a>) and the cloud-init community will be happy to</div><div>help.</div><div><br></div><div>I’ve used a combination of the above tools to track down a few items of</div><div>overhead in the NoCloud DataSource while testing with lxd and kvm booting</div><div>cloud-images yielding ~3 to ~13% improvement[4] (with profiling disabled of</div><div>course) . I’ll provide a follow-up email with some more details, but the</div><div>changes driven from the analysis thus far are captured in these patches[5]</div><div>I’m proposing for upstream which should help in other DataSources as well, but</div><div>I've not yet taken measurements beyond NoCloud instances. Note, these patches</div><div>are currently integrated into the cloud-init included my cloud-init-dev PPA.</div><div><br></div><div>Thanks,</div><div>Ryan Harper</div><div><br></div><div><br></div><div>1. <a href="https://git.launchpad.net/~raharper/+git/cloudinit-analyze">https://git.launchpad.net/~raharper/+git/cloudinit-analyze</a></div><div>2. <a href="http://paste.ubuntu.com/23277326/">http://paste.ubuntu.com/23277326/</a></div><div>3. <a href="http://paste.ubuntu.com/23277328/">http://paste.ubuntu.com/23277328/</a></div><div>4. <a href="http://paste.ubuntu.com/23271663/">http://paste.ubuntu.com/23271663/</a></div><div>5. <a href="https://code.launchpad.net/~raharper/cloud-init/+git/cloud-init/+ref/nocloud-boottime-improvements">https://code.launchpad.net/~raharper/cloud-init/+git/cloud-init/+ref/nocloud-boottime-improvements</a></div><div><br></div></div>