feat(controlplane): log client-correlated fork submit-to-ready latency#868
Open
stubbi wants to merge 7 commits into
Open
feat(controlplane): log client-correlated fork submit-to-ready latency#868stubbi wants to merge 7 commits into
stubbi wants to merge 7 commits into
Conversation
The controller "fork timing complete" totalMs measures forkStartedAt to the end of the reconcile pass, which keeps counting after the ready watch already returned to the client. Prod v1.38 measurements show it decorrelated from client latency (one fork logged totalMs 791.8 while its server submit-to-Ready was 248 and client wall 437), so it cannot be used as the client-latency proxy. Log an authoritative, client-correlated split in the fork path instead: submitToCreateMs (request receipt to a persisted fork CR) and submitToReadyMs (request receipt to the ready watch observing the child Ready). The difference is the controller scheduling + fork work + watch delivery, making the server-side fork latency repeatable without depending on the misleading totalMs. Purely observational: no change to the fork control flow. Adds a design note (docs/perf/fork-fast-path.md) with the measured breakdown and the synchronous fast-path evaluation. Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com> Signed-off-by: Jannes Stubbemann <jannes@openclaw.rocks>
📝 WalkthroughWalkthroughThis PR adds a performance investigation document analyzing hosted fork latency and proposing a synchronous fast-path design, and instruments the control-plane fork handler with structured logging that records submitToCreateMs and submitToReadyMs timing metrics. ChangesFork Latency Investigation and Telemetry
Estimated code review effort: 2 (Simple) | ~10 minutes Possibly related PRs
🚥 Pre-merge checks | ✅ 5✅ Passed checks (5 passed)
✨ Finishing Touches📝 Generate docstrings
🧪 Generate unit tests (beta)
Comment |
![coderabbitai[bot]](https://avatars.githubusercontent.com/in/347564?s=60&v=4){kind=small}
There was a problem hiding this comment.
Actionable comments posted: 1
🤖 Prompt for all review comments with AI agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.
Inline comments:
In `@internal/saas/controlplane/fork.go`:
- Around line 172-189: The "fork served" telemetry in fork() is logged
unconditionally even when pollReady() returns an error, which mixes failed waits
into the success latency bucket. Update the flow around resp, err :=
k.pollReady(...) so slog.Info("fork served", ...) only runs on success, or add
explicit success/error handling and a status field, using the existing symbols
pollReady, fork served, submitToCreateMs, and submitToReadyMs to keep the
client-correlated metrics accurate.
🪄 Autofix (Beta)
Fix all unresolved CodeRabbit comments on this PR:
- Push a commit to this branch (recommended)
- Create a new PR with the fixes
ℹ️ Review info
⚙️ Run configuration
Configuration used: Organization UI
Review profile: ASSERTIVE
Plan: Pro Plus
Run ID: 7f360544-217d-4de9-a089-e35b2295a247
📒 Files selected for processing (2)
docs/perf/fork-fast-path.mdinternal/saas/controlplane/fork.go
Comment on lines
+172
to
+189
| // Timing split for the fork latency investigation. submitToCreateMs is the | ||
| // control plane's own cost to persist the fork Sandbox (request receipt to a | ||
| // successful Create); submitToReadyMs is the full server-side wall the client | ||
| // waits on (request receipt to the ready watch observing the child Ready), so | ||
| // the difference is the controller scheduling + fork work + watch delivery. | ||
| // This is the authoritative, client-correlated server-side fork latency: it | ||
| // does NOT depend on the controller's "fork timing complete" totalMs, which | ||
| // measures to the end of the reconcile pass and overstates the client-observed | ||
| // latency (it can keep counting after the ready watch already returned). | ||
| // Purely observational: it does not change the fork control flow. | ||
| createdAt := k.now() | ||
| resp, err := k.pollReady(ctx, ns, name, startedAt) | ||
| slog.Info("fork served", | ||
| "sandbox", name, | ||
| "submitToCreateMs", createdAt.Sub(startedAt).Milliseconds(), | ||
| "submitToReadyMs", k.now().Sub(startedAt).Milliseconds(), | ||
| ) | ||
| return resp, err |
There was a problem hiding this comment.
🗄️ Data Integrity & Integration | 🟠 Major | ⚡ Quick win
"fork served" is logged even when pollReady fails.
resp, err := k.pollReady(...) can return a non-nil err (e.g. ready-wait timeout), but the slog.Info("fork served", ...) call fires unconditionally with the same submitToReadyMs value. Since this telemetry is explicitly meant to be the "authoritative, client-correlated" latency number the design doc relies on, mixing failed/timed-out polls into the same "served" bucket without any success/error marker will silently corrupt future p50/p99 latency analysis — the same class of problem this PR is fixing for totalMs.
🐛 Proposed fix to distinguish success/failure
createdAt := k.now()
resp, err := k.pollReady(ctx, ns, name, startedAt)
- slog.Info("fork served",
+ slog.Info("fork served",
"sandbox", name,
"submitToCreateMs", createdAt.Sub(startedAt).Milliseconds(),
"submitToReadyMs", k.now().Sub(startedAt).Milliseconds(),
+ "success", err == nil,
)
return resp, err📝 Committable suggestion
‼️ IMPORTANT
Carefully review the code before committing. Ensure that it accurately replaces the highlighted code, contains no missing lines, and has no issues with indentation. Thoroughly test & benchmark the code to ensure it meets the requirements.
Suggested change
| // Timing split for the fork latency investigation. submitToCreateMs is the | |
| // control plane's own cost to persist the fork Sandbox (request receipt to a | |
| // successful Create); submitToReadyMs is the full server-side wall the client | |
| // waits on (request receipt to the ready watch observing the child Ready), so | |
| // the difference is the controller scheduling + fork work + watch delivery. | |
| // This is the authoritative, client-correlated server-side fork latency: it | |
| // does NOT depend on the controller's "fork timing complete" totalMs, which | |
| // measures to the end of the reconcile pass and overstates the client-observed | |
| // latency (it can keep counting after the ready watch already returned). | |
| // Purely observational: it does not change the fork control flow. | |
| createdAt := k.now() | |
| resp, err := k.pollReady(ctx, ns, name, startedAt) | |
| slog.Info("fork served", | |
| "sandbox", name, | |
| "submitToCreateMs", createdAt.Sub(startedAt).Milliseconds(), | |
| "submitToReadyMs", k.now().Sub(startedAt).Milliseconds(), | |
| ) | |
| return resp, err | |
| // Timing split for the fork latency investigation. submitToCreateMs is the | |
| // control plane's own cost to persist the fork Sandbox (request receipt to a | |
| // successful Create); submitToReadyMs is the full server-side wall the client | |
| // waits on (request receipt to the ready watch observing the child Ready), so | |
| // the difference is the controller scheduling + fork work + watch delivery. | |
| // This is the authoritative, client-correlated server-side fork latency: it | |
| // does NOT depend on the controller's "fork timing complete" totalMs, which | |
| // measures to the end of the reconcile pass and overstates the client-observed | |
| // latency (it can keep counting after the ready watch already returned). | |
| // Purely observational: it does not change the fork control flow. | |
| createdAt := k.now() | |
| resp, err := k.pollReady(ctx, ns, name, startedAt) | |
| slog.Info("fork served", | |
| "sandbox", name, | |
| "submitToCreateMs", createdAt.Sub(startedAt).Milliseconds(), | |
| "submitToReadyMs", k.now().Sub(startedAt).Milliseconds(), | |
| "success", err == nil, | |
| ) | |
| return resp, err |
🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.
In `@internal/saas/controlplane/fork.go` around lines 172 - 189, The "fork served"
telemetry in fork() is logged unconditionally even when pollReady() returns an
error, which mixes failed waits into the success latency bucket. Update the flow
around resp, err := k.pollReady(...) so slog.Info("fork served", ...) only runs
on success, or add explicit success/error handling and a status field, using the
existing symbols pollReady, fork served, submitToCreateMs, and submitToReadyMs
to keep the client-correlated metrics accurate.
16 tasks
Contributor
Author
|
Reviewed: log placement is after all Create error returns, uses the injected clock, carries no secrets, and the doc states its provenance (dated prod logs, method described) rather than claiming bench numbers. One named follow-up, not blocking: the fork served line also fires when pollReady returns a timeout/failure response with no outcome discriminator, so percentiles derived from it can be skewed by timed-out forks; add an outcome field in a follow-up. Merging via auto-merge once the branch is updated. |
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 join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
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.
Thinking Path
Linked Issues or Issue Description
No dedicated issue. Problem: there is no authoritative, client-correlated log of
hosted fork latency; the controller
totalMsoverstates it and is decorrelatedfrom what the client waits for, which misdirects fork-latency work. This PR adds
the missing measurement and documents where the latency actually lives.
What Changed
internal/saas/controlplane/fork.go: after the fork Sandbox is created, log astructured
fork servedline withsubmitToCreateMs(request receipt to apersisted CR) and
submitToReadyMs(request receipt to the ready watchobserving the child Ready). Observational only; the fork control flow is
unchanged (same
pollReadycall, same response).docs/perf/fork-fast-path.md: investigation note. Measured prod breakdown(5 forks, co-located, reconcilePasses=1), the finding that
totalMsoverstates, the finding that the p50 scheduling gap is ~20-35 ms (not ~200 ms),
the tail-jitter verdict, and the synchronous fork fast-path design with its
correctness constraints and estimated (modest p50, real p99) drop.
Verification
go build ./internal/saas/controlplane/(exit 0)go test ./internal/saas/controlplane/(ok)golangci-lint run ./internal/saas/controlplane/(darwin, exit 0)GOOS=linux golangci-lint run ./internal/saas/controlplane/(exit 0)client wall + server
fork_time_msvia the SDK, per-stage +totalMsvia thecontroller
fork stage timing/fork timing completelogs.Risks
Low risk. Adds one INFO log line per fork and a docs file. No control-flow,
schema, or response change. The log carries only the sandbox name and two
integer millisecond values (no secrets, no token).
Model Used
Claude Opus 4.8 (claude-opus-4-8), high reasoning effort.
Checklist
#NNN/ mitos-run/mitos URLs)Signed-off-bytrailer (git commit -s)🤖 Generated with Claude Code
Summary by CodeRabbit