From 3326870d82432f8df165d16bc85c05db5bb9f482 Mon Sep 17 00:00:00 2001 From: Manuel de Brito Fontes Date: Fri, 13 Nov 2026 15:39:16 -0300 Subject: [PATCH] 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 | 43 ++++++++++++++----- 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, 89 insertions(+), 19 deletions(-) diff --git a/boot/ssh_first_test.go b/boot/ssh_first_test.go index 525a192..fe55ffb 100644 --- a/boot/ssh_first_test.go +++ b/boot/ssh_first_test.go @@ -94,12 +94,29 @@ 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" @@ -112,11 +129,15 @@ install -d "$MNT/var/lib/systemd/linger" && touch "$MNT/var/lib/systemd/linger/s // connections. Then lab run 43479854381, 20 of each, first login / a second: the runner's // OpenSSH 9.6, which took sntrup761x25519, 489/104; x/crypto/ssh with mlkem768x25519 // 461/40, and with curve25519 461/39. - rows := []variant{ - row("as this branch", asThisBranch), + 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, again, prompt []time.Duration } + type samples struct{ listen, login, accepted, again, prompt []time.Duration } got := map[string]*samples{} failed, classical := map[string]int{}, map[string]int{} for range reps { @@ -135,6 +156,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 { @@ -146,14 +168,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 %14s\n", "", "SSHD ACCEPTS", "FIRST LOGIN", "A SECOND TOOK", "CONSOLE PROMPT", "NO LOGIN", "CURVE25519 IN") + fmt.Fprintf(&b, " %-16s %15s %15s %15s %15s %15s %9s %14s\n", "", "SSHD ACCEPTS", "FIRST LOGIN", "ACCEPT TO LOGIN", "A SECOND TOOK", "CONSOLE PROMPT", "NO LOGIN", "CURVE25519 IN") 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 %14d\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 %14d\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], classical[v.label]) } t.Log(b.String()) diff --git a/boot/waits_probe_test.go b/boot/waits_probe_test.go index f5d8371..6428f3a 100644 --- a/boot/waits_probe_test.go +++ b/boot/waits_probe_test.go @@ -388,6 +388,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 e069029..76e4668 100644 --- a/image/README.md +++ b/image/README.md @@ -101,7 +101,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 2bf71f4..8f02091 100755 --- a/image/build.sh +++ b/image/build.sh @@ -364,6 +364,18 @@ in_image /etc/systemd/system/systemd-logind-varlink.socket.d/10-seats.conf || { grep -qx 'KexAlgorithms mlkem768x25519-sha256' || { echo "ERROR: sshd does not offer mlkem768x25519-sha256 alone" >&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