From 8c0aadb82d76dd1558860942619a5634b77e6ec5 Mon Sep 17 00:00:00 2001 From: Manuel de Brito Fontes Date: Fri, 13 Nov 2026 15:30:45 -0300 Subject: [PATCH 1/2] boot: ssh-first rows for keys early, generators, inert units and the three together (experiment) Each image change of this branch as an overlay edit beside the image as built, and an accept-to-login column: what the first login costs once sshd is listening. Co-Authored-By: Claude Opus 5.5 --- boot/ssh_first_test.go | 63 ++++++++++++++++++++++++++++++++++++++---- 1 file changed, 58 insertions(+), 5 deletions(-) diff --git a/boot/ssh_first_test.go b/boot/ssh_first_test.go index 5c0c84b..03642f6 100644 --- a/boot/ssh_first_test.go +++ b/boot/ssh_first_test.go @@ -91,11 +91,62 @@ install -m 600 -o "${ids%:*}" -g "${ids#*:}" ` + key + `.pub "$MNT/home/spin/.ss test -e "$MNT/usr/lib/systemd/system/multi-user.target.wants/systemd-logind.service" install -d "$MNT/var/lib/systemd/linger" && touch "$MNT/var/lib/systemd/linger/spin" ` + // EXPERIMENT (cold-boot-batch, 2026-11-13): the three image changes of that branch, one row + // each and together, against the image as built. + // + // keys early: the host keys generated from the boot's first dispatch, beside udev and + // journald, rather than by the first connection's sshd@, which waits for them before it + // sends its banner. Lab run 43463472762 measured it alone: accept to login 177 -> 155 ms. + keysEarly := func(v *variant) { + v.files["/etc/systemd/system/spin-machine-sshd-keygen.service.d/early.conf"] = + "[Unit]\nDefaultDependencies=no\nConflicts=shutdown.target\nBefore=shutdown.target\n" + v.links["/etc/systemd/system/sysinit.target.wants/spin-machine-sshd-keygen.service"] = + "/usr/lib/systemd/system/spin-machine-sshd-keygen.service" + } + // generators: the two system generators that decide nothing here masked. sshd-socket-generator + // moves ssh.socket to sshd_config's Port and ListenAddress, which the image leaves at the + // default, and it loads libcrypto to say so: 3.5-23.5 ms in a guest against ~1.5 ms for each + // of systemd's, which run beside it (a laptop, 2026-11-13). systemd-run-generator reads + // systemd.run= off a command line spin-machine writes. + gens := []string{"sshd-socket-generator", "systemd-run-generator"} + generators := func(v *variant) { + for _, g := range gens { + v.setup += "test -x \"$MNT/usr/lib/systemd/system-generators/" + g + "\"\n" + v.links["/etc/systemd/system-generators/"+g] = "/dev/null" + } + } + // inert units: the initial transaction's jobs whose condition fails on every boot of this + // machine - no UKI or TPM to measure into, no AppArmor or modules in the kernel, no virtual + // console, and the distribution's keygen, which waits for a first boot that never comes. + // Each is a unit file PID 1 parses, and its dependencies, while no unit is running, between + // the unit load and the first job (task boot:trace with systemd.log_level=debug). + inert := []string{"systemd-pcrextend.socket", "systemd-pcrlock.socket", "systemd-pcrnvdone.service", + "systemd-pcrproduct.service", "systemd-pcrphase-sysinit.service", "systemd-pcrphase.service", + "kmod-static-nodes.service", "apparmor.service", "sshd-keygen.service", "getty-static.service", + "getty@tty1.service"} + inertUnits := func(v *variant) { + for _, u := range inert { + v.setup += "test -e \"$MNT/usr/lib/systemd/system/" + strings.Replace(u, "@tty1", "@", 1) + "\"\n" + v.links["/etc/systemd/system/"+u] = "/dev/null" + } + } + edited := func(label string, edits ...func(*variant)) variant { + v := row(label, asThisBranch) + v.links = map[string]string{} + for _, e := range edits { + e(&v) + } + return v + } rows := []variant{ - row("as this branch", asThisBranch), + row("as built", asThisBranch), + edited("keys early", keysEarly), + edited("generators", generators), + edited("inert units", inertUnits), + edited("batch", keysEarly, generators, inertUnits), } - type samples struct{ listen, login, again, prompt []time.Duration } + type samples struct{ listen, login, accepted, again, prompt []time.Duration } got := map[string]*samples{} failed := map[string]int{} for range reps { @@ -111,6 +162,7 @@ install -d "$MNT/var/lib/systemd/linger" && touch "$MNT/var/lib/systemd/linger/s } g := got[v.label] g.listen, g.login, g.again, g.prompt = append(g.listen, r.listen), append(g.login, r.login), append(g.again, r.again), append(g.prompt, r.prompt) + g.accepted = append(g.accepted, r.login-r.listen) } } ms := func(ds []time.Duration, q float64) string { @@ -122,14 +174,15 @@ install -d "$MNT/var/lib/systemd/linger" && touch "$MNT/var/lib/systemd/linger/s } var b strings.Builder fmt.Fprintf(&b, "\nms from the moment before QEMU is exec'd, p50/p95 over %d boots of each, interleaved, %s vCPUs\n\n", reps, rows[0].cpus) - fmt.Fprintf(&b, " %-16s %15s %15s %15s %15s %9s\n", "", "SSHD ACCEPTS", "FIRST LOGIN", "A SECOND TOOK", "CONSOLE PROMPT", "NO LOGIN") + fmt.Fprintf(&b, " %-16s %15s %15s %15s %15s %15s %9s\n", "", "SSHD ACCEPTS", "FIRST LOGIN", "ACCEPT TO LOGIN", "A SECOND TOOK", "CONSOLE PROMPT", "NO LOGIN") for _, v := range rows { g := got[v.label] if g == nil { g = &samples{} } - fmt.Fprintf(&b, " %-16s %7s/%-7s %7s/%-7s %7s/%-7s %7s/%-7s %9d\n", v.label, - ms(g.listen, .5), ms(g.listen, .95), ms(g.login, .5), ms(g.login, .95), ms(g.again, .5), ms(g.again, .95), + fmt.Fprintf(&b, " %-16s %7s/%-7s %7s/%-7s %7s/%-7s %7s/%-7s %7s/%-7s %9d\n", v.label, + ms(g.listen, .5), ms(g.listen, .95), ms(g.login, .5), ms(g.login, .95), ms(g.accepted, .5), ms(g.accepted, .95), + ms(g.again, .5), ms(g.again, .95), ms(g.prompt, .5), ms(g.prompt, .95), failed[v.label]) } t.Log(b.String()) From bb713dec80d8b9c33def99b28a3d96d755545895 Mon Sep 17 00:00:00 2001 From: Manuel de Brito Fontes Date: Fri, 13 Nov 2026 15:39:16 -0300 Subject: [PATCH 2/2] image: the SSH host keys are made from the boot's first dispatch spin-machine-sshd-keygen.service is wanted by sysinit.target without default dependencies, so the keys exist before sshd-vsock.socket listens and the first login's sshd@ no longer waits for them before its banner. On the bench fleet, 20 boots of each interleaved (task boot:ssh-first, lab run 43483372488): the first SSH login 489/506 -> 468/494 ms p50/p95, accept to login 177 -> 154 ms. build.sh asserts the want and DefaultDependencies=no. Measured beside it and left out, the conclusions kept by the probes: masking sshd-socket-generator and systemd-run-generator (generators 5.3 -> 3.7 ms, login 489), and masking the eleven initial-transaction units whose condition always fails here (login 484); all three together 469. The ~32 ms with no unit running after the unit load is PID 1 loading the default target's units and building the initial transaction. Co-Authored-By: Claude Opus 5.5 --- boot/ssh_first_test.go | 84 ++++++------------- boot/waits_probe_test.go | 9 ++ image/README.md | 6 +- image/build.sh | 12 +++ .../local/lib/spin-base/optimize-systemd.sh | 6 ++ .../system/spin-machine-sshd-keygen.service | 32 +++++-- 6 files changed, 83 insertions(+), 66 deletions(-) diff --git a/boot/ssh_first_test.go b/boot/ssh_first_test.go index 03642f6..0dd0ab0 100644 --- a/boot/ssh_first_test.go +++ b/boot/ssh_first_test.go @@ -81,70 +81,40 @@ install -m 600 -o "${ids%:*}" -g "${ids#*:}" ` + key + `.pub "$MNT/home/spin/.ss // logind in the boot and spin lingering 510/525, with sshd accepting no later. The image // now has no motd and lingers. Then, lab run 43312419007, 15 boots of each: the host keys // generated in the boot (the keygen wanted by multi-user.target) 518/542 against 514/531 - - // nothing, so the keys stay with the first sshd that needs them. Each row's edit was checked in its setup, so a row that + // nothing: with default dependencies the keygen starts after basic.target, no sooner than the + // first connection's sshd@ starts it. Each row's edit was checked in its setup, so a row that // matched nothing failed rather than measuring the image under another name. // - // The rows below are written so they hold on a release from before this branch as well as - // after it, because the lab boots published releases: each puts the image in the state this - // branch builds - logind in the boot, spin lingering - whether or not it already was. + // + // Then three image changes, one row each and the three together, 20 boots of each, lab run + // 43483372488 (2026-11-13), p50/p95 ms of the first login and of accept to login: as built + // 489/506, 177/194; the host keys generated from the boot's first dispatch 468/494, 154/168; + // sshd-socket-generator and systemd-run-generator masked 489/501, 180/192; the eleven units + // of the initial transaction whose condition fails on every boot here masked (the pcr* + // units, kmod-static-nodes, apparmor, the distribution's sshd-keygen, getty-static, + // getty@tty1) 484/501, 178/191; all three 469/490, 156/173. Only the keys moved the login, + // so the image makes them early and the other two stay out. What those two were after: + // sshd-socket-generator loads libcrypto to find sshd_config at its defaults and is the + // slowest generator, 3.5-23.5 ms in a guest against ~1.5 for each of systemd's, but the + // generators run side by side and masking both took their phase from 5.3 to 3.7 ms p50 (a + // laptop, 8 boots of each); the units are parsed in the gap boot:waits shows after the unit + // load, which is PID 1 building the initial transaction (see waits_probe_test.go). + // + // The row below is written so it holds on a release from before this branch as well as + // after it, because the lab boots published releases: it puts the image in the state this + // branch builds - logind in the boot, spin lingering, the host keys made from the boot's + // first dispatch - whether or not it already was. const asThisBranch = `rm -f "$MNT/etc/systemd/system/multi-user.target.wants/systemd-logind.service" test -e "$MNT/usr/lib/systemd/system/multi-user.target.wants/systemd-logind.service" install -d "$MNT/var/lib/systemd/linger" && touch "$MNT/var/lib/systemd/linger/spin" ` - // EXPERIMENT (cold-boot-batch, 2026-11-13): the three image changes of that branch, one row - // each and together, against the image as built. - // - // keys early: the host keys generated from the boot's first dispatch, beside udev and - // journald, rather than by the first connection's sshd@, which waits for them before it - // sends its banner. Lab run 43463472762 measured it alone: accept to login 177 -> 155 ms. - keysEarly := func(v *variant) { - v.files["/etc/systemd/system/spin-machine-sshd-keygen.service.d/early.conf"] = - "[Unit]\nDefaultDependencies=no\nConflicts=shutdown.target\nBefore=shutdown.target\n" - v.links["/etc/systemd/system/sysinit.target.wants/spin-machine-sshd-keygen.service"] = - "/usr/lib/systemd/system/spin-machine-sshd-keygen.service" - } - // generators: the two system generators that decide nothing here masked. sshd-socket-generator - // moves ssh.socket to sshd_config's Port and ListenAddress, which the image leaves at the - // default, and it loads libcrypto to say so: 3.5-23.5 ms in a guest against ~1.5 ms for each - // of systemd's, which run beside it (a laptop, 2026-11-13). systemd-run-generator reads - // systemd.run= off a command line spin-machine writes. - gens := []string{"sshd-socket-generator", "systemd-run-generator"} - generators := func(v *variant) { - for _, g := range gens { - v.setup += "test -x \"$MNT/usr/lib/systemd/system-generators/" + g + "\"\n" - v.links["/etc/systemd/system-generators/"+g] = "/dev/null" - } - } - // inert units: the initial transaction's jobs whose condition fails on every boot of this - // machine - no UKI or TPM to measure into, no AppArmor or modules in the kernel, no virtual - // console, and the distribution's keygen, which waits for a first boot that never comes. - // Each is a unit file PID 1 parses, and its dependencies, while no unit is running, between - // the unit load and the first job (task boot:trace with systemd.log_level=debug). - inert := []string{"systemd-pcrextend.socket", "systemd-pcrlock.socket", "systemd-pcrnvdone.service", - "systemd-pcrproduct.service", "systemd-pcrphase-sysinit.service", "systemd-pcrphase.service", - "kmod-static-nodes.service", "apparmor.service", "sshd-keygen.service", "getty-static.service", - "getty@tty1.service"} - inertUnits := func(v *variant) { - for _, u := range inert { - v.setup += "test -e \"$MNT/usr/lib/systemd/system/" + strings.Replace(u, "@tty1", "@", 1) + "\"\n" - v.links["/etc/systemd/system/"+u] = "/dev/null" - } - } - edited := func(label string, edits ...func(*variant)) variant { - v := row(label, asThisBranch) - v.links = map[string]string{} - for _, e := range edits { - e(&v) - } - return v - } - rows := []variant{ - row("as built", asThisBranch), - edited("keys early", keysEarly), - edited("generators", generators), - edited("inert units", inertUnits), - edited("batch", keysEarly, generators, inertUnits), + asBuilt := row("as this branch", asThisBranch) + asBuilt.files["/etc/systemd/system/spin-machine-sshd-keygen.service.d/early.conf"] = + "[Unit]\nDefaultDependencies=no\nConflicts=shutdown.target\nBefore=shutdown.target\n" + asBuilt.links = map[string]string{ + "/etc/systemd/system/sysinit.target.wants/spin-machine-sshd-keygen.service": "/usr/lib/systemd/system/spin-machine-sshd-keygen.service", } + rows := []variant{asBuilt} type samples struct{ listen, login, accepted, again, prompt []time.Duration } got := map[string]*samples{} diff --git a/boot/waits_probe_test.go b/boot/waits_probe_test.go index 1c6dba8..6651a57 100644 --- a/boot/waits_probe_test.go +++ b/boot/waits_probe_test.go @@ -385,6 +385,15 @@ func waitsReport(boots []waitsBoot, target string, top int, minGap time.Duration fmt.Fprintf(&b, " %8s %8s %7s %7s %s\n", ms(u.Ready), ms(x.usable), ms(x.usable-u.Ready), "", "(Type=idle: the job queue draining, then exec)") } } + // The first gap, from the end of the unit load to the first job (32 ms p50 on the bench + // fleet, lab run 43361486792), is PID 1 and nothing else. systemd stamps UnitsLoadFinish + // after enumerating mounts, devices and slices, and only then loads the units the boot + // starts: coldplug, then "Activating default unit: default.target" parses every unit file + // default.target reaches, and a stub for each name an After= or RequiresMountsFor= gives, + // builds the initial transaction (64 jobs), and collects the stubs before the first job is + // dispatched - task boot:trace with systemd.log_level=debug, 2026-11-13. It shrinks only with + // the transaction: eleven of its units whose condition fails on every boot here, masked, did + // not move the first SSH login (boot:ssh-first, lab run 43483372488). gaps := x.w.Gaps(x.target().Start, minGap) fmt.Fprintf(&b, "\n no unit activating, for at least %s ms: systemd waiting on the kernel, or on itself\n\n", ms(minGap)) var idle time.Duration diff --git a/image/README.md b/image/README.md index b5b99ab..7c48aa2 100644 --- a/image/README.md +++ b/image/README.md @@ -75,7 +75,11 @@ from outside: them instead: every boot here *is* a first boot, since the root filesystem is a fresh overlay, so the keys live exactly as long as the VM does. Every sshd waits for it, including the per-connection `sshd@.service` that `systemd-ssh-generator` starts for vsock - and `ssh .host`: without that, those connections found no host keys and were dropped. + and `ssh .host`: without that, those connections found no host keys and were dropped. It + starts from the boot's first dispatch, wanted by `sysinit.target` without default + dependencies, so the keys exist before the vsock socket listens and the first login does not + wait for them. A guest checkpointed after it has booted therefore carries its host keys, and + whoever restores it hands each VM its own. - **Two thirds of the boot was systemd asking the console questions.** The kernel execs `/sbin/init` at 59 ms and systemd's first log line arrived at 852, with nothing running in between. It was a terminfo query and a terminal reset, 334 ms of timeout each, waiting for diff --git a/image/build.sh b/image/build.sh index 40e282a..ca885e5 100755 --- a/image/build.sh +++ b/image/build.sh @@ -357,6 +357,18 @@ in_image /etc/systemd/system/systemd-logind-varlink.socket.d/10-seats.conf || { grep -qx 'After=spin-machine-sshd-keygen.service' || { echo "ERROR: sshd@.service does not wait for spin-machine-sshd-keygen.service" >&2 exit 1; } +# And the keys are made from the boot's first dispatch, not by the first login's sshd@, which +# would wait for them before its banner: 18 ms of the first login over vsock (the numbers are in +# the unit). Both halves: the link is what starts it in the boot, and without +# DefaultDependencies=no the unit waits for the sysinit.target that wants it and is late anyway. +stat_in_image /etc/systemd/system/sysinit.target.wants/spin-machine-sshd-keygen.service | + grep -qF '/usr/lib/systemd/system/spin-machine-sshd-keygen.service' || { + echo "ERROR: spin-machine-sshd-keygen.service is not wanted by sysinit.target" >&2 + exit 1; } +"$bin/debugfs" -R "cat /usr/lib/systemd/system/spin-machine-sshd-keygen.service" /work/base.raw 2>/dev/null | + grep -qx 'DefaultDependencies=no' || { + echo "ERROR: spin-machine-sshd-keygen.service has default dependencies; it starts after sysinit.target" >&2 + exit 1; } if stat_in_image /etc/systemd/system/systemd-logind.service | grep -q '/dev/null'; then echo "ERROR: systemd-logind.service is masked - it never starts, no login gets a" \ "session, and spin's manager never starts either" >&2 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 509be5c..416bbee 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 @@ -213,6 +213,12 @@ log "Configuring SSH for socket activation..." rm -f /etc/systemd/system/multi-user.target.wants/ssh.service 2>/dev/null || true mkdir -p /etc/systemd/system/sockets.target.wants ln -sf /lib/systemd/system/ssh.socket /etc/systemd/system/sockets.target.wants/ssh.socket +# The host keys from the boot's first dispatch rather than the first login's: the unit says why +# and what it was worth. Its [Install] says sysinit.target, and this is that enable. Dangling +# until mkosi.postinst.chroot copies the unit in, as the containerd and docker links above are. +mkdir -p /etc/systemd/system/sysinit.target.wants +ln -sf /usr/lib/systemd/system/spin-machine-sshd-keygen.service \ + /etc/systemd/system/sysinit.target.wants/spin-machine-sshd-keygen.service # logind stays in the boot transaction, as the package wants it # (/usr/lib/systemd/system/multi-user.target.wants/systemd-logind.service), because spin diff --git a/image/mkosi.extra/usr/local/lib/spin-base/rootfs/usr/lib/systemd/system/spin-machine-sshd-keygen.service b/image/mkosi.extra/usr/local/lib/spin-base/rootfs/usr/lib/systemd/system/spin-machine-sshd-keygen.service index 7cf86d4..31aa335 100644 --- a/image/mkosi.extra/usr/local/lib/spin-base/rootfs/usr/lib/systemd/system/spin-machine-sshd-keygen.service +++ b/image/mkosi.extra/usr/local/lib/spin-base/rootfs/usr/lib/systemd/system/spin-machine-sshd-keygen.service @@ -17,17 +17,33 @@ [Unit] Description=Generate SSH host keys for this VM -# Ordered before the daemon and pulled in by it, and deliberately NOT by ssh.socket. -# Hanging it off the socket puts it inside sockets.target, which is ordered before -# basic.target, which a service is ordered after by default — and systemd breaks the loop -# by dropping an edge at random: +# Started from the boot's first dispatch, beside journald and udev - wanted by sysinit.target, +# without default dependencies - and not by the first sshd that needs the keys. The first login +# over vsock is accepted by a per-connection sshd@.service, which waits for this unit (its +# drop-in, sshd@.service.d/keygen.conf) before it sends its banner, so a keygen started by that +# connection put the key generation inside the login. Started from the boot, it is done before +# sysinit.target is, and sshd-vsock.socket listens only after that: accept to first login went +# from 177 to 155 ms p50, and the first login from 486 to 468, 20 boots of each interleaved on +# the bench fleet (task boot:ssh-first, lab run 43463472762, 2026-11-13). +# +# Wanted by sysinit.target but not ordered before it: nothing in sysinit waits for host keys, +# and ordering it there would hold the vsock socket behind the key generation instead. +# DefaultDependencies=no takes away the After=sysinit.target and basic.target a service gets by +# default, which would make it wait for the target that wants it. The writes go to /etc/ssh on +# the root filesystem, which the kernel mounts read-write before PID 1 starts. +DefaultDependencies=no +Conflicts=shutdown.target +Before=shutdown.target +# Ordered before the daemons, and NOT pulled in by ssh.socket: hanging it off the socket put it +# inside sockets.target, and with default dependencies systemd broke the loop that made by +# dropping an edge at random: # # basic.target: Found ordering cycle: sockets.target/start after ssh.socket/start # after spin-machine-sshd-keygen.service/start after basic.target/start # -# Socket activation still works: the socket starts ssh.service, and ssh.service waits for -# this. The per-connection sshd@.service that systemd-ssh-generator's vsock and AF_UNIX -# sockets start waits for it through a drop-in of its own (sshd@.service.d/keygen.conf). +# The per-connection sshd@.service that systemd-ssh-generator's vsock and AF_UNIX sockets start +# waits for it through a drop-in of its own (sshd@.service.d/keygen.conf), which stays: it is +# what makes a connection that arrives first wait rather than find no keys. Before=ssh.service sshd.service ConditionPathExists=/usr/bin/ssh-keygen @@ -43,4 +59,4 @@ RemainAfterExit=yes ExecStart=/bin/sh -c 'for t in ed25519 ecdsa; do f=/etc/ssh/ssh_host_$${t}_key; [ -e "$$f" ] || /usr/bin/ssh-keygen -q -t "$$t" -N "" -f "$$f" || exit 1; done' [Install] -WantedBy=ssh.service sshd.service +WantedBy=sysinit.target