feat(observability): unsampled tick heartbeat, interval-relative breach, slow_ticks doctor check, host-load stream (vp-qvqk)

CHANGELOG.md

@@ -47,6 +47,21 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
   on stderr and as `"path": "storeless-fallback"` in `--json` output. With the
   flag unset the behavior is unchanged. New file
   `cmd/gc/cmd_nudge_storeless.go`.
+- **Host-load event stream + slow-tick doctor check (vp-qvqk / defects 3+1).**
+  The controller now emits a periodic `host.load_sample` event (load1/5/15,
+  logical cores, runnable-process count, summed per-process %CPU) at patrol
+  cadence from its own goroutine, so a wedged reconcile tick cannot stall the
+  series that attributes the wedge. Runnable + %CPU ride alongside the load
+  averages because Darwin's load average also counts uninterruptible waits —
+  load alone cannot discriminate CPU oversubscription from blocked-on-I/O.
+  The supervisor doctor gains a `slow_ticks` check that reads the tick
+  heartbeat's `threshold_breach` flag over the doctor window and emits a
+  `doctor.alert` when any tick breached — the consumer that makes the flag
+  load-bearing (it was previously emitted and never read). New event type
+  `host.load_sample` carries a typed payload struct but is deliberately left
+  out of `KnownEventTypes` and the payload registry until the SSE projection
+  follow-up (same deferral as `provider.health_gate_alert`); subscribers
+  receive it via the custom-event envelope.
 
 - **L0 pre-heal in `ensure-project-id`: auto-restore canonical project_id from
   `city.toml [identity_map]` when the DB confirms it but L1 was wiped (vp-cz7o.21).**
@@ -59,6 +74,21 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
   pre-heal step only. New file `cmd/gc/city_identity_map.go`; ~20 lines added to
   `ensureManagedDoltProjectIDWithRecorder`.
 
+### Changed
+
+- **Controller tick heartbeat: emit every tick, breach threshold relative to
+  the patrol interval (vp-qvqk / defects 2+1).** `controller.tick_completed`
+  now fires once per completed tick instead of on breach-or-every-10th: the
+  sampled stream was a biased sample (fast ticks silently omitted), so any
+  period/median arithmetic over it was valid only while every tick breached —
+  a coincidence that would have flipped into a phantom regression the moment
+  the controller got healthy. The `threshold_breach` flag is now computed
+  against 2× the configured `[daemon] patrol_interval` (falling back to the
+  legacy absolute 5s only when the interval is unknown or non-positive)
+  instead of a constant 5s that had been ON for 100% of ticks in a 30-55s
+  regime. Consumers of `threshold_breach` should expect it to mean "lost
+  cadence for a full interval", not "took more than 5 seconds".
+
 ### Upgrading Notes
 
 - **Every graph-owning store scope needs a `Dir`-matched `control-dispatcher`

cmd/gc/city_runtime.go

@@ -119,13 +119,6 @@ type CityRuntime struct {
 	fsPressureConsecutiveSkips int
 	fsPressureEpisodeLogged    bool
 
-	// tickCount counts completed reconcile ticks for the controller
-	// heartbeat. controller.tick_completed is emitted at a patrol multiple
-	// (every tickHeartbeatEvery ticks) or when a tick's duration breaches
-	// tickHeartbeatSlowThreshold — never on every tick. Single-goroutine
-	// (the reconcile loop owns it); no synchronization needed.
-	tickCount uint64
-
 	convScopes          map[string]*convergenceScope // nil until bead store available; keyed by rig name ("" = city/HQ)
 	convScopesMu        sync.RWMutex                 // guards convScopes map pointer
 	convergenceReqCh    chan convergenceRequest      // receives CLI commands from controller.sock
@@ -718,6 +711,10 @@ func (cr *CityRuntime) run(ctx context.Context) {
 	ticker := time.NewTicker(interval)
 	defer ticker.Stop()
 
+	// Host-load series runs on its own goroutine at patrol cadence: a
+	// wedged tick must not stall the stream that attributes the wedge.
+	go cr.hostLoadSampler(ctx, interval)
+
 	// Start the supervisor nudge dispatcher when configured. The wake-socket
 	// listener feeds nudgeWakeCh on every producer enqueue, giving sub-second
 	// dispatch latency. Patrol-tick fallback inside cr.tick() guarantees
@@ -848,37 +845,55 @@ func (cr *CityRuntime) safeTick(fn func(), trigger string) (panicked bool) {
 	return false
 }
 
-// Controller heartbeat cadence. The tick_completed event is the
-// supervisor doctor's tick-age signal; emitting it every tick would make
-// the event log a hot path, so it fires on a patrol multiple or when a
-// tick runs slow.
+// Controller heartbeat. Every completed tick emits a
+// controller.tick_completed event: the stream is both the supervisor
+// doctor's tick-age/slow-tick signal and the fleet's tick-duration
+// series, and an unsampled stream is the only shape consumers can do
+// period/median arithmetic on without de-biasing (vp-qvqk — the earlier
+// breach-or-every-10th sampling silently omitted fast ticks, so the
+// series was complete only while every tick breached). One event per
+// tick is patrol-cadence volume (~2/min at the 30s default), not a hot
+// path.
 const (
-	// tickHeartbeatEvery emits one heartbeat per this many completed ticks.
-	tickHeartbeatEvery = 10
-	// tickHeartbeatSlowThreshold forces an out-of-cadence heartbeat when a
-	// single tick exceeds it, so a degrading controller surfaces before the
-	// next scheduled heartbeat.
-	tickHeartbeatSlowThreshold = 5 * time.Second
+	// tickSlowIntervalMultiple flags a tick as slow when its duration
+	// reaches this many patrol intervals. Scaling with the configured
+	// cadence keeps the canary calibrated to the regime it watches — the
+	// old absolute 5s threshold was ON for 100% of ticks in a 30-55s
+	// regime, a constant carrying zero bits. At 2× the loop has lost
+	// cadence for a full interval, the leading indicator of the doctor's
+	// 3×-patrol tick-age alert.
+	tickSlowIntervalMultiple = 2
+	// tickSlowFallbackThreshold is the slow-tick threshold when the
+	// patrol interval is unknown or non-positive, so the breach flag can
+	// never degenerate to always-true.
+	tickSlowFallbackThreshold = 5 * time.Second
 )
 
-// recordTickHeartbeat emits a controller.tick_completed event at a patrol
-// multiple or on a duration-threshold breach. It is the controller
-// heartbeat the supervisor-cadence doctor reads to compute tick age
-// (plan item 1.9). Best-effort: a nil recorder is a no-op.
-func (cr *CityRuntime) recordTickHeartbeat(trigger string, dur time.Duration) {
-	cr.tickCount++
-	breach := dur >= tickHeartbeatSlowThreshold
-	onMultiple := cr.tickCount%tickHeartbeatEvery == 0
-	if !breach && !onMultiple {
-		return
+// slowTickThreshold returns the duration at or above which a completed
+// tick is flagged (threshold_breach) in its heartbeat event.
+func (cr *CityRuntime) slowTickThreshold() time.Duration {
+	if cr.cfg == nil {
+		return tickSlowFallbackThreshold
 	}
+	if interval := cr.cfg.Daemon.PatrolIntervalDuration(); interval > 0 {
+		return time.Duration(tickSlowIntervalMultiple) * interval
+	}
+	return tickSlowFallbackThreshold
+}
+
+// recordTickHeartbeat emits a controller.tick_completed event for every
+// completed tick. It is the controller heartbeat the supervisor-cadence
+// doctor reads to compute tick age and surface slow ticks (plan item
+// 1.9); ThresholdBreach marks ticks at or past slowTickThreshold.
+// Best-effort: a nil recorder is a no-op.
+func (cr *CityRuntime) recordTickHeartbeat(trigger string, dur time.Duration) {
 	if cr.rec == nil {
 		return
 	}
 	payload, err := json.Marshal(events.ControllerTickCompletedPayload{
 		DurationMs:      dur.Milliseconds(),
 		Phase:           trigger,
-		ThresholdBreach: breach,
+		ThresholdBreach: dur >= cr.slowTickThreshold(),
 	})
 	if err != nil {
 		return

cmd/gc/city_runtime_tick_test.go

@@ -0,0 +1,117 @@
+package main
+
+import (
+	"testing"
+	"time"
+
+	"github.com/gastownhall/gascity/internal/config"
+	"github.com/gastownhall/gascity/internal/events"
+)
+
+// decodeTickPayload decodes one controller.tick_completed event's payload.
+func decodeTickPayload(t *testing.T, e events.Event) events.ControllerTickCompletedPayload {
+	t.Helper()
+	if e.Type != events.ControllerTickCompleted {
+		t.Fatalf("event type = %q, want %q", e.Type, events.ControllerTickCompleted)
+	}
+	decoded, _, err := events.DecodePayload(e.Type, e.Payload)
+	if err != nil {
+		t.Fatalf("decode tick payload: %v", err)
+	}
+	p, ok := decoded.(events.ControllerTickCompletedPayload)
+	if !ok {
+		t.Fatalf("decoded payload type %T, want ControllerTickCompletedPayload", decoded)
+	}
+	return p
+}
+
+// TestRecordTickHeartbeatEmitsEveryTick asserts the heartbeat stream is
+// unsampled: one event per completed tick, fast or slow (vp-qvqk defect 2
+// — the old breach-or-every-10th gate made the stream a biased sample, so
+// period arithmetic over it was valid only while every tick breached).
+func TestRecordTickHeartbeatEmitsEveryTick(t *testing.T) {
+	ep := events.NewFake()
+	cfg := &config.City{}
+	cfg.Daemon.PatrolInterval = "10s"
+	cr := &CityRuntime{cityName: "testcity", cfg: cfg, rec: ep}
+
+	// 25 fast ticks: under the old sampling only ticks 10 and 20 would
+	// emit; every one of these is far below any breach threshold.
+	for i := 0; i < 25; i++ {
+		cr.recordTickHeartbeat("patrol", 10*time.Millisecond)
+	}
+
+	if got := len(ep.Events); got != 25 {
+		t.Fatalf("events emitted = %d, want 25 (one per tick, no sampling)", got)
+	}
+	for i, e := range ep.Events {
+		p := decodeTickPayload(t, e)
+		if p.ThresholdBreach {
+			t.Fatalf("event %d: ThresholdBreach = true for a 10ms tick at 10s patrol", i)
+		}
+		if p.Phase != "patrol" {
+			t.Errorf("event %d: phase = %q, want patrol", i, p.Phase)
+		}
+	}
+}
+
+// TestRecordTickHeartbeatBreachRelativeToPatrolInterval asserts the
+// slow-tick flag is calibrated to the configured cadence, not an absolute
+// constant (vp-qvqk defect 1 — a fixed 5s threshold in a 30-55s tick
+// regime was ON for 100% of ticks and carried zero bits).
+func TestRecordTickHeartbeatBreachRelativeToPatrolInterval(t *testing.T) {
+	tests := []struct {
+		name       string
+		interval   string
+		dur        time.Duration
+		wantBreach bool
+	}{
+		// 10s patrol → 20s threshold.
+		{"under threshold", "10s", 19 * time.Second, false},
+		{"at threshold", "10s", 20 * time.Second, true},
+		{"past threshold", "10s", 443 * time.Second, true},
+		// The vc-wz5 regime: 30-55s ticks at a 30s patrol must NOT breach —
+		// under the old absolute 5s constant every one of them did.
+		{"steady 55s tick at 30s patrol", "30s", 55 * time.Second, false},
+		{"excursion at 30s patrol", "30s", 61 * time.Second, true},
+	}
+	for _, tc := range tests {
+		t.Run(tc.name, func(t *testing.T) {
+			ep := events.NewFake()
+			cfg := &config.City{}
+			cfg.Daemon.PatrolInterval = tc.interval
+			cr := &CityRuntime{cityName: "testcity", cfg: cfg, rec: ep}
+
+			cr.recordTickHeartbeat("patrol", tc.dur)
+
+			if len(ep.Events) != 1 {
+				t.Fatalf("events emitted = %d, want 1", len(ep.Events))
+			}
+			p := decodeTickPayload(t, ep.Events[0])
+			if p.ThresholdBreach != tc.wantBreach {
+				t.Fatalf("ThresholdBreach = %v, want %v (dur=%s interval=%s)", p.ThresholdBreach, tc.wantBreach, tc.dur, tc.interval)
+			}
+			if p.DurationMs != tc.dur.Milliseconds() {
+				t.Errorf("DurationMs = %d, want %d", p.DurationMs, tc.dur.Milliseconds())
+			}
+		})
+	}
+}
+
+// TestSlowTickThresholdFallback asserts the threshold degrades to the
+// legacy absolute rather than to zero (which would make breach
+// always-true, the exact defect this replaces).
+func TestSlowTickThresholdFallback(t *testing.T) {
+	nilCfg := &CityRuntime{}
+	if got := nilCfg.slowTickThreshold(); got != tickSlowFallbackThreshold {
+		t.Fatalf("nil cfg threshold = %s, want %s", got, tickSlowFallbackThreshold)
+	}
+
+	cfg := &config.City{}
+	cfg.Daemon.PatrolInterval = "10s"
+	cr := &CityRuntime{cfg: cfg}
+	want := time.Duration(tickSlowIntervalMultiple) * 10 * time.Second
+	if got := cr.slowTickThreshold(); got != want {
+		t.Fatalf("threshold = %s, want %s (%d× patrol)", got, want, tickSlowIntervalMultiple)
+	}
+}