From 3853f83b547ecd329589e9681145e5163ba8e933 Mon Sep 17 00:00:00 2001 From: Manuel de Brito Fontes Date: Tue, 16 Jun 2026 21:19:42 -0300 Subject: [PATCH] feat(boot): BOOT_TIMELINE wall-clock cold-start breakdown The kernel initcall and vminitd profiles cover only slices of the guest side, and both run in debug mode (verbose, distorted). The userspace profile showed vminitd init is just ~1 ms, so the bulk of boot must be the VM cold-start, which nothing measured. qemu.Start() now emits one always-on BOOT_TIMELINE line per VM start, splitting cold-start on the normal (non-debug) path: qemu_launch = exec + machine/firmware init until QMP responds guest_boot = kernel boot + vminitd init until its vsock RPC accepts Container create/start happen afterwards over RPC and are logged already. TestBootTimeline boots one VM on the normal path and reports the breakdown from the shim journal - the wall-clock companion to TestKernelBootProfile and TestUserspaceBootProfile, without the debug-mode distortion. Co-Authored-By: Claude Opus 4.8 (1M context) --- integration/boot_timeline_test.go | 167 ++++++++++++++++++++++++++++++ internal/host/vm/qemu/start.go | 17 +++ 2 files changed, 184 insertions(+) create mode 100644 integration/boot_timeline_test.go diff --git a/integration/boot_timeline_test.go b/integration/boot_timeline_test.go new file mode 100644 index 0000000..7ac3148 --- /dev/null +++ b/integration/boot_timeline_test.go @@ -0,0 +1,167 @@ +//go:build linux && integration + +package integration + +import ( + "bytes" + "fmt" + "os" + "os/exec" + "path/filepath" + "regexp" + "strconv" + "strings" + "testing" + "time" + + containerd "github.com/containerd/containerd/v2/client" + "github.com/containerd/containerd/v2/pkg/cio" + "github.com/containerd/containerd/v2/pkg/namespaces" + "github.com/containerd/containerd/v2/pkg/oci" +) + +// bootTimelineRE matches the shim's BOOT_TIMELINE line, e.g.: +// +// BOOT_TIMELINE qemu_launch_us=8123 guest_boot_us=146210 total_us=154333 +var bootTimelineRE = regexp.MustCompile(`BOOT_TIMELINE qemu_launch_us=(\d+) guest_boot_us=(\d+) total_us=(\d+)`) + +type bootTimeline struct { + qemuLaunchUS int + guestBootUS int + totalUS int +} + +// TestBootTimeline boots one VM on the normal (non-debug) path and reports the +// shim's BOOT_TIMELINE breakdown from the journal: how cold-start splits between +// QEMU launch (process + firmware/machine init until QMP) and guest boot (kernel +// + vminitd until its vsock RPC accepts). This is the wall-clock companion to the +// kernel/userspace profiles, which only cover slices of the guest side. +func TestBootTimeline(t *testing.T) { + cfg := loadTestConfig() + + client := setupContainerdClient(t, cfg) + defer client.Close() + + ensureImagePulled(t, client, cfg) + + ctx := namespaces.WithNamespace(t.Context(), cfg.Namespace) + + image, err := client.GetImage(ctx, cfg.Image) + if err != nil { + t.Fatalf("get image %s: %v", cfg.Image, err) + } + + name := "qbx-timeline-" + strings.ReplaceAll(time.Now().Format("150405.000"), ".", "") + + stdoutPath := filepath.Join(t.TempDir(), "stdout.log") + stdoutFile, err := os.Create(stdoutPath) + if err != nil { + t.Fatalf("create stdout file: %v", err) + } + defer stdoutFile.Close() + + container, err := client.NewContainer(ctx, name, + containerd.WithSnapshotter(cfg.Snapshotter), + containerd.WithImage(image), + containerd.WithNewSnapshot(name+"-snapshot", image), + containerd.WithRuntime(cfg.Runtime, nil), + containerd.WithNewSpec( + oci.WithImageConfig(image), + oci.WithProcessArgs("/bin/echo", "BOOTED"), + ), + ) + if err != nil { + t.Fatalf("create container %s: %v", name, err) + } + defer func() { + if err := container.Delete(ctx, containerd.WithSnapshotCleanup); err != nil { + t.Logf("cleanup container %s: %v", name, err) + } + }() + + // The VM boots (and emits BOOT_TIMELINE) during NewTask, so capture the + // journal window from just before it. + since := time.Now().Add(-1 * time.Second) + + task, err := container.NewTask(ctx, cio.NewCreator(cio.WithStreams(nil, stdoutFile, nil))) + if err != nil { + t.Fatalf("create task for %s: %v", name, err) + } + defer func() { + if _, err := task.Delete(ctx, containerd.WithProcessKill); err != nil { + if !strings.Contains(err.Error(), "ttrpc: closed") { + t.Logf("cleanup task for %s: %v", name, err) + } + } + }() + + if _, err := task.Wait(ctx); err != nil { + t.Fatalf("wait for task %s: %v", name, err) + } + if err := task.Start(ctx); err != nil { + t.Fatalf("start task %s: %v", name, err) + } + waitForOutput(t, stdoutPath, "BOOTED", 60*time.Second) + + tl := readBootTimeline(t, since) + t.Logf("BOOT_TIMELINE qemu_launch_us=%d guest_boot_us=%d total_us=%d (%.1f ms total: %.1f ms qemu + %.1f ms guest)", + tl.qemuLaunchUS, tl.guestBootUS, tl.totalUS, + float64(tl.totalUS)/1000, float64(tl.qemuLaunchUS)/1000, float64(tl.guestBootUS)/1000) +} + +// readBootTimeline reads the shim journal since the given time and returns the +// most recent BOOT_TIMELINE entry (the boot this test just triggered). +func readBootTimeline(t *testing.T, since time.Time) bootTimeline { + t.Helper() + deadline := time.Now().Add(30 * time.Second) + for { + if tl, ok := parseLastBootTimeline(journalSince(t, since)); ok { + return tl + } + if time.Now().After(deadline) { + t.Fatalf("no BOOT_TIMELINE line in spinbox journal since %s", since.Format(time.RFC3339)) + } + time.Sleep(200 * time.Millisecond) + } +} + +// journalSince returns the spinbox unit's journal output since the given time. +func journalSince(t *testing.T, since time.Time) string { + t.Helper() + cmd := exec.Command("journalctl", + "-u", "spinbox", + "--since", since.Format("2006-01-02 15:04:05"), + "--no-pager", + "-o", "cat", + ) + var stdout, stderr bytes.Buffer + cmd.Stdout = &stdout + cmd.Stderr = &stderr + if err := cmd.Run(); err != nil { + t.Logf("journalctl failed: %v (stderr: %s)", err, stderr.String()) + return "" + } + return stdout.String() +} + +// parseLastBootTimeline returns the last BOOT_TIMELINE entry in the text. +func parseLastBootTimeline(text string) (bootTimeline, bool) { + matches := bootTimelineRE.FindAllStringSubmatch(text, -1) + if len(matches) == 0 { + return bootTimeline{}, false + } + m := matches[len(matches)-1] + return bootTimeline{ + qemuLaunchUS: mustAtoi(m[1]), + guestBootUS: mustAtoi(m[2]), + totalUS: mustAtoi(m[3]), + }, true +} + +func mustAtoi(s string) int { + n, err := strconv.Atoi(s) + if err != nil { + panic(fmt.Sprintf("parse int %q: %v", s, err)) + } + return n +} diff --git a/internal/host/vm/qemu/start.go b/internal/host/vm/qemu/start.go index fabb0e4..bf45206 100644 --- a/internal/host/vm/qemu/start.go +++ b/internal/host/vm/qemu/start.go @@ -10,6 +10,7 @@ import ( "os/exec" "strings" "syscall" + "time" "github.com/containerd/log" "github.com/containerd/ttrpc" @@ -408,6 +409,9 @@ func (q *Instance) Start(ctx context.Context, opts ...vm.StartOpt) error { "cmdline": strings.Join(qemuArgs, " "), }).Debug("qemu: starting VM process") + // tExec marks the QEMU process launch; the deltas below isolate where a + // normal (non-debug) boot spends its cold-start time. See BOOT_TIMELINE below. + tExec := time.Now() if err := q.startQemuProcess(ctx, qemuArgs); err != nil { return err } @@ -416,6 +420,7 @@ func (q *Instance) Start(ctx context.Context, opts ...vm.StartOpt) error { if err := q.connectQMP(ctx); err != nil { return err } + tQMP := time.Now() log.G(ctx).Info("qemu: QMP connected, waiting for vsock...") @@ -431,6 +436,7 @@ func (q *Instance) Start(ctx context.Context, opts ...vm.StartOpt) error { if err := q.connectVsockClient(ctx); err != nil { return err } + tVsock := time.Now() // Monitor liveness of the guest RPC server; if it goes away (guest reboot/poweroff) // ensure QEMU exits so the shim can clean up. @@ -440,6 +446,17 @@ func (q *Instance) Start(ctx context.Context, opts ...vm.StartOpt) error { success = true q.setState(vmStateRunning) + // BOOT_TIMELINE isolates VM cold-start on a normal boot, the half that the + // initcall/userspace profiles do not cover: + // qemu_launch = exec + machine/firmware init until QMP responds + // guest_boot = kernel boot + vminitd init until its vsock RPC accepts + // Container create/start happen afterwards over RPC and are logged separately. + // Always on (one line per VM start) so plain boots emit it - no debug mode. + log.G(ctx).Infof("BOOT_TIMELINE qemu_launch_us=%d guest_boot_us=%d total_us=%d", + tQMP.Sub(tExec).Microseconds(), + tVsock.Sub(tQMP).Microseconds(), + tVsock.Sub(tExec).Microseconds()) + log.G(ctx).Info("qemu: VM fully initialized") return nil