`runsc boot`: Add startup timer instrumentation.
Example output: ``` I0807 10:27:23.158030 1 timing.go:866] ---- runsc boot timing information ---- [10:27:22.991938] ╭─ runsc boot [10:27:22.995285] +3 346µs ▋ ├─ Go code running: 3 346µs [10:27:22.996191] +906µs ▏ ├─ boot subcommand dispatched: 906µs [10:27:22.996643] +451µs ├─ CPUID initialized: 451µs [10:27:22.996645] +2µs ├─ ring0 initialized: 2µs [10:27:22.997012] +367µs ├─ host info read: 367µs [10:27:22.998024] +1 011µs ▏ ├─ spec read: 1 011µs [10:27:22.998555] +530µs ├─ chroot base mounted: 530µs [10:27:22.998822] +267µs ├─ chroot proc mounted: 267µs [10:27:23.000271] +1 449µs ▎ ├─ chroot procfs set up: 1 449µs [10:27:23.000369] +97µs ├─ chroot sealed read-only: 97µs [10:27:23.002635] +2 266µs ▍ ├─ chroot set up: 2 266µs [10:27:23.003523] +887µs ▏ ├─ sandbox capabilities computed: 887µs [10:27:23.003693] +170µs ├─ current capabilities read: 170µs [10:27:23.012905] +9 211µs ▉▊ ├─ bounding set trimmed on all threads: 9 211µs [10:27:23.013139] +233µs ├─ capset applied on all threads: 233µs [10:27:23.013449] +310µs ├─ capabilities applied: 310µs [10:27:23.024366] +10 916µs ▉▉ ├─ resolved mounts read: 10 916µs [10:27:23.029416] +5 049µs ▉ ├─ seccheck initialized: 5 049µs [10:27:23.029419] +3µs ├─ RNG initialized: 3µs [10:27:23.029571] +152µs ├─ memory usage initialized: 152µs [10:27:23.029619] +47µs ├─ GOMAXPROCS set: 47µs [10:27:23.057560] +27 941µs ▉▉▉▉▉▍ ├─ stdio FDs remapped: 27 941µs [10:27:23.057563] +2µs ├─ donated FDs ingested: 2µs [10:27:23.057889] +326µs ├─ systrap memory file created: 326µs [10:27:23.058714] +825µs ▏ ├─ systrap stub initialized: 825µs [10:27:23.063232] +4 517µs █ ├─ systrap source process created: 4 517µs [10:27:23.063244] +12µs ├─ waiting for membarrier: 12µs [10:27:23.063246] +1µs ├─ host membarrier probed: 1µs [10:27:23.063251] +4µs ├─ platform created: 4µs [10:27:23.063390] +138µs ├─ memory file created: 138µs [10:27:23.063438] +48µs ├─ VDSO prepared: 48µs [10:27:23.063473] +34µs ├─ timekeeper configured: 34µs [10:27:23.063675] +201µs ├─ network stack created: 201µs [10:27:23.063854] +179µs ├─ kernel initialized: 179µs [10:27:23.063859] +4µs ├─ filesystems registered: 4µs [10:27:23.063943] +84µs ├─ process args created: 84µs [10:27:23.063947] +3µs ├─ compat logs initialized: 3µs [10:27:23.063948] +0µs ├─ mount hints parsed: 0µs [10:27:23.063949] +1µs ├─ host FS mount created: 1µs [10:27:23.064142] +192µs ├─ control server started: 192µs [10:27:23.064142] +0µs ├─ loader created: 0µs [10:27:23.064152] +9µs ├─ metrics initialized: 9µs [10:27:23.064152] +0µs ├─ notifying parent: 0µs [10:27:23.126745] +62 592µs ▉▉▉▉▉▉▉▉▉▉▉▉ ├─ network args received: 62 592µs [10:27:23.126972] +227µs ├─ start RPC received: 227µs [10:27:23.126982] +10µs ├─ start signal received: 10µs [10:27:23.127852] +869µs ▏ ├─ network configured: 869µs [10:27:23.128646] +794µs ▏ ├─ open FDs validated: 794µs [10:27:23.131274] +2 628µs ▌ ├─ pre-seccomp callback done: 2 628µs [10:27:23.132513] +1 238µs ▎ ├─ seccomp rules computed: 1 238µs [10:27:23.146898] +14 384µs ▉▉▊ ├─ seccomp program compiled: 14 384µs [10:27:23.148596] +1 698µs ▎ ├─ seccomp program installed: 1 698µs [10:27:23.148655] +58µs ├─ seccomp filters installed: 58µs [10:27:23.148655] +0µs ├─ forked: 0µs ╭─ root container [10:27:23.148876] +220µs │ ... 220µs ... ├─ FD table created: 220µs [10:27:23.149125] +249µs │ ... 469µs ... ├─ cgroups mounted: 249µs [10:27:23.149798] +673µs ▏ │ ... 1 143µs ... ├─ rootfs mounted: 673µs [10:27:23.149804] +5µs │ ... 1 148µs ... ├─ submounts prepared: 5µs [10:27:23.150009] +205µs │ ... 1 353µs ... ├─ mounted "/dev": 205µs [10:27:23.150362] +352µs │ ... 1 706µs ... ├─ mounted "/sys": 352µs [10:27:23.150822] +459µs │ ... 2 166µs ... ├─ mounted "/proc": 459µs [10:27:23.150886] +63µs │ ... 2 230µs ... ├─ mounted "/dev/pts": 63µs [10:27:23.150915] +29µs │ ... 2 259µs ... ├─ mounted "/dev/shm": 29µs [10:27:23.151200] +285µs │ ... 2 544µs ... ├─ mounted "/etc/hosts": 285µs [10:27:23.151212] +12µs │ ... 2 557µs ... ├─ mounted "/dev/mqueue": 12µs [10:27:23.151539] +326µs │ ... 2 883µs ... ├─ mounted "/etc/hostname": 326µs [10:27:23.151660] +121µs │ ... 3 004µs ... ├─ mounted "/sys/fs/cgroup": 121µs [10:27:23.151846] +186µs │ ... 3 190µs ... ├─ mounted "/etc/resolv.conf": 186µs [10:27:23.151974] +128µs │ ... 3 319µs ... ├─ submounts mounted: 128µs [10:27:23.151981] +6µs │ ... 3 325µs ... ├─ device files created: 6µs [10:27:23.151981] +0µs │ ... 3 326µs ... ├─ executable path resolved: 0µs [10:27:23.152057] +75µs │ ... 3 401µs ... ├─ exec user home resolved: 75µs [10:27:23.152085] +28µs │ ... 3 429µs ... ├─ FS context created: 28µs [10:27:23.153742] +1 656µs ▎ │ ... 5 086µs ... ├─ memory manager created: 1 656µs [10:27:23.156409] +2 667µs ▌ │ ... 7 753µs ... ├─ executable loaded: 2 667µs [10:27:23.156419] +10µs │ ... 7 763µs ... ├─ VDSO mapped: 10µs [10:27:23.156425] +5µs │ ... 7 769µs ... ├─ stack allocated: 5µs [10:27:23.156491] +65µs │ ... 7 835µs ... ├─ stack contents loaded: 65µs [10:27:23.156497] +5µs │ ... 7 841µs ... ├─ task image loaded: 5µs [10:27:23.156543] +46µs │ ... 7 887µs ... ├─ init task created: 46µs [10:27:23.156599] +56µs ├─ root container created: 7 943µs │ ... 56µs ... [10:27:23.157146] +547µs ├─ signal forwarding started: 547µs │ ... 603µs ... [10:27:23.157575] +428µs ├─ kernel started: 428µs │ ... 1 031µs ... [10:27:23.157575] +0µs │ ... 0µs ... ╰─ END 1 032µs, total 8 919µs [10:27:23.157576] +1µs ╰─ END 1µs, total 165 638µs ---- End of runsc boot timing information ---- ```
E
Etienne Perot committed
5c6c63e020621e9998bb8b0a9762571060ca2d44
Parent: 05b57c9