feat(metrics): split write-path latency and break down master tasks

[beinan]

Problem

http_request_duration_seconds{method,path,status} was the only latency signal for the write path. Three things were unmeasurable:

1. add and flush were the same series. They share one route (routes/mod.rs:87); flush is a query param parsed by hand at routes/rollouts.rs:263. The path label comes from MatchedPath — the route template, which excludes the query string — so a flushing add and a plain add emitted byte-identical labels. And because flush is strictly additive (add at :317, flush at :322), flushing requests were the slow tail contaminating p99 of plain adds, with no way to demix.

2. core had zero metrics. RolloutStore::add, flush, and the WAL merge were uninstrumented, so HTTP duration blended body parsing, multipart decode, blob-budget admission, store open, lock acquisition, and the actual work.

3. master_task_duration_seconds was narrower than its name. It wrapped only the dispatch match (scheduler.rs:90-94), excluding the claim (etcd txn + target lock), the semaphore permit wait, and commit/lease release. MergeWal's join_all fan-out had no per-worker timing — and by join_all semantics the slowest worker sets the whole task's latency, so one straggler was indistinguishable from all workers being slow.

New metrics

rollout_add_duration_seconds{result}                 core: durable append only
rollout_flush_duration_seconds{result,outcome}       core: memtable seal
rollout_wal_merge_duration_seconds{phase,result}     core: 6 merge phases
rollout_add_request_duration_seconds{flush,result}   server: store time only
rollout_wal_merge_request_duration_seconds{result}   worker-side merge
rollout_wal_merge_lock_wait_seconds                  write-lock wait
rollout_compaction_lock_wait_seconds                 write-lock wait
master_task_phase_duration_seconds{kind,phase}       claim|permit_wait|work|commit
master_merge_wal_worker_duration_seconds{result}     per-worker RTT
master_merge_wal_workers_total{result}               per-worker outcome
master_merge_wal_generations_reclaimed_total

Why flush needs an outcome label (sealed|noop|fenced): no-resident-writer is the common case and returns in microseconds. Without the label the histogram is dominated by near-zero samples and its percentiles say nothing about real flush cost.

Why master_merge_wal_workers_total{result} matters: a 404 is tolerated as "owns no shard" (scheduler.rs:182) and N−1 failures still report task success (:209). This counter is currently the only place partial fan-out failure is visible.

rollout_wal_cleanup_total now emits unconditionally with result=merged|noop. Gating it on reclaimed > 0 made the common no-op merge invisible, so a worker that never has anything to merge and a worker that is never called looked identical.

Live verification

Real server, one plain add and one ?flush=true add:

rollout_add_duration_seconds_count{result="ok"} 2
rollout_add_request_duration_seconds_count{flush="true",result="ok"}  1
rollout_add_request_duration_seconds_count{flush="false",result="ok"} 1
rollout_flush_duration_seconds_count{result="ok",outcome="sealed"} 1
# HELP rollout_add_duration_seconds RolloutStore::add — the durable WAL append only.

The two add paths are now distinct series, and only the flushing one recorded flush work.

Deliberate choices

• metrics is an optional, default-on feature of lance-context-core so downstream consumers embedding the library aren't forced to take the dependency. Call sites compile to nothing when disabled — verified with --no-default-features and warning-free under -D warnings. This is the one judgement call worth reviewing: it changes the published crate's feature surface.
• No store/target labels anywhere — dataset and experiment names are unbounded cardinality. That context belongs in a tracing span, not a label.
• master_task_duration_seconds keeps its original scope for back-compat, but gains a result label so a fast failure isn't averaged in with successes.
• New long-running metrics added to JOB_LATENCY_METRICS — without it a 120s merge phase lands in +Inf. Note _lock_wait_seconds matches no suffix rule, so it needs an explicit entry.
• First describe_* calls in the repo — /metrics previously shipped with no HELP/TYPE for any application metric.

Scope

Pure observability, no behaviour change. Bugs this only makes visible are left for their own PRs: MergeWal reporting success when N−1 workers fail, 404→Ok(0), unbounded merge buffering, the 100ms-spin coordination_lock.

Testing

• Workspace tests pass: 168 core / 51 server / 14 master.
• clippy --workspace --all-targets -D warnings clean, with and without the feature.
• New core test drives real store ops and asserts add/flush produce separate series with distinct outcomes.
• The bucket-config assertion was checked to fail when the config is removed — it initially passed vacuously (a bare le="300" substring matched other metrics in the same body) and was tightened to assert on the metric's own series.

🤖 Generated with Claude Code

[beinan]

Reworked for Datadog

The first pass was correct for Prometheus and expensive for Datadog. Datadog bills per unique name+tag combination, and a histogram bills every bucket separately — so label design that reads as harmless in Prometheus is a direct line item there. Measured: 128 series from two requests, worst case 724.

Three changes, add/flush split fully intact:

1. Failures are counted, not timed

result="ok"|"error" on a histogram doubles its series count to describe the latency distribution of a rare event — almost never actionable. The actionable signal is the rate. Dropped result from every latency histogram; added flat counters (1 series each):

rollout_add_errors_total
rollout_flush_errors_total
rollout_wal_merge_errors_total{phase}

The merge counter keeps phase because a merge aborts on its first failing phase — the label also tells you where it died. Server-side this let the add handler go back to plain ? instead of three hand-written error arms.

2. Trimmed bucket ladders

REQUEST 13→9, JOB 11→7. Adjacent ratios stay ≤6×, bounding interpolation error to that factor within the straddling bucket only — ample for latency SLOs. Boundaries sit on values people actually alert on (10ms, 100ms, 250ms, 1s). Coverage verified: 2ms–45s all land in finite buckets.

3. Gauges no longer named _total

master_experiments_total, master_rollout_rows_total, master_rollout_fragments_total are gauges. Datadog's OpenMetrics check infers type from the name, so _total made them ingest as monotonic counts — graphing "experiments created per second" for a metric meaning "how many exist right now." rate() was equally meaningless in Prometheus.

Now master_experiments / master_rollout_rows / master_rollout_fragments, with old names retained as deprecated aliases so existing dashboards keep working. Also added describe_gauge! and units — Datadog uses the exported TYPE to pick gauge vs count, and the declared Unit renders latency as a duration rather than a bare number.

Result

	before	after
series (2-request workload)	128	87 (−32%)
worst case, all combos	724	~361 (−50%)

No signal lost. The add/flush split, the flush outcome breakdown, the six merge phases, and the per-worker fan-out are all intact — and failures are now visible as rates rather than buried in a histogram.

Regression guards

Three, each verified to fail when deliberately broken (I checked, rather than assuming):

1. Latency histograms may not carry result — asserted against the rendered exposition text.
2. Cardinality budget of 125 series, close enough to the actual 112 that adding one two-valued label to a job histogram trips it.
3. Core-level assertion that histogram labels come from a closed, documented set, so an unbounded label (store URI, shard id, experiment name) can't be introduced later.

Live scrape confirms zero result= on any bucket series and both add paths still separable:

rollout_add_request_duration_seconds_count{flush="false"} 1
rollout_add_request_duration_seconds_count{flush="true"}  1
rollout_flush_duration_seconds_count{outcome="sealed"}    1
rollout_add_duration_seconds_count                        2