boot: where a boot's time goes, and the first SSH login 60 ms sooner

.github/workflows/lab.yml

@@ -35,6 +35,11 @@ on:
           - boot:initcalls
           - boot:userspace
           - boot:systemd
+          - boot:waits
+          - boot:jobs
+          - boot:ssh-first
+          - boot:exits
+          - boot:mmio
           - boot:ssh-load
           - boot:page-cache
           - boot:firmware

Taskfile.yml

@@ -701,7 +701,7 @@ tasks:
           pair="${pair%"${pair##*[![:space:]]}"}"
           [ -z "$pair" ] && continue
           key="${pair%%=*}"
-          [[ "$pair" == *=* && "$key" =~ ^(REPS|TOP|GAP|ONLY|FLAGS|CPUS|MEMORY_MIB|DEBUG|FILE_MB|CACHE_TIMEOUT_S|GRAPH_[A-Z_]+|SHARE_[A-Z_]+|SPIN_[A-Z0-9_]+)$ ]] ||
+          [[ "$pair" == *=* && "$key" =~ ^(REPS|TOP|GAP|ONLY|FLAGS|CPUS|TARGET|BUCKET|LINGER|MEMORY_MIB|DEBUG|FILE_MB|CACHE_TIMEOUT_S|GRAPH_[A-Z_]+|SHARE_[A-Z_]+|SPIN_[A-Z0-9_]+)$ ]] ||
             { echo "::error::not a variable this workflow passes on: $pair"; exit 1; }
           case "$key" in
             SPIN_MACHINE_OUTPUT|SPIN_MACHINE_OUTPUT_B|SPIN_KERNEL_B|SPIN_KERNEL_C) echo "::error::$key is set by this workflow"; exit 1 ;;

boot/Taskfile.yml

@@ -134,9 +134,10 @@ tasks:
     desc: >-
       Check first SSH login, reconnect, user services and logout in a disposable guest.
       Needs a built release; uses KVM when available, otherwise TCG.
-      The image does not start logind at boot, so this checks the thing that makes that
-      safe: that the first login activates it and gets a real session. SPIN_LOGIND_NO_SEATS=1
-      removes the drop-in that allows it and is expected to fail, not to measure anything.
+      The image starts logind at boot, for spin's lingering manager, and this checks that
+      logins get a real session. SPIN_LOGIND_NO_SEATS=1 holds logind back from the boot and
+      removes the drop-in that lets an early login still activate it, and is expected to
+      fail, not to measure anything.
     deps: [':tools']
     cmds:
       - SPIN_LOGIND_TEST=1 go test ./boot/ -run '^TestLogindSessions$' -count=1 -v -timeout 5m
@@ -180,6 +181,64 @@ tasks:
     cmds:
       - SPIN_SYSTEMD_DEBUG=1 go test ./boot/ -run TestSystemdDebug -count=1 -v -timeout 15m
 
+  waits:
+    desc: >-
+      What waited on what between the kernel handing over and a login prompt, on the host's
+      clock: each unit's own time against the lag before it started, the critical path to the
+      login that accounts for every millisecond of it, the intervals no unit was working, and
+      what is still starting behind the prompt. Read after the boot from systemd's timestamps.
+      Needs KVM, a built release and sudo. REPS= boots, TARGET= the login unit, TOP= rows,
+      GAP= the shortest idle interval in ms, RAW=<dir> keeps each boot's dump.
+    deps: [':tools']
+    cmds:
+      - SPIN_BOOT_WAITS=1 go test ./boot/ -run '^TestBootWaits$' -count=1 -v -timeout 20m
+
+  jobs:
+    desc: >-
+      PID 1's job queue as it changed during the boot, recorded live over systemd's private
+      socket by boot/jobwatch, a diagnostic binary built into each boot's overlay: what was
+      waiting and what was running every BUCKET ms, the boot:waits gaps with the jobs running
+      through them, jobs that did not end done, and the jobs the first SSH login after the boot
+      sets off. Interleaved with boots
+      without it, and the first table is what recording cost. Needs KVM, a built release and
+      sudo. REPS= boots of each, CPUS= vCPUs of both (3 gives the recorder room of its own),
+      LINGER= how long it records after startup, RAW=<dir> keeps the dumps.
+    deps: [':tools']
+    cmds:
+      - SPIN_BOOT_JOBS=1 go test ./boot/ -run '^TestBootJobs$' -count=1 -v -timeout 30m
+
+  ssh-first:
+    desc: >-
+      When a workspace can first be logged into from the host over SSH, through the machine's
+      vsock: sshd accepting, the first login done, a second login's cost, and the console
+      prompt beside them. Needs KVM, /dev/vhost-vsock (task vsock), a built release, sudo
+      and ssh. REPS= boots.
+    deps: [':tools']
+    cmds:
+      - SPIN_SSH_FIRST=1 go test ./boot/ -run '^TestFirstSSH$' -count=1 -v -timeout 30m
+
+  exits:
+    desc: >-
+      What each phase of a boot made KVM do, from the host: VM exits by kind, EPT faults, and
+      how the guest's RAM is mapped (4K/2M/1G, and how much of it the host holds in huge
+      pages), for the machine as built and without its virtio-rng device, interleaved. Reads
+      /sys/kernel/debug/kvm, so the host must run one VM at a time. Needs KVM, a built release
+      and sudo. REPS= boots of each row, CPUS= vCPUs.
+    deps: [':tools']
+    cmds:
+      - SPIN_BOOT_EXITS=1 go test ./boot/ -run '^TestExitTimeline$' -count=1 -v -timeout 30m
+
+  mmio:
+    desc: >-
+      Who the guest's exits to QEMU are, counted from QEMU's own trace from a launch to the
+      login prompt: every PCI configuration access by device and direction, and every MMIO
+      and port access by the region it reached. Counts, not times, so any host answers.
+      SPIN_KERNEL_B= counts a second kernel beside the release's. Needs KVM and a built
+      release; no sudo. TOP= regions.
+    deps: [':tools']
+    cmds:
+      - SPIN_BOOT_MMIO=1 go test ./boot/ -run '^TestMMIOCensus$' -count=1 -v -timeout 10m
+
   firmware-stages:
     desc: >-
       Where the time before the kernel goes on the machine a workspace boots: QEMU's start and

boot/bench_test.go

@@ -34,6 +34,10 @@ type variant struct {
 	profile bool              // boot with `--profile`: initcall profiling, console silent
 	setup   string            // shell run with the overlay mounted, $MNT its root
 	flags   []string          // spin-machine boot flags after the rest: the feature matrix's axes
+	// -device entries taken out of the machine, by prefix ("virtio-rng-pci"): a diagnostic row
+	// of a machine with another fingerprint, which spin-machine deliberately has no flag for.
+	// Only bootWaits honours it; see machineCommand.
+	without []string
 }
 
 // A drop-in on the instance beats one on the template, which is where the image's own TERM
@@ -89,6 +93,10 @@ func without(units ...string) variant {
 //   - 300 more unit files nothing wants: 236 against 246, 12 boots, 2026-09-26. systemd's unit
 //     cache holds names and modification times, so this measures the scan, which is free; it
 //     does not measure parsing, which only units something pulls in pay for.
+//   - the serial getty without BindsTo= and After= on dev-ttyS0.device, which boot:waits found
+//     its start waiting on in 16 of 20 boots: 342/349 against 345/365, 20 boots on the bench
+//     fleet, 2026-11-12 (lab run 43303190733). The prompt does not come sooner when the getty
+//     stops waiting for udev to announce the port; a laptop had read 16 ms of it, which was noise.
 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
@@ -210,6 +218,11 @@ func TestBootTrace(t *testing.T) {
 	// waits separates the two in one boot:
 	//
 	//   SPIN_GETTY_EXEC="/bin/sh -c 'echo SPIN-READY-login: ; sleep infinity'"
+	//
+	// SPIN_TRACE_APPEND is added to the kernel command line, after this probe's own, so a later
+	// parameter wins: systemd.log_level=debug times PID 1's start-up line by line, which on
+	// 2026-11-12 was how the ~45 ms between "Hostname set" and "Queued start job" was split.
+	// Every line is a VM exit, so the gaps between lines are the work and the lines are not.
 	if x := os.Getenv("SPIN_GETTY_EXEC"); x != "" {
 		body += "ExecStart=\nExecStart=-" + x + "\n"
 	}
@@ -227,8 +240,10 @@ func TestBootTrace(t *testing.T) {
 	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", "init=/sbin/init loglevel=7 systemd.show_status=true "+
-			"systemd.log_level=info systemd.log_target=console")
+		"--append", strings.TrimSpace("init=/sbin/init loglevel=7 systemd.show_status=true "+
+			"systemd.log_level=info systemd.log_target=console "+os.Getenv("SPIN_TRACE_APPEND")))
+	// FLAGS, as the other probes take it: spin-machine boot flags after the rest.
+	cmd.Args = append(cmd.Args, strings.Fields(os.Getenv("FLAGS"))...)
 	cmd.SysProcAttr = &syscall.SysProcAttr{Setpgid: true}
 	stdout, err := cmd.StdoutPipe()
 	if err != nil {

boot/cpushare_test.go

@@ -35,7 +35,7 @@ After=multi-user.target
 [Service]
 Type=oneshot
 StandardOutput=null
-ExecStart=/bin/sh -c "mount -t tracefs none /sys/kernel/tracing 2>/dev/null; echo 0 > /sys/kernel/tracing/tracing_on; { echo SPIN-TRACE-BEGIN; sed -n '1,/initcall_finish: func=FN+/p' /sys/kernel/tracing/trace | grep -E 'sched_switch|workqueue_execute|initcall_(start|finish): func=FN[+]'; echo SPIN-TRACE-END; echo SPIN-DMESG-END; } > /dev/ttyS0"
+ExecStart=/bin/sh -c "mount -t tracefs none /sys/kernel/tracing 2>/dev/null; echo 0 > /sys/kernel/tracing/tracing_on; { ` + traceAccess + ` echo SPIN-TRACE-BEGIN; sed -n '1,/initcall_finish: func=FN+/p' /sys/kernel/tracing/trace | grep -E 'sched_switch|workqueue_execute|initcall_(start|finish): func=FN[+]'; echo SPIN-TRACE-END; echo SPIN-DMESG-END; } > /dev/ttyS0"
 [Install]
 WantedBy=multi-user.target
 `
@@ -52,9 +52,23 @@ WantedBy=multi-user.target
 		kernels = append(kernels, struct{ label, path string }{"kernel B", k})
 	}
 	shares := map[string][]map[string]float64{}
+	// The release's kernel cannot be traced (untraceable), so with a kernel B it is left out
+	// after its first boot says so, and without one the probe stops and says what to build.
+	locked := map[string]bool{}
 	for range reps {
 		for _, k := range kernels {
+			if locked[k.label] {
+				continue
+			}
 			console := bootUntil(t, out, v, k.path, "SPIN-DMESG-END", 180*time.Second)
+			if why := untraceable(console); why != "" {
+				if k.label == "release" && len(kernels) > 1 {
+					t.Logf("the release's kernel is left out: %s", why)
+					locked[k.label] = true
+					continue
+				}
+				t.Fatalf("nothing can be traced on the %s kernel: %s", k.label, why)
+			}
 			begin, end := strings.Index(console, "SPIN-TRACE-BEGIN"), strings.Index(console, "SPIN-TRACE-END")
 			if begin < 0 || end < begin {
 				t.Fatalf("no trace in the console:\n%s", tail([]byte(console), 2000))