amadan
The wake reports how long it took, and how much of that was the app
Discussion #6: Tito Go is enforcing a per-screen performance budget —
150ms warm, 500ms cold — and the cold half is unverifiable, because an
instance cannot time its own wake. The activator execs the binary, the
process starts, opens SQLite, runs ~400 DDL statements (207ms measured),
parses templates per locale, and only THEN can the app's code observe
anything. The number the budget most needs is the one it structurally
cannot produce.
The wake event `carlos logs` already carries now says it:
instance woke in 1.4s (spawn 1.2s) (version 7507a33)
Two figures, because one would not settle the question. `spawn` is
Backend.Start alone — exec to the socket accepting, which is the app's
OWN boot and none of the platform's work; the rest of the total is the
lease, the restore, the seed and starting replication. "woke in 1.4s
(spawn 1.2s)" says the boot is the problem. "woke in 1.4s (spawn 200ms)"
says it is not. #6's actual ask is that an app be able to tell those
apart at all, which today it cannot.
The log line was one of the three shapes #6 offered (a header on the
first response after a wake, a control-socket read, or a line to
scrape), and it is the one that costs nothing in the request path. See
below for why the header half is not here.
Unmeasured is not zero: a wokenInstance with no timings reads exactly as
the line did before, rather than claiming an instant wake. Rounded to a
millisecond — a person reads this and a script greps it, and
microseconds of a several-hundred-millisecond wake are noise in both
directions.
NOT done, deliberately, and the two halves of #6 that remain:
- The edge's Server-Timing header. It belongs in the request path of
every response, and this repo's own rule about ResponseWriter wrappers
is the reason not to add one overnight: the wrappers in internal/edge
share ONE header map from handler to connection, and maybeStore caches
rec.Header().Clone(). A timing header set the obvious way would be
cached and then served to every later visitor as though it described
THEIR request. That is a design question about where in the wrapper
order the header goes and which responses may carry it, not a patch.
- Per-request wake attribution. The figures here are per WAKE, on the
platform's own log stream. Tying one to the request that triggered it
is the header above by another name.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
2 files changed,
+138
−6
internal/activator/activator.go+64 −6internal/activator/waketiming_test.go+74 −0
CI passed — run details
diff --git a/internal/activator/activator.go b/internal/activator/activator.go| index 426b8c5e9..41f326995 100644 |
| --- a/internal/activator/activator.go |
| +++ b/internal/activator/activator.go |
| @@ -620,7 +620,11 @@ func (a *Service) releaseFunc(e *actEntry, stamp bool) func() { |
| func (a *Service) wake(e *actEntry) { |
| ctx, cancel := context.WithTimeout(context.Background(), 5*time.Minute) |
| defer cancel() |
| + wakeStart := a.now() |
| w, err := a.doWake(ctx, e.route) |
| + if w != nil { |
| + w.wakeTook = a.now().Sub(wakeStart) |
| + } |
| // The member-facing record of this wake (spec §5): composed here, where |
| // the route and the whole error are in hand — the journal line below the |
| @@ -628,11 +632,7 @@ func (a *Service) wake(e *actEntry) { |
| if err != nil { |
| emitEvent(a.Logs, e.route, "error", memberSafeWakeReason(err)) |
| } else { |
| - msg := "instance woke" |
| - if w.spawnVersion != "" { |
| - msg += " (version " + w.spawnVersion + ")" |
| - } |
| - emitEvent(a.Logs, e.route, "info", msg) |
| + emitEvent(a.Logs, e.route, "info", wakeEventMessage(w)) |
| } |
| a.mu.Lock() |
| @@ -668,6 +668,44 @@ func (a *Service) wake(e *actEntry) { |
| close(e.ready) |
| } |
| +// wakeEventMessage is the member-facing wake line, split out so the one thing |
| +// an app can actually scrape has a test of its own. |
| +// |
| +// It carries the wake's timing because an instance cannot time its own wake: |
| +// the activator execs the binary, the process starts, opens SQLite, runs its |
| +// migrations and parses its templates, and only THEN can the app's own code |
| +// observe anything. So a cold-start budget's most important number is the one |
| +// the app structurally cannot produce, and every app on the platform meets |
| +// the same wall (discussion #6). |
| +// |
| +// Two figures, because one would not settle the question the budget is |
| +// really asking. `spawn` is Backend.Start alone — exec to the socket |
| +// accepting, which is the app's OWN boot and none of the platform's work. |
| +// The total around it is the lease, the restore, the seed and replication. |
| +// An app reading "woke in 1.4s (spawn 1.2s)" knows its boot is the problem; |
| +// reading "woke in 1.4s (spawn 200ms)" knows it is not, which is the |
| +// distinction #6 says cannot be made at all today. |
| +// |
| +// Rounded to a millisecond: this is a log line a person reads and a script |
| +// greps, and microseconds of a multi-hundred-millisecond wake are noise that |
| +// makes both harder. |
| +func wakeEventMessage(w *wokenInstance) string { |
| + msg := "instance woke" |
| + if w == nil { |
| + return msg |
| + } |
| + if w.wakeTook > 0 { |
| + msg += " in " + w.wakeTook.Round(time.Millisecond).String() |
| + if w.spawnTook > 0 { |
| + msg += " (spawn " + w.spawnTook.Round(time.Millisecond).String() + ")" |
| + } |
| + } |
| + if w.spawnVersion != "" { |
| + msg += " (version " + w.spawnVersion + ")" |
| + } |
| + return msg |
| +} |
| + |
| // wokenInstance is a successful wake's yield. sidecar is nil when the host has |
| // none staged — or when the spawn failed, which is deliberately not an error: |
| // members > bots, so a host whose sidecar won't start still serves (the |
| @@ -678,6 +716,18 @@ type wokenInstance struct { |
| sidecar Proc |
| sidecarWanted bool |
| spawnVersion string // live/<host> target read at exec — for build convergence |
| + // spawnTook is how long Backend.Start took: exec to the socket accepting, |
| + // which is the instance's OWN boot and nothing of the platform's. wakeTook |
| + // is the whole wake around it, filled in by wake() rather than here |
| + // because the caller owns the clock that bounds it. |
| + // |
| + // They exist because an instance cannot time its own wake — almost all of |
| + // it happens before the app's code can observe anything — so the figure |
| + // an app most wants for a cold-start budget is the one it structurally |
| + // cannot produce (discussion #6). Reported on the wake event, where |
| + // `carlos logs` already carries the line. |
| + spawnTook time.Duration |
| + wakeTook time.Duration |
| } |
| func (a *Service) doWake(ctx context.Context, rt registry.Route) (*wokenInstance, error) { |
| @@ -727,7 +777,15 @@ func (a *Service) doWake(ctx context.Context, rt registry.Route) (*wokenInstance |
| // on boot, so waiting for the socket guarantees the file exists for |
| // litestream to open. Writes that land in the gap are picked up by the |
| // replica's first sync. |
| + // Timed, because this is the half an app CANNOT see. Backend.Start execs |
| + // the binary and waits until its socket accepts, so it contains the whole |
| + // of the instance's own boot — opening SQLite, running migrations, |
| + // parsing templates — and none of the platform's lease, restore or |
| + // replication work. An app measuring its own TTFB starts the clock after |
| + // all of it (discussion #6). |
| + spawnStart := a.now() |
| proc, spawnVer, err := a.backend.Start(ctx, rt) |
| + spawnTook := a.now().Sub(spawnStart) |
| if err != nil { |
| _ = lease.Release(ctx) |
| return nil, fmt.Errorf("start %s: %w", host, err) |
| @@ -752,7 +810,7 @@ func (a *Service) doWake(ctx context.Context, rt registry.Route) (*wokenInstance |
| // marked requests pass through the edge while we're awake). A spawn |
| // failure is loud but never fails the wake: members come before bots, and |
| // the sweeper retries with backoff. |
| - w := &wokenInstance{rep: rep, proc: proc, spawnVersion: spawnVer} |
| + w := &wokenInstance{rep: rep, proc: proc, spawnVersion: spawnVer, spawnTook: spawnTook} |
| if a.backend.HasSidecar(rt) { |
| w.sidecarWanted = true |
| if sc, err := a.backend.StartSidecar(ctx, rt); err != nil { |
diff --git a/internal/activator/waketiming_test.go b/internal/activator/waketiming_test.go| new file mode 100644 |
| index 000000000..3b1e5040d |
| --- /dev/null |
| +++ b/internal/activator/waketiming_test.go |
| @@ -0,0 +1,74 @@ |
| +package activator |
| + |
| +import ( |
| + "strings" |
| + "testing" |
| + "time" |
| +) |
| + |
| +// The wake's timing, on the one line an app can actually scrape |
| +// (discussion #6). An instance cannot time its own wake — almost all of it |
| +// happens before the app's code can observe anything — so a cold-start |
| +// budget's most important figure is the one the app structurally cannot |
| +// produce. |
| + |
| +func TestWakeEventMessageCarriesBothFigures(t *testing.T) { |
| + msg := wakeEventMessage(&wokenInstance{ |
| + wakeTook: 1400 * time.Millisecond, |
| + spawnTook: 1200 * time.Millisecond, |
| + spawnVersion: "7507a33", |
| + }) |
| + for _, want := range []string{"instance woke", "1.4s", "spawn 1.2s", "7507a33"} { |
| + if !strings.Contains(msg, want) { |
| + t.Errorf("wake message %q is missing %q", msg, want) |
| + } |
| + } |
| +} |
| + |
| +// The two figures have to be separable, because the whole point is telling |
| +// "our boot is slow" from "the wake path is slow". A message carrying only a |
| +// total answers neither. |
| +func TestWakeEventMessageSeparatesSpawnFromTheRest(t *testing.T) { |
| + slowBoot := wakeEventMessage(&wokenInstance{wakeTook: 1400 * time.Millisecond, spawnTook: 1200 * time.Millisecond}) |
| + slowPlatform := wakeEventMessage(&wokenInstance{wakeTook: 1400 * time.Millisecond, spawnTook: 200 * time.Millisecond}) |
| + if slowBoot == slowPlatform { |
| + t.Fatalf("a slow boot and a slow wake path read identically: %q", slowBoot) |
| + } |
| + if !strings.Contains(slowPlatform, "spawn 200ms") { |
| + t.Errorf("message %q does not carry the spawn figure", slowPlatform) |
| + } |
| +} |
| + |
| +// Unmeasured is not zero. A wake with no timing (a backend or a test that |
| +// does not fill them) must read exactly as the line did before, rather than |
| +// claiming an instant wake. |
| +func TestWakeEventMessageSaysNothingItDoesNotKnow(t *testing.T) { |
| + if got := wakeEventMessage(&wokenInstance{}); got != "instance woke" { |
| + t.Errorf("untimed wake = %q, want the bare line", got) |
| + } |
| + if got := wakeEventMessage(&wokenInstance{spawnVersion: "abc1234"}); got != "instance woke (version abc1234)" { |
| + t.Errorf("untimed wake with a version = %q", got) |
| + } |
| + if got := wakeEventMessage(nil); got != "instance woke" { |
| + t.Errorf("nil wake = %q, want the bare line", got) |
| + } |
| + // A total with no spawn figure still reports the total: half an answer |
| + // beats none, and the alternative is dropping a measurement that was |
| + // actually taken. |
| + if got := wakeEventMessage(&wokenInstance{wakeTook: 900 * time.Millisecond}); !strings.Contains(got, "900ms") { |
| + t.Errorf("wake with only a total = %q", got) |
| + } |
| +} |
| + |
| +// Rounded to a millisecond: a log line a person reads and a script greps, |
| +// where microseconds of a several-hundred-millisecond wake are noise in both |
| +// directions. |
| +func TestWakeEventMessageRoundsToMilliseconds(t *testing.T) { |
| + msg := wakeEventMessage(&wokenInstance{ |
| + wakeTook: 812*time.Millisecond + 417*time.Microsecond, |
| + spawnTook: 640*time.Millisecond + 903*time.Microsecond, |
| + }) |
| + if !strings.Contains(msg, "812ms") || !strings.Contains(msg, "spawn 641ms") { |
| + t.Errorf("wake message %q is not rounded to milliseconds", msg) |
| + } |
| +} |