diff --git a/boot/initcalls_test.go b/boot/initcalls_test.go index 939a530..ff0c1e7 100644 --- a/boot/initcalls_test.go +++ b/boot/initcalls_test.go @@ -9,12 +9,15 @@ import ( "os/exec" "path/filepath" "regexp" + "slices" "sort" "strconv" "strings" "syscall" "testing" "time" + + "github.com/spin-stack/spin-machine/boot" ) // Where the kernel's own boot goes, initcall by initcall. @@ -59,6 +62,9 @@ import ( // SPIN_FORMAT_CHECK=: // fail a boot whose event format still names an enum the eval maps // replace, e.g. timer/hrtimer_start:HRTIMER_MODE_ +// SPIN_EARLY=1 print the kernel's lines before its first initcall, each at its p50 +// stamp over the boots, with the gap to the next: early boot, which +// function_graph cannot see because it runs before ftrace_init // SPIN_CPU_SHARE= after that, SHARE_REPS (default 3) boots per kernel with the // scheduler traced: who had the CPU while initcall fn ran func TestKernelInitcalls(t *testing.T) { @@ -140,6 +146,7 @@ WantedBy=multi-user.target } runs := map[string][]parsed{} + consoles := map[string][]string{} for i := range reps { for _, cv := range cvs { v := base @@ -168,9 +175,15 @@ WantedBy=multi-user.target } } runs[cv.label] = append(runs[cv.label], parse(t, console)) + consoles[cv.label] = append(consoles[cv.label], console) } } compare(t, cvs, runs) + if os.Getenv("SPIN_EARLY") != "" { + for _, cv := range cvs { + t.Logf("\n%s, the kernel before its first initcall:\n%s", cv.label, earlyBoot(consoles[cv.label])) + } + } report(t, runs[cvs[0].label], top, reps) if fns := os.Getenv("SPIN_GRAPH"); fns != "" { graphReport(t, out, base, fns, envInt(t, "GRAPH_REPS", 3), envInt(t, "GRAPH_DEPTH", 3)) @@ -498,3 +511,64 @@ func countUnion(runs []parsed) int { } return len(seen) } + +// earlyBoot lines up the dmesg lines every boot printed before its first initcall by their p50 +// stamp, with the gap from each to the next. A line is named by its text with digits blanked, +// so "Memory: 2012345K" in one boot and "Memory: 2012349K" in the next are one line; a line +// fewer than half the boots printed is left out. +func earlyBoot(consoles []string) string { + stamp := regexp.MustCompile(`^\[\s*([0-9]+\.[0-9]+)\] (.*)$`) + digits := regexp.MustCompile(`[0-9]+`) + at := map[string][]time.Duration{} + text := map[string]string{} + for _, c := range consoles { + seen := map[string]bool{} + for l := range strings.SplitSeq(c, "\n") { + m := stamp.FindStringSubmatch(strings.TrimRight(l, "\r")) + if m == nil { + continue + } + if strings.HasPrefix(m[2], "calling ") { + break + } + key := digits.ReplaceAllString(m[2], "#") + if len(key) > 90 { + key = key[:90] + } + if seen[key] { + continue + } + seen[key] = true + sec, _ := strconv.ParseFloat(m[1], 64) + at[key] = append(at[key], time.Duration(sec*float64(time.Second))) + text[key] = m[2] + } + } + type line struct { + p50 time.Duration + text string + } + var lines []line + for k, ds := range at { + if 2*len(ds) < len(consoles) { + continue + } + p, _ := boot.Percentile(ds, .5) + lines = append(lines, line{p, text[k]}) + } + slices.SortFunc(lines, func(a, b line) int { return cmp.Compare(a.p50, b.p50) }) + var b strings.Builder + fmt.Fprintf(&b, " %9s %8s %s\n", "AT (ms)", "GAP", "LINE (the gap is to the next line)") + for i, l := range lines { + gap := "" + if i+1 < len(lines) { + gap = fmt.Sprintf("%.2f", float64(lines[i+1].p50-l.p50)/float64(time.Millisecond)) + } + txt := l.text + if len(txt) > 110 { + txt = txt[:110] + } + fmt.Fprintf(&b, " %9.2f %8s %s\n", float64(l.p50)/float64(time.Millisecond), gap, txt) + } + return b.String() +} diff --git a/docs/log.md b/docs/log.md index b075232..8550125 100644 --- a/docs/log.md +++ b/docs/log.md @@ -327,6 +327,16 @@ Measured and not shipped: #250 also removes `boot:bench`, `boot:trace`, `boot:userspace`, `boot:systemd` and `boot:ssh-load`, keeping "a gate …, the release's report, the metric a workspace waits for (ssh-first), and one tool per layer". +**11-13 · goal · #251, #252, #254.** The goal is written down: a cold boot to the first SSH login in under 100 ms (AGENTS.md), with restore as the second number. The rules that held exploration back are removed (no init in a release, the fingerprint as an event to avoid, one default per experiment, the bench fleet alone deciding); hotplug and dynamic memory become an invariant that is never traded for boot time. + +**11-13 · boot probes · branch `floor-kernel` (experiment).** The floor without systemd: PID 1 a script that mounts what sshd needs, makes an Ed25519 key and has socat hand vsock connections to `sshd -i`. First login 467 → 220 ms (lab 43492686353), 506 → 240 (lab 43493135230); guest uptime puts init at ~90 ms of kernel and the keys 10-20 ms later. What is left at the floor: QEMU and firmware ~44 ms (boot:firmware-stages, lab 43494513791: QEMU's own start 35.9, qboot ~8.5, of QEMU's start 7.9 copying vmlinux), kernel ~80-90, init ~20, the login ~44. `/proc/uptime` starts partway into the kernel, so it hides ~35 ms that an earlier reading charged to QEMU. + +**11-13 · CI · spin-stack/ci#14, #15, spin-machine#253.** A `bench-metal` fleet (c8i.metal-48xl, then r7i.metal-24xl behind it) and lab.yml's `host` input. It has not run: metal spot scored 1-3 of 10 for placement and failed `UnfulfillableCapacity` in every zone; on-demand failed `VcpuLimitExceeded` at a quota of 96 vCPU. An increase to 288 was requested the same day (case open). + +**11-13 · kernel · #255 (this change).** Where the kernel's ~100 ms goes on the bench fleet (boot:initcalls lab 43495583323): initcalls 52 (acpi_init 12, of which `acpi_pci_root_create` - bus 0's enumeration - 11.2 traced on a kernel without forced lockdown, lab 43499868986; inet_init 7.9, which is vmlinux BTF's first parse; the virtio probes ~17), before the first initcall ~15-20 (SPIN_EARLY, lab 43507472288; ~4 of it the probe's own 18 MB log buffer), SMP ~4, the root mount ~6. Kept: patch 0005 back, 0006 (BTF parsed in the background from a core_initcall), `CONFIG_DEFERRED_STRUCT_PAGE_INIT=y`: kernel 96.3 → 87.1 ms (lab 43505126131), first login 466 → 456 as built and 223 → 214 at the floor (lab 43501992969). `driver_async_probe` for rng, balloon and vsock on the command line: 214 → 209 at the floor (lab 43506390106). + +**11-13 · kernel/qemu · branches `kernel-snapshot`, `qemu-snapshot` (rejected).** QEMU publishes bus 0's configuration space over fw_cfg after the firmware (etc/spin/pci-config) and the kernel answers boot-time configuration reads from it until each dword is written. It works (`PCI: configuration space of 5 devices on bus 0`) and is worth -14 ms against the same kernel without it (lab 43514550646), but only 2-3 ms against 0005, which already removes most repeated reads: 209/217 against 211/222 (lab 43514884598). Not worth a QEMU patch and a 250-line kernel patch. + --- ## 3. Rework cycles @@ -500,6 +510,8 @@ Also the reusable builder, added and reverted on 10-13. | Vsock socket + sshd@ without default deps | No sooner; dropped 7 of 22 first connections (laptop) | `boot/ssh_first_test.go:124-128` | 11-13 | | mapped-ram checkpoints (multifd ×4) | Restore login 385/400 vs 386/399 | #246, lab 43483852339 | 11-13 | | sntrup761 (OpenSSH default) | 104 vs 40 ms per login | #245, lab 43479854381 | 11-13 | +| Configuration-space snapshot over fw_cfg (QEMU + kernel) | 209 vs 211 with 0005 | lab 43514884598 | 11-13 | +| Lower the vCPU ceiling, drop the balloon or ACPI for boot time | Not tried: hotplug and dynamic memory are an invariant | AGENTS.md | 11-13 | --- diff --git a/kernel/Dockerfile b/kernel/Dockerfile index 9629dd2..9b9c23e 100644 --- a/kernel/Dockerfile +++ b/kernel/Dockerfile @@ -290,9 +290,12 @@ RUN < 78.5 ms; with # patches/0004 (PCI configuration through ECAM, one trap an access), 73.7. - # A patch that walked each device's capability list once rather than per search took the - # kernel 95.1 -> 88.9 ms (lab run 43327612594, 2026-11-12) and was dropped on 2026-11-13: a - # first SSH login is ~470 ms, and 6 ms of it was not worth a local patch to carry. + # patches/0005 has each device's capability list walked once rather than per search: the + # kernel 95.1 -> 88.9 ms (lab run 43327612594, 2026-11-12). Dropped and brought back on + # 2026-11-13: against a goal of 100 ms to the first SSH login, 6 ms is 6% of it. + # patches/0006 parses vmlinux BTF in the background from a core_initcall instead of inside + # inet_init on the boot CPU, where it was 11.2 of inet_init's 11.8 ms traced (lab run + # 43498943572). # Boot performance: the RAID6 PQ benchmark probes all SIMD implementations at boot to # pick the fastest. It must stay disabled. (RAID6_PQ itself is not selected today, so diff --git a/kernel/config-7.3-x86_64 b/kernel/config-7.3-x86_64 index f9f0e44..ffc4658 100644 --- a/kernel/config-7.3-x86_64 +++ b/kernel/config-7.3-x86_64 @@ -1031,7 +1031,7 @@ CONFIG_HAVE_SETUP_PER_CPU_AREA=y # CONFIG_CMA is not set CONFIG_PAGE_BLOCK_MAX_ORDER=10 CONFIG_GENERIC_EARLY_IOREMAP=y -# CONFIG_DEFERRED_STRUCT_PAGE_INIT is not set +CONFIG_DEFERRED_STRUCT_PAGE_INIT=y # CONFIG_IDLE_PAGE_TRACKING is not set CONFIG_ARCH_HAS_CACHE_LINE_SIZE=y CONFIG_ARCH_HAS_CURRENT_STACK_POINTER=y diff --git a/kernel/patches/0005-PCI-Remember-a-device-s-standard-capability-list.patch b/kernel/patches/0005-PCI-Remember-a-device-s-standard-capability-list.patch new file mode 100644 index 0000000..3bf4ad7 --- /dev/null +++ b/kernel/patches/0005-PCI-Remember-a-device-s-standard-capability-list.patch @@ -0,0 +1,169 @@ +From: Manuel de Brito Fontes +Date: Thu, 12 Nov 2026 19:45:27 -0300 +Subject: [PATCH 5/6] PCI: Remember a device's standard capability list + +pci_find_capability() reads the status register and walks the +capability list from its start on every call, and +pci_find_next_capability() walks from where it is told. A device is +asked for its capabilities a dozen times or more while it is set up +(PM, MSI, MSI-X, VPD, EA, the reset methods, the PCIe port type) and +again by its driver: virtio-pci looks for four vendor capabilities, each +search a walk of its own. Each step of a walk is a configuration read. + +Under a hypervisor every configuration read is a trap. On this machine +each virtio-pci device took about 240 of them while it was set up, some +110 of which walked the same list again - the status register, the +pointer and six links, fourteen to sixteen times. + +Walk the list once in pci_setup_device(), keep each capability's ID and +offset in struct pci_dev, and answer both searches from there. A +position the list does not hold falls back to walking configuration +space, as does pci_bus_find_capability(), which has no pci_dev to keep +anything in. + +Measured on QEMU's q35 with three virtio-pci devices, nested under KVM +on an AWS c8i.4xlarge, 20 boots interleaved: ECAM accesses per boot +1,032 -> 680, kernel start to "Freeing unused kernel image" 95.1 -> +88.9 ms p50, acpi_init 14 -> 10 ms, virtio_pci_driver_init 6.5 -> 4.7 +ms; inet_init, which reads no configuration space, 7.50 -> 7.49 ms. +It costs 98 bytes in every struct pci_dev. + +The list is read before the early fixups run, so a quirk that changes +which capabilities a device shows would leave it stale. This kernel +runs only in a QEMU guest, where no such quirk applies. + +Local patch for this machine. Not upstream. + +Assisted-by: LLM +--- + drivers/pci/pci.c | 57 +++++++++++++++++++++++++++++++++++++++++++++ + drivers/pci/pci.h | 2 ++ + drivers/pci/probe.c | 1 + + include/linux/pci.h | 4 ++++ + 4 files changed, 64 insertions(+) + +diff --git a/drivers/pci/pci.c b/drivers/pci/pci.c +index f852564..691c73d 100644 +--- a/drivers/pci/pci.c ++++ b/drivers/pci/pci.c +@@ -420,6 +420,20 @@ static u8 __pci_find_next_cap(struct pci_bus *bus, unsigned int devfn, + + u8 pci_find_next_capability(struct pci_dev *dev, u8 pos, int cap) + { ++ int i; ++ ++ if (dev->cap_cached) { ++ for (i = 0; i < dev->cap_count && dev->cap_pos[i] != pos; i++) ++ ; ++ /* A position the list does not hold is the caller's own walk. */ ++ if (i < dev->cap_count) { ++ while (++i < dev->cap_count) ++ if (dev->cap_id[i] == cap) ++ return dev->cap_pos[i]; ++ return 0; ++ } ++ } ++ + return __pci_find_next_cap(dev->bus, dev->devfn, + pos + PCI_CAP_LIST_NEXT, cap); + } +@@ -467,6 +481,14 @@ static u8 __pci_bus_find_cap_start(struct pci_bus *bus, + u8 pci_find_capability(struct pci_dev *dev, int cap) + { + u8 pos; ++ int i; ++ ++ if (dev->cap_cached) { ++ for (i = 0; i < dev->cap_count; i++) ++ if (dev->cap_id[i] == cap) ++ return dev->cap_pos[i]; ++ return 0; ++ } + + pos = __pci_bus_find_cap_start(dev->bus, dev->devfn, dev->hdr_type); + if (pos) +@@ -503,6 +525,41 @@ u8 pci_bus_find_capability(struct pci_bus *bus, unsigned int devfn, int cap) + } + EXPORT_SYMBOL(pci_bus_find_capability); + ++/** ++ * pci_cache_capabilities - read a device's standard capability list once ++ * @dev: PCI device whose header type is known ++ * ++ * Walks the list the way PCI_FIND_NEXT_CAP() does - the same TTL, the same ++ * stop at an ID of 0xff - and keeps each capability's ID and offset, so that ++ * pci_find_capability() and pci_find_next_capability() answer from memory ++ * instead of walking configuration space again. ++ */ ++void pci_cache_capabilities(struct pci_dev *dev) ++{ ++ int ttl = PCI_FIND_CAP_TTL; ++ u8 pos, id; ++ u16 ent; ++ ++ dev->cap_count = 0; ++ pos = __pci_bus_find_cap_start(dev->bus, dev->devfn, dev->hdr_type); ++ if (pos) ++ pci_bus_read_config_byte(dev->bus, dev->devfn, pos, &pos); ++ ++ while (ttl-- && pos >= PCI_STD_HEADER_SIZEOF && ++ dev->cap_count < ARRAY_SIZE(dev->cap_id)) { ++ pos = ALIGN_DOWN(pos, 4); ++ pci_bus_read_config_word(dev->bus, dev->devfn, pos, &ent); ++ id = FIELD_GET(PCI_CAP_ID_MASK, ent); ++ if (id == 0xff) ++ break; ++ dev->cap_id[dev->cap_count] = id; ++ dev->cap_pos[dev->cap_count++] = pos; ++ pos = FIELD_GET(PCI_CAP_LIST_NEXT_MASK, ent); ++ } ++ ++ dev->cap_cached = true; ++} ++ + /** + * pci_find_next_ext_capability - Find an extended capability + * @dev: PCI device to query +diff --git a/drivers/pci/pci.h b/drivers/pci/pci.h +index ba3c3fd..f23ea45 100644 +--- a/drivers/pci/pci.h ++++ b/drivers/pci/pci.h +@@ -18,6 +18,8 @@ struct pcie_tlp_log; + + #define PCI_FIND_CAP_TTL 48 + ++void pci_cache_capabilities(struct pci_dev *dev); ++ + #define PCI_VSEC_ID_INTEL_TBT 0x1234 /* Thunderbolt */ + + #define PCIE_LINK_RETRAIN_TIMEOUT_MS 1000 +diff --git a/drivers/pci/probe.c b/drivers/pci/probe.c +index 52a79b0..a0e6232 100644 +--- a/drivers/pci/probe.c ++++ b/drivers/pci/probe.c +@@ -2031,6 +2031,7 @@ int pci_setup_device(struct pci_dev *dev) + dev->dev.bus = &pci_bus_type; + dev->hdr_type = FIELD_GET(PCI_HEADER_TYPE_MASK, hdr_type); + dev->multifunction = FIELD_GET(PCI_HEADER_TYPE_MFD, hdr_type); ++ pci_cache_capabilities(dev); + dev->error_state = pci_channel_io_normal; + set_pcie_port_type(dev); + +diff --git a/include/linux/pci.h b/include/linux/pci.h +index 272378d..fbaa2fc 100644 +--- a/include/linux/pci.h ++++ b/include/linux/pci.h +@@ -370,6 +370,10 @@ struct pci_dev { + unsigned int class; /* 3 bytes: (base,sub,prog-if) */ + u8 revision; /* PCI revision, low byte of class word */ + u8 hdr_type; /* PCI header type (`multi' flag masked out) */ ++ u8 cap_count; /* Entries in cap_id[] and cap_pos[] */ ++ bool cap_cached; /* The standard capability list is in cap_id[] */ ++ u8 cap_id[48]; /* Standard capability IDs, in list order */ ++ u8 cap_pos[48]; /* and their offsets in configuration space */ + #ifdef CONFIG_PCIEAER + u16 aer_cap; /* AER capability offset */ + struct aer_info *aer_info; /* AER info for this device */ +-- +2.53.0 + diff --git a/kernel/patches/0006-bpf-Parse-vmlinux-BTF-in-the-background-during-boot.patch b/kernel/patches/0006-bpf-Parse-vmlinux-BTF-in-the-background-during-boot.patch new file mode 100644 index 0000000..dde1337 --- /dev/null +++ b/kernel/patches/0006-bpf-Parse-vmlinux-BTF-in-the-background-during-boot.patch @@ -0,0 +1,61 @@ +From: Manuel de Brito Fontes +Date: Fri, 13 Nov 2026 17:30:00 -0300 +Subject: [PATCH 6/6] bpf: Parse vmlinux BTF in the background during boot + +vmlinux BTF is parsed lazily, by the first caller of +bpf_get_btf_vmlinux(). During boot that is an initcall on the boot CPU: +inet_init, through xfrm_init and register_xfrm_state_bpf(), and the +parse is all of its time - 11.2 of inet_init's 11.8 ms under +function_graph, nested under KVM on an AWS c8i.4xlarge. + +Start the parse from a core_initcall with async_schedule(), once the +secondary CPUs are up, so it runs beside the subsys and fs initcalls +instead of inside one. Its first caller still takes btf_vmlinux_lock +and waits for whatever of the parse is left. + +Local patch for this machine. Not upstream. + +Assisted-by: LLM +--- + kernel/bpf/verifier.c | 21 +++++++++++++++++++++ + 1 file changed, 21 insertions(+) + +--- a/kernel/bpf/verifier.c ++++ b/kernel/bpf/verifier.c +@@ -33,6 +33,7 @@ + #include + #include + #include ++#include + + #include "diagnostics.h" + #include "disasm.h" +@@ -20712,6 +20713,26 @@ + } + + /* ++ * Parse vmlinux BTF in the background as soon as the secondary CPUs are up, ++ * rather than on the boot CPU inside whichever initcall first asks for it ++ * (inet_init, through register_xfrm_state_bpf()). The first caller of ++ * bpf_get_btf_vmlinux() still takes btf_vmlinux_lock and so waits for the ++ * parse if it is not done yet; nothing changes for it but when. ++ */ ++static void __init btf_vmlinux_parse_async(void *data, async_cookie_t cookie) ++{ ++ bpf_get_btf_vmlinux(); ++} ++ ++static int __init btf_vmlinux_parse_early(void) ++{ ++ if (IS_ENABLED(CONFIG_DEBUG_INFO_BTF)) ++ async_schedule(btf_vmlinux_parse_async, NULL); ++ return 0; ++} ++core_initcall(btf_vmlinux_parse_early); ++ ++/* + * The add_fd_from_fd_array() is executed only if fd_array_cnt is non-zero. In + * this case expect that every file descriptor in the array is either a map or + * a BTF. Everything else is considered to be trash. +-- +2.51.0 diff --git a/machine/cmdline.go b/machine/cmdline.go index 09b2fca..70ca5d1 100644 --- a/machine/cmdline.go +++ b/machine/cmdline.go @@ -170,6 +170,16 @@ func (c Cmdline) String() string { // rcupdate.rcu_expedited=1 expedite RCU grace periods during boot. parts = append(parts, "no_timer_check", "tsc=reliable", "rcupdate.rcu_expedited=1") + // The virtio devices nothing before init needs - the entropy source, the balloon and + // the vsock transport - probed asynchronously, on the second vCPU beside the + // initcalls, rather than one after the other on the boot CPU. Each probe is a run of + // VM exits (2.2, 2.8 and 3.0 ms on the bench fleet, boot:initcalls lab run + // 43505126131). The root mount still waits for them (wait_for_device_probe), so this + // takes them off the boot CPU, not out of the boot: with kernel patches 0005 and 0006 + // the first SSH login of a minimal init went 214 -> 209 ms (boot:ssh-first, lab run + // 43506390106). The root disk's driver is not here: the mount needs it first. + parts = append(parts, "driver_async_probe=virtio_rng,virtio_balloon,vmw_vsock_virtio_transport") + // The single largest thing in this machine's boot, and it is not the kernel's. // // The kernel execs /sbin/init at 59 ms and systemd's first log line arrives at 852. diff --git a/machine/machine_test.go b/machine/machine_test.go index 900cf6f..84355d8 100644 --- a/machine/machine_test.go +++ b/machine/machine_test.go @@ -645,6 +645,9 @@ func TestCmdline(t *testing.T) { // fails if it goes, the machine just takes five times as long. "TERM=dumb", "console=ttyS0", + // The probes nothing before init waits for run beside the initcalls; the + // root disk's is not among them, because the mount needs it. + "driver_async_probe=virtio_rng,virtio_balloon,vmw_vsock_virtio_transport", }, // No root named, no root= at all: an empty one would be a kernel looking for "". absent: []string{"root="},