From 21bfd95d41122aec87a500c195a53aa4c1a3c656 Mon Sep 17 00:00:00 2001 From: Manuel de Brito Fontes Date: Sat, 26 Sep 2026 11:53:19 -0300 Subject: [PATCH 01/18] The qboot experiment: a pinned build, and a probe that asserts before it times MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit qboot cannot run this machine as upstream ships it. Its ACPI linker-loader implements ALLOCATE, ADD_POINTER and ADD_CHECKSUM and stops on anything else, and vmgenid needs WRITE_POINTER to tell QEMU where the GUID lives. The symptom is a vCPU halted inside the firmware with nothing on the console, not even earlyprintk. write-pointer.patch adds that command and the fw_cfg DMA writes it needs; NOTICE carries its GPL-2.0 provenance, since the repository's own licence does not cover it and nothing here ships it. The build is a container for the same reason kernel/Dockerfile is, and the reason turned out to be load-bearing rather than tidy. The earlier recipe used whatever GCC the host had — 15.2.0, producing 7a316e3c… for the patched binary. The pinned Debian's GCC is 14.2.0 and produces bf7ddddc… from the same commit, the same patch and the same flags, and the saving moves from 6.32 ms to 3.86 ms. The compiler accounts for more than a third of what the firmware change itself buys, which is the same result the SeaBIOS experiment recorded in boot/phases.go. A number in qemu/qboot/README.md is only comparable to another built the same way, and it now says which rows those are. The probe moves from Python to Go, beside the rest of the boot harness and sharing its release discovery, its percentiles and its interleaving. It asserts that the stock firmware hangs with vmgenid on before it times anything: a stock qboot that booted would mean the WRITE_POINTER story is wrong and every timing after it is measuring something else. It then saves the guest, restores it with a fresh GUID and requires the guest to log the reseed — a firmware that boots and quietly fails to publish the table gives every VM restored from one template the same random pool, and nothing on either of them reports a fault. The firmware is about 10 ms of a boot that reaches a login in a few hundred, and this decides whether a firmware can run the machine at all before it argues about the milliseconds. It is also not adoptable yet for a reason that is not the number: Spec.Fingerprint hashes the QEMU binary, the kernel and the initrd, and not the firmware, so two releases differing only in firmware would exchange templates across different ACPI and E820 layouts. Selectable firmware needs that fixed first. Co-Authored-By: Claude Opus 5 (1M context) --- NOTICE | 7 + Taskfile.yml | 15 ++ boot/firmware_test.go | 443 +++++++++++++++++++++++++++++++++ qemu/Taskfile.yml | 19 ++ qemu/qboot/COPYING | 340 +++++++++++++++++++++++++ qemu/qboot/Dockerfile | 119 +++++++++ qemu/qboot/README.md | 102 ++++++++ qemu/qboot/measurements.json | 103 ++++++++ qemu/qboot/write-pointer.patch | 116 +++++++++ 9 files changed, 1264 insertions(+) create mode 100644 boot/firmware_test.go create mode 100644 qemu/qboot/COPYING create mode 100644 qemu/qboot/Dockerfile create mode 100644 qemu/qboot/README.md create mode 100644 qemu/qboot/measurements.json create mode 100644 qemu/qboot/write-pointer.patch diff --git a/NOTICE b/NOTICE index da018a9..1a3b3ff 100644 --- a/NOTICE +++ b/NOTICE @@ -4,6 +4,13 @@ Copyright The spin-stack Authors This product includes software developed by the spin-stack project. Licensed under the Apache License, Version 2.0; see LICENSE. +The patch in qemu/qboot/write-pointer.patch includes context from qboot, +https://github.com/bonzini/qboot, commit +8ca302e86d685fa05b16e2b208888243da319941, under GPL-2.0 (see qemu/qboot/COPYING). +It modifies fw_cfg.c, include/fw_cfg.h and tables.c to implement WRITE_POINTER, +DMA writes and error/bounds checks. This experimental firmware is not shipped +in releases. The Apache-2.0 licence does not apply to that patch or COPYING. + -------------------------------------------------------------------------------- Third-party software in a release, which this licence does NOT cover -------------------------------------------------------------------------------- diff --git a/Taskfile.yml b/Taskfile.yml index 61a693d..e26c040 100644 --- a/Taskfile.yml +++ b/Taskfile.yml @@ -121,6 +121,10 @@ vars: QEMU_CACHE_TO: '{{if eq .CACHE_BACKEND "gha"}}type=gha,scope=qemu,mode=max{{else}}type=local,dest={{.BUILDKIT_CACHE_DIR}}/qemu,mode=max,compression=zstd{{end}}' KERNEL_CACHE_FROM: '{{if eq .CACHE_BACKEND "gha"}}type=gha,scope=kernel{{else}}type=local,src={{.BUILDKIT_CACHE_DIR}}/kernel{{end}}' KERNEL_CACHE_TO: '{{if eq .CACHE_BACKEND "gha"}}type=gha,scope=kernel,mode=max{{else}}type=local,dest={{.BUILDKIT_CACHE_DIR}}/kernel,mode=max,compression=zstd{{end}}' + # The firmware experiment. Its own scope like everything else, and it is never built by + # `task build`: nothing in a release comes from it. + QBOOT_CACHE_FROM: '{{if eq .CACHE_BACKEND "gha"}}type=gha,scope=qboot{{else}}type=local,src={{.BUILDKIT_CACHE_DIR}}/qboot{{end}}' + QBOOT_CACHE_TO: '{{if eq .CACHE_BACKEND "gha"}}type=gha,scope=qboot,mode=max{{else}}type=local,dest={{.BUILDKIT_CACHE_DIR}}/qboot,mode=max,compression=zstd{{end}}' E2FSPROGS_CACHE_FROM: '{{if eq .CACHE_BACKEND "gha"}}type=gha,scope=e2fsprogs{{else}}type=local,src={{.BUILDKIT_CACHE_DIR}}/e2fsprogs{{end}}' E2FSPROGS_CACHE_TO: '{{if eq .CACHE_BACKEND "gha"}}type=gha,scope=e2fsprogs,mode=max{{else}}type=local,dest={{.BUILDKIT_CACHE_DIR}}/e2fsprogs,mode=max,compression=zstd{{end}}' # The container that builds the base image. Small — mkosi, qemu-utils — and cached like @@ -198,6 +202,17 @@ tasks: cmds: - SPIN_LOGIND_TEST=1 go test ./boot/ -run '^TestLogindSessions$' -count=1 -v -timeout 5m + boot:firmware: + desc: >- + Compare firmware for this machine: SeaBIOS against the qboot build in qemu/qboot/. + Needs KVM, a built release, `task qemu:qboot`, and a diagnostic initrd in + SPIN_PROBE_INITRD=. Without the firmware or the initrd it says which is missing and + skips: neither is an artefact a release carries. It asserts a firmware can run this + machine at all before it times one, because a firmware with no WRITE_POINTER loses + vmgenid and a lost vmgenid has no symptom. + cmds: + - SPIN_FIRMWARE_PROBE=1 go test ./boot/ -run TestFirmwareCost -count=1 -v -timeout 20m + boot:trace: desc: >- One boot's console printed against the host's clock, for finding a gap that belongs to diff --git a/boot/firmware_test.go b/boot/firmware_test.go new file mode 100644 index 0000000..a697ed9 --- /dev/null +++ b/boot/firmware_test.go @@ -0,0 +1,443 @@ +// SPDX-License-Identifier: Apache-2.0 + +package boot_test + +import ( + "encoding/json" + "fmt" + "net" + "os" + "os/exec" + "path/filepath" + "sort" + "strings" + "syscall" + "testing" + "time" +) + +// Firmware A/B, against a caller-supplied diagnostic initrd. +// +// The firmware is ~10 ms of vCPU 0's work in a boot that reaches a login in a few hundred, +// so this measures a small line item and says so: what it is for is deciding whether a +// firmware can run this machine at all, and only then what it saves. +// +// qboot cannot, as it stands. Its ACPI linker-loader implements ALLOCATE, ADD_POINTER and +// ADD_CHECKSUM and stops on anything else, and vmgenid needs WRITE_POINTER to tell QEMU +// where the GUID lives. The symptom is a vCPU halted inside the firmware with not one byte +// on the console, not even earlyprintk — which is why the stock variant is booted here +// deliberately and its timeout is the assertion, not a failure. +// +// The inputs are not release artefacts and nothing here builds them: +// +// SPIN_FIRMWARE_PROBE=1 run at all +// SPIN_PROBE_INITRD= a diagnostic initrd; see below +// REPS= boots per firmware (default 20) +// +// The two qboot binaries are read from _output/qboot/, where `task qemu:qboot` writes them, +// and SPIN_QBOOT_STOCK and SPIN_QBOOT_PATCHED override that. Defaulting rather than +// requiring them removes a trap worth naming: a relative path in either variable resolves +// against this package's directory and not the repository root, so `_output/qboot/...` on +// the command line looked right and pointed at boot/_output. +// +// The initrd is diagnostic input because what runs as PID 1 is not this repository's +// business. Its /init must mount proc, print any dmesg line matching vmgenid, print +// SPIN-READY, stay alive, and keep printing new dmesg output so a reseed after restore is +// visible. Its own CPU and memory work lands inside every number here, so the same initrd +// has to be used for both variants or the comparison is between two initrds. +func TestFirmwareCost(t *testing.T) { + if os.Getenv("SPIN_FIRMWARE_PROBE") == "" { + t.Skip("set SPIN_FIRMWARE_PROBE=1: this boots dozens of VMs and needs firmware built outside the release") + } + out := releaseDir(t) + reps := envInt(t, "REPS", 20) + + bios := map[string]string{ + "seabios": filepath.Join(out, "qemu", "bios-256k.bin"), + "stock": firmwareFile(t, "SPIN_QBOOT_STOCK", filepath.Join(out, "qboot", "stock", "bios.bin")), + "patched": firmwareFile(t, "SPIN_QBOOT_PATCHED", filepath.Join(out, "qboot", "patched", "bios.bin")), + } + p := &probe{ + out: out, + firmware: filepath.Join(out, "qemu"), + kernel: filepath.Join(out, "kernel", "vmlinux"), + initrd: envFile(t, "SPIN_PROBE_INITRD"), + bios: bios, + dir: t.TempDir(), + } + + // One: the machine boots this firmware at all, with vmgenid off. A firmware that cannot + // do this is not slow, it is broken, and separating the two is why there are three boots + // before any timing. + if ms := p.mustReach(t, "stock", noVMGenID, "SPIN-READY"); ms > 0 { + t.Logf("stock qboot, no vmgenid: %.1f ms to SPIN-READY", ms) + } + + // Two: the stock firmware is expected to hang once vmgenid is on. Asserted, because a + // stock qboot that booted would mean the WRITE_POINTER story is wrong and every number + // below is measuring something else. + if ms, err := p.reach(t, "stock", withVMGenID, "SPIN-READY", 3*time.Second); err == nil { + t.Fatalf("stock qboot booted with vmgenid in %.1f ms; it implements no WRITE_POINTER, "+ + "so either the firmware is not the one described or the machine no longer asks "+ + "for vmgenid", ms) + } + t.Log("stock qboot, vmgenid on: no console output, as expected") + + // Three: the patched firmware boots, publishes the table, and survives a restore with + // the guest noticing. The reseed is the point of vmgenid; a firmware that boots and + // loses it is worse than one that does not boot, because nothing says so. + p.mustPublishVMGenID(t) + + // Only now, the timing. Interleaved for the reason TestBootCost is: a block schedule + // hands one variant a slow minute and reads it as a difference. + samples := map[string][]float64{} + order := []string{"seabios", "patched"} + for range reps { + for _, v := range order { + ms, err := p.reach(t, v, withVMGenID, "SPIN-READY", 8*time.Second) + if err != nil { + t.Fatalf("%s: %v", v, err) + } + samples[v] = append(samples[v], ms) + } + } + + 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, "%-10s %10s %10s\n", "FIRMWARE", "P50", "P95") + for _, v := range order { + s := append([]float64(nil), samples[v]...) + sort.Float64s(s) + fmt.Fprintf(&b, "%-10s %10.2f %10.2f\n", v, pct(s, 50), pct(s, 95)) + } + // The difference, stated rather than left to the reader: it is the number the decision + // turns on, and it is small enough that a reader who has to subtract will round it up. + sb, pa := append([]float64(nil), samples["seabios"]...), append([]float64(nil), samples["patched"]...) + sort.Float64s(sb) + sort.Float64s(pa) + fmt.Fprintf(&b, "\np50 reduction: %.2f ms\n", pct(sb, 50)-pct(pa, 50)) + t.Log(b.String()) +} + +const ( + withVMGenID = true + noVMGenID = false +) + +type probe struct { + out, firmware, kernel, initrd, dir string + bios map[string]string + n int +} + +// vm is one QEMU, and the socket paths are numbered because a probe starts dozens and a +// reused path is a QMP connection to the previous one's corpse. +type vm struct { + cmd *exec.Cmd + stdout *os.File + out []byte + t0 time.Time + qmp string +} + +func (p *probe) start(t *testing.T, variant string, gen bool, incoming string) *vm { + t.Helper() + p.n++ + qmp := filepath.Join(p.dir, fmt.Sprintf("qmp-%d.sock", p.n)) + + // The machine line is the probe's own, not machine.Spec's: this compares firmware, so + // the disks, NICs and vsock a real machine carries are absent on purpose — every device + // is work inside the interval, and work that is identical in both variants only adds + // variance. It is also why these numbers are not a machine's boot time. + args := []string{ + "-L", p.firmware, + "-machine", "q35,sata=off,smbus=off", + "-accel", "kvm", "-cpu", "host", + "-m", "2048", "-smp", "2", + "-nodefaults", "-display", "none", "-serial", "stdio", "-monitor", "none", + "-qmp", "unix:" + qmp + ",server=on,wait=off", + "-bios", p.bios[variant], + "-kernel", p.kernel, + "-initrd", p.initrd, + "-append", "console=ttyS0 quiet loglevel=3 pci=lastbus=0 no_timer_check " + + "tsc=reliable rcupdate.rcu_expedited=1 TERM=dumb rdinit=/init", + } + if gen { + args = append(args, "-device", "vmgenid,guid=auto") + } + if incoming != "" { + args = append(args, "-incoming", "file:"+incoming) + } + + r, w, err := os.Pipe() + if err != nil { + t.Fatalf("console pipe: %v", err) + } + cmd := exec.Command(filepath.Join(p.out, "bin", "qemu-system-x86_64"), args...) + cmd.Stdout, cmd.Stderr = w, w + cmd.SysProcAttr = &syscall.SysProcAttr{Setpgid: true} + + // t0 before Start, so exec'ing QEMU and the firmware are both inside the interval. They + // are the two things this test exists to compare. + t0 := time.Now() + if err := cmd.Start(); err != nil { + t.Fatalf("launching QEMU: %v", err) + } + _ = w.Close() + return &vm{cmd: cmd, stdout: r, t0: t0, qmp: qmp} +} + +// wait reads the console until marker appears, and returns when it did. A deadline on the +// descriptor rather than a goroutine and a channel: there is one reader, and it is this one. +func (v *vm) wait(marker string, timeout time.Duration) (float64, error) { + deadline := time.Now().Add(timeout) + buf := make([]byte, 65536) + for { + if err := v.stdout.SetReadDeadline(deadline); err != nil { + return 0, fmt.Errorf("setting the console deadline: %w", err) + } + n, err := v.stdout.Read(buf) + v.out = append(v.out, buf[:n]...) + if strings.Contains(string(v.out), marker) { + return float64(time.Since(v.t0).Microseconds()) / 1000, nil + } + if err != nil { + return 0, fmt.Errorf("never saw %q in %s; console was:\n%s", + marker, timeout, tail(v.out, 800)) + } + } +} + +func (v *vm) close() { + if pgid, err := syscall.Getpgid(v.cmd.Process.Pid); err == nil { + _ = syscall.Kill(-pgid, syscall.SIGKILL) + } + _ = v.cmd.Wait() + _ = v.stdout.Close() +} + +func (p *probe) reach(t *testing.T, variant string, gen bool, marker string, timeout time.Duration) (float64, error) { + t.Helper() + v := p.start(t, variant, gen, "") + defer v.close() + return v.wait(marker, timeout) +} + +func (p *probe) mustReach(t *testing.T, variant string, gen bool, marker string) float64 { + t.Helper() + ms, err := p.reach(t, variant, gen, marker, 8*time.Second) + if err != nil { + t.Fatalf("%s firmware (vmgenid=%v): %v", variant, gen, err) + } + return ms +} + +// mustPublishVMGenID boots the patched firmware, saves the machine, restores it into a new +// QEMU with a fresh GUID, and requires the guest to say it noticed. +// +// The reseed is the whole reason the device is on the machine's command line: two guests +// restored from one template share the template's memory, and that memory contains the +// state of the random pool. A firmware that boots and quietly fails to publish the table +// produces two VMs generating the same "random" bytes, and nothing on either of them +// reports a fault. +func (p *probe) mustPublishVMGenID(t *testing.T) { + t.Helper() + v := p.start(t, "patched", withVMGenID, "") + ms, err := v.wait("SPIN-READY", 8*time.Second) + if err != nil { + v.close() + t.Fatalf("patched qboot: %v", err) + } + if !strings.Contains(strings.ToLower(string(v.out)), "vmgenid") { + v.close() + t.Fatalf("patched qboot booted in %.1f ms but the guest saw no VMGENID table; "+ + "console was:\n%s", ms, tail(v.out, 800)) + } + t.Logf("patched qboot, vmgenid on: %.1f ms to SPIN-READY, table present", ms) + + state := filepath.Join(p.dir, "state") + q := dial(t, v.qmp, v) + q.do(t, "stop", nil) + q.do(t, "migrate", map[string]any{"uri": "file:" + state}) + q.until(t, "query-migrate", "completed", 20*time.Second) + q.close() + v.close() + + r := p.start(t, "patched", withVMGenID, state) + defer r.close() + q = dial(t, r.qmp, r) + defer q.close() + // cont only once the incoming migration is done: a cont into a machine still loading + // state is a race that passes most of the time. + q.untilNot(t, "query-status", "inmigrate", 20*time.Second) + q.do(t, "cont", nil) + if _, err := r.wait("crng reseeded due to virtual machine fork", 20*time.Second); err != nil { + t.Fatalf("the restored guest never reseeded, so the GUID did not reach it "+ + "— every VM restored from one template would share its random pool: %v", err) + } + t.Log("restored guest reseeded: the WRITE_POINTER path carries the GUID") +} + +// A QMP client small enough to read: connect, swallow the greeting, negotiate, and send +// commands one at a time. No pipelining, because every call here is followed by a decision. +type qmp struct { + conn net.Conn + enc *json.Encoder + dec *json.Decoder +} + +func dial(t *testing.T, socket string, v *vm) *qmp { + t.Helper() + deadline := time.Now().Add(20 * time.Second) + for { + conn, err := net.Dial("unix", socket) + if err == nil { + if err := conn.SetDeadline(time.Now().Add(30 * time.Second)); err != nil { + t.Fatal(err) + } + q := &qmp{conn: conn, enc: json.NewEncoder(conn), dec: json.NewDecoder(conn)} + var greeting struct { + QMP *struct{} `json:"QMP"` + } + if err := q.dec.Decode(&greeting); err != nil { + t.Fatalf("reading the QMP greeting: %v\n\nQEMU said:\n%s", err, tail(v.out, 800)) + } + q.do(t, "qmp_capabilities", nil) + return q + } + if time.Now().After(deadline) { + t.Fatalf("QEMU never answered on %s: %v\n\nQEMU said:\n%s", + filepath.Base(socket), err, tail(v.out, 800)) + } + time.Sleep(20 * time.Millisecond) + } +} + +func (q *qmp) do(t *testing.T, cmd string, args map[string]any) json.RawMessage { + t.Helper() + req := map[string]any{"execute": cmd} + if args != nil { + req["arguments"] = args + } + if err := q.enc.Encode(req); err != nil { + t.Fatalf("sending %s: %v", cmd, err) + } + for { + var reply struct { + Return json.RawMessage `json:"return"` + Error *struct { + Desc string `json:"desc"` + } `json:"error"` + Event string `json:"event"` + } + if err := q.dec.Decode(&reply); err != nil { + t.Fatalf("reading the reply to %s: %v", cmd, err) + } + if reply.Error != nil { + t.Fatalf("%s was refused: %s", cmd, reply.Error.Desc) + } + // Events arrive interleaved with replies, and a migration emits several. + if reply.Event != "" { + continue + } + return reply.Return + } +} + +// until polls cmd until its "status" field reads want, and fails on "failed" rather than +// waiting out the deadline: a migration that has already given up has nothing to say later. +func (q *qmp) until(t *testing.T, cmd, want string, timeout time.Duration) { + t.Helper() + deadline := time.Now().Add(timeout) + for { + var s struct{ Status string } + if err := json.Unmarshal(q.do(t, cmd, nil), &s); err != nil { + t.Fatalf("reading %s: %v", cmd, err) + } + if s.Status == want { + return + } + if s.Status == "failed" { + t.Fatalf("%s reported failed while waiting for %s", cmd, want) + } + if time.Now().After(deadline) { + t.Fatalf("%s stayed %q for %s, waiting for %q", cmd, s.Status, timeout, want) + } + time.Sleep(10 * time.Millisecond) + } +} + +func (q *qmp) untilNot(t *testing.T, cmd, unwanted string, timeout time.Duration) { + t.Helper() + deadline := time.Now().Add(timeout) + for { + var s struct{ Status string } + if err := json.Unmarshal(q.do(t, cmd, nil), &s); err != nil { + t.Fatalf("reading %s: %v", cmd, err) + } + if s.Status != unwanted { + return + } + if time.Now().After(deadline) { + t.Fatalf("%s stayed %q for %s", cmd, unwanted, timeout) + } + time.Sleep(10 * time.Millisecond) + } +} + +func (q *qmp) close() { _ = q.conn.Close() } + +// firmwareFile takes the override if there is one and the built firmware otherwise, and +// skips rather than failing when neither is there: this compares firmware no release carries, +// so a checkout without it is not a broken checkout. +func firmwareFile(t *testing.T, name, dflt string) string { + t.Helper() + if v := os.Getenv(name); v != "" { + return envFile(t, name) + } + if _, err := os.Stat(dflt); err != nil { + t.Skipf("no %s — run: task qemu:qboot (or set %s)", dflt, name) + } + return dflt +} + +// envFile fails rather than skipping: a path given explicitly and not there is a mistake in +// the invocation, and skipping would hide it. +func envFile(t *testing.T, name string) string { + t.Helper() + v := os.Getenv(name) + if v == "" { + t.Skipf("%s is unset; this probe compares firmware that no release carries", name) + } + abs, err := filepath.Abs(v) + if err != nil { + t.Fatalf("resolving %s=%q: %v", name, v, err) + } + if _, err := os.Stat(abs); err != nil { + t.Fatalf("%s=%s: %v\n(a relative path here resolves against %s, not the repository root)", + name, abs, err, mustCwd(t)) + } + return abs +} + +func mustCwd(t *testing.T) string { + t.Helper() + d, err := os.Getwd() + if err != nil { + t.Fatalf("getwd: %v", err) + } + return d +} + +// pct is nearest-rank on an already sorted slice, matching boot.Percentile so the two +// harnesses cannot disagree about what a p95 is. +func pct(sorted []float64, p int) float64 { + if len(sorted) == 0 { + return 0 + } + i := (p*len(sorted) + 99) / 100 + if i < 1 { + i = 1 + } + return sorted[i-1] +} diff --git a/qemu/Taskfile.yml b/qemu/Taskfile.yml index 49eb8e5..e1ce1e3 100644 --- a/qemu/Taskfile.yml +++ b/qemu/Taskfile.yml @@ -40,6 +40,25 @@ tasks: . - task: verify + qboot: + desc: >- + Build the qboot firmware experiment in qemu/qboot/ — stock and patched — into + _output/qboot/. Not part of a release and not on the path to one: it is the input to + `task boot:firmware`, which decides whether a firmware can run this machine before it + times one. See qemu/qboot/README.md. + cmds: + - mkdir -p {{.OUTPUT_ABS}} + - | + docker buildx build \ + --file qemu/qboot/Dockerfile \ + --target extract \ + --platform linux/amd64 \ + --cache-from {{.QBOOT_CACHE_FROM}} \ + --cache-to {{.QBOOT_CACHE_TO}} \ + --output type=local,dest={{.OUTPUT_ABS}}/qboot \ + . + - cmd: echo "✓ {{.OUTPUT_ABS}}/qboot/{stock,patched}/bios.bin" + verify: desc: Assert the extracted QEMU tree carries what every consumer needs. cmds: diff --git a/qemu/qboot/COPYING b/qemu/qboot/COPYING new file mode 100644 index 0000000..8cdb845 --- /dev/null +++ b/qemu/qboot/COPYING @@ -0,0 +1,340 @@ + GNU GENERAL PUBLIC LICENSE + Version 2, June 1991 + + Copyright (C) 1989, 1991 Free Software Foundation, Inc., + 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA + Everyone is permitted to copy and distribute verbatim copies + of this license document, but changing it is not allowed. + + Preamble + + The licenses for most software are designed to take away your +freedom to share and change it. By contrast, the GNU General Public +License is intended to guarantee your freedom to share and change free +software--to make sure the software is free for all its users. This +General Public License applies to most of the Free Software +Foundation's software and to any other program whose authors commit to +using it. (Some other Free Software Foundation software is covered by +the GNU Lesser General Public License instead.) You can apply it to +your programs, too. + + When we speak of free software, we are referring to freedom, not +price. Our General Public Licenses are designed to make sure that you +have the freedom to distribute copies of free software (and charge for +this service if you wish), that you receive source code or can get it +if you want it, that you can change the software or use pieces of it +in new free programs; and that you know you can do these things. + + To protect your rights, we need to make restrictions that forbid +anyone to deny you these rights or to ask you to surrender the rights. +These restrictions translate to certain responsibilities for you if you +distribute copies of the software, or if you modify it. + + For example, if you distribute copies of such a program, whether +gratis or for a fee, you must give the recipients all the rights that +you have. You must make sure that they, too, receive or can get the +source code. And you must show them these terms so they know their +rights. + + We protect your rights with two steps: (1) copyright the software, and +(2) offer you this license which gives you legal permission to copy, +distribute and/or modify the software. + + Also, for each author's protection and ours, we want to make certain +that everyone understands that there is no warranty for this free +software. If the software is modified by someone else and passed on, we +want its recipients to know that what they have is not the original, so +that any problems introduced by others will not reflect on the original +authors' reputations. + + Finally, any free program is threatened constantly by software +patents. We wish to avoid the danger that redistributors of a free +program will individually obtain patent licenses, in effect making the +program proprietary. To prevent this, we have made it clear that any +patent must be licensed for everyone's free use or not licensed at all. + + The precise terms and conditions for copying, distribution and +modification follow. + + GNU GENERAL PUBLIC LICENSE + TERMS AND CONDITIONS FOR COPYING, DISTRIBUTION AND MODIFICATION + + 0. This License applies to any program or other work which contains +a notice placed by the copyright holder saying it may be distributed +under the terms of this General Public License. The "Program", below, +refers to any such program or work, and a "work based on the Program" +means either the Program or any derivative work under copyright law: +that is to say, a work containing the Program or a portion of it, +either verbatim or with modifications and/or translated into another +language. (Hereinafter, translation is included without limitation in +the term "modification".) Each licensee is addressed as "you". + +Activities other than copying, distribution and modification are not +covered by this License; they are outside its scope. The act of +running the Program is not restricted, and the output from the Program +is covered only if its contents constitute a work based on the +Program (independent of having been made by running the Program). +Whether that is true depends on what the Program does. + + 1. You may copy and distribute verbatim copies of the Program's +source code as you receive it, in any medium, provided that you +conspicuously and appropriately publish on each copy an appropriate +copyright notice and disclaimer of warranty; keep intact all the +notices that refer to this License and to the absence of any warranty; +and give any other recipients of the Program a copy of this License +along with the Program. + +You may charge a fee for the physical act of transferring a copy, and +you may at your option offer warranty protection in exchange for a fee. + + 2. You may modify your copy or copies of the Program or any portion +of it, thus forming a work based on the Program, and copy and +distribute such modifications or work under the terms of Section 1 +above, provided that you also meet all of these conditions: + + a) You must cause the modified files to carry prominent notices + stating that you changed the files and the date of any change. + + b) You must cause any work that you distribute or publish, that in + whole or in part contains or is derived from the Program or any + part thereof, to be licensed as a whole at no charge to all third + parties under the terms of this License. + + c) If the modified program normally reads commands interactively + when run, you must cause it, when started running for such + interactive use in the most ordinary way, to print or display an + announcement including an appropriate copyright notice and a + notice that there is no warranty (or else, saying that you provide + a warranty) and that users may redistribute the program under + these conditions, and telling the user how to view a copy of this + License. (Exception: if the Program itself is interactive but + does not normally print such an announcement, your work based on + the Program is not required to print an announcement.) + +These requirements apply to the modified work as a whole. If +identifiable sections of that work are not derived from the Program, +and can be reasonably considered independent and separate works in +themselves, then this License, and its terms, do not apply to those +sections when you distribute them as separate works. But when you +distribute the same sections as part of a whole which is a work based +on the Program, the distribution of the whole must be on the terms of +this License, whose permissions for other licensees extend to the +entire whole, and thus to each and every part regardless of who wrote it. + +Thus, it is not the intent of this section to claim rights or contest +your rights to work written entirely by you; rather, the intent is to +exercise the right to control the distribution of derivative or +collective works based on the Program. + +In addition, mere aggregation of another work not based on the Program +with the Program (or with a work based on the Program) on a volume of +a storage or distribution medium does not bring the other work under +the scope of this License. + + 3. You may copy and distribute the Program (or a work based on it, +under Section 2) in object code or executable form under the terms of +Sections 1 and 2 above provided that you also do one of the following: + + a) Accompany it with the complete corresponding machine-readable + source code, which must be distributed under the terms of Sections + 1 and 2 above on a medium customarily used for software interchange; or, + + b) Accompany it with a written offer, valid for at least three + years, to give any third party, for a charge no more than your + cost of physically performing source distribution, a complete + machine-readable copy of the corresponding source code, to be + distributed under the terms of Sections 1 and 2 above on a medium + customarily used for software interchange; or, + + c) Accompany it with the information you received as to the offer + to distribute corresponding source code. (This alternative is + allowed only for noncommercial distribution and only if you + received the program in object code or executable form with such + an offer, in accord with Subsection b above.) + +The source code for a work means the preferred form of the work for +making modifications to it. For an executable work, complete source +code means all the source code for all modules it contains, plus any +associated interface definition files, plus the scripts used to +control compilation and installation of the executable. However, as a +special exception, the source code distributed need not include +anything that is normally distributed (in either source or binary +form) with the major components (compiler, kernel, and so on) of the +operating system on which the executable runs, unless that component +itself accompanies the executable. + +If distribution of executable or object code is made by offering +access to copy from a designated place, then offering equivalent +access to copy the source code from the same place counts as +distribution of the source code, even though third parties are not +compelled to copy the source along with the object code. + + 4. You may not copy, modify, sublicense, or distribute the Program +except as expressly provided under this License. Any attempt +otherwise to copy, modify, sublicense or distribute the Program is +void, and will automatically terminate your rights under this License. +However, parties who have received copies, or rights, from you under +this License will not have their licenses terminated so long as such +parties remain in full compliance. + + 5. You are not required to accept this License, since you have not +signed it. However, nothing else grants you permission to modify or +distribute the Program or its derivative works. These actions are +prohibited by law if you do not accept this License. Therefore, by +modifying or distributing the Program (or any work based on the +Program), you indicate your acceptance of this License to do so, and +all its terms and conditions for copying, distributing or modifying +the Program or works based on it. + + 6. Each time you redistribute the Program (or any work based on the +Program), the recipient automatically receives a license from the +original licensor to copy, distribute or modify the Program subject to +these terms and conditions. You may not impose any further +restrictions on the recipients' exercise of the rights granted herein. +You are not responsible for enforcing compliance by third parties to +this License. + + 7. If, as a consequence of a court judgment or allegation of patent +infringement or for any other reason (not limited to patent issues), +conditions are imposed on you (whether by court order, agreement or +otherwise) that contradict the conditions of this License, they do not +excuse you from the conditions of this License. If you cannot +distribute so as to satisfy simultaneously your obligations under this +License and any other pertinent obligations, then as a consequence you +may not distribute the Program at all. For example, if a patent +license would not permit royalty-free redistribution of the Program by +all those who receive copies directly or indirectly through you, then +the only way you could satisfy both it and this License would be to +refrain entirely from distribution of the Program. + +If any portion of this section is held invalid or unenforceable under +any particular circumstance, the balance of the section is intended to +apply and the section as a whole is intended to apply in other +circumstances. + +It is not the purpose of this section to induce you to infringe any +patents or other property right claims or to contest validity of any +such claims; this section has the sole purpose of protecting the +integrity of the free software distribution system, which is +implemented by public license practices. Many people have made +generous contributions to the wide range of software distributed +through that system in reliance on consistent application of that +system; it is up to the author/donor to decide if he or she is willing +to distribute software through any other system and a licensee cannot +impose that choice. + +This section is intended to make thoroughly clear what is believed to +be a consequence of the rest of this License. + + 8. If the distribution and/or use of the Program is restricted in +certain countries either by patents or by copyrighted interfaces, the +original copyright holder who places the Program under this License +may add an explicit geographical distribution limitation excluding +those countries, so that distribution is permitted only in or among +countries not thus excluded. In such case, this License incorporates +the limitation as if written in the body of this License. + + 9. The Free Software Foundation may publish revised and/or new versions +of the General Public License from time to time. Such new versions will +be similar in spirit to the present version, but may differ in detail to +address new problems or concerns. + +Each version is given a distinguishing version number. If the Program +specifies a version number of this License which applies to it and "any +later version", you have the option of following the terms and conditions +either of that version or of any later version published by the Free +Software Foundation. If the Program does not specify a version number of +this License, you may choose any version ever published by the Free Software +Foundation. + + 10. If you wish to incorporate parts of the Program into other free +programs whose distribution conditions are different, write to the author +to ask for permission. For software which is copyrighted by the Free +Software Foundation, write to the Free Software Foundation; we sometimes +make exceptions for this. Our decision will be guided by the two goals +of preserving the free status of all derivatives of our free software and +of promoting the sharing and reuse of software generally. + + NO WARRANTY + + 11. BECAUSE THE PROGRAM IS LICENSED FREE OF CHARGE, THERE IS NO WARRANTY +FOR THE PROGRAM, TO THE EXTENT PERMITTED BY APPLICABLE LAW. EXCEPT WHEN +OTHERWISE STATED IN WRITING THE COPYRIGHT HOLDERS AND/OR OTHER PARTIES +PROVIDE THE PROGRAM "AS IS" WITHOUT WARRANTY OF ANY KIND, EITHER EXPRESSED +OR IMPLIED, INCLUDING, BUT NOT LIMITED TO, THE IMPLIED WARRANTIES OF +MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE. THE ENTIRE RISK AS +TO THE QUALITY AND PERFORMANCE OF THE PROGRAM IS WITH YOU. SHOULD THE +PROGRAM PROVE DEFECTIVE, YOU ASSUME THE COST OF ALL NECESSARY SERVICING, +REPAIR OR CORRECTION. + + 12. IN NO EVENT UNLESS REQUIRED BY APPLICABLE LAW OR AGREED TO IN WRITING +WILL ANY COPYRIGHT HOLDER, OR ANY OTHER PARTY WHO MAY MODIFY AND/OR +REDISTRIBUTE THE PROGRAM AS PERMITTED ABOVE, BE LIABLE TO YOU FOR DAMAGES, +INCLUDING ANY GENERAL, SPECIAL, INCIDENTAL OR CONSEQUENTIAL DAMAGES ARISING +OUT OF THE USE OR INABILITY TO USE THE PROGRAM (INCLUDING BUT NOT LIMITED +TO LOSS OF DATA OR DATA BEING RENDERED INACCURATE OR LOSSES SUSTAINED BY +YOU OR THIRD PARTIES OR A FAILURE OF THE PROGRAM TO OPERATE WITH ANY OTHER +PROGRAMS), EVEN IF SUCH HOLDER OR OTHER PARTY HAS BEEN ADVISED OF THE +POSSIBILITY OF SUCH DAMAGES. + + END OF TERMS AND CONDITIONS + + How to Apply These Terms to Your New Programs + + If you develop a new program, and you want it to be of the greatest +possible use to the public, the best way to achieve this is to make it +free software which everyone can redistribute and change under these terms. + + To do so, attach the following notices to the program. It is safest +to attach them to the start of each source file to most effectively +convey the exclusion of warranty; and each file should have at least +the "copyright" line and a pointer to where the full notice is found. + + {description} + Copyright (C) {year} {fullname} + + This program is free software; you can redistribute it and/or modify + it under the terms of the GNU General Public License as published by + the Free Software Foundation; either version 2 of the License, or + (at your option) any later version. + + This program is distributed in the hope that it will be useful, + but WITHOUT ANY WARRANTY; without even the implied warranty of + MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + GNU General Public License for more details. + + You should have received a copy of the GNU General Public License along + with this program; if not, write to the Free Software Foundation, Inc., + 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA. + +Also add information on how to contact you by electronic and paper mail. + +If the program is interactive, make it output a short notice like this +when it starts in an interactive mode: + + Gnomovision version 69, Copyright (C) year name of author + Gnomovision comes with ABSOLUTELY NO WARRANTY; for details type `show w'. + This is free software, and you are welcome to redistribute it + under certain conditions; type `show c' for details. + +The hypothetical commands `show w' and `show c' should show the appropriate +parts of the General Public License. Of course, the commands you use may +be called something other than `show w' and `show c'; they could even be +mouse-clicks or menu items--whatever suits your program. + +You should also get your employer (if you work as a programmer) or your +school, if any, to sign a "copyright disclaimer" for the program, if +necessary. Here is a sample; alter the names: + + Yoyodyne, Inc., hereby disclaims all copyright interest in the program + `Gnomovision' (which makes passes at compilers) written by James Hacker. + + {signature of Ty Coon}, 1 April 1989 + Ty Coon, President of Vice + +This General Public License does not permit incorporating your program into +proprietary programs. If your program is a subroutine library, you may +consider it more useful to permit linking proprietary applications with the +library. If this is what you want to do, use the GNU Lesser General +Public License instead of this License. + diff --git a/qemu/qboot/Dockerfile b/qemu/qboot/Dockerfile new file mode 100644 index 0000000..bfd6c75 --- /dev/null +++ b/qemu/qboot/Dockerfile @@ -0,0 +1,119 @@ +# qboot, stock and patched, for the firmware experiment in this directory. +# +# Not part of a release and not on the path to one. What it is for is answering whether a +# firmware other than SeaBIOS can run this machine at all, and then what it saves — see +# README.md beside this file, and `task boot:firmware`. +# +# ## Why this is a container and not a shell script +# +# The two binaries it produces are compared against each other in microseconds, so the +# compiler that produced them is part of the measurement. A script running on whatever gcc a +# developer happens to have makes "patched is 5 ms faster" a statement about two toolchains +# as much as about two firmwares. The same reason kernel/Dockerfile pins its Debian by digest +# and its archive by snapshot date applies here, and more sharply: firmware is 65 KiB of +# code where a single inlining decision is visible in the number. +# +# It also removes the freestanding-i386 prerequisite from the host. `gcc -m32 -ffreestanding` +# needs 32-bit code generation compiled into the compiler, which is not a thing every +# distribution's gcc has, and the failure is a wall of assembler errors rather than a missing +# package. +# +# The same pinned toolchain as the kernel, deliberately: one Debian to think about rather +# than two, and moving it is one decision. It does not have to be the kernel's — nothing +# here enters a fingerprint, because nothing here ships — but there is no reason for it to +# differ. +ARG DEBIAN_IMAGE=debian:trixie@sha256:f324c7ff54321e8d9c588493a20244965938ce0aa50bbd1022d38010e9ffc4b1 +ARG DEBIAN_SNAPSHOT=20260914T000000Z + +FROM ${DEBIAN_IMAGE} AS builder + +ARG DEBIAN_SNAPSHOT +ENV DEBIAN_FRONTEND=noninteractive + +RUN echo 'Binary::apt::APT::Keep-Downloaded-Packages "true";' > /etc/apt/apt.conf.d/keep-cache + +# The archive as it stood on DEBIAN_SNAPSHOT rather than the image's live mirrors, so the +# compiler is the same one next month. Valid-Until is off because a snapshot's Release files +# expire by design; the signatures are still checked, and they are what makes plain http +# enough — it has to be http, since the image carries no CA certificates until +# ca-certificates is installed from this very archive. +RUN rm -f /etc/apt/sources.list.d/debian.sources && cat > /etc/apt/sources.list.d/snapshot.sources < upstream.tar && \ + echo "${QBOOT_ARCHIVE_SHA256} upstream.tar" | sha256sum -c - + +COPY qemu/qboot/write-pointer.patch /build/write-pointer.patch + +# Both variants from one tar and one compiler. The flags are upstream's meson.build, with -Os +# fixed rather than taken from a build type: two firmwares compiled at different optimisation +# levels are not a comparison of two firmwares. +RUN set -eux; \ + for variant in stock patched; do \ + rm -rf "src-$variant"; mkdir -p "src-$variant" "out/$variant"; \ + tar -xf upstream.tar -C "src-$variant"; \ + if [ "$variant" = patched ]; then \ + patch -p1 -d "src-$variant" < write-pointer.patch; \ + fi; \ + cd "src-$variant"; \ + for f in *.c *.S; do \ + gcc -Os -m32 -march=i386 -mregparm=3 -fno-stack-protector \ + -fno-delete-null-pointer-checks -ffreestanding \ + -mstringop-strategy=rep_byte -minline-all-stringops -fno-pic \ + -Iinclude -c "$f" -o "/build/out/$variant/${f%.*}.o"; \ + done; \ + gcc -nostdlib -m32 -no-pie -Wl,--build-id=none -Wl,-Tflat.lds \ + "/build/out/$variant/"*.o -o "/build/out/$variant/bios.bin.elf"; \ + objcopy -O binary "/build/out/$variant/bios.bin.elf" "/build/out/$variant/bios.bin"; \ + cd /build; \ + done + +# Asserted on what came out, not on the build having exited 0. +# +# A patch that applies to nothing still leaves a compilable tree, and two identical binaries +# would make the probe report a 0 ms difference and look like a finding. The size is checked +# because objcopy of a linker script gone wrong produces a file, and a firmware that is not +# the size the ROM window expects does not fail at build time — it fails as a guest that +# prints nothing, which is indistinguishable from the bug this experiment is about. +RUN set -eux; \ + for variant in stock patched; do \ + test -s "out/$variant/bios.bin"; \ + size=$(stat -c%s "out/$variant/bios.bin"); \ + test "$size" -eq 65536 || { echo "out/$variant/bios.bin is $size bytes, not 65536" >&2; exit 1; }; \ + done; \ + if cmp -s out/stock/bios.bin out/patched/bios.bin; then \ + echo "stock and patched are byte-identical: the patch changed nothing that compiled" >&2; \ + exit 1; \ + fi; \ + sha256sum out/stock/bios.bin out/patched/bios.bin + +FROM scratch AS extract +COPY --from=builder /build/out/stock/bios.bin /stock/bios.bin +COPY --from=builder /build/out/patched/bios.bin /patched/bios.bin diff --git a/qemu/qboot/README.md b/qemu/qboot/README.md new file mode 100644 index 0000000..e99e10f --- /dev/null +++ b/qemu/qboot/README.md @@ -0,0 +1,102 @@ +# qboot WRITE_POINTER experiment + +qboot at `8ca302e86d685fa05b16e2b208888243da319941` stops in its ACPI loader when +q35 supplies the WRITE_POINTER command needed by vmgenid. The patch adds that +command and fw_cfg DMA writes. The pointer payload is little-endian; the DMA +descriptor is big-endian. A destination offset is applied with SELECT+SKIP before +WRITE. Invalid pointer widths, missing/unallocated sources, out-of-bounds writes, +missing DMA and DMA errors fail rather than silently losing the vmgenid address. +The destination is a writable fw_cfg file, not a guest allocation. + +Protocol references: +[QEMU fw_cfg](https://www.qemu.org/docs/master/specs/fw_cfg.html) and +[the ACPI linker loader](https://github.com/qemu/qemu/blob/master/hw/acpi/bios-linker-loader.c). +The patch is GPL-2.0, like upstream; see COPYING and the repository NOTICE. + +## Reproduce + +```sh +task qemu:qboot +``` + +Both variants land in `_output/qboot/{stock,patched}/bios.bin`. The build is +`qemu/qboot/Dockerfile`, which clones the pinned commit, verifies the SHA-256 of the +tar `git archive` writes for it, and compiles both variants with one compiler and +upstream's meson.build flags plus `-Os`. It asserts on what came out — both 65536 +bytes, and not byte-identical to each other, since a patch that applied to nothing +still leaves a tree that compiles. It does not rebuild QEMU or touch a release tree, +and nothing in a release comes from it. + +It is a container for the same reason `kernel/Dockerfile` is: the compiler is part of +the measurement. That is not a hypothetical here — see the toolchain note below. + +The probe is `TestFirmwareCost` in `boot/firmware_test.go`, beside the rest of the +boot measurement harness and sharing its release discovery, its percentiles and its +interleaving. It requires KVM and a caller-supplied diagnostic initrd. That `/init` +must mount proc, print dmesg lines containing `vmgenid` and then `SPIN-READY`, stay +alive, and keep printing new dmesg output so the host sees the reseed after restore. +The initrd is diagnostic input, not an artifact built or shipped by this repository: +what runs as PID 1 is the caller's business. Use the same initrd for both firmware +variants — its own CPU and memory work lands in every number. + +```sh +task boot:firmware \ + SPIN_QBOOT_STOCK=/tmp/qboot-build/stock/bios.bin \ + SPIN_QBOOT_PATCHED=/tmp/qboot-build/patched/bios.bin \ + SPIN_PROBE_INITRD=/path/to/diagnostic.cpio +``` + +SeaBIOS, QEMU and the kernel come from `_output/`, so there are three paths to pass +rather than eight. With any of the three unset the test says which and skips: none of +them is an artefact a release carries. + +The probe checks the control boot without vmgenid, the stock timeout with vmgenid, +and the patched boot. The stock hang is asserted rather than tolerated: a stock qboot +that booted with vmgenid would mean the WRITE_POINTER story is wrong and every timing +after it measures something else. It saves the patched guest, restores into a new QEMU +with `guid=auto`, waits for incoming migration to finish before `cont`, and requires +`crng reseeded due to virtual machine fork` in the restored guest's log. Then it +interleaves SeaBIOS and patched boots and prints p50, p95 and the difference. + +## Measurements, 2026-09-21 + +QEMU 11.1.1, KVM, i9-13900HK, q35 with SATA and SMBus disabled, 2 vCPUs, +2 GiB, CPU host, no disks or NICs, vmgenid present. The diagnostic initrd used a +static BusyBox and printed the marker after mounting proc/sysfs and filtering +dmesg. No cache dropping or warmup phase; 20 boots per firmware per run for the +first two rows and 10 for the third, interleaved, host wall clock before spawning +QEMU to receipt of SPIN-READY. These are diagnostic init timings, not PVH-entry, +systemd readiness, SSH, or full machine topology measurements. + +| Run | Firmware built by | SeaBIOS p50 / p95 | Patched qboot p50 / p95 | p50 reduction | +|---|---|---|---|---| +| Initial | host GCC 15.2.0 | 101.32 / 112.25 ms | 96.50 / 105.25 ms | 4.83 ms | +| Rebuilt using checked-in recipe and probe | host GCC 15.2.0 | 100.89 / 107.40 ms | 94.57 / 101.68 ms | 6.32 ms | +| Containerised recipe, 10 boots, 2026-09-26 | Debian 14.2.0 in `Dockerfile` | 98.43 / 100.41 ms | 94.57 / 97.62 ms | 3.86 ms | + +All three reproduced the original stall and observed reseeding after restoration. Raw +samples and artifact hashes for the first two are in `measurements.json`. + +## The toolchain is part of the number + +The first two rows were built by whatever GCC the host had — 15.2.0 — and produced +`7a316e3c…` for the patched binary. `Dockerfile` pins Debian trixie, whose GCC is +14.2.0, and produces `bf7ddddc…`. Same commit, same patch, same flags, different +compiler, and the saving moved from 6.32 ms to 3.86 ms: **the compiler accounts for +more of the difference than a third of what qboot itself saves.** + +This is the same result the SeaBIOS experiment recorded in `boot/phases.go` — two +builds of one firmware differing by as much as the change being measured — and it is +why the recipe is pinned rather than convenient. It also means a number in this file +is only comparable to another number built the same way, and the third row is the only +one that can be reproduced from the repository as it stands. + +The 3.9–6.3 ms observed reduction is useful but is not evidence of a larger saving in a +complete userspace boot: measured against this machine's real boot, the firmware is +about 10 ms of a few hundred. + +Before selecting qboot for a release, verify the full device topology, CPU/memory +hotplug, reset, and systemd/SSH readiness. Firmware contents are currently absent +from Spec.Fingerprint: supporting a selectable firmware requires including them +in machine identity, otherwise two different firmware builds could match templates. +Keep the existing SeaBIOS release unchanged until those parts are handled. diff --git a/qemu/qboot/measurements.json b/qemu/qboot/measurements.json new file mode 100644 index 0000000..05e190a --- /dev/null +++ b/qemu/qboot/measurements.json @@ -0,0 +1,103 @@ +{ + "date": "2026-09-21", + "unit": "milliseconds", + "sha256": { + "qemu": "a135a0fd89360f8ffdef7e236ce66569d165de3b775c6b6e45350d9d2514290c", + "kernel": "701d1e83197df124a11d45cc3c1a47311cf35a487f163d8132f5af7c38062e71", + "seabios": "e26615f9ad430328f49ca105e570b2dc4490a08a34ea73d27cae8b809a30ee06", + "qboot": "7a316e3c29b2e0b849376f6c5b37074ca9fb984d88d3045e934ebbc5737cc2ed", + "initrd": "6f8cf8c0e670de2f13f7c21eb1cdcea3a652b26c9afbfdc0f0805b33c5a51d4d" + }, + "initial": { + "seabios": [ + 102.35880105756223, + 112.25439293775707, + 100.28889798559248, + 102.86838398315012, + 106.50323098525405, + 95.72425403166562, + 103.96376601420343, + 98.84804906323552, + 95.40718595962971, + 95.57203890290111, + 96.29417199175805, + 102.55006595980376, + 97.11084398441017, + 104.83874299097806, + 104.32299203239381, + 104.44100107997656, + 95.78418591991067, + 99.08312698826194, + 112.93924308847636, + 100.08574498351663 + ], + "patched": [ + 105.25433393195271, + 104.18533394113183, + 95.48435593023896, + 92.9054650478065, + 100.82862700801343, + 106.84246802702546, + 91.82357206009328, + 92.10725710727274, + 98.81736896932125, + 97.9178820271045, + 95.58443701826036, + 98.44549710396677, + 89.6216289838776, + 97.40561689250171, + 99.78291497100145, + 101.97925101965666, + 92.17968105804175, + 95.42261098977178, + 95.19110899418592, + 92.55115292035043 + ] + }, + "reproduced": { + "seabios": [ + 101.16701200604439, + 103.21687301620841, + 107.40157507825643, + 98.19312707986683, + 99.13265891373158, + 98.06142502930015, + 106.07362200971693, + 100.60387197881937, + 95.82762001082301, + 104.51311303768307, + 97.46884589549154, + 104.29908195510507, + 102.68541902769357, + 108.04147704038769, + 95.84080509375781, + 100.32242396846414, + 104.31455611251295, + 103.8352029863745, + 98.56852795928717, + 95.68912896793336 + ], + "patched": [ + 97.24596794694662, + 99.0585049148649, + 100.83345102611929, + 94.59814697038382, + 94.47652101516724, + 95.54792603012174, + 93.29728805460036, + 100.17871099989861, + 92.76608400978148, + 91.13843296654522, + 90.2360409963876, + 101.68317402713001, + 93.5989060672, + 93.3470360469073, + 95.62408505007625, + 95.18794994801283, + 109.41709589678794, + 94.53495510388166, + 91.33945091161877, + 93.85259903501719 + ] + } +} diff --git a/qemu/qboot/write-pointer.patch b/qemu/qboot/write-pointer.patch new file mode 100644 index 0000000..9cab92f --- /dev/null +++ b/qemu/qboot/write-pointer.patch @@ -0,0 +1,116 @@ +diff --git a/fw_cfg.c b/fw_cfg.c +index f3d9605..a3df595 100644 +--- a/fw_cfg.c ++++ b/fw_cfg.c +@@ -108,6 +108,24 @@ void fw_cfg_dma(int control, void *buf, int len) + while (bswap32(dma.control) & ~FW_CFG_DMA_CTL_ERROR) { + asm(""); + } ++ if (bswap32(dma.control) & FW_CFG_DMA_CTL_ERROR) ++ panic(); ++} ++ ++void fw_cfg_write_file(int id, uint32_t offset, void *buf, int len) ++{ ++ uint32_t control; ++ ++ /* Modern fw_cfg accepts writes only through DMA. */ ++ if (!(version & FW_CFG_VERSION_DMA) || id < 0 || id >= filecnt || ++ len < 0 || offset > files[id].size || len > files[id].size - offset) ++ panic(); ++ control = ((uint32_t)files[id].select << 16) | FW_CFG_DMA_CTL_SELECT; ++ if (offset) { ++ fw_cfg_dma(control | FW_CFG_DMA_CTL_SKIP, NULL, offset); ++ control = 0; ++ } ++ fw_cfg_dma(control | FW_CFG_DMA_CTL_WRITE, buf, len); + } + + void fw_cfg_read(void *buf, int len) +diff --git a/include/fw_cfg.h b/include/fw_cfg.h +index 1ddfc1f..625aad4 100644 +--- a/include/fw_cfg.h ++++ b/include/fw_cfg.h +@@ -43,6 +43,7 @@ + #define FW_CFG_DMA_CTL_READ 0x02 + #define FW_CFG_DMA_CTL_SKIP 0x04 + #define FW_CFG_DMA_CTL_SELECT 0x08 ++#define FW_CFG_DMA_CTL_WRITE 0x10 + + #define FW_CFG_CTL 0x510 + #define FW_CFG_DATA 0x511 +@@ -116,5 +117,6 @@ void fw_cfg_read(void *buf, int len); + void fw_cfg_read_entry(int e, void *buf, int len); + void fw_cfg_dma(int control, void *buf, int len); + void fw_cfg_read_file(int e, void *buf, int len); ++void fw_cfg_write_file(int id, uint32_t offset, void *buf, int len); + + #endif +diff --git a/tables.c b/tables.c +index 9934a91..dee0ede 100644 +--- a/tables.c ++++ b/tables.c +@@ -30,6 +30,14 @@ struct loader_cmd { + uint32_t start; + uint32_t len; + } checksum; ++#define CMD_WRITE_PTR 4 ++ struct { ++ char dest[56]; ++ char src[56]; ++ uint32_t dest_offset; ++ uint32_t src_offset; ++ uint8_t size; ++ } write_ptr; + uint8_t pad[124]; + }; + } __attribute__((__packed__)); +@@ -43,14 +51,36 @@ static uint8_t *file_address[20]; + + static inline void *id_to_addr(int fw_cfg_id) + { ++ if (fw_cfg_id < 0 || fw_cfg_id >= ARRAY_SIZE(file_address)) ++ panic(); + return file_address[fw_cfg_id]; + } + + static inline void set_file_addr(int fw_cfg_id, void *p) + { ++ if (fw_cfg_id < 0 || fw_cfg_id >= ARRAY_SIZE(file_address)) ++ panic(); + file_address[fw_cfg_id] = p; + } + ++static void do_write_ptr(char *dest, char *src, uint32_t dest_offset, ++ uint32_t src_offset, uint8_t size) ++{ ++ int source = fw_cfg_file_id(src); ++ int destination = fw_cfg_file_id(dest); ++ uint8_t *p = id_to_addr(source); ++ uint64_t address; ++ ++ if (!p || src_offset >= fw_cfg_file_size(source) || ++ (size != 1 && size != 2 && size != 4 && size != 8)) ++ panic(); ++ address = (uint64_t)(uintptr_t)p + src_offset; ++ if (size < 8 && address >> (size * 8)) ++ panic(); ++ /* The pointer is little-endian; the DMA descriptor is big-endian. */ ++ fw_cfg_write_file(destination, dest_offset, &address, size); ++} ++ + static void do_alloc(char *file, uint32_t align, uint8_t zone) + { + int id = fw_cfg_file_id(file); +@@ -152,6 +182,11 @@ void extract_acpi(void) + break; + case CMD_QUIT: + return; ++ case CMD_WRITE_PTR: ++ do_write_ptr(s->write_ptr.dest, s->write_ptr.src, ++ s->write_ptr.dest_offset, s->write_ptr.src_offset, ++ s->write_ptr.size); ++ break; + default: + panic(); + } From 1d56d76096ceb23d8d2896e03edc69afb059eee9 Mon Sep 17 00:00:00 2001 From: Manuel de Brito Fontes Date: Sat, 26 Sep 2026 11:53:37 -0300 Subject: [PATCH 02/18] boot: where the kernel's own boot goes, initcall by initcall MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The kernel is the largest block in a cold boot after early userspace, and there was no breakdown of it, only a total. Getting one is not as simple as turning initcall_debug on, and the two ways it goes wrong are both silent. The first is the console. With the messages going to a serial port, every one is a VM exit inside the interval being reported, so a gap between two adjacent stamps is mostly the cost of printing the one before it and the biggest gap is wherever the most was printed. This boots with the console quiet and reads the ring buffer afterwards: `quiet` raises the console's threshold and does not touch what printk stores, and initcall_debug's two lines are KERN_DEBUG printks either way. The second is how the buffer gets out. The obvious unit — StandardOutput=journal+ console — routes the dump through the journal, which forwards it to the kernel log, so every reprinted line arrives carrying a second, fresh stamp: [ 0.199752] sh[106]: [ 0.007375] IOAPIC[0]: apic_id 0, version 17, … A parser reading the first stamp then reads the clock of the dump. The initcall durations stay right, because those are text, and every timestamp-derived number silently describes how long the console took to print a megabyte. It reported the kernel reaching "Freeing unused kernel image" at 931 ms on a machine that boots in about 200, which is the only reason it was caught. The dump now goes straight to /dev/ttyS0, and a line carrying two stamps fails the test rather than being averaged into it. Everything is a p50 with a p95 beside it, because one boot is not a measurement: three consecutive runs on one busy host read 59.5, 96.8 and 167.7 ms for the same kernel. log_buf_len is 2M and not 8M for the same reason the console is quiet — 8M allocates 37 MB and cost 4.9 ms of the thing being measured. Gaps are keyed by the message after them with pids normalised away, because the largest gap in this machine's boot came out as two entries with half the samples each when journald's pid differed between runs. What it says, p50 over 12 boots: 98.2 ms from kernel start to "Freeing unused kernel image", 54.5 of it in 680 initcalls and 35.9 outside them, with the top ten initcalls accounting for 84% of the initcall time. acpi_init is 14.0 ms and inet_init 8.7, and neither can be a module. And the largest gap in the whole boot is not in the kernel at all: 115-144 ms between the kernel handing over and journald's first line. Co-Authored-By: Claude Opus 5 (1M context) --- Taskfile.yml | 9 + boot/initcalls_test.go | 369 +++++++++++++++++++++++++++++++++++++++++ 2 files changed, 378 insertions(+) create mode 100644 boot/initcalls_test.go diff --git a/Taskfile.yml b/Taskfile.yml index e26c040..3439b9c 100644 --- a/Taskfile.yml +++ b/Taskfile.yml @@ -202,6 +202,15 @@ tasks: cmds: - SPIN_LOGIND_TEST=1 go test ./boot/ -run '^TestLogindSessions$' -count=1 -v -timeout 5m + boot:initcalls: + desc: >- + Where the kernel's own boot goes, initcall by initcall, as a p50 over REPS boots. + Needs KVM, a built release and sudo. It boots with the console silent and reads the + ring buffer afterwards, because initcall_debug on a serial console puts a VM exit + inside every interval it reports. TOP= how many rows, REPS= how many boots. + cmds: + - SPIN_INITCALL_PROBE=1 go test ./boot/ -run TestKernelInitcalls -count=1 -v -timeout 30m + boot:firmware: desc: >- Compare firmware for this machine: SeaBIOS against the qboot build in qemu/qboot/. diff --git a/boot/initcalls_test.go b/boot/initcalls_test.go new file mode 100644 index 0000000..80f515b --- /dev/null +++ b/boot/initcalls_test.go @@ -0,0 +1,369 @@ +// SPDX-License-Identifier: Apache-2.0 + +package boot_test + +import ( + "fmt" + "os" + "os/exec" + "path/filepath" + "regexp" + "sort" + "strconv" + "strings" + "syscall" + "testing" + "time" +) + +// Where the kernel's own boot goes, initcall by initcall. +// +// The kernel is the largest single block in a cold boot — far larger than the firmware and +// larger than everything before it put together — and until this existed there was no +// breakdown of it, only a total. What made that hard is that the obvious way to get one is +// wrong: `initcall_debug` with the messages on the console puts a serial write, and a VM +// exit, inside every interval it reports. A gap between two adjacent timestamps then +// includes the cost of printing the line before it, and the numbers come out inflated in +// proportion to how much is being printed — which is exactly the thing being measured. +// +// So the console stays quiet for the whole boot and the ring buffer is read afterwards. +// `quiet` raises the console's threshold and does not touch what printk stores, and +// initcall_debug's two lines are KERN_DEBUG printks from init/main.c's trace callbacks, so +// they are in the buffer either way. A unit ordered after multi-user.target then prints the +// buffer once, after the part being measured is over. +// +// One boot is not a measurement. The same machine on the same host read 59.5, 96.8 and +// 167.7 ms for the kernel's own boot in three consecutive runs, because the host was busy, +// 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. +// +// SPIN_INITCALL_PROBE=1 run at all +// REPS= boots to take (default 10) +// TOP= how many initcalls to print (default 30) +func TestKernelInitcalls(t *testing.T) { + if os.Getenv("SPIN_INITCALL_PROBE") == "" { + t.Skip("set SPIN_INITCALL_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") + } + top := envInt(t, "TOP", 30) + reps := envInt(t, "REPS", 10) + + // Redirected to /dev/ttyS0 inside the shell, with StandardOutput=null, and that detail + // is the whole measurement. + // + // The obvious form — StandardOutput=journal+console — routes the dump through the + // journal, which forwards it to the kernel log, so every reprinted line arrives on the + // console carrying a *second*, fresh stamp: + // + // [ 0.199752] sh[106]: [ 0.007375] IOAPIC[0]: apic_id 0, version 17, … + // + // A parser reading the first stamp on the line then reads the clock of the dump instead + // of the clock of the boot. It does not look like a failure: the initcall durations are + // still right, because those are text, and every number derived from a timestamp is + // silently describing how long the console took to print a megabyte. It reported the + // kernel reaching "Freeing unused kernel image" at 931 ms on a machine that boots in + // about 200, which is the only reason it was caught. + const dump = `[Unit] +Description=Print the kernel ring buffer for the initcall probe +After=multi-user.target +[Service] +Type=oneshot +StandardOutput=null +ExecStart=/bin/sh -c "{ echo SPIN-DMESG-BEGIN; dmesg; echo SPIN-DMESG-END; } > /dev/ttyS0" +[Install] +WantedBy=multi-user.target +` + v := variant{ + label: "initcalls", cpus: "2", memory: "2048", + // log_buf_len because initcall_debug is two lines per initcall and the default ring + // wraps: a wrapped buffer loses the early initcalls, which are the interesting ones. + extra: "initcall_debug log_buf_len=2M", + files: map[string]string{ + "/etc/systemd/system/spin-dmesg.service": dump, + }, + links: map[string]string{ + "/etc/systemd/system/multi-user.target.wants/spin-dmesg.service": "/etc/systemd/system/spin-dmesg.service", + }, + } + + runs := make([]parsed, 0, reps) + for i := range reps { + console := bootUntil(t, out, v, "SPIN-DMESG-END", 90*time.Second) + // The raw buffer of the first boot, for a question this report does not answer yet. + // Written only when asked: a test that drops a megabyte in the working directory on + // every run is a test people stop running. + if f := os.Getenv("SPIN_CONSOLE_OUT"); f != "" && i == 0 { + if err := os.WriteFile(f, []byte(console), 0o644); err != nil { + t.Fatalf("writing the console to %s: %v", f, err) + } + t.Logf("raw console of the first boot written to %s", f) + } + runs = append(runs, parse(t, console)) + } + report(t, runs, top, reps) +} + +// bootUntil boots one machine and returns its console once marker has appeared. +// +// Separate from bootOnce because that one stops at a login prompt, which is the right place +// to stop when a boot time is what is wanted and the wrong one here: everything this reads +// is printed after it. +func bootUntil(t *testing.T, out string, v variant, marker string, timeout time.Duration) string { + t.Helper() + 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) + + cmdline := "root=/dev/vda rw init=/sbin/init" + if v.extra != "" { + cmdline += " " + v.extra + } + 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", cmdline) + cmd.SysProcAttr = &syscall.SysProcAttr{Setpgid: true} + r, w, err := os.Pipe() + if err != nil { + t.Fatalf("console pipe: %v", err) + } + cmd.Stdout, cmd.Stderr = w, w + if err := cmd.Start(); err != nil { + t.Fatalf("launching the machine: %v", err) + } + _ = w.Close() + defer func() { + if pgid, err := syscall.Getpgid(cmd.Process.Pid); err == nil { + _ = syscall.Kill(-pgid, syscall.SIGKILL) + } + _ = cmd.Wait() + _ = r.Close() + }() + + deadline := time.Now().Add(timeout) + var b strings.Builder + buf := make([]byte, 65536) + for { + if err := r.SetReadDeadline(deadline); err != nil { + t.Fatalf("setting the console deadline: %v", err) + } + n, err := r.Read(buf) + b.Write(buf[:n]) + if strings.Contains(b.String(), marker) { + return b.String() + } + if err != nil { + t.Fatalf("never saw %q in %s; console tail:\n%s", + marker, timeout, tail([]byte(b.String()), 2000)) + } + } +} + +var ( + // [ 0.123456] initcall acpi_init+0x0/0x1a0 returned 0 after 1234 usecs + reDone = regexp.MustCompile(`initcall ([^ ]+) returned (-?\d+) after (\d+) usecs`) + // [ 1.234567] Freeing unused kernel image (initmem) memory: 2780K + reStamp = regexp.MustCompile(`^\[\s*(\d+)\.(\d{6})\]`) + // The same thing again further along the line, which means the dump was re-stamped on + // its way out and the first stamp belongs to the dump rather than to the boot. + reDouble = regexp.MustCompile(`^\[\s*\d+\.\d{6}\].*\[\s*\d+\.\d{6}\]`) + // A process id in a userspace line's prefix — `systemd-journald[62]:`. Gaps are keyed by + // the message on the far side of them, and a pid in that key splits one gap across as + // many buckets as the boot happened to hand out pids: the largest gap in this machine's + // boot, kernel handover to journald's first line, came out as two entries with half the + // samples each and no warning that it had. + rePID = regexp.MustCompile(`\[\d+\]:`) +) + +type initcall struct { + name string + us int + ret int +} + +// gap is the time between two adjacent ring-buffer stamps, and what was printed on either +// side of it. The messages are what make it usable: a duration on its own says there is +// 300 ms somewhere and not what the kernel was doing. +type gap struct { + ms float64 + after, before string +} + +func clip(s string) string { + if len(s) > 88 { + return s[:88] + } + return s +} + +// parsed is one boot's ring buffer, reduced. +type parsed struct { + calls map[string]int // initcall -> usecs + gaps map[string]gap // "before" message -> the gap ahead of it + total int // usecs in all initcalls + freeing float64 // seconds to "Freeing unused kernel image" +} + +func parse(t *testing.T, console string) parsed { + t.Helper() + out := parsed{calls: map[string]int{}, gaps: map[string]gap{}} + var prev float64 = -1 + var prevMsg string + for _, line := range strings.Split(console, "\n") { + if reDouble.MatchString(line) { + t.Fatalf("a console line carries two kernel stamps, so the dump is being "+ + "re-stamped on its way out and every timing here would be the console's "+ + "and not the boot's:\n%s", strings.TrimSpace(line)) + } + if m := reStamp.FindStringSubmatch(line); m != nil { + sec, _ := strconv.Atoi(m[1]) + us, _ := strconv.Atoi(m[2]) + at := float64(sec) + float64(us)/1e6 + msg := clip(rePID.ReplaceAllString(strings.TrimSpace(line[len(m[0]):]), "[]:")) + // Monotonic only: the dump reprints the buffer, and a reprint that went + // backwards would produce a negative gap and sort to the top. + if prev >= 0 && at >= prev { + out.gaps[msg] = gap{ms: (at - prev) * 1000, after: prevMsg, before: msg} + } + prev, prevMsg = at, msg + if strings.Contains(line, "Freeing unused kernel image") { + out.freeing = at + } + } + if m := reDone.FindStringSubmatch(line); m != nil { + us, _ := strconv.Atoi(m[3]) + out.calls[m[1]] = us + out.total += us + } + } + if len(out.calls) == 0 { + t.Fatalf("no initcall lines in the ring buffer; was initcall_debug on the command "+ + "line and log_buf_len large enough?\nconsole tail:\n%s", + tail([]byte(console), 2000)) + } + return out +} + +// report reduces every boot to a p50 and a p95, which is the only form these numbers are +// worth reading in. It prints two totals, and the second is the one that is easy to forget +// and usually the larger: memory init, SMP bringup, RCU and the scheduler are not initcalls, +// and no amount of making drivers modular reaches them. +func report(t *testing.T, runs []parsed, top, reps int) { + t.Helper() + var b strings.Builder + fmt.Fprintf(&b, "\nkernel boot, p50/p95 over %d boots\n\n", reps) + + totals := make([]float64, 0, len(runs)) + freeings := make([]float64, 0, len(runs)) + nonInit := make([]float64, 0, len(runs)) + for _, r := range runs { + totals = append(totals, float64(r.total)/1000) + if r.freeing > 0 { + freeings = append(freeings, r.freeing*1000) + nonInit = append(nonInit, r.freeing*1000-float64(r.total)/1000) + } + } + line := func(what string, xs []float64) { + sort.Float64s(xs) + fmt.Fprintf(&b, " %-44s %8.1f %8.1f ms\n", what, pct(xs, 50), pct(xs, 95)) + } + fmt.Fprintf(&b, " %-44s %8s %8s\n", "", "P50", "P95") + line("kernel start to \"Freeing unused kernel image\"", freeings) + line("in initcalls", totals) + line("not in initcalls", nonInit) + fmt.Fprintf(&b, "\n %d initcalls seen\n\n", countUnion(runs)) + + // Gaps, which is where the time that is not in an initcall actually is. Only + // trustworthy because the console was quiet for the whole boot: with the messages going + // to a serial port, a gap between two adjacent stamps is mostly the cost of printing + // the first one, and the biggest gap is wherever the most was printed. + type agg struct { + g gap + ms []float64 + } + byBefore := map[string]*agg{} + for _, r := range runs { + for k, g := range r.gaps { + a := byBefore[k] + if a == nil { + a = &agg{g: g} + byBefore[k] = a + } + a.ms = append(a.ms, g.ms) + } + } + ranked := make([]*agg, 0, len(byBefore)) + for _, a := range byBefore { + sort.Float64s(a.ms) + ranked = append(ranked, a) + } + sort.Slice(ranked, func(i, j int) bool { return pct(ranked[i].ms, 50) > pct(ranked[j].ms, 50) }) + fmt.Fprintf(&b, " %8s %8s %s\n", "GAP P50", "P95", "BETWEEN (ms)") + for i, a := range ranked { + if i >= top/2 { + break + } + fmt.Fprintf(&b, " %8.1f %8.1f after: %s\n %8s %8s before: %s\n", + pct(a.ms, 50), pct(a.ms, 95), a.g.after, "", "", a.g.before) + } + fmt.Fprintln(&b) + + // Initcalls, ranked by their own p50. + type ic struct { + name string + ms []float64 + } + byName := map[string]*ic{} + for _, r := range runs { + for n, us := range r.calls { + c := byName[n] + if c == nil { + c = &ic{name: n} + byName[n] = c + } + c.ms = append(c.ms, float64(us)/1000) + } + } + calls := make([]*ic, 0, len(byName)) + for _, c := range byName { + sort.Float64s(c.ms) + calls = append(calls, c) + } + sort.Slice(calls, func(i, j int) bool { return pct(calls[i].ms, 50) > pct(calls[j].ms, 50) }) + + fmt.Fprintf(&b, " %8s %8s %s\n", "P50", "P95", "INITCALL") + var all float64 + for _, c := range calls { + all += pct(c.ms, 50) + } + for i, c := range calls { + if i < top { + fmt.Fprintf(&b, " %8.2f %8.2f %s\n", pct(c.ms, 50), pct(c.ms, 95), c.name) + } + } + for _, n := range []int{10, 25, 50} { + if n > len(calls) { + continue + } + var c float64 + for i := 0; i < n; i++ { + c += pct(calls[i].ms, 50) + } + fmt.Fprintf(&b, "\n top %d initcalls: %.1f ms (%.0f%% of all initcall time)", n, c, 100*c/all) + } + t.Log(b.String() + "\n") +} + +func countUnion(runs []parsed) int { + seen := map[string]bool{} + for _, r := range runs { + for n := range r.calls { + seen[n] = true + } + } + return len(seen) +} From 301fe713bdbeeffb8985b844ebc88f01c3b58286 Mon Sep 17 00:00:00 2001 From: Manuel de Brito Fontes Date: Sat, 26 Sep 2026 12:15:46 -0300 Subject: [PATCH 03/18] boot: two probes for early userspace, and three ways it loses data MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `systemd-analyze` puts userspace at 139 ms against the kernel's 79, so the largest block in a cold boot is on the far side of the kernel. Nothing could see into it: the other probes read the kernel ring buffer, and the phase in question is before journald exists. boot:userspace asks systemd afterwards — its own kernel/userspace split, `blame` and the critical chain. Type=simple rather than oneshot, and that is not a style choice: startup is finished when every job of the initial transaction completes, a unit in multi-user.target.wants is one of those jobs, and as oneshot it 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 — so it looked like a flake rather than a deadlock. boot:systemd turns systemd's debug log on and ranks the gaps in it. Getting a whole log took three attempts, and each failure looked like an answer: - To the serial console, every line is a VM exit inside the phase being measured. - To kmsg, systemd rate-limits itself and says so in the log it is writing, so lines vanish in bursts — which is where a gap would be. - To the journal, journald's runtime cap is reached mid-boot and it vacuums the beginning, the part nothing else can see. It left 48 lines of some nine hundred, and a ranked list of gaps across 48 lines reads exactly like a finding. So it logs at debug to the journal with the runtime cap raised, and asserts the log is whole before ranking anything: it fails on the kmsg rate-limit message, on a vacuum that freed a non-zero amount, and on a suspiciously small line count. It also sorts by timestamp, because journalctl prints in arrival order and two writers' streams interleave — treating a backwards stamp as the end of the window ranked gaps over fifteen lines and called the largest gap in the boot 8.9 ms. What it says, one boot: 2368 tagged lines over 96.8 ms, systemd-udevd the largest writer at 34.5 ms with udevadm another 11.4, systemd itself 32.1, and udev reporting "Maximum number (14) of children reached" before a 4.5 ms gap. The bench gains two rows and both are negative results worth keeping. serial-getty@ ttyS0 carries BindsTo=dev-ttyS0.device and sits on the critical chain at 128 ms, so masking it and using the image's own device-independent console unit should have been free. It is 340 ms worse, and removing that unit's Type=idle does not bring it back. dev-ttyS0.device on the chain is when udev got to the port, not something the prompt waited for. Read a critical chain as what finished last. Co-Authored-By: Claude Opus 5 (1M context) --- Taskfile.yml | 18 +++ boot/bench_test.go | 58 ++++++++++ boot/initcalls_test.go | 154 ++++++++++++++++++++++---- boot/systemd_debug_test.go | 219 +++++++++++++++++++++++++++++++++++++ boot/userspace_test.go | 150 +++++++++++++++++++++++++ 5 files changed, 578 insertions(+), 21 deletions(-) create mode 100644 boot/systemd_debug_test.go create mode 100644 boot/userspace_test.go diff --git a/Taskfile.yml b/Taskfile.yml index 3439b9c..2a0478c 100644 --- a/Taskfile.yml +++ b/Taskfile.yml @@ -211,6 +211,24 @@ tasks: cmds: - SPIN_INITCALL_PROBE=1 go test ./boot/ -run TestKernelInitcalls -count=1 -v -timeout 30m + boot: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 "console no dev" row in boot/bench_test.go for what that mistake cost. + cmds: + - SPIN_USERSPACE_PROBE=1 go test ./boot/ -run TestUserspaceCost -count=1 -v -timeout 15m + + boot: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. + cmds: + - SPIN_SYSTEMD_DEBUG=1 go test ./boot/ -run TestSystemdDebug -count=1 -v -timeout 15m + boot:firmware: desc: >- Compare firmware for this machine: SeaBIOS against the qboot build in qemu/qboot/. diff --git a/boot/bench_test.go b/boot/bench_test.go index 2f029bb..ff02f39 100644 --- a/boot/bench_test.go +++ b/boot/bench_test.go @@ -168,6 +168,64 @@ var variants = []variant{ // of Type=simple was run against a real agetty whose sleep(1) buried it. {label: "getty no idle", cpus: "2", memory: "2048", files: gettyDropin("Type=simple\n" + gettyEcho)}, + // The login prompt's own dependency on udev, which every row above pays including the + // baseline: the drop-in they use sits on serial-getty@ttyS0, and that unit carries + // `BindsTo=dev-ttyS0.device`. systemd-getty-generator instantiates it from console=ttyS0, + // so nothing has to enable it for it to be on the critical path. + // + // Measured 2026-09-26 with `task boot:userspace`, 5 boots, p50 79 ms kernel + 139 ms + // userspace. The critical chain is the whole story: + // + // multi-user.target @129ms + // └─getty.target @129ms + // └─serial-getty@ttyS0.service @129ms + // └─dev-ttyS0.device @128ms + // + // and `blame` puts dev-vda.device at 109 ms, systemd-udevd at 33 and + // systemd-udev-trigger at 33. The prompt is waiting for udev's coldplug walk to announce + // a 16550 that is on the command line and cannot be absent. + // + // This row masks that unit and enables spin-machine-console.service, which the image + // already carries and which has no device dependency to wait for — the hole that unit's + // own comment says it is the wrong place to close. Same gettyEcho as the baseline, so + // what moves is the dependency and not agetty. + // + // It does not work, and that is why the row is here. 15 boots each, p50/p95 to a usable + // machine, 2026-09-26: + // + // baseline 259/386 console no dev 601/834 + // console no idle 583/1040 + // + // So the device dependency is not the cost: dropping it is 340 ms *worse*, and removing + // the replacement unit's Type=idle does not bring it back. `dev-ttyS0.device @128ms` on + // the critical chain is when udev got to the port, not something the prompt was waiting + // for — the same trap as `blame`, one line further down. Read a critical chain as what + // finished last, never as what was blocking. + // + // What the 340 ms is has not been established. It is suspiciously close to the 334 ms + // terminal-reset timeout that TERM=dumb exists to avoid (see machine/cmdline.go), and + // spin-machine-console.service carries TTYReset=yes and TTYVHangup=yes — but so does the + // unit it replaced, so that is a suspect and not an answer. + labelled("console no dev", variant{cpus: "2", memory: "2048", + mask: []string{"serial-getty@ttyS0.service"}, + files: map[string]string{ + "/etc/systemd/system/spin-machine-console.service.d/zz-bench.conf": "[Service]\n" + gettyEcho, + }, + links: map[string]string{ + "/etc/systemd/system/multi-user.target.wants/spin-machine-console.service": "/usr/lib/systemd/system/spin-machine-console.service", + }}), + // The same, with the unit's Type=idle removed, which is what rules Type=idle out as the + // explanation for the row above: 583 against 601, inside the spread of either. Kept as + // the record of a candidate eliminated, so the next person reading that 340 ms does not + // spend the boots again. + labelled("console no idle", variant{cpus: "2", memory: "2048", + mask: []string{"serial-getty@ttyS0.service"}, + files: map[string]string{ + "/etc/systemd/system/spin-machine-console.service.d/zz-bench.conf": "[Service]\nType=simple\n" + gettyEcho, + }, + links: map[string]string{ + "/etc/systemd/system/multi-user.target.wants/spin-machine-console.service": "/usr/lib/systemd/system/spin-machine-console.service", + }}), // What a tmpfs /tmp and the boot's tmpfiles pass cost against the /tmp on the disk the // image once shipped, which every copy of the disk carried. 20 boots of each, 2026-09-26, // p50/p95 to a usable machine: baseline 223/230, this row 220/232 - 3 ms, within noise. diff --git a/boot/initcalls_test.go b/boot/initcalls_test.go index 80f515b..247aab7 100644 --- a/boot/initcalls_test.go +++ b/boot/initcalls_test.go @@ -37,9 +37,15 @@ 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 +// block schedule hands one variant a slow minute and reads it as a difference. +// // SPIN_INITCALL_PROBE=1 run at all -// REPS= boots to take (default 10) +// REPS= boots per variant (default 10) // TOP= how many initcalls to print (default 30) +// SPIN_KERNEL_B= adds a variant booting this kernel instead of the release's, +// which is how a config change is compared without two runs on a +// host that is not the same host from one minute to the next func TestKernelInitcalls(t *testing.T) { if os.Getenv("SPIN_INITCALL_PROBE") == "" { t.Skip("set SPIN_INITCALL_PROBE=1: boots a VM and needs sudo to write into its overlay") @@ -76,11 +82,10 @@ ExecStart=/bin/sh -c "{ echo SPIN-DMESG-BEGIN; dmesg; echo SPIN-DMESG-END; } > / [Install] WantedBy=multi-user.target ` - v := variant{ - label: "initcalls", cpus: "2", memory: "2048", - // log_buf_len because initcall_debug is two lines per initcall and the default ring - // wraps: a wrapped buffer loses the early initcalls, which are the interesting ones. - extra: "initcall_debug log_buf_len=2M", + addKernelVariant(t) + + base := variant{ + cpus: "2", memory: "2048", files: map[string]string{ "/etc/systemd/system/spin-dmesg.service": dump, }, @@ -89,21 +94,31 @@ WantedBy=multi-user.target }, } - runs := make([]parsed, 0, reps) + runs := map[string][]parsed{} for i := range reps { - console := bootUntil(t, out, v, "SPIN-DMESG-END", 90*time.Second) - // The raw buffer of the first boot, for a question this report does not answer yet. - // Written only when asked: a test that drops a megabyte in the working directory on - // every run is a test people stop running. - if f := os.Getenv("SPIN_CONSOLE_OUT"); f != "" && i == 0 { - if err := os.WriteFile(f, []byte(console), 0o644); err != nil { - t.Fatalf("writing the console to %s: %v", f, err) + for _, cv := range cmdlineVariants { + v := base + v.label = cv.label + // log_buf_len because initcall_debug is two lines per initcall and the default + // ring wraps: a wrapped buffer loses the early initcalls, which are the + // interesting ones. 2M and not 8M — 8M allocates 37 MB and cost 4.9 ms of the + // boot being measured. + v.extra = strings.TrimSpace("initcall_debug log_buf_len=2M " + cv.extra) + console := bootUntil(t, out, v, cv.kernel, "SPIN-DMESG-END", 90*time.Second) + // The raw buffer of the first boot, for a question this report does not answer + // yet. Written only when asked: a test that drops a megabyte in the working + // directory on every run is a test people stop running. + if f := os.Getenv("SPIN_CONSOLE_OUT"); f != "" && i == 0 && cv.label == cmdlineVariants[0].label { + if err := os.WriteFile(f, []byte(console), 0o644); err != nil { + t.Fatalf("writing the console to %s: %v", f, err) + } + t.Logf("raw console of the first boot written to %s", f) } - t.Logf("raw console of the first boot written to %s", f) + runs[cv.label] = append(runs[cv.label], parse(t, console)) } - runs = append(runs, parse(t, console)) } - report(t, runs, top, reps) + compare(t, runs) + report(t, runs[cmdlineVariants[0].label], top, reps) } // bootUntil boots one machine and returns its console once marker has appeared. @@ -111,7 +126,7 @@ WantedBy=multi-user.target // Separate from bootOnce because that one stops at a login prompt, which is the right place // to stop when a boot time is what is wanted and the wrong one here: everything this reads // is printed after it. -func bootUntil(t *testing.T, out string, v variant, marker string, timeout time.Duration) string { +func bootUntil(t *testing.T, out string, v variant, kernel, marker string, timeout time.Duration) string { t.Helper() dir := t.TempDir() overlay := filepath.Join(dir, "overlay.qcow2") @@ -123,9 +138,13 @@ func bootUntil(t *testing.T, out string, v variant, marker string, timeout time. if v.extra != "" { cmdline += " " + v.extra } - 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", cmdline) + args := []string{"boot", "--release", out, "--disk", overlay, + "--memory", v.memory, "--cpus", v.cpus, + "--console", "file:/dev/stdout", "--append", cmdline} + if kernel != "" { + args = append(args, "--kernel", kernel) + } + cmd := exec.Command(filepath.Join(out, "bin", "spin-machine"), args...) cmd.SysProcAttr = &syscall.SysProcAttr{Setpgid: true} r, w, err := os.Pipe() if err != nil { @@ -200,6 +219,99 @@ func clip(s string) string { return s } +// The command lines to compare. The first is the baseline and the one the per-initcall +// table below is taken from. +// +// Boot parameters only, because they cost nothing: a kernel config change invalidates every +// template in existence, so it is worth knowing whether the saving is there at all before +// anybody pays for it. thash_entries and uhash_entries size the TCP and UDP hash tables, +// which inet_init allocates — 8.7 ms of initcall time, with another 8.2 ms of gap around +// "IP idents hash table entries: 32768 (order: 6, 262144 bytes, linear)" on a machine that +// will never hold 32768 connections. +type cmdlineVariant struct{ label, extra, kernel string } + +var cmdlineVariants = []cmdlineVariant{ + {label: "baseline"}, + {label: "small hashes", extra: "thash_entries=2048 uhash_entries=2048"}, +} + +// A second kernel, if one was built. Not a hard-coded path: an experimental vmlinux is not +// in this repository and a variant naming a file nobody has is a variant that fails for +// everyone who did not build it. +func addKernelVariant(t *testing.T) { + t.Helper() + k := os.Getenv("SPIN_KERNEL_B") + if k == "" { + return + } + abs, err := filepath.Abs(k) + if err != nil { + t.Fatalf("resolving SPIN_KERNEL_B=%q: %v", k, err) + } + if _, err := os.Stat(abs); err != nil { + t.Fatalf("SPIN_KERNEL_B=%s: %v", abs, err) + } + cmdlineVariants = append(cmdlineVariants, cmdlineVariant{label: "kernel B", kernel: abs}) +} + +// initcallsOfInterest are printed side by side for every variant, because a variant that +// moved the total is only interesting once it is clear which initcall moved. +var initcallsOfInterest = []string{ + "acpi_init", "inet_init", "ksm_init", "hugepage_init", "kcompactd_init", + "virtio_pci_driver_init", "virtio_blk_init", +} + +// compare prints one row per variant, and is the only part of this test that answers a +// question of the form "is it worth changing". +func compare(t *testing.T, runs map[string][]parsed) { + t.Helper() + var b strings.Builder + fmt.Fprintf(&b, "\n%-14s %10s %10s %10s %s\n", "VARIANT", "FREEING", "INITCALLS", "OUTSIDE", "(p50 ms)") + for _, cv := range cmdlineVariants { + rs := runs[cv.label] + freeing, totals, outside := make([]float64, 0, len(rs)), make([]float64, 0, len(rs)), make([]float64, 0, len(rs)) + for _, r := range rs { + totals = append(totals, float64(r.total)/1000) + if r.freeing > 0 { + freeing = append(freeing, r.freeing*1000) + outside = append(outside, r.freeing*1000-float64(r.total)/1000) + } + } + sort.Float64s(freeing) + sort.Float64s(totals) + sort.Float64s(outside) + fmt.Fprintf(&b, "%-14s %10.1f %10.1f %10.1f\n", cv.label, + pct(freeing, 50), pct(totals, 50), pct(outside, 50)) + } + + fmt.Fprintf(&b, "\n%-26s", "INITCALL (p50 ms)") + for _, cv := range cmdlineVariants { + fmt.Fprintf(&b, " %14s", cv.label) + } + fmt.Fprintln(&b) + for _, name := range initcallsOfInterest { + fmt.Fprintf(&b, "%-26s", name) + for _, cv := range cmdlineVariants { + var xs []float64 + for _, r := range runs[cv.label] { + for n, us := range r.calls { + if strings.HasPrefix(n, name+"+") { + xs = append(xs, float64(us)/1000) + } + } + } + sort.Float64s(xs) + if len(xs) == 0 { + fmt.Fprintf(&b, " %14s", "-") + continue + } + fmt.Fprintf(&b, " %14.2f", pct(xs, 50)) + } + fmt.Fprintln(&b) + } + t.Log(b.String()) +} + // parsed is one boot's ring buffer, reduced. type parsed struct { calls map[string]int // initcall -> usecs diff --git a/boot/systemd_debug_test.go b/boot/systemd_debug_test.go new file mode 100644 index 0000000..92f2f0b --- /dev/null +++ b/boot/systemd_debug_test.go @@ -0,0 +1,219 @@ +// 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) +} + +// 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. +// "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)`) + +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/userspace_test.go b/boot/userspace_test.go new file mode 100644 index 0000000..7a535fe --- /dev/null +++ b/boot/userspace_test.go @@ -0,0 +1,150 @@ +// SPDX-License-Identifier: Apache-2.0 + +package boot_test + +import ( + "fmt" + "os" + "regexp" + "sort" + "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) + } + + sort.Float64s(kernel) + sort.Float64s(userspace) + sort.Float64s(total) + 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 +} From ef963901044d52702287374aa24c0383da779fdf Mon Sep 17 00:00:00 2001 From: Manuel de Brito Fontes Date: Sat, 26 Sep 2026 12:21:32 -0300 Subject: [PATCH 04/18] boot: what udev actually walks, and why there is no single win in it MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `task boot:systemd` counted it: udev coldplugs 266 devices in a 51 ms window on this machine, hitting "Maximum number (14) of children reached" eighteen times, and every worker pays a failing dlopen of libnss_systemd.so.2 and a failing userdb group lookup on the way. udevd and udevadm together are the largest writers in early userspace, ~46 ms of it. Most of those devices are for hardware this machine does not have. Counted: 64 ttyN 16 memoryN 8 loopN 4 ttySN 4 cpuN 3 virtioN The 64 virtual consoles are CONFIG_VT on a machine whose QEMU ships no VGA at all and whose console is ttyS0. The 8 loop devices are never used. One of the four 16550s exists. udev also tries to open /dev/snd/timer and /dev/snd/seq, on a machine with no sound card. The new bench row switches off the two that are boot parameters, and it is a negative: 235/584 against the baseline's 239/423 over 15 boots. That is the arithmetic rather than a surprise — 11 devices of 266 is 4% of 46 ms, about 2 ms, below what this harness resolves. Parameters were the right thing to try first because a kernel config change invalidates every template in existence, and this way nobody paid for one to find out. What it settles is the shape, which is the useful part: the cost is per device and no single device matters. CONFIG_VT=n removes 64 of the 266, so it should be worth 5 to 12 ms of the udev window with 14 workers in parallel — a real prediction to test, and one worth knowing is ~10 ms of a 239 ms boot before spending a build on it. Early userspace is 139 ms and it is not one expensive thing; it is 266 cheap ones. Co-Authored-By: Claude Opus 5 (1M context) --- boot/bench_test.go | 29 +++++++++++++++++++++++++++++ 1 file changed, 29 insertions(+) diff --git a/boot/bench_test.go b/boot/bench_test.go index ff02f39..ead2b8d 100644 --- a/boot/bench_test.go +++ b/boot/bench_test.go @@ -226,6 +226,35 @@ var variants = []variant{ links: map[string]string{ "/etc/systemd/system/multi-user.target.wants/spin-machine-console.service": "/usr/lib/systemd/system/spin-machine-console.service", }}), + // Devices udev does not have to walk. + // + // `task boot:systemd` counted what udev coldplugs on this machine: 266 devices in a 51 ms + // window, with 18 occurrences of "Maximum number (14) of children reached" and, per + // worker, a failing dlopen of libnss_systemd.so.2 and a failing userdb group lookup. The + // families, counted 2026-09-26: + // + // 64 ttyN 16 memoryN 8 loopN 4 ttySN 4 cpuN 3 virtioN + // + // Three of those are for hardware this machine does not have. The 64 virtual consoles are + // CONFIG_VT on a machine whose QEMU has no VGA at all and whose console is ttyS0; the 8 + // loop devices are never used; and only one of the four 16550s exists. This row switches + // off the two that are boot parameters, because a parameter costs nothing to test and a + // kernel config change invalidates every template in existence — worth knowing the saving + // is real before anybody pays for it. + // + // It is not visible: 235/584 against the baseline's 239/423 over 15 boots, 2026-09-26. + // That is the arithmetic working out rather than a surprise — 11 devices of 266 is 4% of + // udev's ~46 ms, about 2 ms, which this harness cannot resolve. What it establishes is the + // shape of the cost: it is per device and there is no one device that matters. + // + // So the prediction for CONFIG_VT=n, which removes the 64 ttys: 24% of the devices, and + // with 14 workers running in parallel somewhere between 5 and 12 ms of the 51 ms udev + // window. Worth a kernel build to find out, and worth knowing beforehand that it is ~10 ms + // of a 239 ms boot. Early userspace is 139 ms and it is not one expensive thing; it is + // 266 cheap ones. + labelled("fewer devices", variant{cpus: "2", memory: "2048", + files: gettyDropin(gettyEcho), + extra: "loop.max_loop=0 8250.nr_uarts=1"}), // What a tmpfs /tmp and the boot's tmpfiles pass cost against the /tmp on the disk the // image once shipped, which every copy of the disk carried. 20 boots of each, 2026-09-26, // p50/p95 to a usable machine: baseline 223/230, this row 220/232 - 3 ms, within noise. From 3819a7949c45f369c2f82bdbd6c4e28e7771be80 Mon Sep 17 00:00:00 2001 From: Manuel de Brito Fontes Date: Sat, 26 Sep 2026 12:30:25 -0300 Subject: [PATCH 05/18] boot: udev is not on the critical path, and three rankings said it was MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The previous commit predicted that CONFIG_VT=n would be worth 5 to 12 ms: it removes 64 of the 266 devices udev coldplugs, a quarter of them, and udevd and udevadm are the largest writers in early userspace at ~46 ms. The kernel was built and the prediction is wrong. 15 boots each on a quiet host, p50/p95 to a login prompt: baseline 228/237 fewer udev rules 228/234 fewer devices 225/238 kernel B (VT=n) 228/246 Zero. Not noise hiding it: at a p95 of 237 a 10 ms saving would be visible. Removing a quarter of the devices, and nineteen rule files for hardware this machine cannot have, changes the time to a login prompt by nothing at all. So udev's 46 ms overlaps with something rather than delaying it. It runs up to 14 workers — it says so, eighteen times — and taking work away hands the wall clock to whatever it was running alongside. That is the same mistake three times in three disguises. `systemd-analyze blame` ranks units by their own duration; a critical chain ranks by what finished last; and `task boot:systemd`, added two commits ago, ranks writers by the time between their log lines. Each looks like a list of savings and none of them is one. The comment on the logind row has said so since 2026-09-10 about the first, and it took building a kernel to learn it about the third. The bench can compare kernels now, which is what made this answerable: SPIN_KERNEL_B adds a row booting a kernel built elsewhere, interleaved with the rest rather than run as a second pass, because three consecutive runs of one kernel on a busy host read 59.5, 96.8 and 167.7 ms. editOverlay also refuses a mask that masks nothing — a symlink to /dev/null whose name matches no rule file switches nothing off and reports a row that looks like a measurement. What is left after this: the image's current arrangement is at or near a local optimum for removing things. logind out of the boot transaction is worth ~20 ms and is already taken; the console unit that looks device-independent costs 340 ms; and the remaining 228 ms is not attributable to anything that has been taken out and measured yet. Co-Authored-By: Claude Opus 5 (1M context) --- boot/bench_test.go | 130 ++++++++++++++++++++++++++++++++++++++++++--- 1 file changed, 122 insertions(+), 8 deletions(-) diff --git a/boot/bench_test.go b/boot/bench_test.go index ead2b8d..9d15b71 100644 --- a/boot/bench_test.go +++ b/boot/bench_test.go @@ -26,6 +26,7 @@ type variant struct { mask []string // units masked by writing into this boot's own overlay files map[string]string // written into the overlay: path under / -> content links map[string]string // symbolic links made in the overlay: path under / -> target + kernel string // a kernel other than the release's, for comparing configs } // Masks are written into the overlay and never passed as `systemd.mask=`. That parameter is @@ -34,6 +35,48 @@ type variant struct { // `systemd.mask=chrony.service` on the command line and `systemctl is-active chrony` // answering `active`. Anything concluded from that parameter is concluded from a boot in // which nothing was masked. +// Rule files for hardware this machine cannot have. udev reads 49 of them and evaluates +// them against the 266 devices it coldplugs; 32 reference cdrom, drm, input, alsa, hidraw, +// tape, v4l, cameras, joysticks, mice, touchpads, graphics and sound cards, or a ProLiant's +// power switch. They arrive with the udev package, not with anything this image asked for. +// +// Conservative on purpose. Not here and not maskable: 60-block and 60-persistent-storage +// (vda), 60-serial (ttyS0), 71-seat (logind), the net-naming rules, 50-udev-default, +// 80-debian-compat and 99-systemd. Masking one of those is a machine that does not boot or +// a disk with no by-uuid link, and the point of the row is the ones that cannot matter. +var impossibleRules = []string{ + "60-cdrom_id.rules", + "60-drm.rules", + "60-evdev.rules", + "60-fido-id.rules", + "60-gpiochip.rules", + "60-persistent-alsa.rules", + "60-persistent-hidraw.rules", + "60-persistent-input.rules", + "60-persistent-storage-tape.rules", + "60-persistent-v4l.rules", + "60-sensor.rules", + "61-persistent-storage-android.rules", + "70-camera.rules", + "70-joystick.rules", + "70-mouse.rules", + "70-touchpad.rules", + "71-power-switch-proliant.rules", + "78-graphics-card.rules", + "78-sound-card.rules", +} + +// maskedRules is what udev's own override mechanism is: a symlink to /dev/null in +// /etc/udev/rules.d shadows the file of the same name in /usr/lib/udev/rules.d, exactly as +// it works for units. +func maskedRules() map[string]string { + m := map[string]string{} + for _, r := range impossibleRules { + m["/etc/udev/rules.d/"+r] = "/dev/null" + } + return m +} + var udevUnits = []string{ "systemd-udevd.service", "systemd-udevd-control.socket", @@ -247,20 +290,73 @@ var variants = []variant{ // udev's ~46 ms, about 2 ms, which this harness cannot resolve. What it establishes is the // shape of the cost: it is per device and there is no one device that matters. // - // So the prediction for CONFIG_VT=n, which removes the 64 ttys: 24% of the devices, and - // with 14 workers running in parallel somewhere between 5 and 12 ms of the 51 ms udev - // window. Worth a kernel build to find out, and worth knowing beforehand that it is ~10 ms - // of a 239 ms boot. Early userspace is 139 ms and it is not one expensive thing; it is - // 266 cheap ones. + // The prediction from that was CONFIG_VT=n — 64 of the 266 devices, 24%, so 5 to 12 ms of + // the 51 ms udev window with 14 workers in parallel. It was built and measured, and it is + // wrong. 15 boots each on a quiet host, 2026-09-26, p50/p95 to a usable machine: + // + // baseline 228/237 + // fewer devices 225/238 + // fewer udev rules 228/234 + // kernel B (VT=n) 228/246 + // + // Nothing. Not noise hiding it either: at a p95 of 237 a 10 ms saving would be visible. + // Removing a quarter of the devices udev walks, and nineteen of its rule files, changes + // the time to a login prompt by zero. + // + // Which means udev's 46 ms is not on the critical path. It runs up to 14 workers while + // other things happen, and taking work away from it gives the wall clock back to whatever + // it was overlapping with. That is the third time the same mistake has been made here in + // a different disguise: `blame` ranks units by their own duration, a critical chain ranks + // by what finished last, and `task boot:systemd` ranks writers by the time between their + // log lines. None of the three is a list of savings. The only way to find out what a boot + // costs is to take something out and measure, and every removal tried so far has bought + // nothing or cost a great deal. labelled("fewer devices", variant{cpus: "2", memory: "2048", files: gettyDropin(gettyEcho), extra: "loop.max_loop=0 8250.nr_uarts=1"}), + // The other half of udev's work: not how many devices, but how many rules each one is + // matched against. This masks the 19 rule files above and changes nothing else. + // + // It is the image-side lever, which is what makes it worth trying before the kernel one: + // no symbol moves, so no template is invalidated, and if it pays it pays in image/ where + // static configuration belongs. + // + // It does not pay — 228/234 against the baseline's 228/237. Kept because the row is the + // only thing that says so, and because it is cheap to re-run against a future image whose + // rule set is larger. See the numbers under "fewer devices". + labelled("fewer udev rules", variant{cpus: "2", memory: "2048", + files: gettyDropin(gettyEcho), + links: maskedRules()}), // What a tmpfs /tmp and the boot's tmpfiles pass cost against the /tmp on the disk the // image once shipped, which every copy of the disk carried. 20 boots of each, 2026-09-26, // p50/p95 to a usable machine: baseline 223/230, this row 220/232 - 3 ms, within noise. labelled("tmp on disk", without("tmp.mount", "systemd-tmpfiles-setup.service")), } +// withKernelVariant adds a row booting a kernel built somewhere else, when SPIN_KERNEL_B +// names one. Interleaved with the rest rather than run as a second pass, which is the only +// way to compare two kernel configurations on a host that is not the same host from one +// minute to the next: three consecutive runs of one kernel read 59.5, 96.8 and 167.7 ms. +// +// Not a hard-coded path, because a kernel built from a changed config is not in this +// repository and a row naming a file nobody has fails for everyone who did not build it. +func withKernelVariant(t *testing.T) { + t.Helper() + k := os.Getenv("SPIN_KERNEL_B") + if k == "" { + return + } + abs, err := filepath.Abs(k) + if err != nil { + t.Fatalf("resolving SPIN_KERNEL_B=%q: %v", k, err) + } + if _, err := os.Stat(abs); err != nil { + t.Fatalf("SPIN_KERNEL_B=%s: %v", abs, err) + } + variants = append(variants, variant{label: "kernel B", cpus: "2", memory: "2048", + files: gettyDropin(gettyEcho), kernel: 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 @@ -277,6 +373,7 @@ func TestBootCost(t *testing.T) { } out := releaseDir(t) reps := envInt(t, "REPS", 20) + withKernelVariant(t) if !canSudo() { for _, v := range variants { @@ -462,9 +559,13 @@ func bootOnce(t *testing.T, out string, v variant) boot.Run { cmdline += " " + v.extra } - 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", cmdline) + args := []string{"boot", "--release", out, "--disk", overlay, + "--memory", v.memory, "--cpus", v.cpus, + "--console", "file:/dev/stdout", "--append", cmdline} + if v.kernel != "" { + args = append(args, "--kernel", v.kernel) + } + cmd := exec.Command(filepath.Join(out, "bin", "spin-machine"), args...) // Its own process group, so the machine can be taken down as a whole. spin-machine execs // QEMU as a child and killing the parent leaves the child running: the first version of // this left one `qemu-system-x86_64` per boot alive, each still holding an overlay open. @@ -542,6 +643,19 @@ func editOverlay(t *testing.T, overlay string, v variant) { } } for path, target := range v.links { + // A mask only masks something. udev reads /etc/udev/rules.d before + // /usr/lib/udev/rules.d and a file of the same name shadows the one below it, so a + // symlink to /dev/null here switches a rule file off — and a symlink whose name + // matches no rule file switches nothing off, changes no timing, and reports a row + // that looks like a measurement. Checked rather than trusted, for the same reason + // image/build.sh opens the filesystem it just made. + if target == "/dev/null" && strings.HasPrefix(path, "/etc/udev/rules.d/") { + shadowed := filepath.Join(mnt, "usr/lib/udev/rules.d", filepath.Base(path)) + if err := exec.Command("sudo", "test", "-e", shadowed).Run(); err != nil { + t.Fatalf("%s masks nothing: there is no %s in this image", + path, filepath.Base(path)) + } + } dst := filepath.Join(mnt, path) mustRun(t, "sudo", "mkdir", "-p", filepath.Dir(dst)) mustRun(t, "sudo", "ln", "-sfn", target, dst) From 2e5b35ac74cb611d1912cf2cb16484a50cdce4f3 Mon Sep 17 00:00:00 2001 From: Manuel de Brito Fontes Date: Sat, 26 Sep 2026 12:35:36 -0300 Subject: [PATCH 06/18] boot: the initcall probe uses --profile instead of redefining it MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `spin-machine boot --profile` already exists and machine.Cmdline.Profiling() is what it means: initcall_debug, printk.time, a log_buf_len the default ring needs, and a silent console. The probe added two commits ago built that command line itself, which is a second definition of the gate — and the two had already drifted, since one used log_buf_len=2M and the other 4M. Profiling()'s own comment also names the mechanism the probe rediscovered the hard way: a console registers during the device_initcall phase and registering it replays the whole printk ring into it synchronously, inside that initcall, so a verbose boot charges the measurement to whichever console driver registered. That was written down before the probe existed. The probe keeps what is its own: p50/p95 over interleaved boots, the gap ranking, and the assertions that fail when the measurement is broken rather than averaging it. Co-Authored-By: Claude Opus 5 (1M context) --- boot/bench_test.go | 17 +++++++++-------- boot/initcalls_test.go | 17 ++++++++++++----- 2 files changed, 21 insertions(+), 13 deletions(-) diff --git a/boot/bench_test.go b/boot/bench_test.go index 9d15b71..d379f82 100644 --- a/boot/bench_test.go +++ b/boot/bench_test.go @@ -19,14 +19,15 @@ import ( // variant is one configuration to boot, and the whole point is that two of them differ in // exactly one thing. type variant struct { - label string - cpus string - memory string - extra string // appended to the kernel command line - mask []string // units masked by writing into this boot's own overlay - files map[string]string // written into the overlay: path under / -> content - links map[string]string // symbolic links made in the overlay: path under / -> target - kernel string // a kernel other than the release's, for comparing configs + label string + cpus string + memory string + extra string // appended to the kernel command line + mask []string // units masked by writing into this boot's own overlay + files map[string]string // written into the overlay: path under / -> content + links map[string]string // symbolic links made in the overlay: path under / -> target + kernel string // a kernel other than the release's, for comparing configs + profile bool // boot with `--profile`: initcall profiling, console silent } // Masks are written into the overlay and never passed as `systemd.mask=`. That parameter is diff --git a/boot/initcalls_test.go b/boot/initcalls_test.go index 247aab7..02f4c73 100644 --- a/boot/initcalls_test.go +++ b/boot/initcalls_test.go @@ -99,11 +99,15 @@ WantedBy=multi-user.target for _, cv := range cmdlineVariants { v := base v.label = cv.label - // log_buf_len because initcall_debug is two lines per initcall and the default - // ring wraps: a wrapped buffer loses the early initcalls, which are the - // interesting ones. 2M and not 8M — 8M allocates 37 MB and cost 4.9 ms of the - // boot being measured. - v.extra = strings.TrimSpace("initcall_debug log_buf_len=2M " + cv.extra) + // The profiling command line is not built here. `spin-machine boot --profile` is, + // through machine.Cmdline.Profiling(), and that is the only definition of what + // profiling a boot means — including the log_buf_len the default ring needs and + // the silent console, whose reason that function already records: a console + // registers during the device_initcall phase and registering it replays the whole + // printk ring into it synchronously, inside that initcall, so a verbose boot + // charges the measurement to whichever console driver registered. + v.extra = cv.extra + v.profile = true console := bootUntil(t, out, v, cv.kernel, "SPIN-DMESG-END", 90*time.Second) // The raw buffer of the first boot, for a question this report does not answer // yet. Written only when asked: a test that drops a megabyte in the working @@ -144,6 +148,9 @@ func bootUntil(t *testing.T, out string, v variant, kernel, marker string, timeo if kernel != "" { args = append(args, "--kernel", kernel) } + if v.profile { + args = append(args, "--profile") + } cmd := exec.Command(filepath.Join(out, "bin", "spin-machine"), args...) cmd.SysProcAttr = &syscall.SysProcAttr{Setpgid: true} r, w, err := os.Pipe() From 4dc505305fab8ff31c51fcea4cb08dde13c95df2 Mon Sep 17 00:00:00 2001 From: Manuel de Brito Fontes Date: Sat, 26 Sep 2026 12:38:51 -0300 Subject: [PATCH 07/18] boot: clarify that releases do not include software that owns a guest --- CLAUDE.md | 83 ++++++++++++++++++++++++++++++++++++------------------- README.md | 8 ++++-- 2 files changed, 60 insertions(+), 31 deletions(-) diff --git a/CLAUDE.md b/CLAUDE.md index 61d8146..5b5ced8 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -5,29 +5,36 @@ A virtual machine: QEMU, a guest kernel, a base image, and the definition of the machine they make. Four artefacts and one version. -**What it is not: anything that runs inside a guest.** No container runtime, no agent, no -supervisor, no RPC, and no init. A release is not bootable on its own and that is deliberate -— whoever runs guests brings the init. There is no exception; there was one, a debug -initramfs, and it was a second init doing what the consumer's already does. It went on -2026-09-10, when udev was turned back on and the machine reached a login prompt through -`root=/dev/vda init=/sbin/init` without it. - -**It does not know about the projects that consume it.** No repository names, no file paths -into other trees, no ADR numbers. If a rationale can only be stated by naming a consumer, -it is either the wrong rationale or the wrong repository for the code. Say what is true of -the machine. +**A release does not carry software that owns a guest.** No container runtime, agent, +supervisor, RPC service, or init is part of the published machine. A release is not bootable +on its own: whoever runs a guest supplies its init. + +Diagnostic input is different from release content. A test or experiment may use a caller +supplied initrd, a temporary guest helper, a disposable overlay, or a separately built +firmware image when it is isolated from `task build` and `task release`. State clearly what +is diagnostic, who supplies it, and what it is measuring. The qboot probe is the model: +it does not change a release tree and compares both variants with the same diagnostic initrd. + +**Keep consumer-specific implementation out of this tree, but record real contracts.** Do +not copy consumer code, paths, or an ADR as a substitute for an explanation. It is correct to +name an external component when its protocol, provisioned file, lifecycle, or compatibility +contract affects this machine; describe the contract here and test the observable behaviour +where possible. ## The three rules that are load-bearing -Everything else is style. These are correctness, and each fails silently. +These are release invariants, not defaults. Everything below them is a strong engineering +default unless it says otherwise; an experiment may depart from a default when it is isolated +and makes its scope and result clear. 1. **A release is one machine.** `machine.Spec.Fingerprint` hashes the QEMU binary, the kernel and the initrd by content, together with the four arguments that decide the machine's shape. Two machines with the same fingerprint may exchange templates; two - without may not, and a restore across them is undefined rather than an error. Any change - to any of those three files invalidates every template in existence. That is the design, - not a bug to work around — but it means "I only changed a comment in `kernel/Dockerfile`" - is a fleet-wide event, and it has already happened once in this repository's history. + without may not, and a restore across them is undefined rather than an error. A content + change to any of those three files invalidates every template in existence. That is the + design, not a bug to work around. A source or recipe change is a possible fleet-wide event; whether + it is one is decided by the resulting artifact hashes and shape, not by the diff's apparent + size. Verify them before promotion. 2. **The base image is never written to.** Every VM maps it read-only through a qcow2 backing chain and many share one file. Anything that opens it for writing invalidates @@ -59,6 +66,25 @@ what it makes clear. systemd unit written by a Go program at run time was the wrong answer to a real problem; the unit belongs in `image/`, and only the symlink that enables it belongs in the boot. +### Experiments + +Experiments are welcome when they make a production decision cheaper to evaluate. They must +not silently become production behaviour. + +- Keep experiment outputs, overlays, initrds, firmware, and caches separate from release + outputs. Do not modify a shared base image; use a disposable overlay or a new artifact. +- A probe may change one production default at a time, including a kernel option, unit, + QEMU sandbox setting, CPU affinity, or diagnostic initrd. Production defaults remain the + safe settings until the result is promoted deliberately. +- Record the baseline, environment, sample count, and the measured result. A fast exploratory + run is enough to decide what to investigate; a promotion needs a reproducible comparison + and the functional check that could reveal a false win. +- If a promoted change alters what a restored guest sees, update the machine identity and + prove that templates do not cross the boundary. If it is host-only (for example launcher + CPU affinity), document why it does not. +- Remove or quarantine an experiment once it no longer has an active question. Keep the + conclusion and durable evidence, not a permanent switch in the release path. + ## Go - **Clarity beats cleverness.** This code is read far more often than it is written, and @@ -82,13 +108,13 @@ what it makes clear. Comments here are longer than usual, on purpose. The rule is what makes them worth reading: - **Say why, not what.** The code says what. If a comment restates it, delete the comment. -- **Carry the evidence.** When something is the way it is because of a measurement, put the - number in: `87.6 ms to 51.1 ms, kernel to init`, `+356 ms and rejected`, `−3.7 ms of - boot`. A claim without a number invites someone to undo it on a hunch. -- **Record what was tried and failed.** The comments that have paid for themselves most - here are the ones naming a dead end: the drop-in that did not lift the device dependency, - the flag that broke a link twenty minutes into a build, the check that passed for every - input because a tool exits 0 on failure. Someone will otherwise try it again. +- **Carry durable evidence.** When a production decision rests on a measurement, put a + concise result and its context near the decision, or link to a maintained measurement + record. Include a number when it is the reason for the decision; do not turn an exploratory + observation into a permanent claim. +- **Record failed approaches selectively.** Keep a failed attempt near code only when it + prevents a plausible, costly regression or repeats a non-obvious tool failure. Put raw + samples and short-lived exploration in a measurement record, issue, or commit instead. - **Date a fact that could go stale.** "measured 2026-09-07" tells a reader whether to re-check. - **Do not write down that it works.** The README had a "Status" section listing what had @@ -97,14 +123,15 @@ Comments here are longer than usual, on purpose. The rule is what makes them wor justified — so it could only rot, and it did. A claim about the state of the tree belongs in a workflow, a badge, or a commit message. Never in prose that nobody re-reads. -- **Do not name the projects that consume this.** See above. +- **Name external contracts when relevant.** See above. ## Artefacts leave this machine -QEMU is linked statically, and anything added beside it should be too. An artefact that -needs the host to have the right libraries is not one artefact, and the failure it produces -arrives on somebody else's machine, at start-up, naming a library rather than a decision -made here. +Host-executed binaries published in a release should be statically linked unless there is a +documented deployment reason not to be. This rule does not apply to guest userspace, build +tools, or diagnostic artifacts. A released host binary that depends on host libraries needs a +compatibility and packaging story, because its failure otherwise arrives on someone else's +machine at start-up. ## Verifying diff --git a/README.md b/README.md index 945f996..2ce26fd 100644 --- a/README.md +++ b/README.md @@ -65,9 +65,11 @@ Each part's targets live beside what they build — `qemu/Taskfile.yml`, `kernel `image/Taskfile.yml` — so `task qemu:build` is next to `qemu/Dockerfile`. The root `Taskfile.yml` holds the vars every part reads and the targets that cross all of them. -**What is deliberately not here: the software that runs inside a guest.** This repository -builds a machine. It knows nothing about what boots on it, and a release is not bootable on -its own by design — whoever runs guests brings the initrd. There is no exception to that. +**What is deliberately not in a release: software that owns a guest.** This repository +builds a machine, and a release is not bootable on its own by design — whoever runs guests +brings the initrd. Tests and performance probes may use caller-supplied diagnostic initrds +or disposable guest helpers, but those are not release artifacts and must stay isolated from +the published machine. ## What it publishes From e8c4c27c855cc18c9c153fe69f5db2606315395a Mon Sep 17 00:00:00 2001 From: Manuel de Brito Fontes Date: Sat, 26 Sep 2026 12:50:52 -0300 Subject: [PATCH 08/18] kernel: a floor, and what this machine's kernel configuration actually costs MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Four removals in a row measured zero — CONFIG_VT, nineteen udev rule files, two device-count boot parameters, smaller TCP hash tables — and each cost a build or a bench run to learn. None of them was measured against anything: there was no answer to how much of the kernel phase is even available. kernel/minimal/ builds the smallest kernel that still boots: tinyconfig plus PVH, the 8250, an initramfs and the handful of symbols needed to exec an init. 573 symbols against the release's 1379, 10.2 MiB against 37.5. From tinyconfig up rather than from the release config down, because subtracting leaves whatever nobody thought to name — the same reason qemu/devices.mak is an allowlist. It is isolated from `task build` and `task release`, with its own cache scope, and it could not be a release kernel: no BTF, BPF, ftrace, cgroups, ext4 or virtio, so it cannot mount the base image or run systemd. Which is why the comparison is against a diagnostic initrd's marker and not a login prompt. That bounds what it measures — the kernel phase and the launch around it — and it is also the point. 20 boots each, interleaved, 2026-09-26, i9-13900HK, KVM, q35, 2 vCPUs, 2 GiB: release 97.95 / 104.91 ms floor 52.33 / 56.95 ms release+lz4 91.56 / 103.53 ms The release kernel's configuration costs 45.6 ms. That is the budget every kernel-config question has been spending against without knowing it, and it is not noise: about 9 ms of it is BTF's one-time section parse, ~10 ms acpi_init, ~6 ms ksm/kcompactd/hugepage and ~5 ms ftrace, by the measurements already recorded in kernel/Dockerfile and by task boot:initcalls. BTF, ftrace and ACPI are not available — BPF and hotplug need them — so the part in play is smaller than 45.6, and now it has a size. The third row answers a question the tree had only argued: kernel/Dockerfile requires RD_LZ4 because unpacking the archive is one of the largest single items in kernel boot. On this machine lz4 rather than gzip for the same 2.1 MB archive is 6.4 ms, more than the qboot firmware experiment's 3.9. Nothing here ships an initrd, so that is a number for whoever supplies one. Two things the probe found on the way, both of which look like unrelated faults: tinyconfig leaves CONFIG_BINFMT_SCRIPT off, so `rdinit=/init` on a shebang script fails, the kernel falls through its default inits and starts an interactive BusyBox shell. And the config assertions run before the compile, because a missing PVH note is twenty minutes of build followed by a guest that halts with nothing on the console. Co-Authored-By: Claude Opus 5 (1M context) --- Taskfile.yml | 12 ++++ boot/firmware_test.go | 21 +++++-- boot/floor_test.go | 108 +++++++++++++++++++++++++++++++++++ kernel/Taskfile.yml | 25 ++++++++ kernel/minimal/Dockerfile | 117 ++++++++++++++++++++++++++++++++++++++ 5 files changed, 277 insertions(+), 6 deletions(-) create mode 100644 boot/floor_test.go create mode 100644 kernel/minimal/Dockerfile diff --git a/Taskfile.yml b/Taskfile.yml index 2a0478c..0b7d226 100644 --- a/Taskfile.yml +++ b/Taskfile.yml @@ -123,6 +123,9 @@ vars: KERNEL_CACHE_TO: '{{if eq .CACHE_BACKEND "gha"}}type=gha,scope=kernel,mode=max{{else}}type=local,dest={{.BUILDKIT_CACHE_DIR}}/kernel,mode=max,compression=zstd{{end}}' # The firmware experiment. Its own scope like everything else, and it is never built by # `task build`: nothing in a release comes from it. + # The floor-kernel experiment, like QBOOT_ above: never built by `task build`. + KMIN_CACHE_FROM: '{{if eq .CACHE_BACKEND "gha"}}type=gha,scope=kmin{{else}}type=local,src={{.BUILDKIT_CACHE_DIR}}/kmin{{end}}' + KMIN_CACHE_TO: '{{if eq .CACHE_BACKEND "gha"}}type=gha,scope=kmin,mode=max{{else}}type=local,dest={{.BUILDKIT_CACHE_DIR}}/kmin,mode=max,compression=zstd{{end}}' QBOOT_CACHE_FROM: '{{if eq .CACHE_BACKEND "gha"}}type=gha,scope=qboot{{else}}type=local,src={{.BUILDKIT_CACHE_DIR}}/qboot{{end}}' QBOOT_CACHE_TO: '{{if eq .CACHE_BACKEND "gha"}}type=gha,scope=qboot,mode=max{{else}}type=local,dest={{.BUILDKIT_CACHE_DIR}}/qboot,mode=max,compression=zstd{{end}}' E2FSPROGS_CACHE_FROM: '{{if eq .CACHE_BACKEND "gha"}}type=gha,scope=e2fsprogs{{else}}type=local,src={{.BUILDKIT_CACHE_DIR}}/e2fsprogs{{end}}' @@ -229,6 +232,15 @@ tasks: cmds: - SPIN_SYSTEMD_DEBUG=1 go test ./boot/ -run TestSystemdDebug -count=1 -v -timeout 15m + boot:floor: + desc: >- + What a kernel costs before anything is configured into it: the release kernel against + the one `task kernel:minimal` builds, interleaved, on a marker both can reach. Needs + KVM, a built release, `task kernel:minimal`, and a diagnostic initrd in + SPIN_PROBE_INITRD=. The answer bounds every kernel-config change that could follow. + cmds: + - SPIN_FLOOR_PROBE=1 go test ./boot/ -run TestKernelFloor -count=1 -v -timeout 20m + boot:firmware: desc: >- Compare firmware for this machine: SeaBIOS against the qboot build in qemu/qboot/. diff --git a/boot/firmware_test.go b/boot/firmware_test.go index a697ed9..921e7f1 100644 --- a/boot/firmware_test.go +++ b/boot/firmware_test.go @@ -140,7 +140,7 @@ type vm struct { qmp string } -func (p *probe) start(t *testing.T, variant string, gen bool, incoming string) *vm { +func (p *probe) start(t *testing.T, variant string, gen bool, incoming, kernel, initrd string) *vm { t.Helper() p.n++ qmp := filepath.Join(p.dir, fmt.Sprintf("qmp-%d.sock", p.n)) @@ -157,8 +157,8 @@ func (p *probe) start(t *testing.T, variant string, gen bool, incoming string) * "-nodefaults", "-display", "none", "-serial", "stdio", "-monitor", "none", "-qmp", "unix:" + qmp + ",server=on,wait=off", "-bios", p.bios[variant], - "-kernel", p.kernel, - "-initrd", p.initrd, + "-kernel", orElse(p.kernel, kernel), + "-initrd", orElse(p.initrd, initrd), "-append", "console=ttyS0 quiet loglevel=3 pci=lastbus=0 no_timer_check " + "tsc=reliable rcupdate.rcu_expedited=1 TERM=dumb rdinit=/init", } @@ -218,7 +218,7 @@ func (v *vm) close() { func (p *probe) reach(t *testing.T, variant string, gen bool, marker string, timeout time.Duration) (float64, error) { t.Helper() - v := p.start(t, variant, gen, "") + v := p.start(t, variant, gen, "", "", "") defer v.close() return v.wait(marker, timeout) } @@ -242,7 +242,7 @@ func (p *probe) mustReach(t *testing.T, variant string, gen bool, marker string) // reports a fault. func (p *probe) mustPublishVMGenID(t *testing.T) { t.Helper() - v := p.start(t, "patched", withVMGenID, "") + v := p.start(t, "patched", withVMGenID, "", "", "") ms, err := v.wait("SPIN-READY", 8*time.Second) if err != nil { v.close() @@ -263,7 +263,7 @@ func (p *probe) mustPublishVMGenID(t *testing.T) { q.close() v.close() - r := p.start(t, "patched", withVMGenID, state) + r := p.start(t, "patched", withVMGenID, state, "", "") defer r.close() q = dial(t, r.qmp, r) defer q.close() @@ -441,3 +441,12 @@ func pct(sorted []float64, p int) float64 { } return sorted[i-1] } + +// orElse is the override or the default, and exists so that a probe varying one argument +// of the machine line does not need a second copy of the whole line. +func orElse(dflt, override string) string { + if override != "" { + return override + } + return dflt +} diff --git a/boot/floor_test.go b/boot/floor_test.go new file mode 100644 index 0000000..08f50f2 --- /dev/null +++ b/boot/floor_test.go @@ -0,0 +1,108 @@ +// SPDX-License-Identifier: Apache-2.0 + +package boot_test + +import ( + "fmt" + "os" + "path/filepath" + "sort" + "strings" + "testing" + "time" +) + +// The floor: what a kernel costs before anything is configured into it. +// +// Removing one thing at a time from the release config has found nothing four times running +// — CONFIG_VT, nineteen udev rule files, two device-count boot parameters, smaller TCP hash +// tables — and each answer cost a build or a bench run. This asks the question from the other +// end. If the release kernel reaches the same marker in about what a kernel with almost +// nothing in it does, then the config is not where the kernel phase goes and no amount of +// subtracting will find it. If the gap is large, the gap is the budget, and it is worth +// knowing its size before hunting inside it. +// +// The marker is a caller-supplied diagnostic initrd's, not a login prompt, because the floor +// kernel has no ext4, no virtio and no cgroups: it cannot mount this machine's base image +// and cannot run systemd. A comparison needs something both kernels can reach, and that +// bounds what this measures — the kernel phase and the launch around it, not a boot. +// +// SPIN_FLOOR_PROBE=1 run at all +// SPIN_PROBE_INITRD= the diagnostic initrd, as for task boot:firmware +// REPS= boots per kernel (default 20) +// +// The floor kernel is read from _output/kernel-minimal/vmlinux, where `task kernel:minimal` +// writes it, and SPIN_KERNEL_FLOOR overrides that. +func TestKernelFloor(t *testing.T) { + if os.Getenv("SPIN_FLOOR_PROBE") == "" { + t.Skip("set SPIN_FLOOR_PROBE=1: boots dozens of VMs and needs a kernel built outside the release") + } + out := releaseDir(t) + reps := envInt(t, "REPS", 20) + + floor := firmwareFile(t, "SPIN_KERNEL_FLOOR", + filepath.Join(out, "kernel-minimal", "vmlinux")) + p := &probe{ + out: out, + firmware: filepath.Join(out, "qemu"), + kernel: filepath.Join(out, "kernel", "vmlinux"), + initrd: envFile(t, "SPIN_PROBE_INITRD"), + bios: map[string]string{"seabios": filepath.Join(out, "qemu", "bios-256k.bin")}, + dir: t.TempDir(), + } + + // Same firmware, same initrd, same machine line: one argument differs. vmgenid stays on + // because it is on the machine this is asking about, and a floor kernel that cannot see + // the table still boots past it. + rows := []struct{ label, kernel, initrd string }{ + {label: "release", kernel: p.kernel}, + {label: "floor", kernel: floor}, + } + // The initrd's own decompression is inside every interval here, so it is a constant on + // both sides and does not move the difference the floor is for. It is worth one row of its + // own anyway: kernel/Dockerfile requires RD_LZ4 because unpacking the archive is one of the + // largest single items in kernel boot, and this says what that choice is worth on the same + // machine rather than on the general claim. + if lz4 := os.Getenv("SPIN_PROBE_INITRD_LZ4"); lz4 != "" { + rows = append(rows, struct{ label, kernel, initrd string }{ + label: "release+lz4", kernel: p.kernel, initrd: envFile(t, "SPIN_PROBE_INITRD_LZ4")}) + } + for _, r := range rows { + if st, err := os.Stat(r.kernel); err == nil { + t.Logf("%-12s kernel %.1f MiB, initrd %s", r.label, float64(st.Size())/(1<<20), + filepath.Base(orElse(p.initrd, r.initrd))) + } + } + + samples := map[string][]float64{} + for range reps { + for _, r := range rows { + v := p.start(t, "seabios", withVMGenID, "", r.kernel, r.initrd) + ms, err := v.wait("SPIN-READY", 15*time.Second) + v.close() + if err != nil { + t.Fatalf("%s: %v", r.label, err) + } + samples[r.label] = append(samples[r.label], ms) + } + } + + var b strings.Builder + fmt.Fprintf(&b, "\nmilliseconds from the moment before QEMU is exec'd to the initrd's "+ + "marker, p50/p95 over %d boots\n\n", reps) + fmt.Fprintf(&b, "%-12s %10s %10s\n", "ROW", "P50", "P95") + for _, r := range rows { + s := append([]float64(nil), samples[r.label]...) + sort.Float64s(s) + fmt.Fprintf(&b, "%-12s %10.2f %10.2f\n", r.label, pct(s, 50), pct(s, 95)) + } + rel := append([]float64(nil), samples["release"]...) + flr := append([]float64(nil), samples["floor"]...) + sort.Float64s(rel) + sort.Float64s(flr) + // Stated rather than left to the reader, because it is the number the next decision turns + // on: it is the whole of what this machine's kernel configuration could ever give back. + fmt.Fprintf(&b, "\nthe release kernel's configuration costs %.2f ms at p50\n", + pct(rel, 50)-pct(flr, 50)) + t.Log(b.String()) +} diff --git a/kernel/Taskfile.yml b/kernel/Taskfile.yml index 9fcaf07..ece4c4a 100644 --- a/kernel/Taskfile.yml +++ b/kernel/Taskfile.yml @@ -13,6 +13,8 @@ version: '3' vars: KERNEL_VERSION: sh: sed -n 's/^ARG KERNEL_VERSION="\{0,1\}\([^"]*\)"\{0,1\}/\1/p' kernel/Dockerfile + KERNEL_SHA256: + sh: sed -n 's/^ARG KERNEL_SHA256=//p' kernel/Dockerfile tasks: @@ -34,6 +36,29 @@ tasks: . - task: verify + minimal: + desc: >- + Build the floor kernel from kernel/minimal/ into _output/kernel-minimal/. An + experiment, not a release artefact: no BTF, BPF, ftrace, cgroups, ext4 or virtio, so + it cannot mount the base image or run systemd. What it is for is `task boot:floor`, + which compares it against the release kernel on a marker both can reach. + cmds: + - mkdir -p {{.OUTPUT_ABS}} + - | + docker buildx build \ + --file kernel/minimal/Dockerfile \ + --target extract \ + --platform linux/amd64 \ + --cache-from {{.KMIN_CACHE_FROM}} \ + --cache-to {{.KMIN_CACHE_TO}} \ + --build-arg KERNEL_VERSION={{.KERNEL_VERSION}} \ + --build-arg KERNEL_SHA256={{.KERNEL_SHA256}} \ + --build-arg KERNEL_ARCH={{.KERNEL_ARCH}} \ + --build-arg KERNEL_NPROC={{.KERNEL_NPROC}} \ + --output type=local,dest={{.OUTPUT_ABS}} \ + . + - cmd: echo "✓ {{.OUTPUT_ABS}}/kernel-minimal/vmlinux" + verify: desc: Assert the built kernel is one QEMU can enter and one this machine can boot. cmds: diff --git a/kernel/minimal/Dockerfile b/kernel/minimal/Dockerfile new file mode 100644 index 0000000..164765c --- /dev/null +++ b/kernel/minimal/Dockerfile @@ -0,0 +1,117 @@ +# The floor: the smallest kernel that still boots this machine, to measure what a kernel +# costs before anything is configured into it. +# +# ## Why a floor and not another removal +# +# Removing one subsystem at a time from the release config has now found zero four times in +# a row — CONFIG_VT, nineteen udev rule files, two device-count boot parameters, smaller TCP +# hash tables — and each of those cost a build or a bench run to learn. A floor says how much +# of the kernel phase is even available before anybody hunts for it: if the release kernel +# reaches the same marker in about what this one does, the config is not where the time is +# and the search should move. If the gap is large, the gap is the budget. +# +# ## Not a release kernel, and it could not be one +# +# Isolated from `task build` and `task release`, like qemu/qboot. It has no BTF, no BPF, no +# ftrace, no netfilter, no cgroups, no overlayfs, no ext4 and no virtio beyond nothing at +# all — so it cannot mount this machine's base image and cannot run systemd. That is the +# point of a floor, and it is why the comparison is made against a caller-supplied +# diagnostic initrd rather than against a login prompt: the marker has to be something both +# kernels can reach. +# +# Built from tinyconfig rather than by subtracting from the release config, because +# subtracting leaves whatever nobody thought to name — the same reason qemu/devices.mak is +# an allowlist. +ARG DEBIAN_IMAGE=debian:trixie@sha256:f324c7ff54321e8d9c588493a20244965938ce0aa50bbd1022d38010e9ffc4b1 +ARG DEBIAN_SNAPSHOT=20260914T000000Z + +FROM ${DEBIAN_IMAGE} AS builder + +ARG DEBIAN_SNAPSHOT +ENV DEBIAN_FRONTEND=noninteractive + +RUN echo 'Binary::apt::APT::Keep-Downloaded-Packages "true";' > /etc/apt/apt.conf.d/keep-cache +RUN rm -f /etc/apt/sources.list.d/debian.sources && cat > /etc/apt/sources.list.d/snapshot.sources <&2; \ + grep -n "CONFIG_${sym}" .config || true; exit 1; }; \ + done; \ + echo "symbols on: $(grep -c '=y$' .config), modules: $(grep -c '=m$' .config)" + +RUN cd linux && make ARCH=${KERNEL_ARCH} -j${KERNEL_NPROC} vmlinux && \ + cp .config /build/kernel-config && \ + strip --strip-debug -o /build/vmlinux vmlinux + +# What came out: the Xen PVH notes QEMU enters through, read from the stripped binary that +# will actually be booted rather than from the one before the strip. +RUN cd /build && \ + readelf -n vmlinux | grep -q "Xen" || { \ + echo "no Xen notes in the stripped vmlinux: QEMU has no entry point" >&2; exit 1; } && \ + ls -l vmlinux && readelf -n vmlinux | grep -A1 Xen | head -6 + +FROM scratch AS extract +COPY --from=builder /build/vmlinux /kernel-minimal/vmlinux +COPY --from=builder /build/kernel-config /kernel-minimal/kernel-config From e0254c53ad52a2160a6805ec72f5689b4a8e253a Mon Sep 17 00:00:00 2001 From: Manuel de Brito Fontes Date: Sat, 26 Sep 2026 12:51:15 -0300 Subject: [PATCH 09/18] boot: keep the conclusions near the code, not the sample tables MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit CLAUDE.md asks for durable evidence near a decision and for raw samples and short-lived exploration to live in a commit or a measurement record instead. The rows added over the last few commits went the other way: three blocks of p50/p95 tables from one afternoon's exploration, pasted beside the variants they came from. The numbers are in the commits that produced them; what belongs here is the claim and the regression it prevents. So the tables go and the warnings stay: that a critical chain is what finished last and never a list of savings, which is what stops the console-unit swap being tried again for 340 ms; and that udev's work overlaps the boot rather than delaying it. The "console no idle" row goes entirely. It existed to tell two candidates apart, it did, and CLAUDE.md asks that an experiment be removed once it has no active question. Its answer — Type=idle is not what the swap costs — is in the commit that added it. One correction, which is why this is not only a deletion. The comment said CONFIG_VT=n changes the time to a login prompt by nothing. That is true and it reads as "it is worth nothing", which is false: `task boot:floor` measures it at 2.09 ms of the kernel phase. This harness cannot resolve that through ~139 ms of userspace, so a kernel-config change belongs in boot:floor first and here only once a login prompt could show it. Four zeroes in a row were the instrument, not the changes. Co-Authored-By: Claude Opus 5 (1M context) --- boot/bench_test.go | 119 +++++++++------------------------------------ 1 file changed, 23 insertions(+), 96 deletions(-) diff --git a/boot/bench_test.go b/boot/bench_test.go index d379f82..1015dd7 100644 --- a/boot/bench_test.go +++ b/boot/bench_test.go @@ -215,41 +215,14 @@ var variants = []variant{ // The login prompt's own dependency on udev, which every row above pays including the // baseline: the drop-in they use sits on serial-getty@ttyS0, and that unit carries // `BindsTo=dev-ttyS0.device`. systemd-getty-generator instantiates it from console=ttyS0, - // so nothing has to enable it for it to be on the critical path. + // so nothing has to enable it for it to be on the critical path, and a critical chain + // puts dev-ttyS0.device at 128 ms. // - // Measured 2026-09-26 with `task boot:userspace`, 5 boots, p50 79 ms kernel + 139 ms - // userspace. The critical chain is the whole story: - // - // multi-user.target @129ms - // └─getty.target @129ms - // └─serial-getty@ttyS0.service @129ms - // └─dev-ttyS0.device @128ms - // - // and `blame` puts dev-vda.device at 109 ms, systemd-udevd at 33 and - // systemd-udev-trigger at 33. The prompt is waiting for udev's coldplug walk to announce - // a 16550 that is on the command line and cannot be absent. - // - // This row masks that unit and enables spin-machine-console.service, which the image - // already carries and which has no device dependency to wait for — the hole that unit's - // own comment says it is the wrong place to close. Same gettyEcho as the baseline, so - // what moves is the dependency and not agetty. - // - // It does not work, and that is why the row is here. 15 boots each, p50/p95 to a usable - // machine, 2026-09-26: - // - // baseline 259/386 console no dev 601/834 - // console no idle 583/1040 - // - // So the device dependency is not the cost: dropping it is 340 ms *worse*, and removing - // the replacement unit's Type=idle does not bring it back. `dev-ttyS0.device @128ms` on - // the critical chain is when udev got to the port, not something the prompt was waiting - // for — the same trap as `blame`, one line further down. Read a critical chain as what - // finished last, never as what was blocking. - // - // What the 340 ms is has not been established. It is suspiciously close to the 334 ms - // terminal-reset timeout that TERM=dumb exists to avoid (see machine/cmdline.go), and - // spin-machine-console.service carries TTYReset=yes and TTYVHangup=yes — but so does the - // unit it replaced, so that is a suspect and not an answer. + // Swapping it for spin-machine-console.service, which the image carries and which has no + // device dependency, is 340 ms *worse* — measured 2026-09-26, and not explained. Removing + // that unit's Type=idle does not recover it either. This row exists to stop the swap being + // tried again on the strength of the chain: a critical chain is what finished last, never + // a list of savings. labelled("console no dev", variant{cpus: "2", memory: "2048", mask: []string{"serial-getty@ttyS0.service"}, files: map[string]string{ @@ -258,73 +231,27 @@ var variants = []variant{ links: map[string]string{ "/etc/systemd/system/multi-user.target.wants/spin-machine-console.service": "/usr/lib/systemd/system/spin-machine-console.service", }}), - // The same, with the unit's Type=idle removed, which is what rules Type=idle out as the - // explanation for the row above: 583 against 601, inside the spread of either. Kept as - // the record of a candidate eliminated, so the next person reading that 340 ms does not - // spend the boots again. - labelled("console no idle", variant{cpus: "2", memory: "2048", - mask: []string{"serial-getty@ttyS0.service"}, - files: map[string]string{ - "/etc/systemd/system/spin-machine-console.service.d/zz-bench.conf": "[Service]\nType=simple\n" + gettyEcho, - }, - links: map[string]string{ - "/etc/systemd/system/multi-user.target.wants/spin-machine-console.service": "/usr/lib/systemd/system/spin-machine-console.service", - }}), - // Devices udev does not have to walk. - // - // `task boot:systemd` counted what udev coldplugs on this machine: 266 devices in a 51 ms - // window, with 18 occurrences of "Maximum number (14) of children reached" and, per - // worker, a failing dlopen of libnss_systemd.so.2 and a failing userdb group lookup. The - // families, counted 2026-09-26: - // - // 64 ttyN 16 memoryN 8 loopN 4 ttySN 4 cpuN 3 virtioN - // - // Three of those are for hardware this machine does not have. The 64 virtual consoles are - // CONFIG_VT on a machine whose QEMU has no VGA at all and whose console is ttyS0; the 8 - // loop devices are never used; and only one of the four 16550s exists. This row switches - // off the two that are boot parameters, because a parameter costs nothing to test and a - // kernel config change invalidates every template in existence — worth knowing the saving - // is real before anybody pays for it. + // Devices udev does not have to walk. udev coldplugs 266 of them on this machine, and + // three families are for hardware it does not have: 64 virtual consoles (CONFIG_VT, on a + // machine whose QEMU ships no VGA), 8 unused loop devices, and three of the four 16550s. + // This row switches off the two that are boot parameters. // - // It is not visible: 235/584 against the baseline's 239/423 over 15 boots, 2026-09-26. - // That is the arithmetic working out rather than a surprise — 11 devices of 266 is 4% of - // udev's ~46 ms, about 2 ms, which this harness cannot resolve. What it establishes is the - // shape of the cost: it is per device and there is no one device that matters. + // Neither this nor CONFIG_VT=n, which removes a quarter of the devices, changes the time + // to a login prompt — measured 2026-09-26, and the kernel was built to be sure. udev's + // work overlaps the boot rather than delaying it, so a ranking of who spent time in early + // userspace is not a list of savings either. // - // The prediction from that was CONFIG_VT=n — 64 of the 266 devices, 24%, so 5 to 12 ms of - // the 51 ms udev window with 14 workers in parallel. It was built and measured, and it is - // wrong. 15 boots each on a quiet host, 2026-09-26, p50/p95 to a usable machine: - // - // baseline 228/237 - // fewer devices 225/238 - // fewer udev rules 228/234 - // kernel B (VT=n) 228/246 - // - // Nothing. Not noise hiding it either: at a p95 of 237 a 10 ms saving would be visible. - // Removing a quarter of the devices udev walks, and nineteen of its rule files, changes - // the time to a login prompt by zero. - // - // Which means udev's 46 ms is not on the critical path. It runs up to 14 workers while - // other things happen, and taking work away from it gives the wall clock back to whatever - // it was overlapping with. That is the third time the same mistake has been made here in - // a different disguise: `blame` ranks units by their own duration, a critical chain ranks - // by what finished last, and `task boot:systemd` ranks writers by the time between their - // log lines. None of the three is a list of savings. The only way to find out what a boot - // costs is to take something out and measure, and every removal tried so far has bought - // nothing or cost a great deal. + // "Not at a login prompt" is the whole claim, and it is not the same as "not at all": + // `task boot:floor` puts CONFIG_VT=n at 2.09 ms of the kernel phase. This harness cannot + // see that, because it measures through ~139 ms of userspace whose own spread is wider. + // A kernel-config change belongs in boot:floor first, and only here once it is large + // enough that a login prompt could show it. labelled("fewer devices", variant{cpus: "2", memory: "2048", files: gettyDropin(gettyEcho), extra: "loop.max_loop=0 8250.nr_uarts=1"}), - // The other half of udev's work: not how many devices, but how many rules each one is - // matched against. This masks the 19 rule files above and changes nothing else. - // - // It is the image-side lever, which is what makes it worth trying before the kernel one: - // no symbol moves, so no template is invalidated, and if it pays it pays in image/ where - // static configuration belongs. - // - // It does not pay — 228/234 against the baseline's 228/237. Kept because the row is the - // only thing that says so, and because it is cheap to re-run against a future image whose - // rule set is larger. See the numbers under "fewer devices". + // The other half of udev's work: not how many devices, but how many rule files each one + // is matched against. 19 of the 49 are for hardware this machine cannot have. No effect + // either, measured the same day; see the row above for why. labelled("fewer udev rules", variant{cpus: "2", memory: "2048", files: gettyDropin(gettyEcho), links: maskedRules()}), From f85ae648bf285bfcfc1989ad56b002f264c424ba Mon Sep 17 00:00:00 2001 From: Manuel de Brito Fontes Date: Sat, 26 Sep 2026 13:01:52 -0300 Subject: [PATCH 10/18] kernel: erofs goes; nothing has mounted one since qcow2 replaced that path MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit CONFIG_EROFS_FS was there as the read-only half of a containerd path that qcow2 replaced. Nothing in this tree builds, mounts or names an erofs any more — the only references left were the assertion that required it and two comments listing the filesystem set. It brought CONFIG_EROFS_FS_ZIP with it, and with that LZMA at 16 streams, DEFLATE and ZSTD decompressors, for an image format this machine never reads. It buys no boot time, and that is not why it goes. Measured with `task boot:floor`, 20 boots each interleaved, 2026-09-26: 100.46 ms against 102.22 with it, which is noise in both directions. The stripped vmlinux is 48 KiB smaller, because the decompressors it pulled in have other users and stay. Dead configuration is worth removing for being dead; the measurement is here so nobody expects the change to pay for itself in milliseconds. The assertion is inverted rather than deleted, so the symbol coming back fails the build and names the reason instead of arriving unnoticed in a config refresh. This is a content change to the kernel, so it invalidates every template in existence. It should not be released on its own: CONFIG_VT=n measures 2.09 ms by the same probe and is not committed yet, and the fleet is better off paying for one fingerprint change than for two. Co-Authored-By: Claude Opus 5 (1M context) --- README.md | 4 ++-- image/build.sh | 4 ++-- kernel/Dockerfile | 14 +++++++++----- kernel/config-7.2.1-x86_64 | 2 +- 4 files changed, 14 insertions(+), 10 deletions(-) diff --git a/README.md b/README.md index 2ce26fd..a4809f5 100644 --- a/README.md +++ b/README.md @@ -326,8 +326,8 @@ the tools a workspace expects, and boot optimizations that were each measured `image/mkosi.extra/usr/local/lib/spin-base/optimize-systemd.sh` names the milliseconds every mask saved, and is an unmodified copy for that reason. -**ext4**, because the guest kernel has `EXT4_FS`, `EROFS_FS` and `OVERLAY_FS` and explicitly -not `XFS_FS`, `BTRFS_FS` or `SQUASHFS`. Anything else starts with a kernel config change one +**ext4**, because the guest kernel has `EXT4_FS` and `OVERLAY_FS` and explicitly not +`XFS_FS`, `BTRFS_FS`, `SQUASHFS` or `EROFS_FS`. Anything else starts with a kernel config change one directory over — which `kernel/Dockerfile` now asserts. **Partitionless**, not a bootable disk with an ESP and a GPT, which nothing here would read. diff --git a/image/build.sh b/image/build.sh index 8905d0c..eebeedb 100755 --- a/image/build.sh +++ b/image/build.sh @@ -12,8 +12,8 @@ # # which is the shape a chain of images is made of: one base, many overlays. # -# ext4 and not something denser: the guest kernel has EXT4_FS, EROFS_FS and OVERLAY_FS and -# explicitly not XFS_FS, BTRFS_FS or SQUASHFS (kernel/config-7.2.1-x86_64). Any other +# ext4 and not something denser: the guest kernel has EXT4_FS and OVERLAY_FS and explicitly +# not XFS_FS, BTRFS_FS, SQUASHFS or EROFS_FS (kernel/config-7.2.1-x86_64). Any other # filesystem here starts with a kernel config change one directory over. set -euo pipefail diff --git a/kernel/Dockerfile b/kernel/Dockerfile index 2e7a9c0..423ffca 100644 --- a/kernel/Dockerfile +++ b/kernel/Dockerfile @@ -145,12 +145,16 @@ RUN < Date: Sat, 26 Sep 2026 13:02:18 -0300 Subject: [PATCH 11/18] boot: measure the console swap from inside, and eliminate a third candidate MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The "console no dev" row costs 340 ms and nothing explained it. Two things here. consoleSwap() is extracted from the row so `task boot:systemd` can measure the same configuration instead of a second copy of it, which is what SPIN_SYSTEMD_VARIANT=console-swap now does. What it shows is not a dependency being waited on: early userspace runs about three times slower throughout — udevd 120 ms against 34.5, udevadm 60 against 11, systemd-sysctl 39 against 3 — and systemd's first logged line lands at 1009 ms instead of 409. And a third candidate eliminated. Both units carry TTYReset and TTYVHangup, but serial-getty@ waits for dev-%i.device where the replacement is ordered only after systemd-user-sessions, so the replacement resets and hangs up /dev/ttyS0 early in the boot rather than near the end of it, while systemd is still using that console. That is the shape that would degrade everything after it. It is not the cause: with TTYReset=no and TTYVHangup=no the swap measures 693 against 701. So: not the device dependency it was meant to remove, not Type=idle, not the tty handling. The cost is real and reproducible and the cause is unknown, which is worth saying plainly rather than leaving three plausible explanations standing. Co-Authored-By: Claude Opus 5 (1M context) --- boot/bench_test.go | 56 ++++++++++++++++++++++++++++++++------ boot/systemd_debug_test.go | 17 ++++++++++++ kernel/config-7.2.1-x86_64 | 4 +-- 3 files changed, 67 insertions(+), 10 deletions(-) diff --git a/boot/bench_test.go b/boot/bench_test.go index 1015dd7..81b43d1 100644 --- a/boot/bench_test.go +++ b/boot/bench_test.go @@ -128,6 +128,38 @@ func without(units ...string) variant { func labelled(l string, v variant) variant { v.label = l; return v } +// withDropin appends to the console unit's drop-in the swap already writes, so a row can vary +// one directive without restating the configuration. +func withDropin(v variant, body string) variant { + const path = "/etc/systemd/system/spin-machine-console.service.d/zz-bench.conf" + files := map[string]string{} + for k, val := range v.files { + files[k] = val + } + files[path] = files[path] + body + v.files = files + return v +} + +// consoleSwap is the configuration behind the "console no dev" row: serial-getty@ttyS0 +// masked and the image's own device-independent console unit enabled in its place, with the +// same cheap ExecStart the baseline uses so what differs is the unit and its ordering rather +// than agetty. +// +// A function rather than a literal in the row because `task boot:systemd` measures the same +// configuration to find out where its 340 ms goes, and two copies of it would be two things +// to keep in step. +func consoleSwap() variant { + return variant{cpus: "2", memory: "2048", + mask: []string{"serial-getty@ttyS0.service"}, + files: map[string]string{ + "/etc/systemd/system/spin-machine-console.service.d/zz-bench.conf": "[Service]\n" + gettyEcho, + }, + links: map[string]string{ + "/etc/systemd/system/multi-user.target.wants/spin-machine-console.service": "/usr/lib/systemd/system/spin-machine-console.service", + }} +} + func withFile(m map[string]string, path, content string) map[string]string { m[path] = content return m @@ -223,14 +255,22 @@ var variants = []variant{ // that unit's Type=idle does not recover it either. This row exists to stop the swap being // tried again on the strength of the chain: a critical chain is what finished last, never // a list of savings. - labelled("console no dev", variant{cpus: "2", memory: "2048", - mask: []string{"serial-getty@ttyS0.service"}, - files: map[string]string{ - "/etc/systemd/system/spin-machine-console.service.d/zz-bench.conf": "[Service]\n" + gettyEcho, - }, - links: map[string]string{ - "/etc/systemd/system/multi-user.target.wants/spin-machine-console.service": "/usr/lib/systemd/system/spin-machine-console.service", - }}), + labelled("console no dev", consoleSwap()), + // The swap with the tty handling taken out, which was the third hypothesis for its cost + // and is wrong like the other two: 693 against the swap's 701 over 12 boots, 2026-09-26. + // + // What `task boot:systemd SPIN_SYSTEMD_VARIANT=console-swap` shows is not one blocking + // dependency but the whole of early userspace running about three times slower — udevd + // 120 ms against 34.5, udevadm 60 against 11, systemd-sysctl 39 against 3 — and its first + // logged line at 1009 ms against 409. Whatever the swap does, it degrades everything + // after it rather than waiting on something. + // + // Eliminated so far: the device dependency it was supposed to remove, the replacement + // unit's Type=idle, and its TTYReset/TTYVHangup — which both units carry anyway, so it + // could never have been a difference between them. The row stays because the cost is real + // and the cause is not known. + labelled("console no tty reset", withDropin(consoleSwap(), + "TTYReset=no\nTTYVHangup=no\n")), // Devices udev does not have to walk. udev coldplugs 266 of them on this machine, and // three families are for hardware it does not have: 64 virtual consoles (CONFIG_VT, on a // machine whose QEMU ships no VGA), 8 unused loop devices, and three of the four 16550s. diff --git a/boot/systemd_debug_test.go b/boot/systemd_debug_test.go index 92f2f0b..888b763 100644 --- a/boot/systemd_debug_test.go +++ b/boot/systemd_debug_test.go @@ -40,6 +40,12 @@ import ( // SPIN_SYSTEMD_DEBUG=1 run at all // TOP= how many gaps to print (default 25) // GAP= ignore gaps under this (default 2) +// SPIN_SYSTEMD_VARIANT=console-swap +// measure the "console no dev" configuration instead of the default +// one, which is the only open question about it: the swap costs +// 340 ms and a static diff of the two units does not explain it. +// Both units carry TTYReset and TTYVHangup, so the terminal-reset +// timeout cannot be a difference between them. 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") @@ -83,6 +89,17 @@ WantedBy=multi-user.target }, } + if os.Getenv("SPIN_SYSTEMD_VARIANT") == "console-swap" { + sw := consoleSwap() + v.mask = sw.mask + for k, val := range sw.files { + v.files[k] = val + } + for k, val := range sw.links { + v.links[k] = val + } + v.label += " + console swap" + } 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 { diff --git a/kernel/config-7.2.1-x86_64 b/kernel/config-7.2.1-x86_64 index 2106a75..13ec184 100644 --- a/kernel/config-7.2.1-x86_64 +++ b/kernel/config-7.2.1-x86_64 @@ -995,7 +995,7 @@ CONFIG_ARCH_ENABLE_THP_MIGRATION=y CONFIG_PCP_BATCH_SCALE_MAX=5 CONFIG_PHYS_ADDR_T_64BIT=y CONFIG_MMU_NOTIFIER=y -CONFIG_KSM=y +# CONFIG_KSM is not set CONFIG_DEFAULT_MMAP_MIN_ADDR=4096 CONFIG_ARCH_SUPPORTS_MEMORY_FAILURE=y # CONFIG_MEMORY_FAILURE is not set @@ -1003,7 +1003,7 @@ CONFIG_ARCH_WANT_GENERAL_HUGETLB=y CONFIG_ARCH_WANTS_THP_SWAP=y # CONFIG_PERSISTENT_HUGE_ZERO_FOLIO is not set CONFIG_MM_ID=y -CONFIG_TRANSPARENT_HUGEPAGE=y +# CONFIG_TRANSPARENT_HUGEPAGE is not set # CONFIG_TRANSPARENT_HUGEPAGE_ALWAYS is not set CONFIG_TRANSPARENT_HUGEPAGE_MADVISE=y # CONFIG_TRANSPARENT_HUGEPAGE_NEVER is not set From 662a170e92c6e4e4a1887dad221148b5b07b3576 Mon Sep 17 00:00:00 2001 From: Manuel de Brito Fontes Date: Sat, 26 Sep 2026 13:18:55 -0300 Subject: [PATCH 12/18] image: TERM=dumb on the console unit, which is worth 331 ms MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit spin-machine-console.service cost 331 ms whenever it was used, and three explanations were measured and wrong before the console named the fourth itself. On a swapped boot the bytes before the login prompt are ESC P + q 6 E 6 1 6 D 6 5 ESC backslash an XTGETTCAP asking for the capability whose name is the hex string 6E616D65, "name", with nothing after it until the wait expires. That is the 334 ms terminfo timeout machine/cmdline.go already puts TERM=dumb on the kernel command line to avoid: the far end of this serial port is a file and never answers. The parameter reaches systemd and not this unit. systemd sets TERM itself for a service that declares its own TTYPath rather than passing its own environment down, so the unit gets a terminal type that looks capable and the tty setup asks. One Environment= line fixes it: 221/233 against 558/572 without, over 12 boots, with a baseline of 227/236. Without it the unit is unusable; with it it costs nothing. Which reopens something. spin-machine-console.service's own comment says the hole it leaves is one this file is the wrong place to close, and the bench row that tried closing it read 340 ms worse. That row now reads 224/230 against the baseline's 227/241. The device-independent console unit is viable; what stands between it and production is the exposure question that comment raises, not a boot cost. What the localisation took, since the wrong reading came first: with DEBUG=1 the bench shows FIRMWARE, KERNEL, PID1 and STARTED identical between the two configurations and only USABLE moving, so the cost was entirely after systemd finished. An earlier reading of `task boot:systemd` had suggested the whole of early userspace running three times slower; that was the debug probe inflating its own window, not the machine. Three candidates are recorded as eliminated rather than kept as rows: the device dependency the swap removes, the unit's Type=idle, and its TTYReset/TTYVHangup, which both units carry and so could never have been a difference between them. The same timeout was tried on the real getty — TERM=dumb on serial-getty@ttyS0 changes nothing, 1229 against 1232 — so the second that `as shipped` reads is agetty's own sleep. Co-Authored-By: Claude Opus 5 (1M context) --- boot/bench_test.go | 38 +++++++++---------- boot/userspace_test.go | 18 +++++++++ .../system/spin-machine-console.service | 14 +++++++ 3 files changed, 50 insertions(+), 20 deletions(-) diff --git a/boot/bench_test.go b/boot/bench_test.go index 81b43d1..bf7247d 100644 --- a/boot/bench_test.go +++ b/boot/bench_test.go @@ -166,6 +166,10 @@ func withFile(m map[string]string, path, content string) map[string]string { } var variants = []variant{ + // The image as it is, with a real agetty rather than the echo every row below uses. It + // reads about a second slower and that is agetty's own sleep, not a fault to hunt: the + // terminfo timeout found on spin-machine-console.service was tried here too and + // TERM=dumb on this unit changes nothing (1229 against 1232, 12 boots, 2026-09-26). {label: "as shipped", cpus: "2", memory: "2048"}, {label: "baseline", cpus: "2", memory: "2048", files: gettyDropin(gettyEcho)}, // The critical chain into multi-user.target, measured 2026-09-10: @@ -247,30 +251,24 @@ var variants = []variant{ // The login prompt's own dependency on udev, which every row above pays including the // baseline: the drop-in they use sits on serial-getty@ttyS0, and that unit carries // `BindsTo=dev-ttyS0.device`. systemd-getty-generator instantiates it from console=ttyS0, - // so nothing has to enable it for it to be on the critical path, and a critical chain - // puts dev-ttyS0.device at 128 ms. + // so nothing has to enable it for it to be on the critical path. // // Swapping it for spin-machine-console.service, which the image carries and which has no - // device dependency, is 340 ms *worse* — measured 2026-09-26, and not explained. Removing - // that unit's Type=idle does not recover it either. This row exists to stop the swap being - // tried again on the strength of the chain: a critical chain is what finished last, never - // a list of savings. - labelled("console no dev", consoleSwap()), - // The swap with the tty handling taken out, which was the third hypothesis for its cost - // and is wrong like the other two: 693 against the swap's 701 over 12 boots, 2026-09-26. + // device dependency, costs nothing: 221/233 against the baseline's 227/236 over 12 boots, + // 2026-09-26. So the hole that unit's own comment describes can be closed after all. // - // What `task boot:systemd SPIN_SYSTEMD_VARIANT=console-swap` shows is not one blocking - // dependency but the whole of early userspace running about three times slower — udevd - // 120 ms against 34.5, udevadm 60 against 11, systemd-sysctl 39 against 3 — and its first - // logged line at 1009 ms against 409. Whatever the swap does, it degrades everything - // after it rather than waiting on something. + // It did not look that way. Without TERM=dumb the same swap is 558/572, and three + // explanations were measured and wrong before the console named the fourth itself — the + // device dependency the swap removes, the unit's Type=idle, and its TTYReset/TTYVHangup, + // which both units carry anyway and so could never have been a difference between them. + // What it is: systemd sets TERM for a service declaring its own TTYPath rather than + // passing its own down, so machine/cmdline.go's TERM=dumb does not reach this unit, and + // the tty setup waits out the 334 ms terminfo timeout asking a serial port with a file + // behind it what it can do. // - // Eliminated so far: the device dependency it was supposed to remove, the replacement - // unit's Type=idle, and its TTYReset/TTYVHangup — which both units carry anyway, so it - // could never have been a difference between them. The row stays because the cost is real - // and the cause is not known. - labelled("console no tty reset", withDropin(consoleSwap(), - "TTYReset=no\nTTYVHangup=no\n")), + // The drop-in mirrors the Environment=TERM=dumb now in image/, and goes when an image + // carrying it is what _output holds. + labelled("console no dev", withDropin(consoleSwap(), "Environment=TERM=dumb\n")), // Devices udev does not have to walk. udev coldplugs 266 of them on this machine, and // three families are for hardware it does not have: 64 virtual consoles (CONFIG_VT, on a // machine whose QEMU ships no VGA), 8 unused loop devices, and three of the four 16550s. diff --git a/boot/userspace_test.go b/boot/userspace_test.go index 7a535fe..c2c864b 100644 --- a/boot/userspace_test.go +++ b/boot/userspace_test.go @@ -27,6 +27,12 @@ import ( // // SPIN_USERSPACE_PROBE=1 run at all // REPS= boots to take (default 5) +// SPIN_SYSTEMD_VARIANT=console-swap +// measure the "console no dev" configuration. Its 331 ms lands +// entirely after `Startup finished` — every phase before that is +// unchanged — so the question is whether the login process starts +// late or starts on time and its bytes are held. systemd's own +// accounting is the only side that can say. 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") @@ -66,6 +72,18 @@ WantedBy=multi-user.target }, } + if os.Getenv("SPIN_SYSTEMD_VARIANT") == "console-swap" { + sw := consoleSwap() + v.mask = sw.mask + for k, val := range sw.files { + v.files[k] = val + } + for k, val := range sw.links { + v.links[k] = val + } + v.label += " + console swap" + } + var kernel, userspace, total []float64 var last string for range reps { diff --git a/image/mkosi.extra/usr/local/lib/spin-base/rootfs/usr/lib/systemd/system/spin-machine-console.service b/image/mkosi.extra/usr/local/lib/spin-base/rootfs/usr/lib/systemd/system/spin-machine-console.service index 62d624b..93fa101 100644 --- a/image/mkosi.extra/usr/local/lib/spin-base/rootfs/usr/lib/systemd/system/spin-machine-console.service +++ b/image/mkosi.extra/usr/local/lib/spin-base/rootfs/usr/lib/systemd/system/spin-machine-console.service @@ -50,6 +50,20 @@ IgnoreOnIsolate=yes # locked, because a password in a filesystem every VM boots read-only is one credential # shared by all of them. Anyone who can attach to this port already holds the VM's disk and # chose its kernel, so a prompt here would guard nothing. +# TERM=dumb, and it is worth 331 ms. +# +# machine/cmdline.go puts TERM=dumb on the kernel command line because a terminal that asks +# a serial port what it can do waits out a 334 ms timeout when the far end is a file rather +# than a terminal. That parameter reaches systemd and does not reach here: systemd sets TERM +# itself for a service that declares its own TTYPath, so this unit gets a terminal type that +# looks capable and something on the tty path asks. The query is visible on the console as +# an XTGETTCAP for the capability named 6E616D65 — "name" — with nothing after it until the +# timeout expires. +# +# Measured 2026-09-26, 12 boots each, p50/p95 to a login prompt, with this unit in place of +# serial-getty@ttyS0: 558/572 without this line and 221/233 with it, against a baseline of +# 227/236. Without it the unit is unusable; with it, it costs nothing. +Environment=TERM=dumb ExecStart=-/usr/sbin/agetty --noreset --noclear --autologin root --keep-baud 115200 ttyS0 $TERM Type=idle Restart=always From 74dfd728abfeda02f26d54d4036cc8fbb1ec1a17 Mon Sep 17 00:00:00 2001 From: Manuel de Brito Fontes Date: Sat, 26 Sep 2026 13:23:02 -0300 Subject: [PATCH 13/18] kernel: KSM and THP are not the remaining candidate either MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `task boot:initcalls` puts ksm_init at 2.00 ms, hugepage_init at 2.00 and kcompactd_init at 2.00, which made the memory-management options look like the largest config change still available. A kernel with CONFIG_KSM and CONFIG_TRANSPARENT_HUGEPAGE off, on top of the erofs removal, measures -0.50 ms against the release kernel at `task boot:floor` — 93.09 against 93.60 over 20 interleaved boots, 2026-09-26. Nothing, on the instrument that resolves the 2.09 ms CONFIG_VT=n is worth. The round 2.00 values are the tell: that is what initcall_debug resolves at CONFIG_HZ=1000, not what those initcalls cost. A per-initcall duration is no more a list of savings than `systemd-analyze blame` is. COMPACTION is not available at all, which the build found before compiling anything: CONFIG_VIRTIO_MEM depends on CONTIG_ALLOC, and that is def_bool (MEMORY_ISOLATION && COMPACTION) || CMA, so compaction is what this machine's memory resize path rides on. The VIRTIO_MEM assertion is what caught it. Recorded in kernel/Dockerfile beside the other candidates measured and rejected, because finding this out costs a kernel build. Co-Authored-By: Claude Opus 5 (1M context) --- kernel/Dockerfile | 13 +++++++++++++ 1 file changed, 13 insertions(+) diff --git a/kernel/Dockerfile b/kernel/Dockerfile index 423ffca..ccd7cf1 100644 --- a/kernel/Dockerfile +++ b/kernel/Dockerfile @@ -219,6 +219,19 @@ RUN < Date: Sat, 26 Sep 2026 13:30:16 -0300 Subject: [PATCH 14/18] boot: the number of unit files is not the boot, and the caches are already warm MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A systemd issue about unit-file cache rescanning looked like it might be this machine's: the message it reports — "Modification times have changed, need to update cache" — is in this image's debug log, twice per boot, and systemd says it spends 212 ms loading units and determining the initial transaction. It is not, and two checks say so. The persistent caches are built at image time and the services that would rebuild them at boot are masked in optimize-systemd.sh: ld.so.cache at 9975 bytes, the journal catalog at 274807, locale-archive at 3064432, and systemd-update-done, systemd-hwdb-update, systemd-journal-catalog-update, ldconfig and systemd-sysusers all symlinked to /dev/null. There is no pre-warm missing. The unit cache is not one of these: it is names and modification times held in memory for the length of one boot, with no on-disk artefact to build, and it is rescanned because the generators write into /run/systemd/generator.late, which is in the search path. That is how systemd starts. And the count is not the cost. A row adding 300 unit files that nothing wants — against 282 in /usr/lib/systemd/system and 65 in /etc/systemd/system — measures 236 against the baseline's 246. The distinction worth keeping is that systemd's cache holds names, not parsed units, so a unit nothing references is scanned and never loaded: this measures the scan, and the scan is free. Parsing is only for units something pulls in, and those cannot be added without starting them too. The variant struct gains `setup`, one shell run with the overlay mounted, because three hundred files through one `sudo tee` each would take longer than the boots they prepare. It runs under `set -u` with $MNT passed through sudo's own assignment rather than the child environment, which sudo resets — the first version failed on the unset variable, and without -u it would have written 300 unit files into the host's /etc/systemd/system. Co-Authored-By: Claude Opus 5 (1M context) --- boot/bench_test.go | 44 +++++++++++++++++++++++++++++++++++++++++++- 1 file changed, 43 insertions(+), 1 deletion(-) diff --git a/boot/bench_test.go b/boot/bench_test.go index bf7247d..943bd5e 100644 --- a/boot/bench_test.go +++ b/boot/bench_test.go @@ -28,6 +28,7 @@ type variant struct { links map[string]string // symbolic links made in the overlay: path under / -> target kernel string // a kernel other than the release's, for comparing configs profile bool // boot with `--profile`: initcall profiling, console silent + setup string // shell run with the overlay mounted, $MNT its root } // Masks are written into the overlay and never passed as `systemd.mask=`. That parameter is @@ -293,6 +294,33 @@ var variants = []variant{ labelled("fewer udev rules", variant{cpus: "2", memory: "2048", files: gettyDropin(gettyEcho), links: maskedRules()}), + // What loading a unit file costs, measured by adding some. + // + // systemd reports "Loaded units and determined initial transaction in 212ms" on this + // machine, and what precedes it is "Modification times have changed, need to update cache" + // right after /run/systemd/generator.late — the generators write into the search path, so + // the cache systemd built moments earlier is stale and it rescans. That is how systemd + // starts, not a cache this image failed to pre-build: the persistent ones (ld.so.cache, + // the journal catalog, locale-archive) are built at image time and the services that would + // rebuild them are masked in optimize-systemd.sh. + // + // So the question is whether the *number* of units is what costs. The image carries 282 in + // /usr/lib/systemd/system and 65 in /etc/systemd/system, and this row adds 300 more that + // nothing wants. It costs nothing: 236 against the baseline's 246 over 12 boots, + // 2026-09-26, on a run whose p95s were wide enough that a per-unit cost of any size would + // still have shown at nearly double the count. + // + // What that does and does not settle, because the two are easy to confuse. systemd's unit + // cache holds names and modification times, not parsed units, and a unit nothing + // references is scanned and never loaded. So this measures the scan, and the scan is free. + // It does not measure parsing, which happens only for units something pulls in — and + // those cannot be added without also starting them, which would measure something else. + // + // The row stays because "we ship 282 unit files, that must be the boot" is a conclusion + // somebody will reach again, and this is the only thing that says it was measured. + labelled("300 more units", variant{cpus: "2", memory: "2048", + files: gettyDropin(gettyEcho), + setup: "for i in $(seq 1 300); do printf '[Unit]\\nDescription=filler %s\\n[Service]\\nType=oneshot\\nExecStart=/bin/true\\n' \"$i\" > \"$MNT/etc/systemd/system/spin-filler-$i.service\"; done"}), // What a tmpfs /tmp and the boot's tmpfiles pass cost against the /tmp on the disk the // image once shipped, which every copy of the disk carried. 20 boots of each, 2026-09-26, // p50/p95 to a usable machine: baseline 223/230, this row 220/232 - 3 ms, within noise. @@ -510,7 +538,7 @@ func bootOnce(t *testing.T, out string, v variant) boot.Run { 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) - if len(v.mask) > 0 || len(v.files) > 0 { + if len(v.mask) > 0 || len(v.files) > 0 || len(v.links) > 0 || v.setup != "" { editOverlay(t, overlay, v) } @@ -608,6 +636,20 @@ func editOverlay(t *testing.T, overlay string, v variant) { t.Fatalf("writing %s: %v\n%s", path, err, out) } } + // One shell with the overlay mounted, for a variant that needs hundreds of files rather + // than a handful. The files map writes each path through its own `sudo tee`, which is + // right for a drop-in and wrong for three hundred units: the setup would take longer than + // the boots it is preparing. + if v.setup != "" { + // MNT through sudo's own assignment rather than the child's environment: sudo resets + // the environment, so cmd.Env reached sh with MNT unset and the snippet failed under + // `set -u` — which is the good case. Without -u it would have written 300 unit files + // into the host's /etc/systemd/system. + cmd := exec.Command("sudo", "MNT="+mnt, "sh", "-euc", v.setup) + if out, err := cmd.CombinedOutput(); err != nil { + t.Fatalf("setting up %s: %v\n%s", v.label, err, out) + } + } for path, target := range v.links { // A mask only masks something. udev reads /etc/udev/rules.d before // /usr/lib/udev/rules.d and a file of the same name shadows the one below it, so a From ea8e0864f9d52b80c5390d5d57bd2a900e67a393 Mon Sep 17 00:00:00 2001 From: Manuel de Brito Fontes Date: Sat, 26 Sep 2026 13:34:23 -0300 Subject: [PATCH 15/18] boot: ask systemd what unit loading costs, and it is 26 ms not 212 MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A systemd issue about unit-cache rescanning pointed at "Loaded units and determined initial transaction in 212ms", which this image's debug log reports. Reading where that message comes from was cheaper than measuring around it. src/core/main.c brackets manager_startup() and do_queue_default_job(), and logs at LOG_DEBUG — except under `--test`, where it logs at LOG_INFO. So systemd will report the number without the debug logging that produced it, and in test mode it does only that work: nothing is started and manager_preset_all is skipped. `systemd --test --system`, seven runs inside one boot, says 26 ms. The 212 was the measurement's own logging, inflating by about eight times — the fourth time today that observing a boot has been most of what a boot appeared to cost. Masking two generators that cannot do anything on this machine — the tpm2 one, whose libtss2-esys.so.0 the boot log says cannot be opened, and the factory-reset one, on a machine the same log says is not booted in EFI mode — is 1.0 ms of that 26. Seven of the thirteen the image carries are masked already. And manager_preset_all does not run here, which the source explains and the logs confirm: it needs first_boot, systemd decides that from /etc/machine-id, and this image ships that file present and empty rather than absent or containing "uninitialized" — so systemd reads an initialised system and skips the preset pass. An empty machine-id is load-bearing for more than rule 3. The probe runs as nobody because systemd refuses test mode for root, which also makes its absolute number a floor for what PID 1 pays: no cgroup setup, no inherited descriptors, nothing to deserialise. It is for the order of magnitude and for the difference between two configurations, and it fails rather than measuring the wrong user if privileges cannot be dropped. Co-Authored-By: Claude Opus 5 (1M context) --- Taskfile.yml | 10 +++ boot/unitload_test.go | 164 ++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 174 insertions(+) create mode 100644 boot/unitload_test.go diff --git a/Taskfile.yml b/Taskfile.yml index 0b7d226..98d208e 100644 --- a/Taskfile.yml +++ b/Taskfile.yml @@ -214,6 +214,16 @@ tasks: cmds: - SPIN_INITCALL_PROBE=1 go test ./boot/ -run TestKernelInitcalls -count=1 -v -timeout 30m + boot:unitload: + desc: >- + What systemd spends loading units and building the initial transaction, from its own + instrumentation: `systemd --test` reports it at LOG_INFO where a real boot logs it at + LOG_DEBUG. Many runs inside one boot, so there is no boot-to-boot noise, and it + measures the generators by masking two that cannot do anything on this machine. Needs + KVM, a built release and sudo. + cmds: + - SPIN_UNITLOAD_PROBE=1 go test ./boot/ -run TestUnitLoadCost -count=1 -v -timeout 15m + boot:userspace: desc: >- systemd's own account of the boot: its kernel/userspace split, `blame` and the diff --git a/boot/unitload_test.go b/boot/unitload_test.go new file mode 100644 index 0000000..939ec6f --- /dev/null +++ b/boot/unitload_test.go @@ -0,0 +1,164 @@ +// SPDX-License-Identifier: Apache-2.0 + +package boot_test + +import ( + "fmt" + "os" + "regexp" + "sort" + "strings" + "testing" + "time" +) + +// What systemd spends loading units and building the initial transaction, and what the +// generators cost inside it. +// +// The number comes from systemd itself. src/core/main.c brackets manager_startup() and +// do_queue_default_job() and logs "Loaded units and determined initial transaction in %s" — +// at LOG_DEBUG normally, and at LOG_INFO under `--test`. So `systemd --test --system` reports +// it without the debug logging that inflates every other way of seeing it, and it does only +// that work: MANAGER_IS_TEST_RUN skips the preset pass and nothing is started. +// +// Which makes this a paired measurement inside one boot rather than a boot per sample. That +// matters more than it sounds: two boots on this host have read 59.5 and 167.7 ms for the +// same kernel, and nothing about generators is a 100 ms effect. +// +// What manager_startup() does, from the source rather than from a guess: +// lookup_paths_init, the environment generators, the generators, manager_preset_all, +// manager_enumerate (device units out of udev, mount units out of mountinfo), deserialize, +// fd distribution. preset_all does not run here — it needs first_boot, and systemd decides +// that from /etc/machine-id, which this image ships present and empty rather than absent or +// "uninitialized", so systemd reads it as an initialised system. +// +// SPIN_UNITLOAD_PROBE=1 run at all +// REPS= `systemd --test` runs per configuration (default 7) +func TestUnitLoadCost(t *testing.T) { + if os.Getenv("SPIN_UNITLOAD_PROBE") == "" { + t.Skip("set SPIN_UNITLOAD_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", 7) + + // Masked, not removed, and both are generators that cannot do anything on this machine: + // the tpm2 one because there is no TPM — the boot log says libtss2-esys.so.0 cannot be + // opened — and the factory-reset one because this machine is not booted in EFI mode, which + // the log also says. Seven of the thirteen the image carries are masked already. + const masked = "systemd-tpm2-generator systemd-factory-reset-generator" + + // Not as root: systemd refuses test mode for the root user outright ("Don't run test mode + // as root."), so this drops to nobody with setpriv. The generators and the unit files are + // world readable, and both configurations run as the same user, so the comparison holds + // even where a generator behaves differently without privileges. + // + // It also means the absolute number is a floor for what PID 1 pays: this run sets up no + // cgroups, inherits no file descriptors and deserialises nothing. What it is for is the + // order of magnitude and the difference between two configurations, and it fails rather + // than measuring the wrong user if setpriv cannot drop privileges. + script := fmt.Sprintf(`set -u +AS="setpriv --reuid=65534 --regid=65534 --clear-groups" +$AS true || { echo "setpriv cannot drop to nobody, nothing to measure" >&2; exit 1; } +run() { + i=0 + while [ $i -lt %d ]; do + $AS /usr/lib/systemd/systemd --test --system 2>&1 | grep -F 'initial transaction' + i=$((i+1)) + done +} +{ + echo SPIN-UNITLOAD-BEGIN + echo TAG:generators-on + run + mkdir -p /etc/systemd/system-generators + for g in %s; do ln -sf /dev/null "/etc/systemd/system-generators/$g"; done + echo TAG:generators-masked + run + echo SPIN-UNITLOAD-END +} > /dev/ttyS0 2>&1 +`, reps, masked) + + v := variant{ + label: "unit load", cpus: "2", memory: "2048", + files: map[string]string{ + "/usr/local/bin/spin-unitload": script, + "/etc/systemd/system/spin-unitload.service": `[Unit] +Description=Measure systemd's unit load with and without two generators +After=multi-user.target +[Service] +Type=simple +StandardOutput=null +ExecStart=/bin/sh /usr/local/bin/spin-unitload +[Install] +WantedBy=multi-user.target +`, + }, + links: map[string]string{ + "/etc/systemd/system/multi-user.target.wants/spin-unitload.service": "/etc/systemd/system/spin-unitload.service", + }, + } + + console := bootUntil(t, out, v, "", "SPIN-UNITLOAD-END", 180*time.Second) + reportUnitLoad(t, console, reps) +} + +// "Loaded units and determined initial transaction in 212ms." — and systemd's spelling of a +// duration varies with its size, so this takes the same route mustDur does. +var reLoaded = regexp.MustCompile(`initial transaction in ([^.]+)\.`) + +func reportUnitLoad(t *testing.T, console string, reps int) { + t.Helper() + samples := map[string][]float64{} + var order []string + var tag string + for _, line := range strings.Split(console, "\n") { + line = strings.TrimSpace(strings.TrimRight(line, "\r")) + if i := strings.Index(line, "TAG:"); i >= 0 { + tag = line[i+4:] + order = append(order, tag) + continue + } + m := reLoaded.FindStringSubmatch(line) + if m == nil || tag == "" { + continue + } + samples[tag] = append(samples[tag], mustDur(t, m[1])) + } + if len(samples) < 2 { + t.Fatalf("expected two tagged sets of `systemd --test` output, got %d; console tail:\n%s", + len(samples), tail([]byte(console), 1500)) + } + + var b strings.Builder + fmt.Fprintf(&b, "\nsystemd's own \"loaded units and determined initial transaction\", "+ + "p50/p95 over %d runs in one boot\n\n", reps) + fmt.Fprintf(&b, "%-20s %8s %8s %6s\n", "CONFIGURATION", "P50", "P95", "N") + var first, second float64 + for i, tag := range dedup(order) { + s := append([]float64(nil), samples[tag]...) + sort.Float64s(s) + fmt.Fprintf(&b, "%-20s %8.1f %8.1f %6d ms\n", tag, pct(s, 50), pct(s, 95), len(s)) + if i == 0 { + first = pct(s, 50) + } else if i == 1 { + second = pct(s, 50) + } + } + fmt.Fprintf(&b, "\ntwo generators masked: %.1f ms\n", first-second) + t.Log(b.String()) +} + +func dedup(in []string) []string { + seen := map[string]bool{} + var out []string + for _, s := range in { + if !seen[s] { + seen[s] = true + out = append(out, s) + } + } + return out +} From bfe9b17076fc17accb37f9f24eec975e8adb288a Mon Sep 17 00:00:00 2001 From: Manuel de Brito Fontes Date: Sat, 26 Sep 2026 13:41:22 -0300 Subject: [PATCH 16/18] boot: disable unnecessary systemd generators and virtual console support for optimized VM performance --- .../usr/local/lib/spin-base/optimize-systemd.sh | 10 ++++++++++ kernel/Dockerfile | 9 +++++++++ kernel/config-7.2.1-x86_64 | 2 +- 3 files changed, 20 insertions(+), 1 deletion(-) 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 1344065..6c2fcaa 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 @@ -162,6 +162,16 @@ DISABLE_GENERATORS=( systemd-rc-local-generator systemd-hibernate-resume-generator systemd-system-update-generator + # Two that cannot do anything on this machine, and the boot log says so in both cases: + # the tpm2 one reports that libtss2-esys.so.0 cannot be opened, and the factory-reset one + # runs on a machine systemd itself logs as not booted in EFI mode. + # + # Worth 1.0 ms of the 26 ms systemd spends loading units and building the initial + # transaction — measured 2026-09-26 with `task boot:unitload`, which asks systemd for that + # number through `systemd --test` rather than reading it out of a debug-logged boot. The + # same number read from a debug boot is 212 ms, and that difference is the logging. + systemd-tpm2-generator + systemd-factory-reset-generator ) for gen in "${DISABLE_GENERATORS[@]}"; do diff --git a/kernel/Dockerfile b/kernel/Dockerfile index ccd7cf1..e403daf 100644 --- a/kernel/Dockerfile +++ b/kernel/Dockerfile @@ -155,6 +155,15 @@ RUN < Date: Sat, 26 Sep 2026 13:48:37 -0300 Subject: [PATCH 17/18] kernel: CONFIG_VT off as dead configuration, and a number withdrawn MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit CONFIG_VT builds 64 tty devices on a machine whose QEMU ships no VGA at all and whose console is one 16550 on ttyS0. Nothing opens them and udev walks them on every boot — a quarter of the 266 devices it coldplugs. It goes for the same reason erofs went: it is dead, and this release is already paying one fingerprint change for that removal, so it costs nothing more to take both. It is not off because it is slow, and the number that said otherwise is withdrawn. An earlier 20-boot run of `task boot:floor` put CONFIG_VT=n at 2.09 ms, and two commits quoted it — the erofs one as a reason to bundle the two, and the KSM one as the instrument's resolution. It does not reproduce: 40 interleaved boots on an idle host read 0.31 ms for erofs and CONFIG_VT together. The 2.09 was measured while this host was building a kernel, and at this size a single run of that probe is a guess. So the standing claim is narrower and duller: nothing found in this configuration is worth more than about half a millisecond. The 45.6 ms between this kernel and the floor one in kernel/minimal/ is BTF, ACPI and ftrace, and BPF and hotplug need all three. Also masked, in image/: systemd-tpm2-generator and systemd-factory-reset-generator, the two of the six still running that cannot do anything here — the boot log says libtss2-esys.so.0 cannot be opened and that this machine is not booted in EFI mode. Worth 1.0 ms of the 26 ms systemd spends loading units, by `task boot:unitload`. That one is an image change and invalidates nothing. Co-Authored-By: Claude Opus 5 (1M context) --- boot/firmware_test.go | 10 +++++----- boot/floor_test.go | 20 +++++++++++++++----- kernel/Dockerfile | 25 +++++++++++++++++-------- 3 files changed, 37 insertions(+), 18 deletions(-) diff --git a/boot/firmware_test.go b/boot/firmware_test.go index 921e7f1..17fd917 100644 --- a/boot/firmware_test.go +++ b/boot/firmware_test.go @@ -140,7 +140,7 @@ type vm struct { qmp string } -func (p *probe) start(t *testing.T, variant string, gen bool, incoming, kernel, initrd string) *vm { +func (p *probe) start(t *testing.T, variant string, gen bool, incoming, kernel, initrd, cpu string) *vm { t.Helper() p.n++ qmp := filepath.Join(p.dir, fmt.Sprintf("qmp-%d.sock", p.n)) @@ -152,7 +152,7 @@ func (p *probe) start(t *testing.T, variant string, gen bool, incoming, kernel, args := []string{ "-L", p.firmware, "-machine", "q35,sata=off,smbus=off", - "-accel", "kvm", "-cpu", "host", + "-accel", "kvm", "-cpu", orElse("host", cpu), "-m", "2048", "-smp", "2", "-nodefaults", "-display", "none", "-serial", "stdio", "-monitor", "none", "-qmp", "unix:" + qmp + ",server=on,wait=off", @@ -218,7 +218,7 @@ func (v *vm) close() { func (p *probe) reach(t *testing.T, variant string, gen bool, marker string, timeout time.Duration) (float64, error) { t.Helper() - v := p.start(t, variant, gen, "", "", "") + v := p.start(t, variant, gen, "", "", "", "") defer v.close() return v.wait(marker, timeout) } @@ -242,7 +242,7 @@ func (p *probe) mustReach(t *testing.T, variant string, gen bool, marker string) // reports a fault. func (p *probe) mustPublishVMGenID(t *testing.T) { t.Helper() - v := p.start(t, "patched", withVMGenID, "", "", "") + v := p.start(t, "patched", withVMGenID, "", "", "", "") ms, err := v.wait("SPIN-READY", 8*time.Second) if err != nil { v.close() @@ -263,7 +263,7 @@ func (p *probe) mustPublishVMGenID(t *testing.T) { q.close() v.close() - r := p.start(t, "patched", withVMGenID, state, "", "") + r := p.start(t, "patched", withVMGenID, state, "", "", "") defer r.close() q = dial(t, r.qmp, r) defer q.close() diff --git a/boot/floor_test.go b/boot/floor_test.go index 08f50f2..01e2a15 100644 --- a/boot/floor_test.go +++ b/boot/floor_test.go @@ -54,7 +54,7 @@ func TestKernelFloor(t *testing.T) { // Same firmware, same initrd, same machine line: one argument differs. vmgenid stays on // because it is on the machine this is asking about, and a floor kernel that cannot see // the table still boots past it. - rows := []struct{ label, kernel, initrd string }{ + rows := []struct{ label, kernel, initrd, cpu string }{ {label: "release", kernel: p.kernel}, {label: "floor", kernel: floor}, } @@ -64,20 +64,30 @@ func TestKernelFloor(t *testing.T) { // largest single items in kernel boot, and this says what that choice is worth on the same // machine rather than on the general claim. if lz4 := os.Getenv("SPIN_PROBE_INITRD_LZ4"); lz4 != "" { - rows = append(rows, struct{ label, kernel, initrd string }{ + rows = append(rows, struct{ label, kernel, initrd, cpu string }{ label: "release+lz4", kernel: p.kernel, initrd: envFile(t, "SPIN_PROBE_INITRD_LZ4")}) } + // A named CPU model instead of the host's, which the machine already supports for a + // different reason: `-cpu host` shows the guest this host's silicon, so a template cannot + // move between machines, and Spec.Identity hashes the host CPU only in that case. What it + // costs at boot was never measured, and QEMU has to enumerate the host's CPUID and build + // the guest's from it either way — this says whether the migratable choice is also the + // cheaper one. + if cpu := os.Getenv("SPIN_CPU_MODEL"); cpu != "" { + rows = append(rows, struct{ label, kernel, initrd, cpu string }{ + label: "named cpu", kernel: p.kernel, cpu: cpu}) + } for _, r := range rows { if st, err := os.Stat(r.kernel); err == nil { - t.Logf("%-12s kernel %.1f MiB, initrd %s", r.label, float64(st.Size())/(1<<20), - filepath.Base(orElse(p.initrd, r.initrd))) + t.Logf("%-12s kernel %.1f MiB, initrd %s, cpu %s", r.label, float64(st.Size())/(1<<20), + filepath.Base(orElse(p.initrd, r.initrd)), orElse("host", r.cpu)) } } samples := map[string][]float64{} for range reps { for _, r := range rows { - v := p.start(t, "seabios", withVMGenID, "", r.kernel, r.initrd) + v := p.start(t, "seabios", withVMGenID, "", r.kernel, r.initrd, r.cpu) ms, err := v.wait("SPIN-READY", 15*time.Second) v.close() if err != nil { diff --git a/kernel/Dockerfile b/kernel/Dockerfile index e403daf..6fc515a 100644 --- a/kernel/Dockerfile +++ b/kernel/Dockerfile @@ -158,11 +158,16 @@ RUN < Date: Sat, 26 Sep 2026 13:57:52 -0300 Subject: [PATCH 18/18] boot: the two largest items in QEMU's startup are cold-boot only MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The ~27 ms between exec'ing QEMU and the guest's first instruction had a breakdown but no attribution, and two attempts to find something reducible in it came back empty: 321 ioctls are issued before the first KVM_RUN, which cannot be the 12 ms of accel, realize and ACPI build, and a perf profile bounded to the first 85 ms puts QEMU's own code at 3.67%. What it is, is the host. kernel_init_pages — zeroing pages as guest RAM is faulted in — is 18.8% of a cold start over twelve launches. On a restore it is 3.0%, with next_uptodate_folio and filemap_get_entry in its place: the template's memory arrives as mapped file pages instead of fresh anonymous ones. rom_reset's 6 ms goes the same way and QEMU says so in its own source rather than leaving it to be measured, skipping every ROM under RUN_STATE_INMIGRATE "because we'll fill the data in during the next incoming migration in all cases". The caveat on the comparison: the cold window includes the guest executing and the restore window does not, since a machine started with -incoming waits in inmigrate for a cont. The item in dispute is in the setup phase of both. So the largest cost in this phase is the host giving a machine memory it does not have yet, which is not a configuration problem, and the thing that avoids it is a template — at 2 GiB on disk each, not sparse, plus ~92 MiB of device state, fast to restore only while that file is in the host's page cache, and coupled to exactly one fingerprint. Recorded where the breakdown is so the next person reading those five lines knows which two a restore does not pay. Co-Authored-By: Claude Opus 5 (1M context) --- boot/phases.go | 15 +++++++++++++++ 1 file changed, 15 insertions(+) diff --git a/boot/phases.go b/boot/phases.go index 74aa0a3..2e0d7b3 100644 --- a/boot/phases.go +++ b/boot/phases.go @@ -77,6 +77,21 @@ const ( // ~6 ms rom_reset copying the kernel's 36 MB, at ~6 GB/s // ~2 ms cont to the first vCPU entering the guest // + // Two of those five are paid only by a cold boot, and it is worth knowing before anybody + // hunts for savings in them. Profiled 2026-09-26 with perf over twelve 85 ms launches, + // kernel_init_pages — the host zeroing pages as guest RAM is faulted in — is 18.8% of a + // cold start and 3.0% of a restore, where next_uptodate_folio and filemap_get_entry + // replace it: the template's memory arrives as mapped file pages rather than fresh + // anonymous ones. rom_reset's 6 ms goes the same way, and QEMU says so in hw/core/loader.c + // rather than leaving it to be measured — it skips every ROM under RUN_STATE_INMIGRATE + // "because we'll fill the data in during the next incoming migration in all cases". + // + // So the largest item here is the host setting up memory for a machine that does not have + // any yet, and that is not a configuration problem. What it costs to avoid is a template: + // 2 GiB on disk per template, not sparse, plus ~92 MiB of device state, restored fast only + // while that file is in the host's page cache — and one fingerprint's worth of coupling, + // since a template restores into this machine and no other. + // // There is no gap after machine init, and an earlier version of this comment said there // was — it read "~8 ms to a QMP round trip" and put ~14 ms after it. The 8 ms was the QMP // *greeting*, which the monitor emits from qemu_create_late_backends() at vl.c:3835,