Skip to content

feat(run): Measure guest boot time and report it as a ready event - #42

Draft
ananos wants to merge 4 commits into
mainfrom
feat/1527-boot-time
Draft

ananos wants to merge 4 commits into
mainfrom
feat/1527-boot-time

Conversation

@ananos

@ananos ananos commented Sep 8, 2026

Copy link
Copy Markdown
Member

Summary

We quote boot times in the README and nothing in the repo produces them: the telemetry start event's boot: ok means the VMM process spawned, and the harnesses wait on console markers without reading a clock. This adds the measurement.

run now reports a ready telemetry event carrying ready_ms: the time from the VMM spawn (InstanceState.StartTime) to the guest agent's first answer to /bin/true, on all three backends. It is a separate event rather than a delayed start, so start keeps its timing and a guest that never answers sends nothing instead of a bogus value. The probe runs on its own goroutine next to the console attach, bounded by a two minute budget, so it never delays the user. Foreground runs only: a detached run returns to its caller at once, and a restore resumes memory rather than booting.

The pty and hvi harnesses now print the elapsed time to their markers (boot: kernel-to-init 0.46s (backend vz), kernel-to-shell, kernel-to-entrypoint, hull-spawn-to-*), print only, no assertion. Neither harness runs --net shared, so there is no DHCP milestone to print. The README rows stay hand-typed until someone regenerates them from this output on a real machine; the CI gate is a follow-up.

The unit tests drive the probe against a fake agent speaking the real protocol. No live VM was booted for this PR.

Changes

  • exec_compose.go: agent error replies are wrapped in an errGuestAgent sentinel so callers can tell "agent refused" from "instance gone"
  • telemetry.go, run.go: probeGuestReady, readyEventFields, sendReadyEvent; the run path starts the probe after the instance is recorded as running
  • docs/telemetry.md: the ready event, and start no longer implies the guest booted
  • test/pty-terminal-test.py, test/hvi-boot-test.py: print boot timings; the hvi harness streams output instead of buffering it and cleans up on overrun

Checklist

  • make test passes
  • make macos builds hull, vz-runner and hvi, if Go, Swift or Rust code changed (CI build lane)
  • I have added or updated tests covering the change
  • I have run the e2e harnesses (test/*.py) for changes touching boot, console, or the run path (CI unit + e2e lane)
  • I have updated the affected docs (README, docs/)

@ananos
ananos force-pushed the feat/1527-boot-time branch from e541426 to c2bf880 Compare September 8, 2026 09:39
@ananos

ananos commented Sep 9, 2026

Copy link
Copy Markdown
Member Author

@claude-fleet review

@claude-fleet

claude-fleet Bot commented Sep 9, 2026

Copy link
Copy Markdown

Review task queued.

Task: 70a74d74-2bfd-46e2-9692-2c2b782c7401
Commit: c2bf880
Model: executor default (effort high)
Executor: ci-16gb-fsn1-1
Status: done. Review posted.

@claude-fleet claude-fleet Bot left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Verdict: approve. This is a well-constructed, well-tested change. I read the probe path end to end, verified the error-sentinel semantics the probe relies on, checked every new test bites against the code it exercises, and confirmed the harness edits compile and are print-only. Findings are two nits, neither blocking.

What I verified holds

  • Sentinel semantics are correct. execCapture (exec_compose.go:186) now wraps agent error replies in errGuestAgent; transport failures wrap errAgentTransport. probeGuestReady returns true on nil || errors.Is(err, errGuestAgent) — so an agent that refuses /bin/true counts as up, matching the doc and TestProbeGuestReadyCountsARefusalAsUp. A stopped/missing instance returns a plain error (exec_compose.go:126,129) that wraps neither sentinel, so execCaptureRetry returns at once and the probe reports unready without retrying — matching TestProbeGuestReadyStopsWhenTheInstanceIsGone. Confirmed execCaptureRetry retries only on errAgentTransport.
  • Measurement endpoints are right. state.StartTime is set at run.go:2360, immediately before vmmCmd.Start(), so ready_ms is spawn→first-answer and excludes image pull, as the docs claim. The goroutine passes state.ID, vmmType, state.StartTime by value (run.go:2433), so no race on later state mutation.
  • The --restore and detach guards are real. checkpoint.go:240-241 appends --restore to cmdArgs, so slices.Contains(cmdArgs, "--restore") in run.go:2428 correctly suppresses the event on restore. Detached runs are excluded.
  • No panic / nil risk from the new goroutine. Client.Enabled() and Send are nil-safe, so sendReadyEvent on an uninitialized client is a no-op, not a crash on a non-main goroutine.
  • Store access is concurrency-safe. GetInstance/SaveInstance take s.mu (RWMutex), and background goroutines already share s (metrics sampler, lease discovery), so the probe adds nothing new.
  • Tests are not tautologies. Each TestProbeGuestReady* targets a distinct branch: startup-window EOFs (fakeAgent(...,2,0)), refusal-as-up (fakeRefusingAgent), budget bound (2s budget, asserts <6s), instance-gone short-circuit. TestReadyEventFieldsAreWholeMilliseconds pins truncation, the negative-clamp, and the exact two-field shape.
  • Harness edits. Both read via os.read(fileno) after select, bypassing Python buffering correctly; VMM_MARKER/b"VMM started (PID" matches hull's actual line (run.go:2384). The hvi harness kills the process and dies on overrun. Both py_compile clean.

Gates

  • GOOS=darwin GOARCH=arm64 go build ./cmd/hull/ — clean.
  • GOOS=darwin GOARCH=arm64 go vet ./cmd/hull/ — clean.
  • GOOS=darwin GOARCH=arm64 go test -c ./cmd/hull/ — test binary compiles.
  • python3 -m py_compile on both harnesses — clean.
  • Not run: the Go test suite. This is a macOS/vz/hvi target; the package does not build for linux (compose/gateway files are darwin-tagged) and the tests need a darwin runtime, so I could not execute make test here. ruff unavailable in this environment. The PR checkbox claims make test passes; I did not independently confirm it.

Findings (both nits)

  1. The kernel-to-* labels are measured from hull's VMM started line, not from kernel start — so they overstate the kernel-to-init/shell/entrypoint intervals by the firmware/VMM-init time. Since these numbers are what feeds the README, the label is misleading.
  2. A new ready event is added but schema_version stays 1, while the page states it is "bumped on any schema change." Additive, so defensible, but worth a deliberate call.

Not checked:

  • Execution of the Go test suite (make test): package builds only for darwin and tests need a darwin/vz/hvi runtime; verified via cross-compile + test-binary compile + vet only.
  • Live boot: no VM was booted, so real ready_ms values and the harness boot-timing output were not observed end to end.
  • ruff/shellcheck on the Python harnesses (ruff unavailable here); only py_compile was run.
  • Whether concurrent probe exec of /bin/true perturbs the guest workload or console on a real backend.

Task 70a74d74-2bfd-46e2-9692-2c2b782c7401 on ci-16gb-fsn1-1, model executor default, effort high.

Comment thread test/pty-terminal-test.py
die(f"run exited during boot (rc={child.poll()})")
die(f"boot marker {marker!r} not seen within {timeout}s")

def print_boot_time(label, t_marker):

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

nit: print_boot_time computes origin from t_vmm, the timestamp of hull's VMM started (PID line, then labels the interval kernel-to-init/kernel-to-shell. That host line is printed right after spawn, before guest firmware and kernel, so the printed number includes VMM/firmware startup and overstates the true kernel-to-X time. These values feed the README boot-time rows, so the mislabel propagates. Consider vmm-start-to-init or subtracting to a kernel marker.

Comment thread test/hvi-boot-test.py
origin = t_vmm if t_vmm is not None else t_spawn
origin_note = "" if t_vmm is not None else ", from hull spawn: no VMM-started line seen"
if markers[b"Run /."] is not None:
print(f"boot: kernel-to-init {markers[b'Run /.'] - origin:.2f}s (backend hvi{origin_note})")

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

nit: Same as the pty harness: origin is the VMM started (PID timestamp but the label reads kernel-to-init/kernel-to-entrypoint. Measured from the host spawn line, not kernel start, so the printed interval is larger than a true kernel-to-X and the README rows it feeds would inherit the inflation.

Comment thread docs/telemetry.md Outdated
@@ -78,7 +78,7 @@ All events share a common envelope:
| field | example | notes |
|---|---|---|
| `schema_version` | `1` | bumped on any schema change, with this page updated |

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

nit: A new ready event type is added but schema_version stays 1, while this same row says it is bumped on any schema change, with this page updated. Additive events keep existing consumers working, so 1 is defensible, but confirm this is intentional rather than an omission.

execCapture distinguishes transport failures (errAgentTransport) from
everything else, but "everything else" mixes two things a caller may
need to tell apart: the guest agent answering with an Error frame, and
the instance not being there at all (no record, or not running). Both
came back as plain formatted errors.

Wrap the agent's Error reply in errGuestAgent so errors.Is can pick it
out. The message text is unchanged ("guest agent: <sanitized text>"),
so nothing printed to the user moves. The readiness probe that follows
needs the distinction: an agent that refuses /bin/true is up, while an
instance that stopped is not.

Signed-off-by: Anastassios Nanos <ananos@nofire.ai>
The `start` event's `boot: ok` only means the VMM process spawned. We
had no measurement of when the guest actually came up, so the boot
times we quote are hand-typed and cannot be checked against what users
see. Measure it instead.

A foreground `run` now probes the guest agent with /bin/true, the same
retried session the compose pre-warms use, from the moment the VMM
process exists. When the agent first answers (an error reply counts:
the agent is up, the image just has no /bin/true), a `ready` event
carries `backend` and `ready_ms`, milliseconds from the recorded
StartTime to that answer. This covers firmware, kernel, init and the
agent on vz, hvi and qemu alike, with nothing backend-specific.

A separate event rather than a field on `start`: `start` is sent the
instant the process exists and its semantics stay as they are. Holding
it back until the probe resolved would either delay it by the whole
budget on an image without an agent or force a made-up value. With a
separate event a guest that never answers sends nothing, and an absent
`ready` after a `start` is itself the signal.

The probe runs on its own goroutine beside the console attach, so it
never delays the user; the two-minute budget only bounds how long an
agent-less guest keeps being dialed. Detached runs return to their
caller before the guest is up and have no process left to wait in, so
they do not report one. A restore resumes a guest rather than booting
it, so the restore path (which shares launchVMM) is excluded too.

Signed-off-by: Anastassios Nanos <ananos@nofire.ai>
The `start` paragraph read as if `boot: ok` meant the guest booted. It
means the VMM process spawned, and nothing about the guest; say so, and
point at the `ready` event for the guest side.

Document `ready`: when it is sent (foreground runs only, once, when the
guest agent first answers), the two ends of `ready_ms` (VMM spawn to
the agent's first reply, whole milliseconds), and the cases that send
no event at all (no agent, guest gone first, detached runs, restore).

Signed-off-by: Anastassios Nanos <ananos@nofire.ai>
README quotes boot times that were typed in by hand and cannot be
reproduced. Both harnesses already watch the console for the boot
markers, so have them say when each one showed up.

pty-terminal-test.py checks the console read by read instead of on a
one-second tick, so a marker's timestamp is the read that carried it.
It prints kernel-to-init (hull's "VMM started" line to the init
wrapper's "Run /." line) and, in the type scenario, kernel-to-shell,
plus spawn-to-init which includes any image pull.

hvi-boot-test.py streamed nothing: it collected the console at exit.
Read it as it arrives and print kernel-to-init where the image's init
prints the marker, kernel-to-entrypoint, and spawn-to-exit. The 300s
bound is kept; on overrun the harness now kills the run and cleans up
instead of dying on a TimeoutExpired traceback (exit code stays 1).

Neither harness runs `--net shared`, so there is no DHCP milestone to
print, and hull prints nothing when the agent answers; the telemetry
`ready` event carries that one. Times are printed, never asserted on.
Exit codes and the checks made are unchanged.

Signed-off-by: Anastassios Nanos <ananos@nofire.ai>
@ananos
ananos force-pushed the feat/1527-boot-time branch from c2bf880 to 820631c Compare September 12, 2026 20:50
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant