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/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/README.md b/README.md index 945f996..a4809f5 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 @@ -324,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/Taskfile.yml b/Taskfile.yml index 61a693d..98d208e 100644 --- a/Taskfile.yml +++ b/Taskfile.yml @@ -121,6 +121,13 @@ 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. + # 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}}' 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 +205,63 @@ 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: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 + 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: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/. + 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/bench_test.go b/boot/bench_test.go index 2f029bb..943bd5e 100644 --- a/boot/bench_test.go +++ b/boot/bench_test.go @@ -19,13 +19,16 @@ 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 + 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 + 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 @@ -34,6 +37,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", @@ -84,12 +129,48 @@ 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 } 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: @@ -168,12 +249,108 @@ 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. + // + // Swapping it for spin-machine-console.service, which the image carries and which has no + // 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. + // + // 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. + // + // 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. + // This row switches off the two that are boot parameters. + // + // 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. + // + // "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 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()}), + // 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. 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 @@ -190,6 +367,7 @@ func TestBootCost(t *testing.T) { } out := releaseDir(t) reps := envInt(t, "REPS", 20) + withKernelVariant(t) if !canSudo() { for _, v := range variants { @@ -360,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) } @@ -375,9 +553,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. @@ -454,7 +636,34 @@ 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 + // 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) diff --git a/boot/firmware_test.go b/boot/firmware_test.go new file mode 100644 index 0000000..17fd917 --- /dev/null +++ b/boot/firmware_test.go @@ -0,0 +1,452 @@ +// 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, kernel, initrd, cpu 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", orElse("host", cpu), + "-m", "2048", "-smp", "2", + "-nodefaults", "-display", "none", "-serial", "stdio", "-monitor", "none", + "-qmp", "unix:" + qmp + ",server=on,wait=off", + "-bios", p.bios[variant], + "-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", + } + 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] +} + +// 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..01e2a15 --- /dev/null +++ b/boot/floor_test.go @@ -0,0 +1,118 @@ +// 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, cpu 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, 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, 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, r.cpu) + 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/boot/initcalls_test.go b/boot/initcalls_test.go new file mode 100644 index 0000000..02f4c73 --- /dev/null +++ b/boot/initcalls_test.go @@ -0,0 +1,488 @@ +// 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. +// +// 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 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") + } + 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 +` + addKernelVariant(t) + + base := variant{ + cpus: "2", memory: "2048", + 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 := map[string][]parsed{} + for i := range reps { + for _, cv := range cmdlineVariants { + v := base + v.label = cv.label + // 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 + // 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) + } + runs[cv.label] = append(runs[cv.label], parse(t, console)) + } + } + compare(t, runs) + report(t, runs[cmdlineVariants[0].label], 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, kernel, 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 + } + 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) + } + 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() + 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 +} + +// 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 + 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) +} 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, diff --git a/boot/systemd_debug_test.go b/boot/systemd_debug_test.go new file mode 100644 index 0000000..888b763 --- /dev/null +++ b/boot/systemd_debug_test.go @@ -0,0 +1,236 @@ +// 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) +// 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") + } + 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", + }, + } + + 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 { + 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/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 +} diff --git a/boot/userspace_test.go b/boot/userspace_test.go new file mode 100644 index 0000000..c2c864b --- /dev/null +++ b/boot/userspace_test.go @@ -0,0 +1,168 @@ +// 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) +// 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") + } + 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", + }, + } + + 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 { + 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 +} 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/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/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 diff --git a/kernel/Dockerfile b/kernel/Dockerfile index 2e7a9c0..6fc515a 100644 --- a/kernel/Dockerfile +++ b/kernel/Dockerfile @@ -145,12 +145,30 @@ RUN <- + 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/config-7.2.1-x86_64 b/kernel/config-7.2.1-x86_64 index 55338f2..9a47184 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 @@ -2239,7 +2239,7 @@ CONFIG_SERIO_LIBPS2=y # Character devices # CONFIG_TTY=y -CONFIG_VT=y +# CONFIG_VT is not set CONFIG_CONSOLE_TRANSLATIONS=y CONFIG_VT_CONSOLE=y # CONFIG_VT_HW_CONSOLE_BINDING is not set @@ -3271,7 +3271,7 @@ CONFIG_MISC_FILESYSTEMS=y # CONFIG_ROMFS_FS is not set # CONFIG_PSTORE is not set # CONFIG_UFS_FS is not set -CONFIG_EROFS_FS=y +# CONFIG_EROFS_FS is not set # CONFIG_EROFS_FS_DEBUG is not set CONFIG_EROFS_FS_XATTR=y CONFIG_EROFS_FS_POSIX_ACL=y 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 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(); + }