perf(hts): attribute + trim the uniform throughput residual since v0.2.0 (#298) by mauripunzueta · Pull Request #347 · HeliosSoftware/hfs

mauripunzueta · 2026-07-22T17:18:23Z

Issue

Advances #298: attribute the remaining ~24% of the uniform HTS throughput drop since v0.2.0 (the part left after #233 fixed the EX02/EX08 collapse and #292 removed the span/reqlog per-request instrumentation), and fix or file each cause.

Summary

Two things, one measured end to end:

The always-on Prometheus metrics recording that fix(observability): stop paying for unconsumed per-request instrumentation (#227) #292 deliberately left on was a large uniform per-request cost. This PR removes most of it: off→default overhead at vu50 goes 11.3% → ~2.9%.
The "~24% non-observability residual" in HTS perf: bisect the remaining ~24% of the uniform throughput drop (non-observability) since v0.2.0 #298 does not exist. A version-arm A/B against a binary built from v0.2.0 (run 30015496998, 3 rounds, vu1+vu50, all tests, err 0.0, 0.5–1M samples/cell) puts the full vu50 throughput gap to v0.2.0 at −6.5% — and decomposes it as ~4.8% remaining metrics + ~1.7% all other code change. With instrumentation stripped from both binaries, current code is within 1.7% of v0.2.0 in aggregate, and ~11% faster on validate-code.

The issue's premise assumed #292 had removed observability's cost; it had not — metrics alone measured ~11.3% at vu50 on main. What #298 called a non-observability residual was largely still-present metrics cost. Once that is measured and trimmed (this PR), nothing large is left underneath it: the genuine non-obs code delta is ~1.7%, spread thin and partly offset by validate-code gains — below the threshold that would justify a bisect.

Sizing this was a measurement, not a guess, so this PR also adds the harness that took it (see "Benchmark tooling — version arms").

Version-arm result (run `30015496998`, sqlite, 3 rounds, all tests)

Aggregate throughput vs the v0.2.0 binary, same corpus, arms interleaved and paired:

Comparison	vu1	vu50	what it is
`off / baseline`	−1.9%	−1.7%	all code change since v0.2.0, instrumentation excluded
`default / baseline`	−7.7%	−6.5%	code change + today's (already-trimmed) metrics
`off → default`	−5.9%	−4.9%	today's remaining metrics cost

Per-test at vu50 the code-only delta (off/baseline) ranges −6.4% (CM01) to +11.8% (VC01) — validate-code is materially faster than v0.2.0 (likely #233 + the FTS/closure work). No test shows anything near a 24% code regression.

Debug build (opt-level 0): the metrics rows overstate release magnitude (constant per-request cost is amplified); the off/baseline code row is structural and less sensitive to profile. A release-profile confirmation is the one open item (see Follow-ups).

Root-cause analysis

The regression fingerprint is uniform across every benchmark family (LK/VC/CM/SS/EX) and equal across both backends — the signature of backend-agnostic per-request overhead on the shared request path, in an opt-level-0 debug build that amplifies constant per-request work. Prime suspect: the always-on Prometheus metrics recording in the observability track middleware (added to HTS server.rs in 4efd2d819; HTS had no per-request middleware at v0.2.0). In ObsMode::Default — what the benchmark measures — every request paid ~4 heap allocations, a rebuilt metric Key, a Vec<Label>, and a label-hashed registry lookup.

Measured results

All figures are the within-run paired off→default delta — the arms are interleaved and differenced inside a single run, which is what makes the ratio comparable across runs even though absolute p50 is not (the runner drifts ~10%).

Step 1 — label allocations (VU=1, 3 rounds, p50)

Test	`main` overhead	+ label fix	Δ
VC01	19.3% `SIGNAL`	16.8% `SIGNAL`	−2.5pp
VC02	18.4% `SIGNAL`	14.9% `SIGNAL`	−3.5pp
LK03	18.5% `SIGNAL`	11.3% `SIGNAL`	−7.2pp
LK02	13.4% `SIGNAL`	7.3% `WEAK`	−6.1pp
LK01	11.5% `SIGNAL`	8.6% `WEAK`	−2.8pp
SS01	9.5% `WEAK`	2.1% `NOISE`	−7.4pp
CM01	6.2% `SIGNAL`	6.8% `WEAK`	~flat
mean	~13.8%	~9.7%	≈⅓ less

Runs 29948736549 (baseline) / 29948738546 (treatment). Both arms clean — err 0.0, 69k–108k samples/cell, no false-zero.

Step 2 — vu50 sizing, and handle caching

vu50 is the load level the "~24% throughput" figure actually came from.

Build	`off→default` overhead @ vu50	Run
`main`	~11.3% (8–15%, all `SIGNAL`, CV 0.2–1.1%)	`29957052096`
+ label fix	~9.4%	`29957054469`
+ handle caching (this PR)	~2.9%	`29972539614`

At vu1 the same run measures ~4.9% mean, and total throughput across the suite differs by only −2.1% @ vu50 / −1.3% @ vu1 between metrics-off and metrics-on.

Findings:

Root cause confirmed. On main, metrics-on is 6–19% slower per request than the idle middleware, SIGNAL on 5/7 tests, uniform across families — a genuine uniform per-request cost, as hypothesized.
Both fixes work, cumulatively. Label interning removed the allocations; handle caching removed the residual Key rebuild + registry hashing. Together: 11.3% → ~2.9% at vu50, without removing a single metric.
Observability is now largely exhausted as an explanation. ~2–3% is what is left to win by turning instrumentation off entirely. The remaining residual is elsewhere.
The precedence-caching change is marginal — no measurable effect (off-arm absolute p50 unchanged, 0.15–0.29 ms). Kept as a harmless allocation cleanup; no throughput is claimed from it, matching the DB-review prediction that the cached resolvers short-circuit before the format!.

Caveats (honest): debug build (opt-level 0) amplifies constant per-request costs — direction holds, magnitude will shrink in release, and no release-profile sizing has been run. Steps 1 and 2 are separate dispatches; only the paired ratio is compared across them, never absolute p50.

Changes

perf(observability) — standard HTTP methods & common status codes become Cow::Borrowed(&'static str) metric labels (clone-free), removing ~4 allocations/request on the always-on metrics path. Label values byte-identical (unit test).
perf(observability) — cache resolved (Counter, Histogram) handles keyed by (method, route, status), so the hot path is a read-locked map lookup plus two atomic updates instead of a rebuilt Key + Vec<Label> + registry lookup. Bounded by construction: only the statically-known borrowed labels are cached, so an exotic method/status bypasses the cache and cannot grow it without bound. Test cache_holds_known_labels_and_skips_exotic.
perf(hts) — cache the precedence ORDER BY in a LazyLock, return Cow::Borrowed instead of format!-rebuilding per resolve; unexpected aliases rebuild via the same shared builder (byte-equivalence test). Backend-agnostic (SQLite + Postgres).
fix(observability) ×2 — obs-A/B harness fixes (required to measure any of this; HTS benchmark: same-session A/B for observability instrumentation cost (definitive magnitude) #297 was DOA on first dispatch, main too):
- An empty RUST_LOG ("", set-but-unset) made EnvFilter::try_from_default_env() enable nothing, silencing the startup line — a real operator footgun. Now treated as unset; harness uses env -u RUST_LOG.
- The fmt layer colourized unconditionally, writing ANSI escapes into redirected log files (corrupting journald/CloudWatch capture) and splitting the obs_mode= stamp so the harness grep couldn't match. Now gated on stdout().is_terminal(); harness strips ANSI as belt-and-suspenders.

Metrics are made cheaper, not removed throughout — deleting a product surface to win a benchmark would be masking the cost, not fixing it.

Benchmark tooling — version arms

Every arm in the #297 ladder is an env-var switch on one binary, so the harness could price instrumentation and nothing else. It could not answer the question this PR raises: how much of the gap to v0.2.0 is already recovered, versus never observability's fault.

This PR adds a baseline arm — a second binary built from the new baseline_ref input (e.g. v0.2.0), interleaved and paired like any other arm. baseline off default brackets it: baseline→off is all code change with instrumentation excluded; off→default is what observability costs today.

A version arm breaks the ladder's "restart the app, keep the database" invariant, because the two binaries run different startup migrations against the shared DB (HEAD adds authority_rank and concepts_search_fts; both boots run prebuild_concepts_fts). Whichever arm ran first would leave the next measuring a mutated database. So the workflow snapshots the post-import DB once and restores it before every arm, making arms order-independent rather than merely warm. The run aborts up front if a baseline arm is requested without its binary or its snapshot, rather than reporting numbers that look fine and mean nothing.

Guards, since a baseline arm silently running the current binary would report "no regression" and be believed: assert /proc/<pid>/exe is the binary the arm asked for, and assert the port is held by the pid we started. The existing obs_mode= assertion cannot cover a pre-#292 build, and /health had no uptime_seconds before v0.2.1.

Scoped to sqlite — rolling back Postgres would be a full re-clone of a multi-GB database, so a Postgres leg with baseline_ref set fails fast in the matrix resolver instead of reporting cross-migrated numbers.

Confound stated rather than hidden (it prints in the run summary): the corpus is imported once by the current binary, so baseline measures old serving code over new data. That holds the data constant to isolate per-request serving cost — it is not a reproduction of the v0.2.0 release.

Validated end-to-end by smoke run 30012060180 (all three arms started and verified; v0.2.0 still builds on current stable), then run in anger as 30015496998 — the source of the Summary table above.

Follow-ups (not in this PR)

Release-profile sizing. Every number here is debug. The off→default metrics rows will shrink in release; a build_profile workflow input would let us quote a release magnitude. The off/baseline code delta (~1.7%) is already small enough that release is unlikely to change the conclusion.
HTS perf: bisect the remaining ~24% of the uniform throughput drop (non-observability) since v0.2.0 #298 scope. The version-arm run answers the issue's core question: the non-observability residual is ~1.7% at vu50, not ~24%. The remaining lever is metrics, which this PR addresses. Recommend re-scoping or closing the "bisect the 24%" framing rather than continuing it — there is no large code regression to bisect toward.
Not done: materializing the EXISTS "has-concepts" precedence tier — index-backed already, ~20 write-path sync points, would re-open the HTS: $validate-code default-resolves audit-event-type to incomplete 4.0.1 fragment instead of complete THO 1.0.0 #200 incoherence class if it drifts. File only if a future A/B proves that tier hot.

Refs #298, #297.

The always-on metrics path in `track` records a counter and a histogram on every request in every obs mode except `Off` (metrics back the `/metrics` product surface, so #292 deliberately kept them on). Each did `method.as_str().to_owned()` + `status.to_string()` and then cloned both for the second macro — ~4 heap allocations per request of constant, backend- and endpoint-agnostic work, amplified in the opt-level-0 benchmark build. `metrics::SharedString` is `Cow<'static, str>`, so map the standard HTTP methods and common status codes to `Cow::Borrowed(&'static str)` whose clone is free. Exotic methods/codes keep their exact spelling via an owned fallback, so every emitted label value is byte-identical — only the allocation is gone. Benefits every server (hfs/hts/sof/fhirpath), not just HTS. Refs #298.

…ing it `cs_precedence_order_by`/`vs_precedence_order_by` are spliced into ~40 hot-path resolver queries — every $lookup/$validate-code/$expand/$translate/$subsumes resolves a canonical URL through one — and each call `format!`-rebuilt the ~400-char ORDER BY string. Only three aliases are ever passed, so render each once into a `LazyLock<String>` and return `Cow::Borrowed`; an unexpected alias still rebuilds via the same shared builder, so the SQL text is byte-identical. A byte-equivalence test locks the exact clause (the single arbiter of which same-canonical-URL row wins) against silent drift, covering both the cached fast path and the owned fallback. Backend-agnostic — applies to SQLite and Postgres identically, since both embed the same clause. Refs #298.

`EnvFilter::try_from_default_env()` treats a set-but-empty `RUST_LOG` (`""`, as opposed to unset) as a valid filter that enables nothing — silently silencing all output, including a server's startup line. This is an operator footgun and it left the #297 obs-A/B benchmark harness dead on its first dispatch: `run-arms.sh` launches its non-probe arms with an empty `RUST_LOG` (despite the comment claiming "unset"), so every arm's startup log came out empty and the `obs_mode=` verification grep failed every arm. Fix it on both sides: the server now falls back to its default level when `RUST_LOG` is empty/whitespace (an unparseable value still falls back, as before), and the harness uses `env -u RUST_LOG` so the non-probe arms truly inherit no `RUST_LOG`. Unblocks obs-A/B benchmarking (needed to measure #298). Refs #298, #297.

…g sink The tracing `fmt` layer colourizes unconditionally, so servers wrote raw ANSI escapes into redirected log files (and journald/CloudWatch). Besides corrupting those logs, it split the startup `obs_mode=<Mode>` stamp with escape sequences, so the obs-A/B harness's `grep obs_mode=Off` never matched even once the line was emitted — the second reason every arm failed to verify. Gate colour on `stdout().is_terminal()` so file/pipe sinks get clean text, and make the harness strip ANSI before the grep as belt-and-suspenders. Verified against the captured arm log: the stripped line matches `obs_mode=Off`. Refs #298, #297.

codecov · 2026-07-22T20:50:48Z

Codecov Report

❌ Patch coverage is 93.90863% with 12 lines in your changes missing coverage. Please review.

Files with missing lines	Patch %	Lines
crates/observability/src/middleware.rs	93.18%	9 Missing ⚠️
crates/observability/src/telemetry.rs	86.95%	3 Missing ⚠️

📢 Thoughts on this report? Let us know!

`metrics::counter!`/`histogram!` rebuild a `Key` (hashing the name + every label) and allocate a `Vec<Label>` on every call, then look the metric up in the recorder's registry — repeated for two metrics on every request in every mode except `Off`. The handle for a given (method, route, status) triple never changes, so cache it: the hot path becomes a read-locked map lookup plus two atomic updates, dropping the per-request `Key` build, label-Vec allocation, and registry lookup. The cache is bounded by construction — only the statically-known method/status labels (which `method_label`/`status_label` return as `Cow::Borrowed`) crossed with the finite set of matched-path route templates are cached; an exotic (owned) method/status is recorded directly and never inserted, so a client cannot grow it without bound. `route` becomes an `Arc<str>` so the key clone is a refcount bump, not an allocation. Label values are unchanged. The vu50 A/B showed ~9% residual metrics overhead after the label-allocation fix; this targets the remaining per-request hashing/allocation. Refs #298.

…_arg `build_handles` took `&Cow<'static, str>` for the method and status labels, which `clippy::ptr_arg` rejects. Both call sites pass a `&Cow` that deref-coerces to `&str`, so narrowing the parameters is source-compatible. The labels now allocate via `to_string()` instead of cloning the `Cow`; `build_handles` only runs on a cache miss, so this stays amortized to once per distinct metric series.

The A/B ladder could only switch env vars on one binary, so it could price instrumentation and nothing else. Run 29972539614 used it to show that turning observability fully off buys ~2% throughput and ~3-5% p50 — which refutes the working hypothesis for #298 but cannot say how much of the regression the perf commits on this branch already recovered, because every arm ran the same code. Add a `baseline` arm that runs a SECOND binary, built from the new `baseline_ref` input (e.g. v0.2.0), interleaved and paired like any other arm. `baseline off default` then brackets the question: baseline->off is all code change with instrumentation excluded, off->default is what observability costs today. A version arm breaks the "restart the app, keep the database" invariant the ladder rests on, because the two binaries run different startup migration sets against the shared DB (HEAD added authority_rank and concepts_search_fts; both boots also run prebuild_concepts_fts). Whichever arm ran first would leave the next measuring a mutated database, so the workflow snapshots the post-import DB once and run-arms.sh restores it before every arm — making arms order-independent rather than merely warm. The run aborts up front if a baseline arm is requested without its binary or without the snapshot, rather than reporting numbers that look fine and mean nothing. Guards, since a baseline arm that silently ran the current binary would report "no regression" and be believed: assert /proc/pid/exe is the binary the arm asked for, and assert the port is held by the pid we started. The existing obs_mode= assertion cannot cover a pre-#292 build, which emits no such line, and the uptime_seconds zombie check is absent from /health before v0.2.1. Scoped to sqlite: rolling back postgres would be a full re-clone of a multi-GB database, so a postgres leg with baseline_ref set fails fast in the matrix resolver instead of reporting cross-migrated numbers. The confound that remains, stated in the run summary rather than hidden: the corpus is imported once by the CURRENT binary, so `baseline` measures old serving code over new data. That isolates per-request serving cost with data held constant, which is the question — it is not a reproduction of the v0.2.0 release.

mauripunzueta added 2 commits July 22, 2026 13:17

mauripunzueta linked an issue Jul 22, 2026 that may be closed by this pull request

HTS perf: bisect the remaining ~24% of the uniform throughput drop (non-observability) since v0.2.0 #298

Closed

mauripunzueta added 2 commits July 22, 2026 14:29

mauripunzueta added 3 commits July 22, 2026 21:43

mauripunzueta marked this pull request as ready for review July 23, 2026 14:23

mauripunzueta requested a review from smunini July 23, 2026 14:26

mauripunzueta assigned mauripunzueta and smunini and unassigned mauripunzueta Jul 23, 2026

mauripunzueta mentioned this pull request Jul 23, 2026

HTS perf: bisect the remaining ~24% of the uniform throughput drop (non-observability) since v0.2.0 #298

Closed

smunini approved these changes Jul 23, 2026

View reviewed changes

smunini merged commit c9496e9 into main Jul 23, 2026
26 checks passed

smunini deleted the perf/298-hts-uniform-regression branch July 23, 2026 22:56

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

perf(hts): attribute + trim the uniform throughput residual since v0.2.0 (#298)#347

perf(hts): attribute + trim the uniform throughput residual since v0.2.0 (#298)#347
smunini merged 7 commits into
mainfrom
perf/298-hts-uniform-regression

mauripunzueta commented Jul 22, 2026 •

edited

Loading

Uh oh!

codecov Bot commented Jul 22, 2026 •

edited

Loading

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

Uh oh!

Conversation

mauripunzueta commented Jul 22, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Issue

Summary

Version-arm result (run 30015496998, sqlite, 3 rounds, all tests)

Root-cause analysis

Measured results

Step 1 — label allocations (VU=1, 3 rounds, p50)

Step 2 — vu50 sizing, and handle caching

Changes

Benchmark tooling — version arms

Follow-ups (not in this PR)

Uh oh!

codecov Bot commented Jul 22, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Codecov Report

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

mauripunzueta commented Jul 22, 2026 •

edited

Loading

Version-arm result (run `30015496998`, sqlite, 3 rounds, all tests)

codecov Bot commented Jul 22, 2026 •

edited

Loading