diff --git a/.github/workflows/lab.yml b/.github/workflows/lab.yml index 53b8ab9..566d137 100644 --- a/.github/workflows/lab.yml +++ b/.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 diff --git a/Taskfile.yml b/Taskfile.yml index c9232c9..5281e33 100644 --- a/Taskfile.yml +++ b/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 diff --git a/boot/Taskfile.yml b/boot/Taskfile.yml index 2d3dfec..7424221 100644 --- a/boot/Taskfile.yml +++ b/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 - diff --git a/boot/bench_test.go b/boot/harness_test.go similarity index 74% rename from boot/bench_test.go rename to boot/harness_test.go index d9f4ae6..f945959 100644 --- a/boot/bench_test.go +++ b/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. // diff --git a/boot/initcalls_test.go b/boot/initcalls_test.go index f1d1a32..939a530 100644 --- a/boot/initcalls_test.go +++ b/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 diff --git a/boot/report_test.go b/boot/report_test.go index 0b2640c..cd4963f 100644 --- a/boot/report_test.go +++ b/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") diff --git a/boot/ssh_first_test.go b/boot/ssh_first_test.go index 27fed67..e6dba00 100644 --- a/boot/ssh_first_test.go +++ b/boot/ssh_first_test.go @@ -25,8 +25,8 @@ 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 @@ -34,7 +34,7 @@ import ( // `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 diff --git a/boot/ssh_load_test.go b/boot/ssh_load_test.go deleted file mode 100644 index 2877b48..0000000 --- a/boot/ssh_load_test.go +++ /dev/null @@ -1,195 +0,0 @@ -// SPDX-License-Identifier: Apache-2.0 - -package boot_test - -import ( - "fmt" - "os" - "os/exec" - "path/filepath" - "regexp" - "slices" - "strconv" - "strings" - "syscall" - "testing" - "time" -) - -// TestSSHUnderLoad times SSH logins into a guest that is busy, and says whether a login still -// gets in. -// -// The guest runs testdata/ssh-load.sh once it is up: logins while idle, while a service -// burns every vCPU eight times over, while a login session does the same, and with /tmp full. -// The client runs with a weight nothing else in the guest has, so a slow login is sshd's. Each case also reports what the guest was under - -// runnable tasks, memory available, PSI - so a load that did not happen cannot pass for one -// sshd shrugged off. -// -// It exists because SSH connections to busy VMs were timing out and the obvious fix was to -// give sshd priority. Measured 2026-09-28, 7.2.8, 2 vCPUs, 1 GiB, 3 boots of 10 logins per -// case, p50 / max in ms, in two runs that each compared a drop-in on ssh.service against the -// image as built: -// -// idle cpu-service cpu-session memory-64 memory-16 -// as built 102/203 105/207 105/207 102/204 313/614 -// CPUWeight=1000, -// IOWeight=1000 102/203 104/107 105/208 102/103 213/826 -// -// as built 102/203 104/208 104/208 102/103 212/430 -// MemoryLow=64M 102/208 105/205 104/206 102/103 211/354 -// -// No login failed. CPU load, at 14-41% PSI cpu-some with 17-20 tasks runnable, does not slow -// one: cgroup v2's fair share already gives ssh.service its part of the machine whatever runs -// beside it, so a weight on it buys nothing. Memory at 16 MiB available doubles a login, and -// neither variant changes that. So the guest, loaded like this, is not where the timeouts -// come from, and nothing here is shipped for it. (The memory columns were a tmpfs of the test's -// own filled to 64 and 16 MiB left; since MGLRU's min_ttl_ms is set, 16 MiB left is an OOM kill -// of whatever the kernel finds, so the case is /tmp filling to its cap instead.) Not -// OOMScoreAdjust either: sshd sets its own oom_score_adj to -1000 and restores the inherited value in the processes it forks, so on -// the unit the -1000 would be what the users' sessions inherit. -// -// SPIN_SSH_LOAD=1 run at all -// REPS= boots (default 2), 10 logins per case in each -// -// Needs /dev/kvm and a built release; edits a private raw copy of the base image with the -// release's debugfs, so no sudo. -func TestSSHUnderLoad(t *testing.T) { - if os.Getenv("SPIN_SSH_LOAD") == "" { - t.Skip("set SPIN_SSH_LOAD=1: this boots the image and loads it") - } - out := releaseDir(t) - reps := envInt(t, "REPS", 2) - - cases := []string{"idle", "cpu-service", "cpu-session", "tmp-full"} - got := map[string][]string{} - var psi []string - for range reps { - r := sshLoadRun(t, out, sshLoadGuest{}, 10*time.Minute) - if !r.finished { - t.Fatalf("the load script did not finish; the console ends:\n%s", r.console) - } - for c, ms := range r.logins { - got[c] = append(got[c], ms...) - } - psi = append(psi, r.notes...) - } - - var r strings.Builder - fmt.Fprintf(&r, "\nSSH login, ms: p50 / p95 / max, and failures, over %d boots\n\n", reps) - for _, c := range cases { - fmt.Fprintf(&r, " %-12s %s\n", c, loginSummary(got[c])) - } - r.WriteString("\nwhat each case was under, per boot (tasks runnable, memory available, and PSI avg10 where the kernel has it):\n") - for _, p := range psi { - fmt.Fprintf(&r, " %s\n", p) - } - t.Log(r.String()) -} - -var ( - sshLoadLine = regexp.MustCompile(`SSHLOAD (\S+)((?: (?:\d+|FAIL))+)`) - sshLoadNote = regexp.MustCompile(`SSHLOAD(?:PSI|EXHAUST) (.*)`) -) - -// sshLoadGuest is what one boot of the load script changes in its guest: files and symlinks -// written into its root, files removed from it, and which of the script's cases run (its own -// list by default). -type sshLoadGuest struct { - files map[string]string - links map[string]string - remove []string - cases string -} - -// sshLoadResult is one boot: each case's logins, the lines saying what the guest was under, -// and whether the script got to the end - a guest that stopped answering is a result here. -type sshLoadResult struct { - logins map[string][]string - notes []string - finished bool - console string -} - -// sshLoadRun boots one guest with the load script in its root, and gives it until the deadline -// to finish. -func sshLoadRun(t *testing.T, out string, g sshLoadGuest, deadline time.Duration) sshLoadResult { - t.Helper() - root := newRawRoot(t, out, filepath.Join(out, "image/rootfs.qcow2")) - - script, err := os.ReadFile(filepath.Join("testdata", "ssh-load.sh")) - if err != nil { - t.Fatal(err) - } - all := map[string]string{ - "/sshload.sh": string(script), - "/etc/systemd/system/sshload.service": "[Unit]\nAfter=multi-user.target\n[Service]\nType=oneshot\n" + - "Environment=SSHLOAD_CASES=\"" + g.cases + "\"\n" + - "ExecStart=/bin/sh /sshload.sh\nStandardOutput=journal+console\nStandardError=journal+console\n", - "/etc/systemd/system/sshload.timer": "[Timer]\nOnBootSec=3s\nAccuracySec=100ms\n", - } - for p, c := range g.files { - all[p] = c - } - for p, c := range all { - root.write(p, c) - } - for _, p := range g.remove { - root.remove(p) - } - links := map[string]string{"/etc/systemd/system/timers.target.wants/sshload.timer": "/etc/systemd/system/sshload.timer"} - for l, target := range g.links { - links[l] = target - } - for l, target := range links { - root.link(l, target) - } - - console := filepath.Join(t.TempDir(), "console") - cmd := exec.Command(filepath.Join(out, "bin/spin-machine"), "boot", "--release", out, - "--disk", root.path, "--disk-format", "raw", "--memory", "1024", "--cpus", "2", - "--console", "file:"+console, "--init", "/sbin/init") - cmd.SysProcAttr = &syscall.SysProcAttr{Setpgid: true} - if err := cmd.Start(); err != nil { - t.Fatal(err) - } - defer func() { - _ = syscall.Kill(-cmd.Process.Pid, syscall.SIGKILL) - _ = cmd.Wait() - }() - - end := time.Now().Add(deadline) - for { - b, _ := os.ReadFile(console) - s := string(b) - done := strings.Contains(s, "SSHLOAD_DONE") - if done || strings.Contains(s, "SSHLOAD_FAILED") || time.Now().After(end) { - r := sshLoadResult{logins: map[string][]string{}, finished: done, console: tail(b, 3000)} - for _, m := range sshLoadLine.FindAllStringSubmatch(s, -1) { - r.logins[m[1]] = strings.Fields(m[2]) - } - for _, m := range sshLoadNote.FindAllStringSubmatch(s, -1) { - r.notes = append(r.notes, strings.TrimSpace(m[1])) - } - return r - } - time.Sleep(200 * time.Millisecond) - } -} - -// loginSummary is p50 / p95 / max of the logins that got in, and how many did not. -func loginSummary(v []string) string { - var ms []float64 - failed := 0 - for _, s := range v { - n, err := strconv.Atoi(s) - if err != nil { - failed++ - continue - } - ms = append(ms, float64(n)) - } - if len(ms) == 0 { - return fmt.Sprintf("all %d failed", failed) - } - return fmt.Sprintf("%.0f / %.0f / %.0f, %d failed", pct(ms, 50), pct(ms, 95), slices.Max(ms), failed) -} diff --git a/boot/systemd_debug_test.go b/boot/systemd_debug_test.go deleted file mode 100644 index 5778f5e..0000000 --- a/boot/systemd_debug_test.go +++ /dev/null @@ -1,218 +0,0 @@ -// SPDX-License-Identifier: Apache-2.0 - -package boot_test - -import ( - "fmt" - "os" - "regexp" - "sort" - "strconv" - "strings" - "testing" - "time" -) - -// Inside early userspace, in systemd's own words. -// -// `systemd-analyze` says userspace is 139 ms and `blame` names dev-vda.device at 109, but -// neither says what was happening during it, and the critical chain is a list of what -// finished last rather than what was waiting. This turns systemd's debug log on and reads the -// gaps in it, which is the only account of the phase that comes from the thing running it. -// -// Not to the console, which is the same discipline the initcall probe needs for the same -// reason: debug logging is thousands of lines and on a serial port every one is a VM exit -// inside the phase being measured. And not to kmsg either, which was the first attempt and -// lost data: systemd rate-limits its own kmsg output and says so in the log it is writing — -// "Too many messages being logged to kmsg, ignoring" — so lines disappear in bursts, which -// is exactly where a gap would be. -// -// So the default target, which is journal-or-kmsg: systemd uses kmsg until journald exists -// and the journal after, journald keeps both, and `journalctl -o short-monotonic` prints the -// lot against the monotonic clock. Reading the journal also settles a bug the kmsg version -// had: in dmesg, kernel lines like "IOAPIC[0]: apic_id 0" are indistinguishable from a -// userspace "systemd[1]: ..." by shape, so 61.6 ms of kernel time was attributed to a writer -// called IOAPIC. journalctl puts a hostname before the tag and gives the kernel no pid. -// -// This still inflates early userspace, so the absolute numbers are not comparable to -// `task boot:bench` — but the shape is, and the shape is what nothing else shows. -// -// SPIN_SYSTEMD_DEBUG=1 run at all -// TOP= how many gaps to print (default 25) -// GAP= ignore gaps under this (default 2) -func TestSystemdDebug(t *testing.T) { - if os.Getenv("SPIN_SYSTEMD_DEBUG") == "" { - t.Skip("set SPIN_SYSTEMD_DEBUG=1: boots a VM and needs sudo to write into its overlay") - } - out := releaseDir(t) - if !canSudo() { - t.Skip("this writes a unit into the boot's own overlay through qemu-nbd, which needs sudo") - } - top := envInt(t, "TOP", 25) - minGap := float64(envInt(t, "GAP", 2)) - - const dump = `[Unit] -Description=Print the kernel ring buffer for the systemd debug probe -After=multi-user.target -[Service] -Type=simple -StandardOutput=null -ExecStart=/bin/sh -c "{ echo SPIN-DMESG-BEGIN; journalctl -b -o short-monotonic --no-pager; echo SPIN-DMESG-END; } > /dev/ttyS0" -[Install] -WantedBy=multi-user.target -` - v := variant{ - label: "systemd debug", cpus: "2", memory: "2048", - // log_buf_len because the part before journald exists still goes to kmsg, and that is - // the part nothing else can see. - extra: "systemd.log_level=debug printk.devkmsg=on log_buf_len=16M", - files: map[string]string{ - "/etc/systemd/system/spin-dmesg.service": dump, - // The third way this measurement loses data, after the serial console's cost and - // kmsg's rate limit. The runtime journal is a tmpfs with a default cap, and at - // debug level it fills during the boot: journald logs "Journal header limits - // reached or header out-of-date, rotating" and then "Vacuuming", and what it - // vacuums is the beginning — the part before journald existed, which is the only - // part nothing else can see. It left 48 of some nine hundred lines behind, and a - // ranked list of gaps over 48 lines looks like an answer. - "/etc/systemd/journald.conf.d/zz-probe.conf": "[Journal]\n" + - "RuntimeMaxUse=256M\nRuntimeMaxFileSize=256M\nRateLimitIntervalSec=0\nRateLimitBurst=0\n", - }, - links: map[string]string{ - "/etc/systemd/system/multi-user.target.wants/spin-dmesg.service": "/etc/systemd/system/spin-dmesg.service", - }, - } - console := bootUntil(t, out, v, "", "SPIN-DMESG-END", 120*time.Second) - if f := os.Getenv("SPIN_CONSOLE_OUT"); f != "" { - if err := os.WriteFile(f, []byte(console), 0o644); err != nil { - t.Fatalf("writing the console to %s: %v", f, err) - } - t.Logf("raw console written to %s", f) - } - reportSystemd(t, console, top, minGap) -} - -// "Vacuuming done, freed 0B of archived journals from …" — anything but 0B is loss. -var reVacuumed = regexp.MustCompile(`Vacuuming done, freed ((?:[1-9][0-9]*(?:\.[0-9]+)?)[KMGT]?i?B)`) - -// journalctl -o short-monotonic: "[ 2.123456] hostname systemd[1]: message". -// -// The pid is required, and that is the whole point of the pattern: the kernel's own lines -// come through as "hostname kernel: message" with no pid, so requiring one is what keeps a -// kernel message from being counted as a process that spent time. -var reJournal = regexp.MustCompile(`^\[\s*(\d+)\.(\d+)\]\s+\S+\s+([a-zA-Z0-9@._:\\-]+)\[\d+\]:\s*(.*)$`) - -func reportSystemd(t *testing.T, console string, top int, minGap float64) { - t.Helper() - type ev struct { - at float64 - who string - msg string - } - var evs []ev - var first, last float64 - for _, line := range strings.Split(console, "\n") { - m := reJournal.FindStringSubmatch(strings.TrimRight(line, "\r")) - if m == nil { - continue - } - sec, _ := strconv.Atoi(m[1]) - frac := m[2] - for len(frac) < 6 { - frac += "0" - } - us, _ := strconv.Atoi(frac[:6]) - at := float64(sec) + float64(us)/1e6 - evs = append(evs, ev{at: at, who: m[3], msg: clip(m[4])}) - } - // Sorted, because journalctl does not print in timestamp order. Two writers' streams - // arrive interleaved and come out that way: - // - // [ 1.046419] localhost systemd[1]: tmp.mount: Child 62 belongs to tmp.mount. - // [ 1.049546] localhost systemd-journald[63]: Data hash table … suggesting rotation. - // [ 1.046434] localhost systemd[1]: tmp.mount: Mount process exited … - // - // The first version of this treated a stamp going backwards as the end of the window and - // stopped, which left it ranking gaps across fifteen lines of a nine-hundred-line log and - // reporting the largest gap in the boot as 8.9 ms. - sort.Slice(evs, func(i, j int) bool { return evs[i].at < evs[j].at }) - if len(evs) > 0 { - first, last = evs[0].at, evs[len(evs)-1].at - } - if len(evs) < 2 { - t.Fatalf("fewer than two tagged userspace lines in the journal; did "+ - "systemd.log_level=debug take effect, and did journalctl run?\nconsole tail:\n%s", - tail([]byte(console), 1500)) - } - // The rate limit that made the kmsg version lose data. Asserted rather than hoped for: - // a log with holes in it ranks gaps that are missing lines, not gaps that are time. - if strings.Contains(console, "Too many messages being logged to kmsg") { - t.Errorf("systemd rate-limited its own kmsg output, so the log has holes and the " + - "gaps below may be missing lines rather than containing time") - } - // journald vacuums as routine housekeeping and says so even when it discards nothing, so - // the word is not the signal — "freed 0B" is the common case and the first version of this - // check failed every green run on it. What means data is gone is a non-zero amount. - if m := reVacuumed.FindStringSubmatch(console); m != nil { - t.Errorf("journald freed %s of journal during the boot, so the earliest entries are "+ - "gone — raise RuntimeMaxUse further; %d lines survived", m[1], len(evs)) - } - // systemd is thousands of lines at debug level. A few hundred means something dropped - // them, and every number below would be computed over whatever was left. - if len(evs) < 400 { - t.Errorf("only %d tagged lines: systemd at debug writes far more than that, so this "+ - "log is truncated and the gaps are between surviving lines rather than events", - len(evs)) - } - - var b strings.Builder - fmt.Fprintf(&b, "\n%d tagged userspace lines, %.1f ms from the first to the last\n", - len(evs), (evs[len(evs)-1].at-evs[0].at)*1000) - fmt.Fprintf(&b, "first at %.1f ms, last at %.1f ms\n\n", first*1000, last*1000) - - // Who spent the time, before which gap. Aggregated per writer as well as listed, because - // one 40 ms gap and forty 1 ms gaps in the same unit are different problems and the - // ranked list alone hides the second. - type g struct { - ms float64 - who, before string - after string - } - var gaps []g - spent := map[string]float64{} - for i := 1; i < len(evs); i++ { - d := (evs[i].at - evs[i-1].at) * 1000 - spent[evs[i-1].who] += d - if d >= minGap { - gaps = append(gaps, g{ms: d, who: evs[i-1].who, after: evs[i-1].msg, before: evs[i].msg}) - } - } - sort.Slice(gaps, func(i, j int) bool { return gaps[i].ms > gaps[j].ms }) - - type ws struct { - who string - ms float64 - } - var writers []ws - for w, ms := range spent { - writers = append(writers, ws{w, ms}) - } - sort.Slice(writers, func(i, j int) bool { return writers[i].ms > writers[j].ms }) - fmt.Fprintf(&b, " %10s %s\n", "MS AFTER", "WRITER (time between its line and the next, summed)") - for i, w := range writers { - if i >= 12 { - break - } - fmt.Fprintf(&b, " %10.1f %s\n", w.ms, w.who) - } - - fmt.Fprintf(&b, "\n %8s %s\n", "GAP MS", fmt.Sprintf("GAPS OVER %.0f ms", minGap)) - for i, x := range gaps { - if i >= top { - break - } - fmt.Fprintf(&b, " %8.1f %s\n%10s after: %s\n%10s before: %s\n", - x.ms, x.who, "", x.after, "", x.before) - } - t.Log(b.String() + "\n") -} diff --git a/boot/testdata/ssh-load.sh b/boot/testdata/ssh-load.sh deleted file mode 100644 index 7378031..0000000 --- a/boot/testdata/ssh-load.sh +++ /dev/null @@ -1,93 +0,0 @@ -#!/bin/sh -# SPDX-License-Identifier: Apache-2.0 -# Times SSH logins while the guest is loaded, in a disposable test guest. Runs once, as root. -set -eu -trap 'journalctl -b -u ssh.service --no-pager | tail -20; echo SSHLOAD_FAILED' EXIT - -ip link set lo up -ssh-keygen -q -t ed25519 -N '' -f /run/sshload-key -install -d -m 700 -o spin -g spin /home/spin/.ssh -install -m 600 -o spin -g spin /run/sshload-key.pub /home/spin/.ssh/authorized_keys -systemctl start ssh.socket - -SSH="ssh -F /dev/null -i /run/sshload-key -o BatchMode=yes -o StrictHostKeyChecking=no \ - -o UserKnownHostsFile=/dev/null -o LogLevel=error -o ConnectTimeout=10 spin@127.0.0.1" - -# One login, in ms, or FAIL. The client runs in a slice that outweighs everything else in the -# guest, so what is timed is the server: a client starved by the same load would be measured -# instead of sshd. -login() { - systemd-run --scope --quiet --slice=sshload-probe.slice -p CPUWeight=10000 -p IOWeight=10000 \ - sh -c "t0=\$(date +%s%N) - if timeout 20 $SSH true /dev/null || true -} - -cpu_session() { - # The same load inside a login session, which is where a user's build runs. - $SSH "nohup sh -c '$hog' >/dev/null 2>&1 &" /run/sshload-dd; then - echo "tmp_full: /tmp took everything dd had and never filled" >&2 - return 1 - fi - grep -q 'No space left on device' /run/sshload-dd - measure tmp-full - echo "SSHLOADPSI tmp-full-oom kills=$(( $(journalctl -k -b --no-pager | grep -c 'Out of memory: Killed' || true) - kills ))" \ - "tmp=$(df -m --output=size,used /tmp | tail -1 | tr -s ' ')MiB" - rm -f /tmp/sshload-fill -} - -for c in ${SSHLOAD_CASES:-idle cpu_service cpu_session tmp_full}; do - case $c in - idle) measure idle ;; - *) "$c" ;; - esac -done - -trap - EXIT -echo SSHLOAD_DONE diff --git a/boot/userspace_test.go b/boot/userspace_test.go deleted file mode 100644 index b0c3722..0000000 --- a/boot/userspace_test.go +++ /dev/null @@ -1,146 +0,0 @@ -// SPDX-License-Identifier: Apache-2.0 - -package boot_test - -import ( - "fmt" - "os" - "regexp" - "strings" - "testing" - "time" -) - -// Where early userspace goes. -// -// This exists because the initcall probe found the largest single gap in the boot and it is -// not in the kernel: between the kernel's last message and journald's first line there are -// 115-144 ms, which is more than the kernel's own boot. Nothing measured inside it, because -// nothing in the ring buffer is printed there — systemd has not started journald yet, so -// the one instrument the other probes use is blind exactly where the time is. -// -// systemd knows, and will say so after the fact. `systemd-analyze` splits the boot at the -// point the kernel handed over, and `blame` and `critical-chain` say which units are on the -// far side of it. Read after the boot for the same reason the ring buffer is: asking during -// the boot changes it. -// -// SPIN_USERSPACE_PROBE=1 run at all -// REPS= boots to take (default 5) -func TestUserspaceCost(t *testing.T) { - if os.Getenv("SPIN_USERSPACE_PROBE") == "" { - t.Skip("set SPIN_USERSPACE_PROBE=1: boots a VM and needs sudo to write into its overlay") - } - out := releaseDir(t) - if !canSudo() { - t.Skip("this writes a unit into the boot's own overlay through qemu-nbd, which needs sudo") - } - reps := envInt(t, "REPS", 5) - - // Type=simple, and it is the difference between this working and deadlocking. - // - // `systemd-analyze` refuses while the boot is still going — "Bootup is not yet finished - // (FinishTimestampMonotonic=0)" — and startup is finished when every job of the initial - // transaction has completed. A unit in multi-user.target.wants is one of those jobs, so - // as Type=oneshot this waits for a timestamp that cannot be set until it exits: it - // retried for four seconds and gave up, while `blame`, which needs no finish timestamp, - // answered immediately and made it look like a flake. - // - // A Type=simple job completes when the process is exec'd rather than when it exits. So - // startup finishes, and the loop below is what waits for it. - const dump = `[Unit] -Description=Print systemd's own boot accounting -After=multi-user.target -[Service] -Type=simple -StandardOutput=null -ExecStart=/bin/sh -c "{ echo SPIN-ANALYZE-BEGIN; i=0; while [ $i -lt 40 ]; do systemd-analyze && break; i=$((i+1)); sleep 0.1; done; echo '--- BLAME ---'; systemd-analyze blame --no-pager | head -25; echo '--- CHAIN ---'; systemd-analyze critical-chain --no-pager; echo SPIN-ANALYZE-END; } > /dev/ttyS0 2>&1" -[Install] -WantedBy=multi-user.target -` - v := variant{ - label: "userspace", cpus: "2", memory: "2048", - files: map[string]string{"/etc/systemd/system/spin-analyze.service": dump}, - links: map[string]string{ - "/etc/systemd/system/multi-user.target.wants/spin-analyze.service": "/etc/systemd/system/spin-analyze.service", - }, - } - - var kernel, userspace, total []float64 - var last string - for range reps { - console := bootUntil(t, out, v, "", "SPIN-ANALYZE-END", 90*time.Second) - begin := strings.Index(console, "SPIN-ANALYZE-BEGIN") - if begin < 0 { - t.Fatalf("no analyze output; console tail:\n%s", tail([]byte(console), 1500)) - } - last = console[begin:] - k, u, tt := splitStartup(t, last) - kernel = append(kernel, k) - userspace = append(userspace, u) - total = append(total, tt) - } - - t.Logf("\nsystemd's own split, p50/p95 over %d boots\n\n"+ - " %-12s %8.1f %8.1f ms\n %-12s %8.1f %8.1f ms\n %-12s %8.1f %8.1f ms\n", - reps, - "kernel", pct(kernel, 50), pct(kernel, 95), - "userspace", pct(userspace, 50), pct(userspace, 95), - "total", pct(total, 50), pct(total, 95)) - - // The last boot's own words, because `blame` and `critical-chain` are the part worth - // reading and averaging them across boots would lose which unit waited on which. - t.Logf("\nthe last boot, verbatim:\n\n%s", strings.TrimSpace(last)) -} - -// "Startup finished in 43ms (kernel) + 158ms (userspace) = 201ms" — and the units vary: a -// number under a second is printed in ms, over one as "1.234s", and systemd will write -// "1min 2.345s" given the chance. -var reStartup = regexp.MustCompile( - `Startup finished in ([^(]+)\(kernel\)(?: \+ ([^(]+)\(initrd\))? \+ ([^(]+)\(userspace\) = (.+)`) - -func splitStartup(t *testing.T, s string) (kernel, userspace, total float64) { - t.Helper() - m := reStartup.FindStringSubmatch(s) - if m == nil { - t.Fatalf("no \"Startup finished\" line in systemd-analyze's output:\n%s", tail([]byte(s), 1200)) - } - return mustDur(t, m[1]), mustDur(t, m[3]), mustDur(t, m[4]) -} - -// mustDur reads systemd's spelling of a duration into milliseconds. Written out rather than -// handed to time.ParseDuration because systemd separates its parts with a space — -// "1min 2.345s" — which ParseDuration rejects, and because a wrong answer here is a boot -// time that is wrong by a factor of sixty and looks plausible. -func mustDur(t *testing.T, s string) float64 { - t.Helper() - var ms float64 - for _, part := range strings.Fields(strings.TrimSpace(s)) { - var n float64 - var unit string - switch { - case strings.HasSuffix(part, "min"): - unit, part = "min", strings.TrimSuffix(part, "min") - case strings.HasSuffix(part, "ms"): - unit, part = "ms", strings.TrimSuffix(part, "ms") - case strings.HasSuffix(part, "s"): - unit, part = "s", strings.TrimSuffix(part, "s") - default: - t.Fatalf("%q in %q has no unit this understands", part, s) - } - if _, err := fmt.Sscanf(part, "%g", &n); err != nil { - t.Fatalf("%q in %q is not a number: %v", part, s, err) - } - switch unit { - case "min": - ms += n * 60000 - case "s": - ms += n * 1000 - case "ms": - ms += n - } - } - if ms == 0 { - t.Fatalf("%q read as zero, which no boot takes", s) - } - return ms -} diff --git a/boot/waits_probe_test.go b/boot/waits_probe_test.go index 3471d34..0186811 100644 --- a/boot/waits_probe_test.go +++ b/boot/waits_probe_test.go @@ -32,8 +32,7 @@ import ( // one boot of five, which it cannot have. Read a difference smaller than that as none. What is // before that zero is QEMU and the firmware; task boot:firmware-stages splits it. // -// The login is serial-getty@ttyS0 replaced by an echo (gettyEcho), as task boot:bench's -// baseline does, so agetty's own second is not in it. The getty keeps Type=idle, so what is +// The login is serial-getty@ttyS0 replaced by an echo (gettyEcho), so agetty's own second is not in it. The getty keeps Type=idle, so what is // between its fork and the prompt is it waiting for the job queue to drain, and that is // printed as its own row because it is in no unit's timestamps. // @@ -79,8 +78,8 @@ func TestBootWaits(t *testing.T) { // waitsVariant is the boot both probes take: the getty an echo, and spin-waits.service printing // every unit's timestamps once startup has finished. func waitsVariant(cpus string) variant { - // Type=simple and a loop on FinishTimestampMonotonic, for the reason TestUserspaceCost - // gives: this unit is one of the initial transaction's jobs. + // Type=simple and a loop on FinishTimestampMonotonic: this unit is one of the initial + // transaction's jobs, and a oneshot there would hold startup open until it was done. // // The units are list-units --all and not `systemctl show '*'`: the pattern matches only // the units still loaded and active, 57 of them on 2026-11-12, and drops every oneshot @@ -394,7 +393,7 @@ func waitsReport(boots []waitsBoot, target string, top int, minGap time.Duration // starts: coldplug, then "Activating default unit: default.target" parses every unit file // default.target reaches, and a stub for each name an After= or RequiresMountsFor= gives, // builds the initial transaction (64 jobs), and collects the stubs before the first job is - // dispatched - task boot:trace with systemd.log_level=debug, 2026-11-13. It shrinks only with + // dispatched - one boot's console with systemd.log_level=debug, 2026-11-13. It shrinks only with // the transaction: eleven of its units whose condition fails on every boot here, masked, did // not move the first SSH login (boot:ssh-first, lab run 43483372488). gaps := x.w.Gaps(x.target().Start, minGap) diff --git a/image/mkosi.extra/usr/local/lib/spin-base/configure-system.sh b/image/mkosi.extra/usr/local/lib/spin-base/configure-system.sh index f9539dd..2a9225a 100755 --- a/image/mkosi.extra/usr/local/lib/spin-base/configure-system.sh +++ b/image/mkosi.extra/usr/local/lib/spin-base/configure-system.sh @@ -93,7 +93,7 @@ EOF # reboots and advertise a subscription - network calls and package queries in a machine that # is started, does one piece of work and is thrown away. This image's own replacement, a line # saying how long the boot took, ran systemd-analyze inside every login, which is the one -# thing a workspace waits for; a boot time belongs to task boot:bench and boot:ssh-first, +# thing a workspace waits for; a boot time belongs to task boot:ssh-first and the release's report, # which measure it on purpose, not to a greeting nobody acts on (removed 2026-11-12). # # pam_motd goes from every PAM stack that has it, not only ssh's: with it enabled, whatever a diff --git a/image/mkosi.extra/usr/local/lib/spin-base/optimize-systemd.sh b/image/mkosi.extra/usr/local/lib/spin-base/optimize-systemd.sh index 416bbee..6b71fb8 100755 --- a/image/mkosi.extra/usr/local/lib/spin-base/optimize-systemd.sh +++ b/image/mkosi.extra/usr/local/lib/spin-base/optimize-systemd.sh @@ -83,8 +83,8 @@ MASK_UNITS=( modprobe@fuse.service modprobe@efi_pstore.service - # Debug and tracing mounts. Masked, not absent: `task boot:trace` mounts - # tracefs by hand when it needs it, which is the only thing here that ever does. + # Debug and tracing mounts. Masked, not absent: a probe that needs tracefs + # mounts it by hand. sys-kernel-debug.mount sys-kernel-tracing.mount diff --git a/kernel/Dockerfile b/kernel/Dockerfile index bea2616..9629dd2 100644 --- a/kernel/Dockerfile +++ b/kernel/Dockerfile @@ -18,7 +18,7 @@ # # Both are versions.yaml's `debian` and `debian-snapshot`, handed in by kernel/Taskfile.yml with # no default here. To move them: `task bump NAME=debian` and `task bump NAME=debian-snapshot`, -# together, and the boot measured again (`task boot:bench`). +# together, and the boot measured again (`task boot:ssh-first`). ARG DEBIAN_IMAGE ARG DEBIAN_SNAPSHOT diff --git a/versions.yaml b/versions.yaml index abda761..16b366f 100644 --- a/versions.yaml +++ b/versions.yaml @@ -76,7 +76,7 @@ is the series', kernel/config-.-x86_64, so a release within the series moves this entry and nothing else: refresh.yml proposes it every day, and kernel.yml builds it on the pull request. A new series renames the configuration in the same commit, then - `task kernel:build`, `task boot:bench`. The series is a person's choice, the same as + `task kernel:build`, `task boot:ssh-first`. The series is a person's choice, the same as spin-ami's host kernel. - name: debian @@ -89,7 +89,7 @@ the kernel's toolchain (and qboot's), with its packages from debian-snapshot. A new toolchain is a new vmlinux: bump it together with debian-snapshot, then `task kernel:build`, and check the vmlinux is still reproducible - (kernel/Dockerfile, two --no-cache builds) before `task boot:bench`. + (kernel/Dockerfile, two --no-cache builds) before `task boot:ssh-first`. - name: moby-check-config kind: download @@ -145,7 +145,7 @@ note: >- image/Dockerfile. Which mkosi assembles the tree decides what ends up in it. image/mkosi.conf's MinimumVersion says the same version, and a test holds the two together. After the bump: - `task image:build`, then `task shell` and `task boot:bench`: a new mkosi can change the + `task image:build`, then `task shell` and `task boot:ssh-first`: a new mkosi can change the tree without failing the build. - name: task