boot: five probes out whose questions are answered

.github/workflows/lab.yml

@@ -31,13 +31,9 @@ on:
         required: true
         type: choice
         options:
-          - boot:bench
           - boot:initcalls
-          - boot:userspace
-          - boot:systemd
           - boot:waits
           - boot:ssh-first
-          - boot:ssh-load
           - boot:page-cache
           - boot:firmware
           - boot:firmware-stages

Taskfile.yml

@@ -876,7 +876,7 @@ tasks:
     env:
       BODY: >-
         The newest release of the pinned kernel series, proposed by refresh.yml. kernel.yml builds
-        it on this pull request. Before merging, boot it: `task kernel:build boot:bench`.
+        it on this pull request. Before merging, boot it: `task kernel:build boot:ssh-first`.
     cmds:
       - |
         set -euo pipefail

boot/Taskfile.yml

@@ -98,25 +98,6 @@ tasks:
     cmds:
       - SPIN_COMPAT_PREVIOUS="$(cat {{.OUTPUT_ABS}}/compat/previous)" go test ./boot/ -run '^TestACheckpointOfTheReleaseBeforeResumesHere$' -count=1 -v -timeout 10m
 
-  bench:
-    desc: >-
-      What a boot costs, measured from the host and repeated enough to believe. Needs
-      /dev/kvm, a built release, and sudo — variants that mask a unit write into a throwaway
-      overlay through qemu-nbd. REPS= to change the count, DEBUG=1 for kernel and systemd
-      logging (which inflates what it measures, equally in every variant).
-    deps: [':tools']
-    cmds:
-      - SPIN_BOOT_BENCH=1 go test ./boot/ -run TestBootCost -v -timeout 60m
-
-  ssh-load:
-    desc: >-
-      SSH logins into a guest under load: idle, every vCPU busy from a service and from a login
-      session, and /tmp filled to its cap, with what the guest was under (PSI) beside each.
-      Needs /dev/kvm and a built release; no sudo. REPS= boots.
-    deps: [':tools']
-    cmds:
-      - SPIN_SSH_LOAD=1 go test ./boot/ -run '^TestSSHUnderLoad$' -count=1 -v -timeout 30m
-
   page-cache:
     desc: >-
       The page caches a machine has: a guest writing, reading and removing a file, with QEMU's
@@ -161,26 +142,6 @@ tasks:
     cmds:
       - SPIN_INITCALL_PROBE=1 go test ./boot/ -run TestKernelInitcalls -count=1 -v -timeout 30m
 
-  userspace:
-    desc: >-
-      systemd's own account of the boot: its kernel/userspace split, `blame` and the
-      critical chain, read after the boot rather than during it. Needs KVM, a built release
-      and sudo. Read a critical chain as what finished last, never as what was blocking —
-      see the blame note in optimize-systemd.sh for what removing the tail gave back.
-    deps: [':tools']
-    cmds:
-      - SPIN_USERSPACE_PROBE=1 go test ./boot/ -run TestUserspaceCost -count=1 -v -timeout 15m
-
-  systemd:
-    desc: >-
-      Inside early userspace, in systemd's own words: debug logging to the journal, read
-      afterwards, ranked by the gaps in it. Needs KVM, a built release and sudo. It inflates
-      the phase it measures, so the absolute numbers are not `task boot:bench`'s — the shape
-      is what it is for. GAP= the floor in ms, TOP= how many gaps.
-    deps: [':tools']
-    cmds:
-      - SPIN_SYSTEMD_DEBUG=1 go test ./boot/ -run TestSystemdDebug -count=1 -v -timeout 15m
-
   waits:
     desc: >-
       What waited on what between the kernel handing over and a login prompt, on the host's
@@ -225,12 +186,3 @@ tasks:
     cmds:
       - SPIN_FIRMWARE_PROBE=1 go test ./boot/ -run '^TestFirmwareRuns$' -count=1 -v -timeout 20m
 
-  trace:
-    desc: >-
-      One boot's console printed against the host's clock, for finding a gap that belongs to
-      neither systemd nor the kernel. SPIN_GETTY_EXEC= replaces agetty to tell its own delays
-      apart from the tty's.
-    deps: [':tools']
-    cmds:
-      - SPIN_BOOT_TRACE=1 go test ./boot/ -run TestBootTrace -v -timeout 10m
-

boot/bench_test.go → boot/harness_test.go

@@ -10,8 +10,6 @@ import (
 	"os"
 	"os/exec"
 	"path/filepath"
-	"slices"
-	"sort"
 	"strings"
 	"syscall"
 	"testing"
@@ -132,188 +130,6 @@ func kernelB(t *testing.T) string {
 	return abs
 }
 
-// TestBootCost boots each variant many times, interleaved, and prints what each phase cost.
-//
-// Interleaved (A B C A B C …) rather than in blocks, because the host is shared with
-// whatever else is running on it: a block schedule gives one variant all of a slow minute
-// and reads it as a regression. Every variant sees the same minutes.
-func TestBootCost(t *testing.T) {
-	if os.Getenv("SPIN_BOOT_BENCH") == "" {
-		t.Skip("set SPIN_BOOT_BENCH=1: this boots dozens of VMs and takes minutes")
-	}
-	out := releaseDir(t)
-	reps := envInt(t, "REPS", 20)
-	vs := slices.Clone(variants)
-	if k := kernelB(t); k != "" {
-		vs = append(vs, variant{label: "kernel B", cpus: "2", memory: "2048",
-			files: gettyDropin(gettyEcho), kernel: k})
-	}
-
-	if !canSudo() {
-		for _, v := range vs {
-			if len(v.mask) > 0 {
-				t.Skipf("masking a unit means writing into the overlay through qemu-nbd, "+
-					"which needs sudo; %q cannot be measured here", v.label)
-			}
-		}
-	}
-
-	samples := map[string]map[boot.Phase][]time.Duration{}
-	failures := map[string]int{}
-	for rep := range reps {
-		for _, v := range vs {
-			run := bootOnce(t, out, v)
-			if samples[v.label] == nil {
-				samples[v.label] = map[boot.Phase][]time.Duration{}
-			}
-			for _, p := range []boot.Phase{boot.Firmware, boot.Kernel, boot.PID1, boot.Started, boot.Usable} {
-				if d, ok := run.At[p]; ok {
-					samples[v.label][p] = append(samples[v.label][p], d)
-				}
-			}
-			// Not reaching a login is the failure this exists to catch, and it is not the
-			// same as being slow. A variant that never gets there has no p50 worth reading.
-			if !run.Reached(boot.Usable) {
-				failures[v.label]++
-				if failures[v.label] == 1 {
-					t.Logf("%s: no login prompt on rep %d; console tail:\n%s",
-						v.label, rep+1, tail(run.Output, 800))
-				}
-			}
-		}
-	}
-
-	labels := make([]string, 0, len(samples))
-	for l := range samples {
-		labels = append(labels, l)
-	}
-	sort.Strings(labels)
-
-	var b strings.Builder
-	fmt.Fprintf(&b, "\nmilliseconds from the moment before QEMU is exec'd, p50/p95 over %d boots\n\n", reps)
-	fmt.Fprintf(&b, "%-14s %10s %10s %10s %10s %10s %8s\n", "CONFIGURATION", "FIRMWARE", "KERNEL", "PID1", "STARTED", "USABLE", "NO LOGIN")
-	for _, l := range labels {
-		fmt.Fprintf(&b, "%-14s", l)
-		for _, p := range []boot.Phase{boot.Firmware, boot.Kernel, boot.PID1, boot.Started, boot.Usable} {
-			fmt.Fprintf(&b, " %10s", cell(samples[l][p]))
-		}
-		fmt.Fprintf(&b, " %8d\n", failures[l])
-	}
-	t.Log(b.String())
-}
-
-// TestBootTrace boots once and prints the console with the host's clock against it, which is
-// the only way to see a gap that belongs to neither systemd nor the kernel.
-//
-// It exists because the guest and the host disagreed about a whole second: systemd reported
-// agetty started at 171 ms of guest-monotonic time and the host did not see a login prompt
-// until 1247 ms. Both numbers were right; what was between them was not visible from either
-// side alone.
-func TestBootTrace(t *testing.T) {
-	if os.Getenv("SPIN_BOOT_TRACE") == "" {
-		t.Skip("set SPIN_BOOT_TRACE=1 to print one boot's console against the host clock")
-	}
-	out := releaseDir(t)
-
-	body := "ExecStartPre=/bin/sh -c 'echo SPIN-GETTY-EXEC > /dev/console'\n"
-	// SPIN_GETTY_EXEC replaces agetty itself, which is how to find out whether a delay
-	// belongs to agetty or to the tty it is handed. Substituting a shell that prints and
-	// waits separates the two in one boot:
-	//
-	//   SPIN_GETTY_EXEC="/bin/sh -c 'echo SPIN-READY-login: ; sleep infinity'"
-	//
-	// SPIN_TRACE_APPEND is added to the kernel command line, after this probe's own, so a later
-	// parameter wins: systemd.log_level=debug times PID 1's start-up line by line, which on
-	// 2026-11-12 was how the ~45 ms between "Hostname set" and "Queued start job" was split.
-	// Every line is a VM exit, so the gaps between lines are the work and the lines are not.
-	if x := os.Getenv("SPIN_GETTY_EXEC"); x != "" {
-		body += "ExecStart=\nExecStart=-" + x + "\n"
-	}
-	v := variant{label: "trace", cpus: "2", memory: "2048", files: map[string]string{
-		// A marker written the moment systemd starts the service, so the console itself says
-		// which side of the gap the exec falls on.
-		"/etc/systemd/system/serial-getty@ttyS0.service.d/trace.conf": "[Service]\n" + body,
-	}}
-	dir := t.TempDir()
-	overlay := filepath.Join(dir, "overlay.qcow2")
-	mustRun(t, filepath.Join(out, "bin", "qemu-img"), "create", "-f", "qcow2",
-		"-F", "qcow2", "-b", filepath.Join(out, "image", "rootfs.qcow2"), overlay)
-	editOverlay(t, overlay, v)
-
-	cmd := exec.Command(filepath.Join(out, "bin", "spin-machine"), "boot",
-		"--release", out, "--disk", overlay, "--memory", v.memory, "--cpus", v.cpus,
-		"--console", "file:/dev/stdout",
-		"--append", strings.TrimSpace("init=/sbin/init loglevel=7 systemd.show_status=true "+
-			"systemd.log_level=info systemd.log_target=console "+os.Getenv("SPIN_TRACE_APPEND")))
-	// FLAGS, as the other probes take it: spin-machine boot flags after the rest.
-	cmd.Args = append(cmd.Args, strings.Fields(os.Getenv("FLAGS"))...)
-	cmd.SysProcAttr = &syscall.SysProcAttr{Setpgid: true}
-	stdout, err := cmd.StdoutPipe()
-	if err != nil {
-		t.Fatalf("console pipe: %v", err)
-	}
-	t0 := time.Now()
-	if err := cmd.Start(); err != nil {
-		t.Fatalf("launching the machine: %v", err)
-	}
-	kill := func() {
-		if pgid, err := syscall.Getpgid(cmd.Process.Pid); err == nil {
-			_ = syscall.Kill(-pgid, syscall.SIGKILL)
-		}
-	}
-	timer := time.AfterFunc(30*time.Second, kill)
-	defer func() { timer.Stop(); kill(); _ = cmd.Wait() }()
-
-	// Assembled into lines, each stamped with the arrival of its *first* byte, because a
-	// serial console delivers a byte at a time: a first version printed one row per read and
-	// every row was a single character, so no row ever contained a whole marker to look for.
-	// The first byte is the interesting one — it is when the writer had something to say.
-	var b strings.Builder
-	var line []byte
-	var lineAt time.Duration
-	flush := func() {
-		if len(line) == 0 {
-			return
-		}
-		fmt.Fprintf(&b, "%8.1fms  %s\n", float64(lineAt.Microseconds())/1000, strings.TrimRight(string(line), "\r\n"))
-		line = line[:0]
-	}
-	buf := make([]byte, 32*1024)
-	for {
-		n, err := stdout.Read(buf)
-		if n > 0 {
-			at := time.Since(t0)
-			for _, c := range buf[:n] {
-				if len(line) == 0 {
-					lineAt = at
-				}
-				line = append(line, c)
-				if c == '\n' {
-					flush()
-				}
-			}
-			if strings.Contains(string(line), "login:") {
-				flush()
-				break
-			}
-		}
-		if err != nil {
-			break
-		}
-	}
-	flush()
-	t.Log("\n" + b.String())
-}
-
-func cell(ds []time.Duration) string {
-	p50, ok := boot.Percentile(ds, 0.5)
-	if !ok {
-		return "—"
-	}
-	p95, _ := boot.Percentile(ds, 0.95)
-	return fmt.Sprintf("%d/%d", p50.Milliseconds(), p95.Milliseconds())
-}
-
 // bootOnce runs one boot over a throwaway overlay and returns when the machine powers off or
 // the timeout expires.
 //

boot/initcalls_test.go

@@ -38,7 +38,7 @@ import (
 // so every number here is a p50 over REPS boots and the p95 is printed beside it to say how
 // settled it is. A wide spread means the host was shared, not that the kernel changed.
 //
-// Variants are interleaved rather than run in blocks, for the reason TestBootCost is: a
+// Variants are interleaved rather than run in blocks, because a
 // block schedule hands one variant a slow minute and reads it as a difference.
 //
 //	SPIN_INITCALL_PROBE=1   run at all

boot/report_test.go

@@ -76,7 +76,7 @@ func combinations() [][]choice {
 // Needs /dev/kvm and a built release tree (SPIN_MACHINE_OUTPUT, or _output). The vsock rows
 // need /dev/vhost-vsock; without it those rows are listed as skipped rather than reported as
 // failing. With sudo and /dev/nbd0 the getty is
-// replaced by an echo, as in TestBootCost, and every variant of the image runs; without them
+// replaced by an echo, and every variant of the image runs; without them
 // the usable column carries agetty's second and the variants that edit the image are skipped.
 func TestReport(t *testing.T) {
 	path := os.Getenv("SPIN_REPORT")

boot/ssh_first_test.go

@@ -25,16 +25,16 @@ import (
 )
 
 // When a workspace can first be logged into, from the host, over SSH - the thing a workspace
-// waits for, where boot:bench's `usable` is the serial console's prompt, which nothing a
-// workspace does waits for.
+// waits for, where the serial console's prompt is something nothing a workspace does waits
+// for.
 //
 // The machine gets a vsock device (--vsock-cid), and the image's systemd-ssh-generator binds
 // sshd to AF_VSOCK port 22 when it finds one. From the moment before QEMU is exec'd the host
 // tries to connect every few milliseconds; the first connection accepted is `listen`, and then
 // `true` run as spin over SSH is `login`. The client is golang.org/x/crypto/ssh offering only
 // mlkem768x25519-sha256, the one key exchange the image's sshd accepts: the runners' OpenSSH
 // (9.6 on 2026-11-13) has no ML-KEM and is refused. The console's prompt is timed in the
-// same boot, with the getty an echo as boot:bench's baseline has it, so the two read side by
+// same boot, with the getty an echo, so the two read side by
 // side.
 //
 // What `login` holds beyond `listen` is the first login's own chain: sshd's host keys, the key