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