amadan
Merge branch 'activator-wake-timing' into main
2 files changed,
+138
−6
internal/activator/activator.go+64 −6internal/activator/waketiming_test.go+74 −0
CI cancelled — superseded by a newer push — 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) |
| + } |
| +} |