Ubuntu 16.04: Analyze boot time

This article will describe analyzing boot time.

1 kernel (printk's timestamp)

printk is a log function in kernel. When CONFIG_PRINTK_TIME is enabled, printk has a timestamp.

Because CONFIG_PRINTK_TIME is enabled by default on Ubuntu 16.04, you can analyze kernel boot time with printk's timestamp.

$ dmesg
<snip>
[    1.848747] virtio_net virtio0 ens3: renamed from eth0
[    1.868691] input: VirtualPS/2 VMware VMMouse as
/devices/platform/i8042/serio1/input/input4
[    1.873850] input: VirtualPS/2 VMware VMMouse as
/devices/platform/i8042/serio1/input/input3
[    1.883397] FDC 0 is a S82078B
[    2.272250] EXT4-fs (dm-0): mounted filesystem with ordered data
mode. Opts: (null)
<snip>

2 initrd (/dev/kmsg)

When starting initrd, root filesystem is not mounted yet. syslogd and journald is not running yet. It is difficult to save initrd's log to userspace.

This article will redirect initrd's stdout to /dev/kmsg and save initrd's log to printk's buffer.

Take a backup of initrd.

$ version=$(uname -r)
$ sudo cp /boot/initrd.img-${version} /boot/initrd.img-${version}.org

Move original init script to scripts directory.

$ sudo mv /usr/share/initramfs-tools/init \
     /usr/share/initramfs-tools/scripts/init

Create new init script.

  • /dev will be used by original init script. Create /printk directory and mount devtmpfs to /printk.
  • Execute /script/init and redirect stdout to /printk/kmsg.
  • busybox's ash cannot write stderr to /dev/kmsg. /bin/sh -x cannot be done.
  • busybox's hush can write stderr to /dev/kmsg. But original init script cannot be completed.
$ cat <<EOF | sudo tee /usr/share/initramfs-tools/init
#!/bin/sh
mkdir -p /log
mount -t devtmpfs -o nosuid,mode=0755 udev /printk
exec /bin/sh /scripts/init > /printk/kmsg
EOF
$ sudo chmod a+x /usr/share/initramfs-tools/init

Update initrd and reboot Ubuntu 16.04.

$ sudo update-initramfs -u
$ sudo reboot

dmesg's output is as below after reboot.

$ dmesg
<snip>
[    1.563504] Write protecting the kernel read-only data: 14336k
[    1.565144] Freeing unused kernel memory: 1824K (ffff880001838000 -
ffff880001a00000)
[    1.566810] Freeing unused kernel memory: 152K (ffff880001dda000 -
ffff880001e00000)
[    1.570844] Loading, please wait...
[    1.577172] random: udevadm: uninitialized urandom read (16 bytes
read, 2 bits of entropy available)
[    1.578679] random: udevadm: uninitialized urandom read (16 bytes
read, 2 bits of entropy available)
[    1.580151] random: udevadm: uninitialized urandom read (16 bytes
read, 2 bits of entropy available)
[    1.581989] random: systemd-udevd: uninitialized urandom read (16
bytes read, 2 bits of entropy available)
[    1.583496] random: systemd-udevd: uninitialized urandom read (16
bytes read, 2 bits of entropy available)
[    1.584940] random: systemd-udevd: uninitialized urandom read (16
bytes read, 2 bits of entropy available)
[    1.586417] random: systemd-udevd: uninitialized urandom read (16
bytes read, 2 bits of entropy available)
[    1.588545] random: udevadm: uninitialized urandom read (16 bytes
read, 2 bits of entropy available)
[    1.590054] random: udevadm: uninitialized urandom read (16 bytes
read, 2 bits of entropy available)
[    1.591477] random: udevadm: uninitialized urandom read (16 bytes
read, 2 bits of entropy available)
[    1.634014] virtio_net virtio0 ens3: renamed from eth0
[    1.644640] input: VirtualPS/2 VMware VMMouse as
/devices/platform/i8042/serio1/input/input4
[    1.646164] input: VirtualPS/2 VMware VMMouse as
/devices/platform/i8042/serio1/input/input3
[    1.669312] FDC 0 is a S82078B
[    1.688616] Begin: Loading essential drivers ... done.
[    1.689657] Begin: Running /scripts/init-premount ... done.
[    1.692942] Begin: Mounting root file system ... Begin: Running
/scripts/local-top ... done.
[    1.947036] Begin: Running /scripts/local-premount ... done.
[    1.965256] Begin: Will now check root file system ...
[    1.969435] fsck from util-linux 2.27.1
[    1.975002] [/sbin/fsck.ext4 (1) -- /dev/mapper/ubuntu--vg-root]
fsck.ext4 -a -C0 /dev/mapper/ubuntu--vg-root
[    1.997830] /dev/mapper/ubuntu--vg-root: clean, 275895/5152768
files, 1845138/20583424 blocks
[    2.027183] done.
[    2.035616] EXT4-fs (dm-0): mounted filesystem with ordered data
mode. Opts: (null)
[    2.037986] done.
[    2.068452] Begin: Running /scripts/local-bottom ... done.
[    2.072004] Begin: Running /scripts/init-bottom ... done.
[    2.333182] clocksource: tsc: mask: 0xffffffffffffffff max_cycles:
0x30e602f0f5d, max_idle_ns: 440795236409 ns
[    3.140509] systemd[1]: systemd 229 running in system mode. (+PAM
+AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP
+GCRYPT +GNUTLS +ACL +XZ -LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD -IDN)
[    3.146419] systemd[1]: Detected virtualization kvm.
[    3.148571] systemd[1]: Detected architecture x86-64.
<snip>

initrd's log is between "[ 1.570844] Loading, please wait…" with "[ 2.072004] Begin: Running /scripts/init-bottom … done.".

If you need more detailed log, you need to add echo statement to scripts in /usr/share/initramfs-tools.

3 userspace (systemd-analyze)

systemd-analyze provides boot time of kernel, initrd and systemd. This is the replacement package of bootchart.

Boot time of initrd is included in boot time of kernel on Ubuntu 16.04.

$ systemd-analyze
Startup finished in 2.002s (kernel) + 2.067s (userspace) = 4.069s

"systemd-analyze blame" outputs units by consumed time.

$ systemd-analyze blame
           675ms lvm2-monitor.service
           644ms console-setup.service
           629ms dev-mapper-ubuntu\x2d\x2dvg\x2droot.device
           436ms networking.service
           416ms accounts-daemon.service
           274ms grub-common.service
           244ms alsa-restore.service
           239ms gpu-manager.service
           238ms apport.service
           235ms irqbalance.service
<snip>

"systemd-analyze critical-chain" output unit path which consumes the most time. @ means start time and + means consuming time. graphical.target is leaf node and .slice is root node.

But systemd is running in parallel, if you shorten 500ms from this path, userspace might not be shortened 500ms.

$ systemd-analyze critical-chain
The time after the unit is active or started is printed after the "@" character.
The time the unit takes to start is printed after the "+" character.

graphical.target @2.015s
'─multi-user.target @2.013s
  '─getty.target @2.012s
    '─getty@tty1.service @2.009s
      '─rc-local.service @1.845s +43ms
        '─network.target @1.843s
          '─NetworkManager.service @1.659s +177ms
<snip>
                                    '─lvm2-lvmetad.service @340ms
                                      '─system.slice @142ms
                                        '─-.slice @80ms

"sykstemd-analyze plot" outputs plot as svg file. This helps you to understand overall userspace.

$ systemd-analyze plot > a.svg

0001_systemd-analyze-plot.png