This repository was archived by the owner on Sep 20, 2026. It is now read-only.
Repository navigation
Boot profile: stop measuring the measurement, and let memory hotplug reach the guest - #65
Merged
Merged
Conversation
Taking `pciSlotVirtioSerial` out shortened the longest name in the block, so gofmt's alignment of the remaining `=` moved. `task lint` caught it. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Codecov Report❌ Patch coverage is
📢 Thoughts on this report? Let us know! |
The last profile: `sum_us=53465` against `last_ts_us=122181`. The initcalls account for 53 ms and something accounts for the other 69, and the profile had no way to say what — `initcall_debug` times each call and is silent about the time between them, which is the larger half. Two additions, neither of which prints anything while the boot is running. That rule is what the previous commit was about, and it is why both of these collect in-kernel and dump afterwards. **KMSG_GAP — where the kernel fell silent.** The ring buffer already carries a timestamp per record; the largest deltas between consecutive records, named by the last thing said before each one, are the neighbourhoods that time went to. A gap that opens right after initcall_debug's `calling ...` line is skipped: that is the initcall, already reported by name and duration. What is left is exactly the unaccounted time. Free — no kernel option, no cmdline, no cost to a boot that did not ask. **KMSG_LEVEL — how long each initcall level took.** The one number /dev/kmsg cannot give: the kernel never logs a level boundary, so the time a level spends outside its own initcalls has no name in the log. The initcall tracepoints have been compiled in all along (CONFIG_EVENT_TRACING=y); all that was missing was `trace_event=initcall:*` at boot and reading /sys/kernel/tracing/trace afterwards, which vminitd now does the same way it reads /dev/kmsg. tracefs is mounted there and only there, so a VM that is not profiling carries nothing. Not done, and deliberately: `CONFIG_FUNCTION_TRACER` + function_graph, which is the only thing that would name *functions* inside those 69 ms. It puts an __fentry__ site in every function and makes boot do a patching pass, so it costs the thing being measured — and building a separate profiling kernel to avoid that would mean profiling a kernel nobody runs, which is the mistake this branch just finished removing. Worth doing once these two say which stretch deserves it, and with ftrace_init's own cost read off the same profile. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
TestVminitdReady measures it directly: the guest is serving at 119.4 ms and the host's first connection arrives at 134.0. Nothing happens in between on either side. `connectVsockRPC` polls with a backoff capped at 20 ms, and until vminitd listens the dial fails fast with ECONNREFUSED — so the cap is not a wait for work, it is the chance of being asleep at the moment the guest became ready. Expected lag, half the cap: about 10 ms. Measured 14.7. The cap goes to 2 ms, which makes that about 1. It costs roughly fifty extra failed dials spread across the guest's boot — one host syscall each, microseconds, and not on the guest's critical path at all. That is 11% of the 134 ms to first RPC, and it needed nothing to get faster. **This is the second time the constant has been lowered instead of removed**, and the comment now says so where the next person will be standing: the fix is to stop polling. The guest knows when it is ready and can dial the host (vsock CID 2) rather than wait to be discovered, which makes the lag zero and deletes the loop. That is a change to who listens, so it is its own piece of work; this bounds the damage until then. Not touched: StartStream's loop, which has the same shape and a 100 ms cap. Its listener is bound during plugin loading, before the RPC port answers at all, so by the time the host opens a stream it is already there and the backoff does not fire on the happy path. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
…efore it
First run of the gap report found the largest single item in the whole boot:
KMSG_GAP 44695 us after: initcall late_trace_init+0x0/0xd0 returned 0 after 0 usecs
44.7 ms — 40% of kernel boot, more than acpi_init, jent_mod_init and every other initcall
put together — and the line reports only that it starts once the initcalls are over. Which
is the one thing that was already obvious.
So each gap now carries both sides and the instant it opens. The far side is the half that
names it: whatever the kernel says when it comes back is what it was doing. The near side
still matters for the small gaps, where it is the thing that just finished.
The same run also priced the tracepoints that produced KMSG_LEVEL: `event_trace_enable_again`
is 6 ms, new in the top ten and paid only by a profiling boot (`trace_event=` is in the debug
branch alone). Worth knowing before reading the next profile as if it were a production one —
it is the console lesson in miniature, one level down.
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
…ernel boot
The gap report named it once it reported both sides of a silence:
KMSG_GAP 41558 us at 70235 us
after: initcall late_trace_init+0x0/0xd0 returned 0 after 0 usecs
|| before: Freeing initrd memory: 6584K
41.6 ms — 34% of the kernel's 122 ms, more than acpi_init and every other initcall put
together — spent unpacking a 6.58 MB cpio compressed with `gzip -9`, in a kernel built with
`CONFIG_RD_GZIP` and nothing else. No initcall owns that time, which is why three rounds of
initcall profiling never saw it.
`-9` is the part worth naming: it changes how hard the *build* tries and does nothing for
the boot. gzip decompresses slowly whatever the level. We optimised the artefact and billed
every VM for it.
Measured here, same machine, same kernel, same QEMU, from "Unpacking initramfs..." to
"Freeing initrd memory":
gzip -9 58.7 ms 6,738,472 bytes
lz4 -l -9 9.5 ms 7,834,657 bytes
**49 ms for 1.05 MB.** The kernel gets CONFIG_RD_LZ4 (RD_GZIP stays, so an older initrd
still boots), checked after olddefconfig with the others because losing it is not a warning
but a VM that does not start. `-l` for the same reason: the kernel's initramfs decompressor
wants lz4's legacy frame format and does not recognise the default framing at all.
Not taken: an uncompressed cpio, which is the floor and needs no kernel option. It triples
what QEMU copies into guest RAM at launch, so it moves the cost into qemu_launch_us instead
of removing it, and deserves measuring on both sides before anyone reaches for it. The
comment says so where the next person will be standing.
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
`pci_subsys_init`, 29-30 ms, reproducible across every local boot and the largest single
item left in kernel boot. It is enumerating a handful of virtio devices on a bus that never
had a second segment: every device is placed by hand at a fixed slot on bus 0
(qemu_command.go, 0x02 through 0x1e) and nothing here creates a PCIe root port. The kernel
has no way to know that, so it keeps looking.
`pci=lastbus=0` tells it. Measured on one machine, full device set, two runs each,
kernel-to-init (VMINITD_READY pid1-entry):
without 87.6 / 85.0 ms pci_subsys_init 30 / 29 ms
lastbus=0 51.1 / 51.8 ms pci_subsys_init gone
~34 ms, and nothing is lost: the block device is still found in 173 us, vsock still listens,
virtio-net and virtio-rng still attach.
**It is a constraint and not just a flag**, which is why it is also written at the slot
constants: a device behind a root port lands on bus 1 and simply does not exist for the
guest — no error, no warning, an absent disk. The fixed-slot scheme is what makes this safe,
and whoever changes that has to change this line with it.
Two things this does not claim. The CI runner attributes the same work differently — there
`pci_subsys_init` is under 39 us and `acpi_init` is 18 ms, while here it is 29 ms and 11 —
so the saving there will not be the same number, and why two machines split it differently
is not explained. And ACPI, which the last round set out to attack, turned out not to care
about the ACPI surface at all: memory slots, maxmem and maxcpus each moved `acpi_init` by
less than the 1 ms the early clock can resolve. That hypothesis is dead; this is what was
actually there.
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
…er than guessed
The previous commit said the kernel "probes 256 buses" and left it there. Reading
arch/x86/pci says why it does, and the why is the part that makes the flag safe to keep:
/* mmconfig-shared.c, __pci_mmcfg_init */
if (pcibios_last_bus < 0)
list_for_each_entry(cfg, &pci_mmcfg_list, list)
pcibios_last_bus = cfg->end_bus;
The kernel takes the last bus of the ECAM window as the last bus worth probing, and a q35
advertises `ECAM [mem 0xb0000000-0xbfffffff] for domain 0000 [bus 00-ff]` — so 255.
pci_subsys_init then calls pcibios_fixup_peer_bridges(), which walks buses 0..255 reading a
vendor ID at 32 devfns each: 8192 config reads, every one a VM exit, to discover nothing
behind buses this VM never had.
The command line wins because pcibios_setup() runs before MMCONFIG init, so the `< 0` test
no longer fires. `pci=lastbus=255` — the value it would have taken anyway — behaves exactly
like no flag, which is the control that says this is the mechanism and not a coincidence:
no flag pci_subsys_init 34 ms
pci=lastbus=0 pci_subsys_init 1 ms
pci=lastbus=255 pci_subsys_init 32 ms
pci=norom pci_subsys_init 30 ms
Also corrected here: two claims of mine that the source disproves. `pcibios_last_bus`
defaults to -1, so I said the peer scan could not be running by default — it is running,
because MMCONFIG overwrites the default. And the DMI quirks near it set PCI_SCAN_ALL_PCIE_DEVS
for particular Stratus and HP machines, not the bus count, so they were never involved.
Still open, and now in the comment: the CI runner does not pay this at all — pci_subsys_init
is under 39 us there against 30 ms here, and the flag buys nothing on it. Same kernel, same
QEMU. The likely candidate is pci_mmcfg_reject_broken() rejecting the ECAM window over that
host's E820 map, which would leave last_bus at -1 and skip the loop. Where the loop does not
run, the flag changes nothing, which is why keeping it costs that host nothing either.
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Restores 2af533e, which the previous commit reverted by accident — and now with the measurement it was missing. The gap report put 4.5 ms of silence between "Freeing unused kernel image" and "x86/mm: Checked W+X mappings: passed, no W+X pages found", which is CONFIG_DEBUG_WX walking the kernel's page tables to confirm that none is both writable and executable. Four boots of each kernel on one machine, same devices and command line, kernel-to-init (VMINITD_READY pid1-entry, ms): CONFIG_DEBUG_WX=y 54.2 54.8 56.4 60.1 not set 44.5 45.6 49.8 51.7 The distributions do not overlap — the worst boot without is faster than the best boot with — which is what carries the claim on a machine whose run-to-run spread is ~6 ms. Minimum to minimum is 9.7 ms and median to median 7.9, so it costs more than the 4.5 ms the gap shows: the check also makes the mark_rodata_ro() pass ahead of it more expensive. **CONFIG_STRICT_KERNEL_RWX stays**, and the distinction is the whole argument: that is the protection — the kernel's text and rodata really are mapped read-only and non-executable. DEBUG_WX is the *verification* that the protection has no holes, and what it verifies is a property of this kernel image and its page-table setup: identical on every boot of the same binary. Paying for it in every tenant's VM buys an answer that does not vary. Where it is still worth running: once, on a kernel whose config changed. Flip it on, boot one VM, read the line, flip it off — the same workflow this commit's numbers came from. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Asked why CONFIG_DEBUG_MEMORY_INIT was on, the answer turned out to be "inheritance". Its
Kconfig reads:
config DEBUG_MEMORY_INIT
bool "Debug memory initialisation" if EXPERT
default !EXPERT
and this config sets CONFIG_EXPERT=y, so the default for us is **n**. `make olddefconfig`
keeps whatever the file already says, so the =y comes from the config's ancestry and has
been carried forward ever since. The same is true of the three beside it.
**No performance claim.** Both measurements came back null:
getppid, 3M calls with 56.2 / 56.9 / 55.9 ns without 57.3 / 55.0 / 55.8 ns
kernel-to-init too noisy on this machine to say anything at all
That includes CONFIG_DEBUG_ENTRY, which I expected to be the expensive one: its help says
the checks "may slow down kernel entries and exits" and "If unsure, say N", and on the
syscall fast path of this build they cost nothing I can measure. The expectation was
reasonable and the number disagrees, so the number wins.
The reason to turn them off is that they are debug instrumentation in a kernel that boots
tenants' VMs, and what each buys is a developer's answer:
DEBUG_MEMORY_INIT two one-shot verifications of the memory model at init; the
per-page check older kernels had is gone from this tree
DEBUG_ENTRY sanity checks in x86's low-level entry code
DEBUG_STACK_USAGE poisons each new stack to report high-water marks in sysrq-T
DEBUG_MISC "miscellaneous debug code that should be under a more specific
debug option but isn't"
Each is one line and a rebuild away when someone is actually debugging — the workflow the
DEBUG_WX commit describes.
Not touched, because I have not read their definitions in this tree and will not turn off
what I have not read: X86_CHECK_BIOS_CORRUPTION and its BOOTPARAM twin, X86_DEBUG_FPU,
VIRTIO_DEBUG, CGROUP_DEBUG, PNP_DEBUG_MESSAGES, FW_LOADER_DEBUG. DEBUG_FS stays because
tracefs needs it, and DEBUG_BUGVERBOSE because a BUG() without file and line is a worse
incident.
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to subscribe to this conversation on GitHub.
Already have an account?
Sign in.
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Follows the profile from the last CI run:
The largest entry was the profiler writing itself out
virtio_console_initdoes not spend 24 ms initialising a console.register_console()replays the printk ring into the console that just came up — synchronously, inside that initcall. Debug mode made the ring big on purpose (loglevel=8,log_buf_len=4M) and then routed it through virtio-console so the replay would not go a byte at a time through the 8250. That fixed the symptom and moved the cost into the profile's own top line.Same run corroborates it: 137.7 ms kernel-to-init against the ~90 ms the README documents for a normal boot.
None of it was necessary — vminitd reads the per-initcall lines from
/dev/kmsg, not from the console. So the profiling boot now says nothing on the console (loglevel=0, the console threshold; the ring stays complete) and keeps the production console,ttyS0. The VM being profiled is now the VM that runs: same devices, same console, one extra kernel argument.log_buf_len=4Mstays — the one piece that was never about the console.Deleted: the virtio-serial/virtconsole pair the debug boot added,
addChardevFileand its PCI slot, andTestKernelBootProfile, which scraped initcall lines out of the console log. It was already superseded byTestKernelBootProfileComplete(which reads all of them, early ones included) and was the only reason the console had to be chatty. Its shared helpers moved tointegration/profile_helpers_test.go.Memory hotplug reaches the guest
The subsystem was complete except for the last step:
internal/shim/memhotplugdecides,qmp_memory.goadds a memory-backend and a pc-dimm,query-memory-devicesshows it — and the guest agent writes/sys/devices/system/memory/memory<N>/online, a file that only exists withCONFIG_MEMORY_HOTPLUG. The shipped config said# CONFIG_MEMORY_HOTPLUG is not set. Every DIMM the host added was memory the guest never saw. CPU hotplug worked; memory was the half that did not.Dependencies were already in place (
SPARSEMEM,MIGRATION,ARCH_ENABLE_MEMORY_HOTPLUG). Auto-online left at its default: the guest handles both policies, but the path the controller drives is the explicit one, and changing the default would change which code runs.All three are now verified after
make olddefconfig, next toVIRTIO_NETandNET_CLS_ACT, because olddefconfig resolves what it cannot satisfy and a dropped symbol is silent. Verified locally:task build:kernelcompletes and the resultingkernel-configcarries all three plus theMEMORY_ISOLATIONthey select.What to watch in the next profile
Two effects land together, and they pull in opposite directions:
virtio_console_initshould leave the list. If it does, the 24 ms was the replay.acpi_initshould rise: the guest now walks the ACPI memory-hotplug objects for all eight slots instead of ignoring them. That is the real cost of the feature, and it was invisible before because the guest could not use it.last_ts_usmoving toward 90 ms is the other half of the console result.Cross-repo
The kernel artefact changes content at the same version, so
spin-stack/storage'sGUEST_KERNEL_SHA256pin has to be bumped once this is published (task guest:kernel:pinthere).To rewind
main, with the lease naming exactly what it expects to replace:🤖 Generated with Claude Code