Record web and composed-panel read durations into hourly latency histograms in the store (#4442)

[erikdarlingdata]

Refs #4442 (scope 2).

Why

Slow reads on the /api/read/* surface and the composed-panel runner have no stored history — the only
signal is the 5-second slow-query log tail, which can show the newest offender but never a percentile or a
"how often does this time out" answer. This adds an in-process histogram that records every finished read,
so a later store table and read tool can answer that question from stored series instead.

What changes

• ReadLatencyAccumulator: a CollectorCostAccumulator-shaped histogram keyed by (surface, route, outcome),
  fixed log-scale buckets (10 ms – 120 s plus overflow), thread-safe, drained (and reset) for a later hourly
  flush.
• ReadLatencyPercentiles.FromBuckets: pure percentile math over the buckets — an upper-bound estimate,
  never an interpolation, flagged IsAtLeast when the true value only proven to exceed the last finite bound.
• ReadOutcomeClassifier: maps an exception, or a tool's own caught-and-formatted error sentence, to
  Ok / Timeout / Cancelled / Error, reusing CollectorFaultCancelOrigin's SQLSTATE-plus-wording rule
  rather than a second copy of it.
• Recording wired into DarlingWebEndpoints.MapAll's /api/read/* dispatch loop (both the binding-layer
  catch and the tool-result arm) and into RunComposedPanelAsync's one call site, with a bounded-cardinality
  measureKey label (never the caller's free text). Recording never throws into the request — a try/catch
  logs at Debug and swallows.
• DI wiring in Program.cs and DarlingWebHostService.
• The store: migration V148 adds collect.read_latency (metric_time, surface, route, outcome, run_count, total_ms, max_ms, bucket_counts bigint[], primary key on the first four columns), a plain table — the
  collector_cost (V105) shape: internal self-telemetry, not a hypertable, with its own bounded retention
  delete. It needs no per-table GRANT (the collect schema's blanket grant covers it once provisioning
  re-runs).
• The flush: ReadLatencyAccumulator.FlushAsync drains the in-memory buckets and writes one row per
  (surface, route, outcome) actually hit in the hour, upserting with ON CONFLICT when a second flush lands
  in the same hour (adding counts, totals and bucket counts element-wise, and taking the greater max_ms),
  followed by a 90-day retention delete — mirroring CollectorCostAccumulator.FlushAsync in every way but
  one: Npgsql's array binding rejects a jagged bigint[][] bulk-insert parameter, so this flush issues one
  INSERT per drained key instead of collector_cost's single unnest(...) bulk insert. The row count is
  bounded by distinct (surface, route, outcome) combinations actually hit — at most a few hundred, never one
  per read — so the extra round trips are the right shape for this table's real size.
• The call site: DarlingWorker takes the same ReadLatencyAccumulator singleton DI hands the web host,
  and flushes it on the same tick and connection as collector_cost, right after it, isolated in its own
  try/catch so a failed read-latency flush costs only its own hour's rows and never the collector-cost series.

This pass finished the previous one's work: ran the three unit test classes plus DocCommentHygieneTests,
FleetSweepWebFeedTests, SharedBaselineCacheTests (all touched by the change), fixed one test bug (below),
and added the product-path pin that was missing.

Test plan

The percentile fixture (ReadLatencyPercentilesTests.Percentiles_OverAFieldShapedFixture_LandInTheExpectedBuckets):
1,000 samples — 900 uniformly spread 50–200 ms (fast), 90 uniformly spread 1,000–5,000 ms (slow), 10
uniformly spread 20,000–60,000 ms (very slow). p50 lands at or under 200 ms; p95 lands strictly above 200 ms
and at or under 5,000 ms. Fixed a test bug: the original assertion expected p99 strictly above 5,000 ms,
but with this exact 90/9/1 split the 990th-of-1,000 sample (ceil(0.99 * 1000)) is the top of the slow tier
itself — the correct, honest upper-bound answer is exactly 5,000 ms, not a value past it. Assertion now reads
Assert.Equal(5_000, p99.UpperBoundMs).

Total lines after the fix, in-process on this machine:

• ReadLatencyAccumulatorTests + ReadLatencyPercentilesTests + ReadOutcomeClassifierTests +
  DocCommentHygieneTests + FleetSweepWebFeedTests + SharedBaselineCacheTests:
  Total: 145, Errors: 0, Failed: 0, Skipped: 0, Not Run: 0.

The product-path pin (ReadLatencyWebRecordingTests, live-Postgres, [Collection("live-postgres")]):
drives a real /api/read/get_notification_routes request through the ACTUAL DarlingWebHostService.ConfigurePipeline

• DarlingWebEndpoints.MapAll wiring (the same TestServer pattern DarlingWebFailureHandlingTests uses),
  with its own freshly-constructed ReadLatencyAccumulator instance passed straight to that request's MapAll
  call — captured before the request rather than read back off the shared process-lifetime static, so no
  [Collection] lock against any other class's own MapAll call is needed. Asserts the accumulator drained
  exactly one Web sample for get_notification_routes with outcome Ok. A second case sends a request to a
  test-only route that throws the 57014 statement-timeout shape and asserts the response is a 503 (the existing
  ToHttpResult classification DarlingWebFailureHandlingTests already pins); because that route sits outside
  BuildReadDispatch, the /api/read/* loop's own Record call never runs for it, so this pin asserts nothing
  drained rather than asserting a Timeout sample that route can never produce.

A third fact covers the timeout outcome through the loop itself: BuildReadDispatch now folds in one extra, test-only dispatch entry
(s_testOnlyExtraDispatchEntry, internal, null in every production run — no production caller ever sets it)
when a test has registered one, so a real PostgresException with SqlState 57014 and the statement-timeout
wording travels through the SAME /api/read/* loop every production route uses, not a hand-called Record
standing in for that wiring. The fact registers the entry under a name no real tool uses, sends a request to
it, and asserts the drained accumulator holds exactly one Web sample for that route with outcome Timeout
and count 1.
Total: 3, Errors: 0, Failed: 0, Skipped: 0, Not Run: 0.

A second real mutation, for the new fact: removed the classifier's 57014-to-Timeout arm in
ReadOutcomeClassifier.Classify (falling through to Error for every PostgresException), rebuilt, reran —
the new fact went RED (Assert.Single(...) Failure: The collection did not contain exactly 1 matching element,
because no sample carried Timeout). Restored the arm, rebuilt, reran: green again (Total: 3, Failed: 0).

The composed-panel path (RunComposedPanelAsync) was not given an extra assertion here: its own live pins
(DarlingComposeLivePostgresTests, RunComposedPanel_RejectsBadAbsoluteWindows) exercise validation and a
plain-store round trip, not a store-side statement timeout, and building a cheap live low-timeout rig for it
was out of scope for this pin — a later change can add that fact beside these once a route/panel combination
for it exists.

RED on origin/dev at runtime: origin/dev has none of the new types (ReadLatencyAccumulator.cs,
ReadLatencyPercentiles.cs, ReadOutcomeClassifier.cs, the MapAll/DarlingWebHostService constructor
parameters) — copying the new test files onto that commit does not build; RED there is a compile failure,
not a runtime one.

A real mutation: removed the RecordWebReadLatency(name, webOutcome, stopwatch.ElapsedMilliseconds);
call from the /api/read/* dispatch loop's success arm, rebuilt, reran ReadLatencyWebRecordingTests — the
first fact went RED (Assert.Single() Failure: The collection did not contain any matching items), the
second still passed (it never depends on that line). Restored the line, rebuilt, reran: both green again
(Total: 2, Failed: 0).

Both Darling.Tests and Lite.Tests build 0 errors (Windows-targeting build on macOS; Lite.Tests still
cannot run here).

The V148 rung (ReadLatencyFlushLiveTests): the top-of-ladder claim (PgMigrations.Scripts[^1].Version,
StorageVersion.SchemaVersion, ViewerDataService.RequiredStoreSchemaVersion all equal 148) and the viewer
probe sentinel/arm ordering, taking over the "top rung" claim from ComposeStatementTimeoutV147MigrationLiveTests
(V147), which now asserts it sits one below the top instead. Four live facts against a fresh scratch database
per fact: a record-and-flush round trip matching counts/totals/maxes/buckets element-wise; a second same-hour
flush adding to the first; retention removing rows past 90 days while keeping newer ones; and an empty flush
writing no rows.
Total: 6, Errors: 0, Failed: 0, Skipped: 0, Not Run: 0 for ReadLatencyFlushLiveTests alone.

RED on origin/dev at runtime: origin/dev (e25452175) has no ReadLatencyAccumulator.cs at all —
copying ReadLatencyFlushLiveTests.cs there does not build; RED is a compile failure, not a runtime one.

A real mutation: replaced the bucket_counts insert parameter with an all-zero array of the same length
(skipping the real histogram), rebuilt, reran the round-trip fact — it went RED (Assert.Equal() Failure: Values differ, the stored buckets no longer matched the recorded ones). Restored the line, rebuilt, reran:
green again (Total: 6, Failed: 0).

Also run, all green: ManagedConfVerdictsRungTests (3), ComposeStatementTimeoutV147MigrationLiveTests
(5, updated now that V148 is the top rung), MigrationDataMovingRungCensusPins (28), ViewerDataServiceTests (1),
MigrationUpgradeLadderLiveTests (5), DocCommentHygieneTests (77, after moving a cross-project cref to
plain prose — PgMigrations.cs, in the Storage project, cannot resolve a symbol declared in Service),
ReadLatencyAccumulatorTests (7), ReadLatencyPercentilesTests (9), ReadOutcomeClassifierTests (8),
ReadLatencyWebRecordingTests (3), and ScheduledPurgeLaunchTests (5, updated for the new constructor
parameter). Both Darling.Tests and Lite.Tests build 0 errors after the V148 change.

• Two more source-shape pins, same push: AlertReadFailureSurfaceTests now exempts the read-latency
  flush's catch (it writes instrumentation, not an alerting read — losing an hour's rows can't hide an
  alert condition), and SharedBaselineCacheTests now matches BaselineCache baselineCache followed by
  either , or ) (the constructor's parameter order is arbitrary, and a later parameter after it
  shouldn't need a pin update). Mutating the classifier's SqlState-57014 arm out of
  ReadOutcomeClassifier turned ADispatchEntryThatThrowsA57014PostgresException_RecordsOneWebSample_WithOutcomeTimeout
  RED (Outcome recorded as Error, not Timeout); restoring it brought all four classes back to green
  at a9e36ec7: Total: 112, Errors: 0, Failed: 0, Skipped: 0, Not Run: 0.

Final head: a9e36ec72 on feat/4442-read-latency-histograms.

CHANGELOG entry

SECTION: None
ENTRY: None: the store table and the hourly flush have no user-visible effect until the read tool lands (a later change).

Next

MCP tool timing and the read tool.