diff --git a/.github/scripts/telemetry/check_regression_bounds.py b/.github/scripts/telemetry/check_regression_bounds.py index 03d0288946..5454d5dd29 100644 --- a/.github/scripts/telemetry/check_regression_bounds.py +++ b/.github/scripts/telemetry/check_regression_bounds.py @@ -56,10 +56,18 @@ without having checked anything is the same green-build-that-is-not failure this script exists to prevent, so renaming or deleting one of its inputs must not silence it. +A baseline ENTRY that is not a positive finite number is rejected before any +rule runs, by ``_unusable_baseline``. Every rule does arithmetic on that value, +and a degenerate one made the script crash with a traceback (rule D divides by +it) or emit advice about the wrong file (a negative value inverts rule D's +comparison). Reporting malformed input is what this script is for, so it must +name the key rather than die on it. + Exit 0 when every rule holds, 1 with per-key detail otherwise. """ import json +import math import re import sys from pathlib import Path @@ -217,13 +225,78 @@ def check_exclusions(metrics_cfg, thresholds, baseline_metrics, declared): return failures +def _unusable_baseline(key, value, unit): + """Reject a baseline value no rule below could evaluate, or None if it is fine. + + Every rule downstream does arithmetic on this number, and two of them break + on a degenerate one rather than reporting it: + + * rule D computes ``100 * bound / value``, which raises + ZeroDivisionError on ``0.0``. The script then dies with a traceback + instead of naming the key -- a validator that crashes where it should + report is the same green-build-that-is-not failure in reverse; + * a NEGATIVE value makes that same ratio negative, so ``pct >= ratio`` is + true for any configured percentage and rule D fires with a message + telling the maintainer to lower ``max_pct_increase``. The advice is + wrong: the fault is the baseline, not the threshold; + * a non-numeric value raises TypeError inside rule E's subtraction. + + Rule E does not cover the zero case, which is easy to assume it does: its + test ``abs(value - quantile * first_edge) <= 1e-9 * first_edge`` reduces to + ``quantile <= 1e-9`` when value is ``0.0``, and that is false for every + quantile this harness captures (0.5, 0.95, 0.99). + + None of these arise from the normal pipeline -- ``histogram_quantile`` over + a first-bucket-only histogram returns ``quantile x first_edge``, never zero, + and rule E is the guard for exactly that. They arise from a hand-edited or + truncated baseline, which is precisely the input this script exists to + reject. + + Args: + key: Flat metric key, for the message. + value: The baseline value as read from the file. + unit: The entry's unit, for the message. + + Returns: + A failure string, or None when the value is usable. + """ + # bool is a subclass of int; True would otherwise pass as the number 1. + if isinstance(value, bool) or not isinstance(value, (int, float)): + return ( + f"{key}: baseline value {value!r} is not a number, so no bound can be " + f"derived from it. Recapture the baseline from a CI run rather than " + f"editing it by hand -- see baselines/README.md" + ) + if not math.isfinite(value) or value <= 0: + return ( + f"{key}: baseline is {value!r}{unit}, but a captured latency quantile " + f"is strictly positive and finite. A zero baseline leaves the " + f"percentage bound undefined, a negative one inverts it, and neither " + f"can bracket to a bucket -- so no rule below can be evaluated. " + f"Recapture the baseline from a CI run rather than editing it by hand " + f"-- see baselines/README.md" + ) + return None + + def check_key(key, entry, thresholds, ladders): - """Apply rules B, C, D and E to one gated key. Returns a list of failures.""" + """Apply rules B, C, D and E to one gated key. Returns a list of failures. + + The rules assume the baseline entry holds a strictly positive, finite + number, which is what ``histogram_quantile`` yields. Anything else is + malformed input, and reporting malformed input is this script's whole job, + so it is rejected up front rather than arithmetic being attempted on it -- + see ``_unusable_baseline``. + """ value, unit = entry.get("value"), entry.get("unit", "") edges = ladders.get(unit) if value is None or edges is None: return [f"{key}: baseline has no value, or unknown unit {unit!r}"] + unusable = _unusable_baseline(key, value, unit) + if unusable: + return [unusable] + failures = [] first_edge = edges[0] quantile = int(key.rsplit(".p", 1)[1]) / 100.0 diff --git a/.github/scripts/telemetry/test_check_regression_bounds.py b/.github/scripts/telemetry/test_check_regression_bounds.py index ba025b0036..ba3da1848c 100644 --- a/.github/scripts/telemetry/test_check_regression_bounds.py +++ b/.github/scripts/telemetry/test_check_regression_bounds.py @@ -78,6 +78,25 @@ class CheckerCase(unittest.TestCase): mutate(data) path.write_text(json.dumps(data, indent=2)) + def read_json(self, rel): + """Read a scratch input without modifying it.""" + return json.loads((self.tree / rel).read_text()) + + def gated(self, key): + """Return ``(baseline_value, configured_bound)`` for one gated key. + + Read from the scratch copies of the real inputs rather than written as + literals, because a literal here is a copy of one particular baseline: + two of these tests previously hard-coded values from the 2026-08-24 + capture and both broke the moment the baseline was refreshed, which is + the very drift check_regression_bounds.py exists to catch. Deriving the + figure keeps the assertion pinned to the rule instead of to a snapshot. + """ + group, quantile = key.rsplit(".", 1) + rule = self.read_json(THRESHOLDS)["overrides"][group][quantile] + bound = rule.get("max_abs_increase_ms", rule.get("max_abs_increase_us")) + return self.read_json(BASELINE)["metrics"][key]["value"], bound + class TestInputHandling(CheckerCase): """A placeholder passes; a missing or broken input must not.""" @@ -160,10 +179,14 @@ class TestRules(CheckerCase): self.assertIn("(rule B)", out) def test_rule_c_flags_rounded_bound(self): + """A bound rounded for readability is still not the derived bound.""" + _, exact = self.gated("span.tx.process.p99") + rounded = round(exact, 4) + self.assertNotEqual(rounded, exact, "pick a key whose bound rounds visibly") self.edit_json( THRESHOLDS, lambda d: d["overrides"]["span.tx.process"]["p99"].update( - max_abs_increase_ms=4.0055 + max_abs_increase_ms=rounded ), ) code, out = self.run_checker() @@ -172,7 +195,7 @@ class TestRules(CheckerCase): def test_rule_c_accepts_bound_within_relative_tolerance(self): """The tolerance is 1e-12 relative, not exact equality.""" - exact = 4.005485184848892 + _, exact = self.gated("span.tx.process.p99") self.edit_json( THRESHOLDS, lambda d: d["overrides"]["span.tx.process"]["p99"].update( @@ -183,16 +206,32 @@ class TestRules(CheckerCase): self.assertEqual(code, 0, out) def test_rule_d_flags_percentage_bound_becoming_operative(self): + """Rule D trips at exactly 100 x bound / baseline, its ``>=`` boundary.""" + baseline, bound = self.gated("span.tx.apply.p99") + boundary = 100.0 * bound / baseline self.edit_json( THRESHOLDS, lambda d: d["overrides"]["span.tx.apply"]["p99"].update( - max_pct_increase=150.0 + max_pct_increase=boundary ), ) code, out = self.run_checker() self.assertEqual(code, 1, out) self.assertIn("(rule D)", out) + def test_rule_d_accepts_percentage_bound_just_below_the_boundary(self): + """The other side of rule D's boundary, so the test cannot pass vacuously.""" + baseline, bound = self.gated("span.tx.apply.p99") + boundary = 100.0 * bound / baseline + self.edit_json( + THRESHOLDS, + lambda d: d["overrides"]["span.tx.apply"]["p99"].update( + max_pct_increase=boundary * (1 - 1e-9) + ), + ) + code, out = self.run_checker() + self.assertEqual(code, 0, out) + def test_rule_a_ignores_an_excluded_key(self): """An excluded key must not read as a baseline that was never captured. @@ -253,6 +292,65 @@ class TestRules(CheckerCase): self.assertIn("(rule F)", out) self.assertIn("still has a baseline value", out) + # A key that is GATED, so seeding it exercises the numeric guard rather than + # rule F. It must not be one of the excluded keys: putting a value there + # trips "excluded but still has a baseline value" first and the test would + # pass for the wrong reason. + DEGENERATE_KEY = "span.tx.process.p50" + + def _seed_degenerate_baseline(self, value): + """Replace one gated key's baseline value with an unusable one. + + The threshold is deliberately left alone. The numeric guard runs before + every rule, so no bound arrangement is needed to reach it -- and on the + pre-fix checker this same seeding still reached the crash, because rule C + appends its failure and falls through to rule D's division. + """ + key = self.DEGENERATE_KEY + self.assertNotIn( + key, + self.read_json(METRICS).get("excluded_keys", {}), + "DEGENERATE_KEY must be gated, not excluded", + ) + self.edit_json( + BASELINE, + lambda d: d["metrics"].update({key: {"unit": "ms", "value": value}}), + ) + + def test_degenerate_baseline_is_reported_not_crashed(self): + """A zero, negative or non-numeric baseline must NAME the key, not raise. + + Rule D computes ``100 * bound / value``, so a 0.0 baseline used to exit + via ZeroDivisionError and a traceback, and a negative one used to emit a + rule-D failure blaming ``max_pct_increase`` when the fault was the + baseline. Rule E does not cover the zero case: its test reduces to + ``quantile <= 1e-9`` there, false for every quantile captured. + """ + # Asserting the guard's OWN wording, not merely "exit 1 with no + # traceback": the negative and bool cases already exited 1 without a + # traceback before the fix, by emitting a rule-D failure that blamed the + # wrong file. A looser assertion passes on that and proves nothing. + cases = ( + (0.0, "strictly positive"), + (-1.0, "strictly positive"), + (float("nan"), "strictly positive"), + (float("inf"), "strictly positive"), + ("0.006", "is not a number"), + (True, "is not a number"), + ) + for value, expected in cases: + with self.subTest(value=value): + self.setUp() # a clean scratch tree per value + self._seed_degenerate_baseline(value) + code, out = self.run_checker() + self.assertEqual(code, 1, out) + self.assertNotIn("Traceback", out) + self.assertIn(self.DEGENERATE_KEY, out) + self.assertIn(expected, out) + # The old rule-D message told the maintainer to lower the + # percentage bound; the baseline is what is wrong. + self.assertNotIn("(rule D)", out) + def test_rule_e_flags_ladder_floor_signature(self): """ledger.store's quantiles were the ladder floor times the quantile.""" store = {"p50": 0.005, "p95": 0.0095, "p99": 0.0099} diff --git a/docker/telemetry/workload/README.md b/docker/telemetry/workload/README.md index c5573f5f25..c11e812432 100644 --- a/docker/telemetry/workload/README.md +++ b/docker/telemetry/workload/README.md @@ -271,11 +271,24 @@ Per-run tuning: re-derive the bounds. See `_absolute_bound_derivation` in that file; `.github/scripts/telemetry/check_regression_bounds.py` enforces it in CI. - That bound budgets for **quantization** noise only, so a key whose run-to-run - variance is larger than it cannot be gated at all — `span.ledger.validate.p95` - and `.p99` are excluded for that reason and are listed, with the measurements, - in `excluded_keys` in `regression-metrics.json`. Check a key's observed maximum - across runs against `baseline + bound` before gating it; widening the bound is - not the fix. See `baselines/README.md`. + variance is larger than it cannot be gated at all. **Five keys are excluded** + for that reason: `span.ledger.validate.p95` and `.p99`, plus + `span.tx.apply.p50`, `span.ledger.build.p50` and + `span.consensus.ledger_close.p50` as of the 2026-08-26 refresh. Each carries + its measurements in `excluded_keys` in `regression-metrics.json`. Check a key's + observed maximum across runs against `baseline + bound` before gating it; + widening the bound is not the fix, and neither is re-baselining until a run + lands favourably. See `baselines/README.md`. +- A refresh moves sensitivity in **both** directions, because the trip point is + derived from the baseline, and a single run carries no information about + spread. The 2026-08-26 refresh loosened `job.acceptLedger.running.p95` from a + 5.74x detection floor to 16.28x (it does not fire, so it stays gated) and cut + the three `p50` keys above from a bound that had absorbed their spread to one + that could not — `span.tx.apply.p50` read 0.7917 ms in the previous baseline + and 0.00597 ms in this one, a 132x move on the same workload, taking its bound + from 4.21 ms to 0.0440 ms. Gating those keys again needs a **multi-run + baseline** (or a spread measurement captured beside it), not a new threshold. + All of it is measured in `baselines/README.md`; re-check after every refresh. See [`baselines/README.md`](./baselines/README.md) for the baseline lifecycle and refresh process. @@ -426,6 +439,42 @@ internal log-record counters, and Loki's own entry counts for the selector with and without the line filter. Read that block first; it identifies the broken leg without reproducing anything. +Those two entry counts **must** be wrapped in `sum()`. The `filelog` receiver's +`regex_parser` leaves `message` and `timestamp` as log-record attributes, and +Loki's OTLP path stores them as structured metadata that joins the label set of a +metric query — so an unaggregated `count_over_time` returns one series per log +line and Loki rejects it with `HTTP 400 maximum number of series (500) reached` +past a few hundred lines. That is not hypothetical: it made both legs print +`unavailable` on runs `32877465763` and `32964262700`, at which point the block +distinguished nothing. `_loki_json` in `validate_telemetry.py` and +`diag_loki_count` in `run-full-validation.sh` now print the HTTP status and +Loki's own plain-text body, so a future rejection names its own cause instead of +surfacing as a mimetype error. + +`log.trace_id_cross_reference` polls Tempo for up to `METRIC_POLL_TIMEOUT_SEC` +(45 s, the same window and interval every other poll in the file uses) before +reporting that a logged trace id does not resolve. A trace id reaches a log line +when its span is created but is queryable only after export, ingest and indexing, +so a single query races that pipeline. A failure now means the id was absent for +the whole window. + +The check distinguishes three outcomes, not two, because "Tempo never answered" +and "the spans were not exported" send a reader to different subsystems: + +| outcome | Tempo said | reported as | +| --------------------------------- | ---------------------------------------- | --------------------------------- | +| resolved | 200 with spans | pass | +| absent for the whole window | 404, or 200 with no spans, every attempt | "…do not resolve; not exported" | +| query failed and nothing resolved | any other non-200 (4xx/5xx) | "could not verify … last error …" | + +`_tempo_get_trace` treats **404 as absence** and returns an empty list, because a +trace id read from a log line is legitimately not yet indexed and every caller +loops over candidates relying on that. Any **other** non-200 raises +`TempoQueryError` — previously an error body was fed straight to `resp.json()`, +so a JSON 5xx read as "0 spans" and a `text/plain` 5xx surfaced as a mimetype +complaint. `_tempo_search` has no absence status at all (an empty match is 200 +with an empty list), so there every non-200 raises. + The same block prints locally: ```bash diff --git a/docker/telemetry/workload/baselines/README.md b/docker/telemetry/workload/baselines/README.md index eaa3c8e9ca..136683788a 100644 --- a/docker/telemetry/workload/baselines/README.md +++ b/docker/telemetry/workload/baselines/README.md @@ -25,10 +25,14 @@ was invoked with. Capture and comparison are profile-agnostic — they only read Prometheus — so all existing profiles (`full-validation`, `quick-smoke`, `stress`) continue to work unchanged. -## Current state: 23 metrics gate, on a baseline captured 2026-08-24 +## Current state: 20 metrics gate, on a baseline captured 2026-08-26 -`baseline-timings.json` holds real captured values for the 23 keys the harness gates. The -previous entries, captured on 2026-06-05, were voided into a placeholder first: they predated the +`baseline-timings.json` holds real captured values for the 20 keys the harness gates, from CI run +`32964262700` at `8418d474a7`, profile `full-validation`, window `3m`. It replaced a capture taken +at `6a82fc6f37` that predated two workload changes — the removal of the refused path-finding RPC +load (`59a0595a6e`) and everything after it — so its numbers described a workload the harness no +longer runs. The entries before that, captured on 2026-06-05, were voided into a placeholder: they +predated the spanmetrics ladder re-cut of 2026-08-04 (`3860c93db2`), which made every sub-millisecond quantile in that capture bucket-edge arithmetic rather than a latency (a p95 of `0.95` ms is `0.95 × 1 ms`). Because the comparator only flags a metric when the current value _exceeds_ the baseline, a @@ -64,11 +68,17 @@ Two earlier generations of this bound were wrong, in opposite directions: | ------------------------------ | -------------------------------------------- | --------------------- | ---------------------------------------- | | flat | 10 ms `p50`/`p95`, 15 ms `p99`, 20000 us job | 5 / 28 keys | 2 / 25 keys | | 2 × enclosing bucket width | per metric | 28 / 28 keys | **21 / 25 keys** | -| `hi_next − baseline` (current) | per metric | 23 / 23 keys | **0 / 23 keys** | +| `hi_next − baseline` (current) | per metric | 19 / 20 keys | **0 / 20 keys** | The first two rows were measured when 28 and 25 keys were gated; the current row was re-measured -over today's 23 by injecting a 10x regression into each gated key in turn against a real CI -`timings.json`, which the gate flagged in all 23 cases. The zero in the last column is by +over today's 20 by injecting a 10x regression into each gated key in turn against a real CI +`timings.json`. The gate flagged 19. The exception is `job.acceptLedger.running.p95`, whose +detection floor is 16.28x: 10x reaches 61429 us against a 100000 us trip point, and the gate first +fires at 16.28x (measured — 16.2x passes, 16.28x fails). At **20x the sweep catches 20 of 20**. That +is the ladder, not the rule; the key is listed under +[weakly guarded](#which-keys-are-only-weakly-guarded) below. On the 2026-08-24 baseline the same key +had a 5.74x floor and 10x did catch it, which is what a baseline refresh can silently do to +sensitivity. The zero in the last column is by construction rather than by sampling: rule C in [`check_regression_bounds.py`](../../../../.github/scripts/telemetry/check_regression_bounds.py) fails the build unless every trip point is exactly `hi_next`, and a trip point at a bucket edge @@ -94,26 +104,35 @@ signature described below. The guarantee costs sensitivity where the ladder is coarse: the detection floor is `hi_next / baseline`, so a baseline sitting just above an edge is guarded loosely. Measured over -the current baseline the floor ranges 2.02x to 9.42x. Do **not** read these as guarded: +the current baseline the floor ranges 2.21x to 16.28x. Do **not** read these as guarded: -| key | baseline | fires at | floor | -| --------------------------------- | ---------- | --------- | ----- | -| `span.ledger.build.p50` | 1.0612 ms | 10 ms | 9.42x | -| `span.tx.process.p95` | 0.7240 ms | 5 ms | 6.91x | -| `span.tx.apply.p50` | 0.7917 ms | 5 ms | 6.32x | -| `span.rpc.ws_message.p95` | 0.8443 ms | 5 ms | 5.92x | -| `job.acceptLedger.running.p95` | 17428.6 us | 100000 us | 5.74x | -| `span.consensus.accept.p50` | 1.7436 ms | 10 ms | 5.74x | -| `span.consensus.ledger_close.p99` | 0.9314 ms | 5 ms | 5.37x | -| `span.rpc.ws_message.p99` | 0.9878 ms | 5 ms | 5.06x | -| `span.tx.process.p99` | 0.9945 ms | 5 ms | 5.03x | +| key | baseline | fires at | floor | limiting ladder step | +| --------------------------------- | --------- | --------- | ------ | -------------------- | +| `job.acceptLedger.running.p95` | 6142.9 us | 100000 us | 16.28x | 25000 us → 100000 us | +| `span.consensus.accept.p50` | 0.5287 ms | 5 ms | 9.46x | 1 ms → 5 ms | +| `job.transaction.running.p95` | 600.0 us | 5000 us | 8.33x | 1000 us → 5000 us | +| `span.tx.process.p95` | 0.6100 ms | 5 ms | 8.20x | 1 ms → 5 ms | +| `span.rpc.ws_message.p95` | 0.6977 ms | 5 ms | 7.17x | 1 ms → 5 ms | +| `span.consensus.ledger_close.p95` | 0.7830 ms | 5 ms | 6.39x | 1 ms → 5 ms | +| `span.rpc.ws_message.p99` | 0.9757 ms | 5 ms | 5.12x | 1 ms → 5 ms | -`span.ledger.build.p50` is the one that matters most: ledger construction is the hot path this -gate exists to guard, and at a 9.42x floor it could get almost ten times slower and still pass. -All nine are limited by two 5x-wide -ladder steps, 1 ms → 5 ms and 5000 us → 25000 us. The fix is a 2 ms edge (ideally 3 ms as well) in -the collector's spanmetrics `buckets` list plus the matching entries in `kMillisecondBuckets`, and -a 10000 us edge in `kMicrosecondBuckets`. That work belongs to the branch that owns the ladders. +`job.acceptLedger.running.p95` is the one that matters most, because it is the only gated key a +10x regression does not catch (see the generation table above). Its floor moved there **in this +refresh**, from 5.74x: the baseline fell from 17428.6 us to 6142.9 us while `hi_next` stayed at +100000 us. It does **not** fire on any observed run — its worst reading is 0.16 of its trip point — +so it stays gated, and the weak floor is recorded here so it is visible rather than surprising. The +fix is a 2 ms edge (ideally 3 ms as well) in the collector's spanmetrics `buckets` list plus the +matching entries in `kMillisecondBuckets`, and 2000 us plus 50000 us edges in `kMicrosecondBuckets`. +That work belongs to the branch that owns the ladders. + +`span.tx.apply.p50` is absent from this table because it is **no longer gated at all** — see +[what all five excluded keys have in common](#what-all-five-excluded-keys-have-in-common). Beyond +its variance it had a second, independent problem: its baseline of `0.00597` ms sat inside the +ladder's **first** bucket `(0, 0.01]`, so the reported figure was interpolation across that bucket, +tracking the _fraction_ of applies finishing under 10 us rather than a latency — the same mechanism +that disqualified `ledger.store` below. Rule E did not flag it, correctly: the value is not +`quantile × first_edge` exactly, so some mass does sit above 0.01 ms. Restoring the key therefore +needs a finer low-end ladder **as well as** a spread-aware baseline. ## Known exclusion: `ledger.store` is below the ladder's resolution @@ -148,7 +167,7 @@ Measured across four CI runs: | key | baseline | trip point | observed min | observed max | spread | | --------------------------------- | --------- | ---------- | ------------ | ------------ | ------ | -| `span.ledger.validate.p50` (kept) | 0.0779 ms | 0.25 ms | 0.0484 ms | 0.0778 ms | 1.6x | +| `span.ledger.validate.p50` (kept) | 0.0647 ms | 0.25 ms | 0.0484 ms | 0.0778 ms | 1.6x | | `span.ledger.validate.p95` | 0.2404 ms | 0.5 ms | 0.1281 ms | 0.7500 ms | 5.9x | | `span.ledger.validate.p99` | 1.0600 ms | 10 ms | 0.3875 ms | 25.8750 ms | 66.8x | @@ -181,12 +200,60 @@ the bound is simply the wrong size and the gate reddens on a healthy run. **Before gating any key, check its observed maximum across several runs against its trip point (`baseline + bound`), and gate it only if the maximum stays below that with margin.** Spread alone -proves nothing: `span.tx.apply.p50` swings 364x across runs (0.0064 → 2.3378 ms) and never fires, -because its 5 ms trip point absorbs the whole range. It is spread **relative to the trip point** -that decides. Measured over the runs behind this baseline, the worst surviving key reaches 0.67 of -its trip point (`span.consensus.ledger_close.p95`) and the other 22 sit at or below 0.60 — the two -excluded keys, at 1.50 and 2.59, were the only ones above 1.0. A key that fails this test is not -fixed by widening its bound; exclude it and say why. +proves nothing; it is spread **relative to the trip point** that decides. And because the trip +point is derived from the baseline, a baseline that lands at the **low end** of a metric's own +range shrinks that trip point without anything about the metric having changed. + +That is what the 2026-08-26 refresh did to three `p50` keys, and **all three are now excluded** — +this rule being applied, not a new exception. Measured across the three CI runs `32862589645`, +`32867433073` and `32964262700` (the last of which is this baseline): + +| key | bound | trip point | observed max | max ÷ trip | spread | +| --------------------------------- | --------- | ---------- | ------------ | ---------- | ------ | +| `span.tx.apply.p50` | 0.0440 ms | 0.05 ms | 2.3378 ms | **46.76x** | 391.8x | +| `span.ledger.build.p50` | 0.3849 ms | 0.5 ms | 2.3826 ms | **4.77x** | 20.7x | +| `span.consensus.ledger_close.p50` | 0.0613 ms | 0.1 ms | 0.2377 ms | **2.38x** | 6.1x | + +Before the exclusion, replaying **either** older run against this baseline reported exactly those +three and nothing else — and run `32867433073` carries the same post-path-finding-removal workload +as the baseline itself, so the movement was metric variance, not a workload difference. Those two +runs are what would have reddened CI. After the exclusion both replay clean. + +The evidence that settles it is `span.tx.apply.p50`'s own history. It read **0.7917 ms** in the +previous baseline and **0.00597 ms** in this one — a 132x difference between two runs of the same +workload. At the old value the identical `hi_next − baseline` rule produced a 4.21 ms bound whose +5 ms trip point absorbed the entire range; at the new value it produces 0.0440 ms and cannot. +Nothing about the metric changed. **Whether the gate functioned was decided by where in its own +distribution the captured run happened to land** — which is not a threshold that needs tuning, it +is a key that cannot be gated from a single-run baseline at all. + +So the remedy is the `excluded_keys` entry with the measurement behind it, exactly as +`ledger.validate` p95 and p99 got — **not** a widened bound, and **not** re-baselining until a run +lands favourably. A key that fails this test is never fixed by widening its bound. The remaining +20 gated keys sit at or below 0.58 of their trip points, the worst being `span.consensus.accept.p50`. + +### What all five excluded keys have in common + +| key | trip point | observed max | mechanism | +| --------------------------------- | ---------- | ------------ | ------------------------------------- | +| `span.tx.apply.p50` | 0.05 ms | 2.3378 ms | baseline in the ladder's first bucket | +| `span.consensus.ledger_close.p50` | 0.1 ms | 0.2377 ms | baseline in a low bucket | +| `span.ledger.build.p50` | 0.5 ms | 2.3826 ms | baseline in a low bucket | +| `span.ledger.validate.p95` | 0.5 ms | 0.7500 ms | baseline in a low bucket | +| `span.ledger.validate.p99` | 10 ms | 25.8750 ms | spread too large for any bound | + +One invariant covers all five: **the observed maximum exceeds `baseline + bound`**, so an ordinary +run clears the trip point with nothing having regressed. Two mechanisms produce it. Four of the five +have a baseline sitting low in the ladder, where the derived bound is tiny because the bound _is_ +the distance to the next edge up. The fifth, `ledger.validate.p99`, has a comparatively generous +8.94 ms bound and still fails, because a 66.8x spread reaches 25.875 ms against a 10 ms trip point. + +**The follow-up that would restore coverage**, stated rather than left implied: a baseline captured +from a **single run** cannot support these keys, because one sample carries no information about +spread and the bound is derived from that one sample alone. What would let them be gated again is a +**multi-run baseline** — or a spread measurement captured alongside the baseline — so a bound can be +sized against observed variance instead of against the ladder only. That is not implemented; it is +the design change these five exclusions are waiting on. ## Bootstrapping the baseline diff --git a/docker/telemetry/workload/baselines/baseline-timings.json b/docker/telemetry/workload/baselines/baseline-timings.json index 07b289c864..f7060cbbd5 100644 --- a/docker/telemetry/workload/baselines/baseline-timings.json +++ b/docker/telemetry/workload/baselines/baseline-timings.json @@ -1,98 +1,86 @@ { - "captured_at": "2026-08-24T21:22:37Z", - "git_sha": "6a82fc6f37c9e6cb747722906e83aaf949d100b8", + "captured_at": "2026-08-26T11:54:41Z", + "git_sha": "8418d474a7a63aa981a4854aa94388a556517b0d", "metrics": { "job.acceptLedger.queued.p95": { "unit": "us", - "value": 91.10576923076925 + "value": 166.13636363636323 }, "job.acceptLedger.running.p95": { "unit": "us", - "value": 17428.571428571428 + "value": 6142.857142857149 }, "job.transaction.queued.p95": { "unit": "us", - "value": 476.6129032258061 + "value": 426.19047619047586 }, "job.transaction.running.p95": { "unit": "us", - "value": 427.1084337349388 + "value": 599.9999999999986 }, "span.consensus.accept.p50": { "unit": "ms", - "value": 1.7435897435897438 + "value": 0.5287356321839081 }, "span.consensus.accept.p95": { "unit": "ms", - "value": 8.9296875 + "value": 8.969696969696969 }, "span.consensus.accept.p99": { "unit": "ms", - "value": 15.150000000000082 - }, - "span.consensus.ledger_close.p50": { - "unit": "ms", - "value": 0.15142857142857144 + "value": 20.800000000000026 }, "span.consensus.ledger_close.p95": { "unit": "ms", - "value": 0.49328358208955236 + "value": 0.7829999999999997 }, "span.consensus.ledger_close.p99": { "unit": "ms", - "value": 0.9314285714285726 - }, - "span.ledger.build.p50": { - "unit": "ms", - "value": 1.0612244897959187 + "value": 2.0299999999999896 }, "span.ledger.build.p95": { "unit": "ms", - "value": 4.679591836734694 + "value": 4.53333333333333 }, "span.ledger.build.p99": { "unit": "ms", - "value": 5.075000000000041 + "value": 9.109090909090913 }, "span.ledger.validate.p50": { "unit": "ms", - "value": 0.07787769784172663 + "value": 0.06471894002114831 }, "span.rpc.ws_message.p50": { "unit": "ms", - "value": 0.15990942879094971 + "value": 0.16003451676528602 }, "span.rpc.ws_message.p95": { "unit": "ms", - "value": 0.8443074003795064 + "value": 0.6977397260273974 }, "span.rpc.ws_message.p99": { "unit": "ms", - "value": 0.9878368121442125 - }, - "span.tx.apply.p50": { - "unit": "ms", - "value": 0.791666666666667 + "value": 0.9757123287671235 }, "span.tx.apply.p95": { "unit": "ms", - "value": 4.627368421052632 + "value": 3.524999999999999 }, "span.tx.apply.p99": { "unit": "ms", - "value": 4.959157894736842 + "value": 5.066666666666704 }, "span.tx.process.p50": { "unit": "ms", - "value": 0.34281067382135394 + "value": 0.20062219789579117 }, "span.tx.process.p95": { "unit": "ms", - "value": 0.7239865112994349 + "value": 0.6100467289719625 }, "span.tx.process.p99": { "unit": "ms", - "value": 0.9945148151511076 + "value": 2.758787878787877 } }, "profile": "full-validation", diff --git a/docker/telemetry/workload/collect_system_metrics.sh b/docker/telemetry/workload/collect_system_metrics.sh index e7b52aba7b..cfefca8937 100755 --- a/docker/telemetry/workload/collect_system_metrics.sh +++ b/docker/telemetry/workload/collect_system_metrics.sh @@ -68,6 +68,17 @@ OUTPUT_FILE="$3" IFS=',' read -ra RPC_PORTS <<<"$RPC_PORTS_CSV" SAMPLE_INTERVAL=5 +# Hard ceiling on every RPC probe below. curl applies no overall timeout of its +# own, so a node that accepts the connection and then stops answering — what a +# stalled job queue looks like from outside — parks the sampling loop for the +# rest of the run. 5 s is one sample interval and some thousands of times a +# healthy server_info, so it bounds a wedged node's cost to one lost sample +# while never truncating a real reply. A probe that hits the ceiling exits +# non-zero and is therefore skipped rather than recorded, which is the same +# rule the latency loop already applies to a refused connection; if every +# probe hits it, the empty file trips the placeholder warning below. +CURL_MAX_TIME=5 + # Reject anything the sample arithmetic cannot use, instead of silently # treating it as 0. case "$DURATION" in @@ -136,7 +147,7 @@ trap cleanup EXIT INITIAL_SEQ=0 INITIAL_TIME=$(date +%s) for port in "${RPC_PORTS[@]}"; do - seq=$(curl -sf "http://localhost:$port" \ + seq=$(curl -sf --max-time "$CURL_MAX_TIME" "http://localhost:$port" \ -d '{"method":"server_info"}' 2>/dev/null | jq -r '.result.info.validated_ledger.seq // 0' 2>/dev/null || echo 0) if [ "$seq" -gt "$INITIAL_SEQ" ]; then @@ -185,7 +196,7 @@ for sample in $(seq 1 "$SAMPLES"); do # and recording that as ~0 ms would pull the reported p99 down. for port in "${RPC_PORTS[@]}"; do start_ns=$(now_ns) - if curl -sf "http://localhost:$port" \ + if curl -sf --max-time "$CURL_MAX_TIME" "http://localhost:$port" \ -d '{"method":"server_info"}' >/dev/null 2>&1; then end_ns=$(now_ns) latency_ms=$(((end_ns - start_ns) / 1000000)) @@ -195,7 +206,7 @@ for sample in $(seq 1 "$SAMPLES"); do # Record current validated ledger seq. for port in "${RPC_PORTS[@]}"; do - seq=$(curl -sf "http://localhost:$port" \ + seq=$(curl -sf --max-time "$CURL_MAX_TIME" "http://localhost:$port" \ -d '{"method":"server_info"}' 2>/dev/null | jq -r '.result.info.validated_ledger.seq // 0' 2>/dev/null || echo 0) echo "$seq" >>"$LEDGER_FILE" @@ -269,7 +280,7 @@ fi # TPS calculation from ledger sequence advancement. FINAL_SEQ=0 for port in "${RPC_PORTS[@]}"; do - seq=$(curl -sf "http://localhost:$port" \ + seq=$(curl -sf --max-time "$CURL_MAX_TIME" "http://localhost:$port" \ -d '{"method":"server_info"}' 2>/dev/null | jq -r '.result.info.validated_ledger.seq // 0' 2>/dev/null || echo 0) if [ "$seq" -gt "$FINAL_SEQ" ]; then @@ -291,7 +302,12 @@ if [ "$ELAPSED" -gt 0 ] && [ "$LEDGER_ADVANCE" -gt 0 ]; then # but a strict parser rejects the whole file. awk's %.2f always pads. TPS=$(awk -v a="$LEDGER_ADVANCE" -v b="$ELAPSED" 'BEGIN { printf "%.2f", a / b }') else + # No ledger advance means the cluster produced nothing to divide, so 0 here + # is an absence of data, not a measured rate. Flagged like every other empty + # source so the run reports itself inconclusive instead of a real 0 TPS. + warn "Ledger seq did not advance (advance=$LEDGER_ADVANCE over ${ELAPSED}s); tps is a 0 placeholder" TPS="0" + METRICS_COMPLETE=false fi # Mean inter-ledger interval in ms: DURATION / (distinct ledgers - 1) * 1000. @@ -304,7 +320,16 @@ if [ -s "$LEDGER_FILE" ]; then UNIQUE_LEDGERS=$(sort -u "$LEDGER_FILE" | wc -l) # The > 1 test also keeps the divisor below at 1 or more. if [ "$UNIQUE_LEDGERS" -gt 1 ]; then - CONSENSUS_MEAN=$(echo "scale=0; $DURATION * 1000 / ($UNIQUE_LEDGERS - 1)" | bc 2>/dev/null || echo "0") + # awk rather than bc, for the same reason as the TPS calculation above. + # bc is an optional package, and the `|| echo "0"` this replaces turned + # a missing or failing bc into a 0 that read exactly like a measured + # value: no warn(), and METRICS_COMPLETE left true, so the run reported + # a complete measurement and exited 0. awk is already required by the + # sampling loop and the CPU average, so computing this with awk removes + # the failure path rather than reporting it. The divisor is >= 1 by the + # test above. + CONSENSUS_MEAN=$(awk -v d="$DURATION" -v u="$UNIQUE_LEDGERS" \ + 'BEGIN { printf "%.0f", d * 1000 / (u - 1) }') else warn "Ledger seq never advanced ($UNIQUE_LEDGERS distinct); consensus_round_mean_ms is a 0 placeholder" CONSENSUS_MEAN="0" diff --git a/docker/telemetry/workload/regression-metrics.json b/docker/telemetry/workload/regression-metrics.json index dbc0ba055b..4b07a17512 100644 --- a/docker/telemetry/workload/regression-metrics.json +++ b/docker/telemetry/workload/regression-metrics.json @@ -4,7 +4,11 @@ "_excluded_spans": "rpc.process is deliberately absent from spans.names. It is created only in ServerHandler::processRequest() on the HTTP/JSON-RPC path, which the workload load generators, being WebSocket-only, never reach, so its quantiles were captured as null every run and could never gate. (The harness shell scripts do issue a few HTTP JSON-RPC health polls, far too few to produce a meaningful quantile.) See baselines/README.md.", "_excluded_ledger_store": "ledger.store is deliberately absent from spans.names too, for a different reason: it is below the ladder's resolution. The 2026-08-24 capture returned p50/p95/p99 of exactly 0.005/0.0095/0.0099 ms, which is 0.5/0.95/0.99 x the ladder's first edge of 0.01 ms — the signature of every sample landing in the first bucket, so the numbers are interpolation arithmetic on the bucket floor rather than latencies. That is physically plausible: LedgerMaster.cpp:463 wraps an in-memory ledgerHistory_.insert, which completes in single-digit microseconds. While all mass stays under 10 us the reported quantile cannot move materially, so NO absolute bound can gate it — every ledger.store slowing from 2 us to 9 us, 4.5x, leaves the reported value unchanged. Three keys that read as covered but cannot fire are worse than no keys (the same argument that excluded rpc.process), so they were removed rather than left in with a bound that looks derived. Restoring the key needs sub-10us edges on the collector's spanmetrics ladder (for example 0.001ms and 0.005ms) plus the matching entries in HistogramBuckets.h — that is the ladder's branch, not this file. ledger.store presence is still asserted by expected_spans.json and docker/telemetry/integration-test.sh, and its rate is still on the ledger-operations dashboard; only the latency gate drops it.", "_excluded_quantiles": "A THIRD KIND OF EXCLUSION, and the only one that deleting a name cannot express. spans.names lists span NAMES while _quantiles is shared across all of them, so the declared surface is the names x quantiles product and dropping ONE quantile of ONE span needs a subtraction. excluded_keys below is that subtraction: a flat {category}.{name}.p{quantile} key, exactly as _key_format defines it, mapped to the reason it is not gated. It can only ever remove a key, never add one, so a typo cannot silently start gating something new -- and check_regression_bounds.py rule F rejects an entry that would not otherwise be declared, an entry with an empty reason, and an entry that still carries a threshold override or a baseline value, so the exclusion cannot rot into dead config. Both prom_queries.py (which builds the capture plan) and check_regression_bounds.py (rule A) subtract it, so an excluded key is not queried, never reaches timings.json, and is not expected in the baseline. NOTHING ELSE CHANGES: the quantile is still computable from Prometheus with the _query_template above, the span is still asserted by expected_spans.json, and its rate is still on the ledger-operations dashboard. Only the latency gate drops it.", + "_excluded_shape": "ALL FIVE ENTRIES BELOW SHARE ONE SHAPE, and it is worth naming because it will recur: the observed maximum across CI runs exceeds (baseline + bound), so an ordinary run clears the trip point with nothing having regressed. Two mechanisms produce that, and both are visible here. (1) A baseline that lands in the ladder's LOW buckets gets a tiny derived bound, because the bound IS the distance to the next edge up -- span.tx.apply.p50 at 0.0060 ms sits in the first bucket (0, 0.01] and gets 0.0440 ms of headroom, against a metric that has been measured at 2.3378 ms. (2) A spread so large that no bucket of headroom could absorb it -- span.ledger.validate.p99's 66.8x range reaches 25.8750 ms against a 10 ms trip point even though its bound is a comparatively generous 8.94 ms. The first mechanism is the one that bit three keys on the 2026-08-26 refresh, and it is a property of WHERE THE CAPTURED RUN LANDED rather than of the metric: the same span.tx.apply.p50 read 0.7917 ms in the previous baseline, mid-distribution, where the identical rule produced a 4.21 ms bound that absorbed the whole range. Whether the gate functioned was therefore decided by luck of the draw. THE FOLLOW-UP THAT WOULD RESTORE COVERAGE, stated so it is not left implied: a baseline captured from a SINGLE run cannot support these keys, because one sample carries no information about spread and the bound is derived from that one sample alone. What would let them be gated again is a multi-run baseline -- or a spread measurement captured alongside the baseline, so a bound can be sized against observed variance instead of against the ladder only. That is not implemented; it is the design change these five exclusions are waiting on. Until then, do NOT re-gate any of them by re-baselining until a run happens to land favourably, which is the failure this note exists to prevent.", "excluded_keys": { + "span.consensus.ledger_close.p50": "Run-to-run variance exceeds the bound this ladder can derive, the same limit as the ledger.validate pair and the same mechanism as the two sibling p50 keys excluded alongside it. Baseline 0.0387 ms sits in the low bucket (0.01, 0.05], so hi_next is 0.1 ms and the derived bound is 0.0613 ms -- a 2.58x trip point. Measured across three CI runs the value spans 0.0387 to 0.2377 ms, a 6.1x spread (5.9x over four runs), and run 32867433073 read 0.2377 ms, 2.38x the trip point, on the SAME post-path-finding-removal workload as this baseline. So a healthy run reddens CI. This is a variance limit, not a defect and not a missing bound: widening is unavailable, because a bound tolerating 0.2377 ms would reach past the 0.25 ms edge and gate almost nothing. Do NOT re-gate by widening, and do NOT re-baseline until a run lands higher -- see _excluded_shape.", + "span.ledger.build.p50": "The same mechanism as span.consensus.ledger_close.p50, one bucket up. Baseline 0.1151 ms sits in (0.1, 0.25], so hi_next is 0.5 ms and the bound is 0.3849 ms -- a 4.34x trip point. Across three CI runs the value spans 0.1151 to 2.3826 ms, a 20.7x spread (25.3x over four runs), and the observed maximum is 4.77x the trip point. Note what the previous baseline hid: at 1.0612 ms the same rule gave a 8.94 ms bound and a 10 ms trip point, which absorbed the entire range, so this key read as gated purely because that capture landed mid-distribution. Ledger construction is the hot path this gate most wants to guard, which makes the loss real and worth fixing properly -- with a baseline that carries spread information, not with a wider bound.", + "span.tx.apply.p50": "The most extreme case of the low-bucket mechanism, and the clearest evidence that a single-run baseline cannot size a bound for these keys. Baseline 0.00597 ms lands in the ladder's FIRST bucket (0, 0.01], so hi_next is 0.05 ms and the bound is 0.0440 ms. Across three CI runs the value spans 0.00597 to 2.3378 ms, a 391.8x spread (364x over four runs), putting the observed maximum at 46.76x its trip point -- by far the worst of the five. The previous baseline read 0.7917 ms for the same key on the same workload, a 132x difference between two runs, and at that value the identical rule produced a 4.21 ms bound whose 5 ms trip point absorbed the full range. Nothing about the metric changed between those two captures; only where the sampled run fell in its own distribution did. Separately, a baseline inside the first bucket means the reported figure is interpolation across that bucket and tracks the FRACTION of applies finishing under 10 us rather than a latency, which is the ledger.store problem in embryo -- so restoring this key needs a finer low-end ladder as well as a spread-aware baseline. Rule E does not flag it because the value is not quantile x first_edge exactly.", "span.ledger.validate.p95": "Run-to-run variance is larger than the bound this ladder can derive. Measured across four CI runs the value spans 0.1281 to 0.7500 ms, a 5.9x spread, against a baseline of 0.2404 ms whose trip point is the next ladder edge at 0.5 ms -- so an ordinary run clears the trip point with nothing having regressed. Run 32867433073 read 0.7500 ms, +212%, and turned CI red. The derived bound models QUANTIZATION noise only (hi_next - baseline is one bucket of headroom); the dominant noise term for this span is peer-validation arrival timing in a 5-node cluster, and that term was never measured before the key was gated. Widening is not available: a bound that tolerated 0.7500 ms would reach past the 1 ms edge and leave the key gating nothing. This is a variance limit, not a defect and not a missing bound -- do NOT re-gate it by widening.", "span.ledger.validate.p99": "The same mechanism as p95, two orders of magnitude worse. Across the same four runs the value spans 0.3875 to 25.8750 ms, a 66.8x spread, against a baseline of 1.0600 ms and a 10 ms trip point; run 32862589645 read 25.8750 ms, +2341%. The span opens only once a quorum-completing validation arrives (LedgerMaster.cpp:987, inside checkAccept, past the tvc < minVal early return) and wraps the promotion work that follows -- setValidated, setFull, setValidLedger, pendSaveValidated -- so its duration tracks peer-validation arrival timing and what promotion then triggers. One slow consensus round therefore dominates the tail of a 3m rate window, and which round that is differs every run. A bound tolerating 25.8750 ms would be ~24.8 ms against a 1.0600 ms baseline, which gates nothing at all. Note that the two CI failures landed on DIFFERENT quantiles in different runs while the other quantile stayed well inside its bound in the same run: that asymmetry is the signature of variance, not of a regression." }, diff --git a/docker/telemetry/workload/regression-thresholds.json b/docker/telemetry/workload/regression-thresholds.json index 7ea8672996..b31fa1cf71 100644 --- a/docker/telemetry/workload/regression-thresholds.json +++ b/docker/telemetry/workload/regression-thresholds.json @@ -1,22 +1,22 @@ { "_description": "Per-metric regression thresholds. A metric regresses when current - baseline exceeds BOTH the percentage and absolute bounds (AND, not OR \u2014 this tolerates small-value noise). Defaults apply unless a per-metric override exists.", "_bucket_note": "SpanMetrics latency histograms use explicit buckets [0.01,0.05,0.1,0.25,0.5,1,5,10,25,50,100,250,500]ms then [1,2,3,4,5,10,30]s (20 edges; docker/telemetry/otel-collector-config.yaml is the authoritative list). Second-scale consensus spans have 2s/3s/4s boundaries, so their quantiles quantize to ~1s widths there \u2014 the ladder is NOT uniformly 2x-or-coarser, which matters for _percentage_bound_note. The native job_queue histograms are microsecond-valued on the ladder [1,2,5,10,25,50,100,250,500,1000,5000,25000,100000,500000]us then [1,5,10,30,60]s (19 edges; include/xrpl/telemetry/HistogramBuckets.h is authoritative). NOTE: BOTH ladders were re-cut, and a baseline captured before its own ladder changed is an interpolation artefact, not a latency. The job_queue floor moved 100us \u2192 1us. The span ladder was re-cut on 2026-08-04 in 3860c93db2, moving the floor 1ms \u2192 0.01ms; so any sub-millisecond span quantile captured before that date is equally void \u2014 a p95 reading 0.95ms is 0.95 \u00d7 the old 1ms first edge, not a measurement. An earlier note asserted that the surviving span baselines were unaffected by the ladder work; that is wrong for every span quantile below 1ms. Only the band from 1ms to 1s is safe: those edges are byte-identical across the two ladders. The re-cut also ADDED edges above 1s (2s/3s/4s/10s/30s), so a span whose quantiles land in the second-scale range \u2014 consensus.round ~3.9s, consensus.establish ~1.9s, the ledger.acquire tail \u2014 is distorted just as much, and any pre-2026-08-04 baseline for it is equally void. Do not read this note as licensing a stale second-scale baseline.", - "_absolute_bound_derivation": "HOW EVERY max_abs_increase_* NUMBER BELOW WAS OBTAINED. Rule: locate the baseline value in the half-open bucket (lo, hi] of its own ladder, take hi_next = the next edge above hi, and set the bound to (hi_next - baseline). The trip point is therefore exactly hi_next: the gate fires only when the reported value EXCEEDS the top of the bucket above the baseline's own bucket. WHY THAT AND NOT A MULTIPLE OF THE BUCKET WIDTH: histogram_quantile returns a value interpolated inside whichever bucket the true quantile falls in, so a reading taken while the true quantile sits anywhere in the baseline's bucket OR anywhere in the one immediately above is at most hi_next and cannot fire. Firing requires the true quantile to have moved at least two buckets up. A multiple of the ENCLOSING width cannot deliver that, because once the quantile crosses hi the interpolation happens across the NEXT bucket, which on this ladder is up to 8x wider \u2014 (0.5,1] has width 0.5 and (1,5] has width 4 \u2014 so the reading's excursion is not bounded by any multiple of the enclosing width. Worked example: span.tx.process.p99 has baseline 0.9945ms in bucket (0.5, 1], hi_next = 5, so its bound is 4.0055ms and the gate fires only above 5ms. Bounds are stored as exact doubles rather than rounded figures so that rounding cannot break the guarantee and so check_regression_bounds.py can assert each one against the ladder to within a 1e-12 relative tolerance -- tight enough that a bound rounded for readability, such as 4.0055 for 4.005485184848892, is rejected; _derivation_table below shows the arithmetic for each one. Measured over the committed baseline this rule yields a detection floor of 2.02x to 9.42x of baseline, per key. WHAT THIS RULE DOES NOT COVER, AND THE ONE CHECK TO RUN BEFORE GATING ANY KEY: hi_next - baseline is derived from the LADDER, so it budgets for QUANTIZATION noise -- one bucket of interpolation headroom -- and for nothing else. It knows nothing about how much the metric itself moves between runs on identical code. Where run-to-run workload variance is the larger term the bound is simply the wrong size, and the gate reddens on a healthy run. So before adding a key here, capture it over several runs and check its OBSERVED MAXIMUM against its trip point (baseline + bound); gate it only if the observed maximum stays below that trip point with margin. Spread on its own proves nothing -- span.tx.apply.p50 swings 364x across runs and never fires, because its 5ms trip point absorbs the whole range -- it is spread RELATIVE TO THE TRIP POINT that decides. Measured across the runs behind this baseline, the worst surviving key reaches 0.67 of its trip point (span.consensus.ledger_close.p95), and the only two that exceeded it were span.ledger.validate p95 and p99, now excluded. A key that fails this test is not fixed by widening its bound: see excluded_keys in regression-metrics.json. WHAT THIS REPLACED, IN TWO GENERATIONS: (1) a single flat pair of bounds (10ms for span p50/p95, 15ms for span p99, 20000us for job_queue p95) justified as 'roughly two bucket widths in the 5-25ms band where most span quantiles actually sit'. The 2026-08-24 capture falsifies that premise \u2014 18 of the 28 quantiles gated at that time sat below 1ms \u2014 so the absolute bound sat 1.15x to 2000x above the metric it guarded and, because the rule is an AND, the percentage bound could never carry a regression on its own; a 10x regression injected into each key in turn was caught on only 5 of 28, and a 100x regression injected into span.ledger.store.p95 produced 0 regressions and exit 0. (2) a first correction to 2 \u00d7 the ENCLOSING bucket width, which caught 10x on 28 of 28 but placed the trip point INSIDE the adjacent bucket -- and so left a single-crossing false positive reachable -- on 21 of the 25 keys gated at the time, 4 of them tripping on a tail-mass shift under 1.5% of samples. That is the assumption this rule removes. RE-DERIVE THESE NUMBERS whenever baseline-timings.json is refreshed or either ladder changes: a refreshed baseline can land in a different bucket, which changes hi_next. .github/scripts/telemetry/check_regression_bounds.py enforces the rule in CI so a stale bound cannot survive a baseline refresh. LIMITATION \u2014 WHICH KEYS ARE ONLY WEAKLY GUARDED: the guarantee costs sensitivity wherever the ladder is coarse, and the detection floor is hi_next/baseline, so a baseline sitting just above an edge is guarded loosely. span.ledger.build.p50 (baseline 1.0612ms, fires at 10ms, 9.42x) is NOT meaningfully guarded: it fires only at 10ms, so it could get up to 9.4x slower -- 1.06ms to just under 10ms -- and still pass. span.tx.process.p95 (6.91x), span.tx.apply.p50 (6.32x), span.rpc.ws_message.p95 (5.92x), job.acceptLedger.running.p95 (5.74x), span.consensus.accept.p50 (5.74x), span.consensus.ledger_close.p99 (5.37x), span.rpc.ws_message.p99 (5.06x) and span.tx.process.p99 (5.03x) are weak. All nine are limited by two 5x-wide ladder steps, 1ms\u21925ms and 5000us\u219225000us. The fix is a 2ms edge (and ideally 3ms) in the collector's spanmetrics ladder plus the matching edges in kMillisecondBuckets, and a 10000us edge in kMicrosecondBuckets \u2014 that work belongs to the branch that owns the ladders, not here. Until then do not read these keys as guarded. span.ledger.store is absent from the overrides below because it was removed from the gated surface entirely: its quantiles were the ladder floor times the quantile, so no bound could gate it. See _excluded_ledger_store in regression-metrics.json.", - "_percentage_bound_note": "For every key gated today the absolute bound is the binding half of the AND and the percentage bound never decides the outcome: measured, (bound / baseline) ranges from 102% (span.tx.apply.p99) to 842% (span.ledger.build.p50), all above the 50% and 5% percentage bounds configured here, and the minimum trip multiple of all 23 keys is set by the absolute bound. THIS IS NOT A GENERAL GUARANTEE, and an earlier version of this note wrongly claimed it was, on the false premise that 'every step of both ladders is at least a factor of 2'. The span ladder breaks that three times at the top: 2s->3s is 1.5x, 3s->4s is 1.33x, 4s->5s is 1.25x, so second-scale consensus quantiles quantize to ~1s widths there. Because the bound is (hi_next - baseline), a baseline between about 2667ms and 3000ms, or between about 3334ms and 4000ms, gets an absolute bound worth less than 50% of itself and the PERCENTAGE bound becomes the operative one -- at which point the metric fires on a 50% move that is smaller than one bucket width, and the single-crossing guarantee in _absolute_bound_derivation is lost. That band is not hypothetical: the collector config names consensus.round (~3.9s) as a reason those edges exist, and 3900ms sits in the second sub-band with an absolute bound of 5000 - 3900 = 1100, only 28.2% of baseline. Whoever gates a key whose baseline lands in either sub-band MUST lower its max_pct_increase below (bound / baseline) for that key, or state explicitly that the metric is percentage-gated and the bucket guarantee does not hold for it. check_regression_bounds.py enforces this as rule D so the trap cannot be walked into silently. The percentage entries are required and still meaningful regardless: compare_to_baseline.py treats a missing max_pct_increase as 'no threshold configured' and would stop gating the metric entirely; they record the intended relative tolerance (consensus spans 5%, everything else 50%); and they are the operative bound on the defaults path (see _defaults_note).", + "_absolute_bound_derivation": "HOW EVERY max_abs_increase_* NUMBER BELOW WAS OBTAINED. Rule: locate the baseline value in the half-open bucket (lo, hi] of its own ladder, take hi_next = the next edge above hi, and set the bound to (hi_next - baseline). The trip point is therefore exactly hi_next: the gate fires only when the reported value EXCEEDS the top of the bucket above the baseline's own bucket. WHY THAT AND NOT A MULTIPLE OF THE BUCKET WIDTH: histogram_quantile returns a value interpolated inside whichever bucket the true quantile falls in, so a reading taken while the true quantile sits anywhere in the baseline's bucket OR anywhere in the one immediately above is at most hi_next and cannot fire. Firing requires the true quantile to have moved at least two buckets up. A multiple of the ENCLOSING width cannot deliver that, because once the quantile crosses hi the interpolation happens across the NEXT bucket, which on this ladder is up to 8x wider \u2014 (0.5,1] has width 0.5 and (1,5] has width 4 \u2014 so the reading's excursion is not bounded by any multiple of the enclosing width. Worked example: span.tx.process.p99 has baseline 2.7588ms in bucket (1, 5], hi_next = 10, so its bound is 7.2412ms and the gate fires only above 10ms. Bounds are stored as exact doubles rather than rounded figures so that rounding cannot break the guarantee and so check_regression_bounds.py can assert each one against the ladder to within a 1e-12 relative tolerance -- tight enough that a bound rounded for readability, such as 7.2412 for 7.241212121212123, is rejected; _derivation_table below shows the arithmetic for each one. Measured over the committed baseline this rule yields a detection floor of 2.21x to 16.28x of baseline, per key. WHAT THIS RULE DOES NOT COVER, AND THE ONE CHECK TO RUN BEFORE GATING ANY KEY: hi_next - baseline is derived from the LADDER, so it budgets for QUANTIZATION noise -- one bucket of interpolation headroom -- and for nothing else. It knows nothing about how much the metric itself moves between runs on identical code. Where run-to-run workload variance is the larger term the bound is simply the wrong size, and the gate reddens on a healthy run. So before adding a key here, capture it over several runs and check its OBSERVED MAXIMUM against its trip point (baseline + bound); gate it only if the observed maximum stays below that trip point with margin. Spread on its own proves nothing -- it is spread RELATIVE TO THE TRIP POINT that decides, and a baseline that lands at the LOW end of a metric's own range shrinks that trip point even though nothing about the metric changed. THREE KEYS FAILED THIS TEST ON THE 2026-08-26 BASELINE AND ARE NOW EXCLUDED, all of them p50: span.tx.apply.p50 (bound 0.0440ms, trips at 0.05ms, observed max 2.3378ms = 46.76x its trip point), span.ledger.build.p50 (bound 0.3849ms, trips at 0.5ms, observed max 2.3826ms = 4.77x) and span.consensus.ledger_close.p50 (bound 0.0613ms, trips at 0.1ms, observed max 0.2377ms = 2.38x). Their spreads across three runs are 391.8x, 20.7x and 6.1x. This is the general rule above being APPLIED, not a new exception: a key is gateable only when its run-to-run spread fits inside its bound, and these three do not. The evidence that settles it is span.tx.apply.p50's own history -- it read 0.7917ms in the previous baseline and 0.00597ms in this one, a 132x difference between two runs of the SAME workload. At the old value the identical rule produced a 4.21ms bound whose 5ms trip point absorbed the whole range; at the new one it produces 0.0440ms and cannot. Whether the gate functioned was therefore decided by where in its distribution the captured run happened to land, which is not a threshold needing tuning but a key that cannot be gated from a single-run baseline at all. Before the exclusion, replaying the two preceding CI runs 32862589645 and 32867433073 against this baseline reported exactly those three and nothing else on BOTH runs, and 32867433073 carries the same post-path-finding-removal workload as the baseline itself -- so the movement was metric variance, not a workload difference. After it, both runs replay clean. The remaining 20 keys sit at or below 0.58 of their trip points, the worst being span.consensus.accept.p50. See _excluded_shape in regression-metrics.json for what all five excluded keys have in common and for the multi-run-baseline work that would let them be gated again. A key that fails this test is not fixed by widening its bound: see excluded_keys in regression-metrics.json. WHAT THIS REPLACED, IN TWO GENERATIONS: (1) a single flat pair of bounds (10ms for span p50/p95, 15ms for span p99, 20000us for job_queue p95) justified as 'roughly two bucket widths in the 5-25ms band where most span quantiles actually sit'. The 2026-08-24 capture falsifies that premise \u2014 18 of the 28 quantiles gated at that time sat below 1ms \u2014 so the absolute bound sat 1.15x to 2000x above the metric it guarded and, because the rule is an AND, the percentage bound could never carry a regression on its own; a 10x regression injected into each key in turn was caught on only 5 of 28, and a 100x regression injected into span.ledger.store.p95 produced 0 regressions and exit 0. (2) a first correction to 2 \u00d7 the ENCLOSING bucket width, which caught 10x on 28 of 28 but placed the trip point INSIDE the adjacent bucket -- and so left a single-crossing false positive reachable -- on 21 of the 25 keys gated at the time, 4 of them tripping on a tail-mass shift under 1.5% of samples. That is the assumption this rule removes. RE-DERIVE THESE NUMBERS whenever baseline-timings.json is refreshed or either ladder changes: a refreshed baseline can land in a different bucket, which changes hi_next. .github/scripts/telemetry/check_regression_bounds.py enforces the rule in CI so a stale bound cannot survive a baseline refresh. LIMITATION \u2014 WHICH KEYS ARE ONLY WEAKLY GUARDED: the guarantee costs sensitivity wherever the ladder is coarse, and the detection floor is hi_next/baseline, so a baseline sitting just above an edge is guarded loosely. job.acceptLedger.running.p95 (baseline 6142.86us, fires at 100000us, 16.28x) is NOT meaningfully guarded, and it is now the one key a 10x regression does NOT catch: measured, 10x reaches 61429us and passes, and the gate first fires at 16.28x. It sits just above the 5000us edge while hi_next is 100000us, two steps up. Its floor moved there in this refresh, from 5.74x, because its baseline fell 17428.57us to 6142.86us while hi_next stayed at 100000us -- it does NOT fire on any observed run, so it stays gated, but the weak floor is recorded here so it is visible rather than surprising. span.consensus.accept.p50 (9.46x), job.transaction.running.p95 (8.33x), span.tx.process.p95 (8.20x), span.rpc.ws_message.p95 (7.17x), span.consensus.ledger_close.p95 (6.39x) and span.rpc.ws_message.p99 (5.12x) are also weak. Four of the seven are limited by the 1ms\u21925ms step; the rest by 1000us\u21925000us (job.transaction.running.p95) and 25000us\u2192100000us (job.acceptLedger.running.p95). The fix is a 2ms edge (and ideally 3ms) in the collector's spanmetrics ladder plus the matching edges in kMillisecondBuckets, and 2000us plus 50000us edges in kMicrosecondBuckets \u2014 that work belongs to the branch that owns the ladders, not here. Until then do not read these keys as guarded. span.ledger.store is absent from the overrides below because it was removed from the gated surface entirely: its quantiles were the ladder floor times the quantile, so no bound could gate it. See _excluded_ledger_store in regression-metrics.json.", + "_percentage_bound_note": "For every key gated today the absolute bound is the binding half of the AND and the percentage bound never decides the outcome: measured, (bound / baseline) ranges from 121% (span.ledger.build.p95) to 1528% (job.acceptLedger.running.p95), all above the 50% and 5% percentage bounds configured here, and the minimum trip multiple of all 20 keys is set by the absolute bound. THIS IS NOT A GENERAL GUARANTEE, and an earlier version of this note wrongly claimed it was, on the false premise that 'every step of both ladders is at least a factor of 2'. The span ladder breaks that three times at the top: 2s->3s is 1.5x, 3s->4s is 1.33x, 4s->5s is 1.25x, so second-scale consensus quantiles quantize to ~1s widths there. Because the bound is (hi_next - baseline), a baseline between about 2667ms and 3000ms, or between about 3334ms and 4000ms, gets an absolute bound worth less than 50% of itself and the PERCENTAGE bound becomes the operative one -- at which point the metric fires on a 50% move that is smaller than one bucket width, and the single-crossing guarantee in _absolute_bound_derivation is lost. That band is not hypothetical: the collector config names consensus.round (~3.9s) as a reason those edges exist, and 3900ms sits in the second sub-band with an absolute bound of 5000 - 3900 = 1100, only 28.2% of baseline. Whoever gates a key whose baseline lands in either sub-band MUST lower its max_pct_increase below (bound / baseline) for that key, or state explicitly that the metric is percentage-gated and the bucket guarantee does not hold for it. check_regression_bounds.py enforces this as rule D so the trap cannot be walked into silently. The percentage entries are required and still meaningful regardless: compare_to_baseline.py treats a missing max_pct_increase as 'no threshold configured' and would stop gating the metric entirely; they record the intended relative tolerance (consensus spans 5%, everything else 50%); and they are the operative bound on the defaults path (see _defaults_note).", "_defaults_note": "A MISSING OVERRIDE IS DETECTED BY CI, NOT BY THESE DEFAULTS. .github/scripts/telemetry/check_regression_bounds.py fails the build at lint time, naming the key and the exact value its bound should have, before the workload ever runs. That is the mechanism; the defaults below are only a runtime backstop for the case where that check is bypassed. The defaults carry the FLOOR of each ladder as their absolute bound \u2014 0.01ms for spans, 1us for job_queue \u2014 deliberately too small to bind for any real metric, which leaves max_pct_increase (50%) as the operative bound on this path. Measured: a metric with no override and a baseline of 3900ms passes at +49% and fires at +51%; a job metric with a baseline of 5000us behaves the same. The backstop is honestly imperfect and the earlier version of this note oversold it. At 50% relative it CAN false-fire: a metric whose baseline is 1.06ms inside the 4ms-wide (1,5] bucket fires on a single-bucket-width move (measured: 1.06 \u2192 5.06ms, +377%, regressed). An earlier note called that 'the intended signal that the override is missing', which was wrong \u2014 CI prints REGRESSION and a reader cannot tell it from a real one, and rejecting a tighter alternative for exactly that cries-wolf risk while shipping it here would be inconsistent. The check is what makes the signal legible. The backstop is kept only because a metric silently not gated at all is the worse of the two failures.", "_derivation_table": { "_format": "override key: in -> hi_next - baseline = ", - "job.acceptLedger.queued": "p95 91.10576923076925 in (50,100] -> hi_next 250 - baseline = 158.89423076923075", - "job.acceptLedger.running": "p95 17428.571428571428 in (5000,25000] -> hi_next 100000 - baseline = 82571.42857142858", - "job.transaction.queued": "p95 476.6129032258061 in (250,500] -> hi_next 1000 - baseline = 523.3870967741939", - "job.transaction.running": "p95 427.1084337349388 in (250,500] -> hi_next 1000 - baseline = 572.8915662650612", - "span.consensus.accept": "p50 1.7435897435897438 in (1,5] -> hi_next 10 - baseline = 8.256410256410255 | p95 8.9296875 in (5,10] -> hi_next 25 - baseline = 16.0703125 | p99 15.150000000000082 in (10,25] -> hi_next 50 - baseline = 34.849999999999916", - "span.consensus.ledger_close": "p50 0.15142857142857144 in (0.1,0.25] -> hi_next 0.5 - baseline = 0.34857142857142853 | p95 0.49328358208955236 in (0.25,0.5] -> hi_next 1 - baseline = 0.5067164179104476 | p99 0.9314285714285726 in (0.5,1] -> hi_next 5 - baseline = 4.068571428571428", - "span.ledger.build": "p50 1.0612244897959187 in (1,5] -> hi_next 10 - baseline = 8.938775510204081 | p95 4.679591836734694 in (1,5] -> hi_next 10 - baseline = 5.320408163265306 | p99 5.075000000000041 in (5,10] -> hi_next 25 - baseline = 19.924999999999958", - "span.ledger.validate": "p50 0.07787769784172663 in (0.05,0.1] -> hi_next 0.25 - baseline = 0.17212230215827337 (p95 and p99 are NOT gated -- see excluded_keys in regression-metrics.json: their run-to-run spread, 5.9x and 66.8x over four CI runs, exceeds any bound this rule can derive)", - "span.rpc.ws_message": "p50 0.15990942879094971 in (0.1,0.25] -> hi_next 0.5 - baseline = 0.3400905712090503 | p95 0.8443074003795064 in (0.5,1] -> hi_next 5 - baseline = 4.155692599620494 | p99 0.9878368121442125 in (0.5,1] -> hi_next 5 - baseline = 4.012163187855787", - "span.tx.apply": "p50 0.791666666666667 in (0.5,1] -> hi_next 5 - baseline = 4.208333333333333 | p95 4.627368421052632 in (1,5] -> hi_next 10 - baseline = 5.372631578947368 | p99 4.959157894736842 in (1,5] -> hi_next 10 - baseline = 5.040842105263158", - "span.tx.process": "p50 0.34281067382135394 in (0.25,0.5] -> hi_next 1 - baseline = 0.6571893261786461 | p95 0.7239865112994349 in (0.5,1] -> hi_next 5 - baseline = 4.276013488700565 | p99 0.9945148151511076 in (0.5,1] -> hi_next 5 - baseline = 4.005485184848892" + "job.acceptLedger.queued": "p95 166.13636363636323 in (100,250] -> hi_next 500 - baseline = 333.8636363636368", + "job.acceptLedger.running": "p95 6142.857142857149 in (5000,25000] -> hi_next 100000 - baseline = 93857.14285714286", + "job.transaction.queued": "p95 426.19047619047586 in (250,500] -> hi_next 1000 - baseline = 573.8095238095241", + "job.transaction.running": "p95 599.9999999999986 in (500,1000] -> hi_next 5000 - baseline = 4400.000000000002", + "span.consensus.accept": "p50 0.5287356321839081 in (0.5,1] -> hi_next 5 - baseline = 4.471264367816092 | p95 8.969696969696969 in (5,10] -> hi_next 25 - baseline = 16.03030303030303 | p99 20.800000000000026 in (10,25] -> hi_next 50 - baseline = 29.199999999999974", + "span.consensus.ledger_close": "p95 0.7829999999999997 in (0.5,1] -> hi_next 5 - baseline = 4.2170000000000005 | p99 2.0299999999999896 in (1,5] -> hi_next 10 - baseline = 7.97000000000001 (p50 is NOT gated -- see excluded_keys in regression-metrics.json)", + "span.ledger.build": "p95 4.53333333333333 in (1,5] -> hi_next 10 - baseline = 5.46666666666667 | p99 9.109090909090913 in (5,10] -> hi_next 25 - baseline = 15.890909090909087 (p50 is NOT gated -- see excluded_keys in regression-metrics.json)", + "span.ledger.validate": "p50 0.06471894002114831 in (0.05,0.1] -> hi_next 0.25 - baseline = 0.1852810599788517 (p95 and p99 are NOT gated -- see excluded_keys in regression-metrics.json: their run-to-run spread, 5.9x and 66.8x over four CI runs, exceeds any bound this rule can derive)", + "span.rpc.ws_message": "p50 0.16003451676528602 in (0.1,0.25] -> hi_next 0.5 - baseline = 0.339965483234714 | p95 0.6977397260273974 in (0.5,1] -> hi_next 5 - baseline = 4.302260273972602 | p99 0.9757123287671235 in (0.5,1] -> hi_next 5 - baseline = 4.024287671232877", + "span.tx.apply": "p95 3.524999999999999 in (1,5] -> hi_next 10 - baseline = 6.475000000000001 | p99 5.066666666666704 in (5,10] -> hi_next 25 - baseline = 19.933333333333294 (p50 is NOT gated -- see excluded_keys in regression-metrics.json)", + "span.tx.process": "p50 0.20062219789579117 in (0.1,0.25] -> hi_next 0.5 - baseline = 0.29937780210420883 | p95 0.6100467289719625 in (0.5,1] -> hi_next 5 - baseline = 4.389953271028038 | p99 2.758787878787877 in (1,5] -> hi_next 10 - baseline = 7.241212121212123" }, "defaults": { "span": { @@ -44,115 +44,103 @@ "job.acceptLedger.queued": { "p95": { "max_pct_increase": 50.0, - "max_abs_increase_us": 158.89423076923075 + "max_abs_increase_us": 333.8636363636368 } }, "job.acceptLedger.running": { "p95": { "max_pct_increase": 50.0, - "max_abs_increase_us": 82571.42857142858 + "max_abs_increase_us": 93857.14285714286 } }, "job.transaction.queued": { "p95": { "max_pct_increase": 50.0, - "max_abs_increase_us": 523.3870967741939 + "max_abs_increase_us": 573.8095238095241 } }, "job.transaction.running": { "p95": { "max_pct_increase": 50.0, - "max_abs_increase_us": 572.8915662650612 + "max_abs_increase_us": 4400.000000000002 } }, "span.consensus.accept": { "p50": { "max_pct_increase": 5.0, - "max_abs_increase_ms": 8.256410256410255 + "max_abs_increase_ms": 4.471264367816092 }, "p95": { "max_pct_increase": 5.0, - "max_abs_increase_ms": 16.0703125 + "max_abs_increase_ms": 16.03030303030303 }, "p99": { "max_pct_increase": 5.0, - "max_abs_increase_ms": 34.849999999999916 + "max_abs_increase_ms": 29.199999999999974 } }, "span.consensus.ledger_close": { - "p50": { - "max_pct_increase": 5.0, - "max_abs_increase_ms": 0.34857142857142853 - }, "p95": { "max_pct_increase": 5.0, - "max_abs_increase_ms": 0.5067164179104476 + "max_abs_increase_ms": 4.2170000000000005 }, "p99": { "max_pct_increase": 5.0, - "max_abs_increase_ms": 4.068571428571428 + "max_abs_increase_ms": 7.97000000000001 } }, "span.ledger.build": { - "p50": { - "max_pct_increase": 50.0, - "max_abs_increase_ms": 8.938775510204081 - }, "p95": { "max_pct_increase": 50.0, - "max_abs_increase_ms": 5.320408163265306 + "max_abs_increase_ms": 5.46666666666667 }, "p99": { "max_pct_increase": 50.0, - "max_abs_increase_ms": 19.924999999999958 + "max_abs_increase_ms": 15.890909090909087 } }, "span.ledger.validate": { "p50": { "max_pct_increase": 50.0, - "max_abs_increase_ms": 0.17212230215827337 + "max_abs_increase_ms": 0.1852810599788517 } }, "span.rpc.ws_message": { "p50": { "max_pct_increase": 50.0, - "max_abs_increase_ms": 0.3400905712090503 + "max_abs_increase_ms": 0.339965483234714 }, "p95": { "max_pct_increase": 50.0, - "max_abs_increase_ms": 4.155692599620494 + "max_abs_increase_ms": 4.302260273972602 }, "p99": { "max_pct_increase": 50.0, - "max_abs_increase_ms": 4.012163187855787 + "max_abs_increase_ms": 4.024287671232877 } }, "span.tx.apply": { - "p50": { - "max_pct_increase": 50.0, - "max_abs_increase_ms": 4.208333333333333 - }, "p95": { "max_pct_increase": 50.0, - "max_abs_increase_ms": 5.372631578947368 + "max_abs_increase_ms": 6.475000000000001 }, "p99": { "max_pct_increase": 50.0, - "max_abs_increase_ms": 5.040842105263158 + "max_abs_increase_ms": 19.933333333333294 } }, "span.tx.process": { "p50": { "max_pct_increase": 50.0, - "max_abs_increase_ms": 0.6571893261786461 + "max_abs_increase_ms": 0.29937780210420883 }, "p95": { "max_pct_increase": 50.0, - "max_abs_increase_ms": 4.276013488700565 + "max_abs_increase_ms": 4.389953271028038 }, "p99": { "max_pct_increase": 50.0, - "max_abs_increase_ms": 4.005485184848892 + "max_abs_increase_ms": 7.241212121212123 } } } diff --git a/docker/telemetry/workload/rpc_load_generator.py b/docker/telemetry/workload/rpc_load_generator.py index 4d6ea894a3..36834de9ef 100644 --- a/docker/telemetry/workload/rpc_load_generator.py +++ b/docker/telemetry/workload/rpc_load_generator.py @@ -30,6 +30,7 @@ Usage: import argparse import asyncio +import itertools import json import logging import math @@ -90,10 +91,17 @@ DRAIN_TIMEOUT_S = RECV_TIMEOUT_S + 2.0 # Requests allowed to own one connection's recv() at a time. websockets # rejects a second concurrent recv() on the same socket, so this must stay 1 -# unless request/response correlation by id is added. Concurrency comes from -# spreading requests round-robin over the endpoints instead. +# until a single reader task per connection demultiplexes replies to their +# waiters; correlating by id, which send_rpc now does, is necessary for that +# but not sufficient on its own. Concurrency comes from spreading requests +# round-robin over the endpoints instead. MAX_INFLIGHT_PER_CONNECTION = 1 +# Source of the ``id`` sent with every request. xrpld echoes a request's id at +# the top level of the reply, which is what lets send_rpc tell its own reply +# from one that an earlier, timed-out request left in the receive buffer. +_request_ids = itertools.count(1) + # Fraction of dispatched requests that must reach the server for a run to # count as a measurement. The gate is one connection deep, so the ceiling is # len(connections) / round-trip requests per second; asking for more than @@ -364,6 +372,59 @@ def choose_command(weights: dict[str, int]) -> str: # --------------------------------------------------------------------------- +async def _recv_matching_reply( + conn: Connection, request_id: int, command: str +) -> dict[str, Any]: + """Read replies on ``conn`` until the one for ``request_id`` arrives. + + Cancelling a ``recv()`` does not discard the reply it was waiting for: the + library queues incoming messages independently of any reader, so a request + that hit RECV_TIMEOUT_S leaves its reply in the buffer. The next request on + that connection used to read it and time its own round trip against + somebody else's reply -- a near-zero latency, and a ``status`` belonging to + a different command. The skew was permanent, because every later request on + the connection stayed one reply behind for the rest of the run, so a single + timeout quietly invalidated that connection's whole latency distribution. + Discarding replies by id puts the stream back in step. + + The caller holds ``conn.gate``, so no other request can consume a reply + while this loop runs. The deadline covers the whole exchange rather than + each message, so a run of buffered replies cannot extend the wait without + bound. + + Args: + conn: Connection to read from, with its gate already held. + request_id: The ``id`` sent with this request. + command: RPC command name, for logging. + + Returns: + The parsed reply whose ``id`` matches, or that carries no ``id``. + + Raises: + asyncio.TimeoutError: If no matching reply arrived within + RECV_TIMEOUT_S. + """ + deadline = time.monotonic() + RECV_TIMEOUT_S + while True: + remaining = deadline - time.monotonic() + if remaining <= 0: + raise asyncio.TimeoutError(f"{command} (id {request_id}) got no reply") + raw = await asyncio.wait_for(conn.ws.recv(), timeout=remaining) + reply = json.loads(raw) + # A reply with no id counts as this request's: a few xrpld error paths + # answer before the id is parsed, and treating those as stale would + # turn a reported error into a timeout. + reply_id = reply.get("id") + if reply_id is None or reply_id == request_id: + return reply + logger.debug( + "Discarded a reply for id %s while awaiting id %s (%s)", + reply_id, + request_id, + command, + ) + + async def send_rpc( conn: Connection, command: str, @@ -388,6 +449,8 @@ async def send_rpc( to the request for context propagation testing. """ request = build_rpc_request(command) + request_id = next(_request_ids) + request["id"] = request_id # Inject W3C traceparent for context propagation testing. # The rippled WebSocket handler extracts this from the JSON body @@ -404,11 +467,11 @@ async def send_rpc( # being counted as one more failed request. try: await conn.ws.send(json.dumps(request)) - raw = await asyncio.wait_for(conn.ws.recv(), timeout=RECV_TIMEOUT_S) + reply = await _recv_matching_reply(conn, request_id, command) latency = time.monotonic() - t0 # Native WS responses have {"status": "success", "result": {...}} # or {"status": "error", "error": "...", "error_message": "..."}. - success = json.loads(raw).get("status") == "success" + success = reply.get("status") == "success" except REQUEST_FAILURES as exc: logger.debug("RPC %s failed: %s", command, exc) # No reply, so no latency sample -- see LoadStats.record(). diff --git a/docker/telemetry/workload/run-full-validation.sh b/docker/telemetry/workload/run-full-validation.sh index 3524ef5648..4d1fec7bc1 100755 --- a/docker/telemetry/workload/run-full-validation.sh +++ b/docker/telemetry/workload/run-full-validation.sh @@ -614,9 +614,22 @@ diag_validator_const() { # rather than as zero — "Loki said none" and "Loki did not answer" are # different findings. diag_loki_count() { - local body - body=$(diag_run curl -sfG --max-time 10 "$LOKI_URL/loki/api/v1/query" \ + local raw status body + # No -f here on purpose. curl -f discards the response body on a 4xx, and + # Loki explains a rejected query only in that body (as text/plain), so -f + # turned a self-describing failure into a bare "unavailable". Append the + # status code instead and read the body either way. + raw=$(diag_run curl -sG --max-time 10 -w $'\n%{http_code}' \ + "$LOKI_URL/loki/api/v1/query" \ --data-urlencode "query=$1" --data-urlencode "time=$2" 2>/dev/null) || return 1 + status=${raw##*$'\n'} + body=${raw%$'\n'*} + if [ "$status" != "200" ]; then + # To stderr: this function's stdout is the count its caller captures. + printf ' Loki rejected the diagnostic query (HTTP %s): %.300s\n' \ + "$status" "$(printf '%s' "$body" | tr -s '[:space:]' ' ')" >&2 + return 1 + fi printf '%s' "$body" | jq -er '[.data.result[].value[1] | tonumber] | add // 0' 2>/dev/null || return 1 } @@ -796,8 +809,14 @@ diag_loki_stream() { "$DIAG_LOG_SELECTOR $DIAG_LOG_FILTER") [ -n "$selector" ] || selector="$DIAG_LOG_SELECTOR" [ -n "$correlation" ] || correlation="$DIAG_LOG_SELECTOR $DIAG_LOG_FILTER" - query_all="count_over_time($selector[${DIAG_LOG_WINDOW_SECONDS}s])" - query_filtered="count_over_time($correlation [${DIAG_LOG_WINDOW_SECONDS}s])" + # sum() is required, for the reason recorded at _log_loki_diagnostics in + # validate_telemetry.py: the filelog regex_parser leaves message/timestamp + # as log-record attributes, Loki's OTLP path turns those into structured + # metadata that joins a metric query's label set, so an unaggregated + # count_over_time yields one series per log line and Loki rejects the query + # with HTTP 400 past 500 series. Both legs then print "unavailable". + query_all="sum(count_over_time($selector[${DIAG_LOG_WINDOW_SECONDS}s]))" + query_filtered="sum(count_over_time($correlation [${DIAG_LOG_WINDOW_SECONDS}s]))" echo " validator LogQL: $correlation" echo " diagnostic LogQL: $query_all" echo " $query_filtered" diff --git a/docker/telemetry/workload/tx_submitter.py b/docker/telemetry/workload/tx_submitter.py index 745ce0ae9a..da9b2659ca 100644 --- a/docker/telemetry/workload/tx_submitter.py +++ b/docker/telemetry/workload/tx_submitter.py @@ -8,13 +8,13 @@ consensus.*, and all associated attributes. Pre-funds test accounts from the genesis account, then submits a configurable mix of transaction types at a target TPS. -Supported transaction types: - - Payment (XRP and issued currencies) +Supported transaction types (the 10 in TX_BUILDERS): + - Payment (XRP transfers) - OfferCreate / OfferCancel (DEX activity) - TrustSet (trust line creation) - - NFTokenMint / NFTokenCreateOffer / NFTokenAcceptOffer - - EscrowCreate / EscrowFinish - - AMMCreate / AMMDeposit / AMMWithdraw (if amendment enabled) + - NFTokenMint / NFTokenCreateOffer (NFT activity) + - EscrowCreate / EscrowFinish (escrow lifecycle) + - AMMCreate / AMMDeposit (AMM pool operations, if amendment enabled) Usage: python3 tx_submitter.py --endpoint ws://localhost:6006 --tps 5 --duration 120 @@ -26,6 +26,7 @@ Usage: import argparse import asyncio +import itertools import json import logging import random @@ -111,6 +112,14 @@ SEQ_REFETCH_AFTER_FAILURES = 5 # ledger, to stay close to sequences other submitters have advanced. SEQ_REFRESH_INTERVAL_S = 10.0 +# How long one request waits for the reply that belongs to it. +RECV_TIMEOUT_S = 30.0 + +# Source of the ``id`` sent with every request. xrpld echoes a request's id at +# the top level of the reply, which is what lets ws_request tell its own reply +# from one that an earlier, timed-out request left in the receive buffer. +_request_ids = itertools.count(1) + def consumes_sequence(engine_result: str | None) -> bool: """Report whether an engine result tied up the submitted sequence number. @@ -243,14 +252,49 @@ async def ws_request( The inner ``result`` dict from the response. Raises: - RuntimeError: If the request fails or times out. + TimeoutError: If no reply carrying this request's ``id`` arrived within + RECV_TIMEOUT_S. """ + request_id = next(_request_ids) request: dict[str, Any] = {"command": command} if params: request.update(params) + # Set after the merge so a caller's parameter can never shadow the id. + request["id"] = request_id await ws.send(json.dumps(request)) - raw = await asyncio.wait_for(ws.recv(), timeout=30.0) - resp = json.loads(raw) + + # Read until the reply carrying this request's id turns up. Cancelling a + # recv() does not discard the reply it was waiting for: the library queues + # incoming messages independently of any reader, so a request that timed + # out leaves its reply in the buffer and the NEXT request used to read it + # instead of its own. That mis-attribution is permanent, because every + # later request on the connection stays one reply behind: a submit would + # read an account_info reply, see no engine result, and stop advancing the + # account's sequence, failing every remaining transaction for a reason + # nothing logged. Discarding by id puts the stream back in step. + # + # The deadline is for the whole exchange rather than per message, so a run + # of buffered replies cannot extend the wait without bound. A reply with no + # id is accepted as this request's: a few xrpld error paths answer before + # the id is parsed, and treating those as stale would hide a real error. + deadline = time.monotonic() + RECV_TIMEOUT_S + while True: + remaining = deadline - time.monotonic() + if remaining <= 0: + raise TimeoutError(f"{command} (id {request_id}) got no reply") + raw = await asyncio.wait_for(ws.recv(), timeout=remaining) + resp = json.loads(raw) + reply_id = resp.get("id") + if reply_id is None or reply_id == request_id: + break + _log_first_failure( + "stale-reply", + "Discarded a reply for id %s while awaiting id %s (%s); an earlier " + "request timed out and left it buffered", + reply_id, + request_id, + command, + ) # WS command format: {"status": "success", "result": {...}, "type": "response"} # On error: {"status": "error", "error": "...", "error_message": "..."} diff --git a/docker/telemetry/workload/validate_telemetry.py b/docker/telemetry/workload/validate_telemetry.py index f193f2975e..6e1f350785 100644 --- a/docker/telemetry/workload/validate_telemetry.py +++ b/docker/telemetry/workload/validate_telemetry.py @@ -300,6 +300,23 @@ def _log_query_window() -> dict[str, str]: } +class TempoQueryError(RuntimeError): + """Tempo answered a query with a failure, as distinct from "nothing found". + + The two must not be conflated. An empty search result and a 404 on a trace + id are legitimate answers meaning the data is not there; an HTTP 5xx, a 401 + or a 400 mean the question was never answered, and reporting that as "0 + traces" or "0 spans" turns a broken backend into a green-looking negative + result. Callers that loop over candidates catch absence and move on; this + exception is what they must NOT swallow. + """ + + +def _short_body(text: str, limit: int = 300) -> str: + """Collapse a response body to one bounded line, for a log or a message.""" + return " ".join(text.split())[:limit] or "(empty body)" + + async def _tempo_search( session: aiohttp.ClientSession, tempo_url: str, @@ -319,6 +336,19 @@ async def _tempo_search( """ params = {"q": query, "limit": str(limit)} async with session.get(f"{tempo_url}/api/search", params=params) as resp: + # /api/search answers 200 with an empty (or absent) "traces" list when + # nothing matches, so there is no "legitimately absent" status to + # tolerate here: every non-200 is a real failure. Left unchecked, + # resp.json() on an error body yields a dict with no "traces" key and + # this returns [], which every caller reports as "no traces found" -- + # indistinguishable from a healthy Tempo holding nothing. That is the + # same silent-failure shape as a span query that returned 200 with an + # empty list, and it must not be reproduced here. + if resp.status != 200: + raise TempoQueryError( + f"GET /api/search returned HTTP {resp.status}: " + f"{_short_body(await resp.text())}" + ) data = await resp.json() return data.get("traces", []) @@ -337,10 +367,36 @@ async def _tempo_get_trace( tempo_url: Tempo API base URL. trace_id: Hex trace ID string. + A 404 means Tempo holds no such trace, which is returned as an empty list + rather than raised: see the note in the body. Any other non-200 raises + TempoQueryError. + Returns: - Flat list of span dicts with 'name' and 'attributes' keys. + Flat list of span dicts with 'name' and 'attributes' keys. Empty when + Tempo has no trace with this id. + + Raises: + TempoQueryError: Tempo answered with a status other than 200 or 404. """ async with session.get(f"{tempo_url}/api/traces/{trace_id}") as resp: + # 404 is Tempo's answer for "no trace with that id", and for an id read + # out of a log line that is an ordinary outcome, not an error: the span + # may not have been exported yet, or its block may not be searchable. + # Every caller either loops over candidate ids or over several traces + # and relies on an empty list meaning "not this one", so a 404 must stay + # absent -- raising here would turn a normal miss into a check failure + # and abort the loop over the remaining candidates. + if resp.status == 404: + return [] + # Anything else is a real failure. Unchecked, resp.json() on an error + # body yields a dict with no "batches" key, so this returned [] and the + # caller reported "0 spans" -- a backend fault laundered into a + # negative result. + if resp.status != 200: + raise TempoQueryError( + f"GET /api/traces/{trace_id} returned HTTP {resp.status}: " + f"{_short_body(await resp.text())}" + ) data = await resp.json() spans: list[dict[str, Any]] = [] for batch in data.get("batches", []): @@ -1585,6 +1641,20 @@ async def _loki_json( """ try: async with session.get(f"{loki_url}{path}", params=params or {}) as resp: + if resp.status != 200: + # Loki reports a rejected query as text/plain, so resp.json() + # would raise ContentTypeError and the log would carry a + # mimetype complaint instead of Loki's own explanation. Read + # the body and print it: a diagnostic that swallows the + # server's reason is worse than no diagnostic. + body = " ".join((await resp.text()).split()) + logger.warning( + "Loki diagnostic: GET %s returned HTTP %d: %s", + path, + resp.status, + body[:500] or "(empty body)", + ) + return None return await resp.json() except Exception as exc: # noqa: BLE001 - diagnostic must never raise logger.warning("Loki diagnostic: GET %s failed: %s", path, exc) @@ -1658,11 +1728,23 @@ async def _log_loki_diagnostics(session: aiohttp.ClientSession, loki_url: str) - "Loki diagnostic: service_name values: %s", ", ".join(found) or "(none)" ) + # sum() is load-bearing, not cosmetic. The filelog receiver's regex_parser + # leaves message, timestamp, trace_id and span_id as log-record attributes, + # and Loki's OTLP path stores those as structured metadata, which joins the + # label set of a metric query. Because `message` and `timestamp` are unique + # per line, an unaggregated count_over_time returns ONE SERIES PER LOG LINE + # and blows past limits_config.max_query_series (500) at a few hundred + # lines: Loki answers HTTP 400 "maximum number of series (500) reached for + # a single query", both legs report "unavailable", and the diagnostic loses + # the one distinction it exists to draw. Aggregating collapses the result to + # a single series regardless of line count. An empty result still decodes to + # 0, so the deliberate "0 entries" versus "could not answer" split above is + # preserved. for label, query in ( - ("selector only", f"count_over_time({LOG_STREAM_SELECTOR}{window})"), + ("selector only", f"sum(count_over_time({LOG_STREAM_SELECTOR}{window}))"), ( "selector + line filter", - f"count_over_time({LOG_CORRELATION_QUERY} {window})", + f"sum(count_over_time({LOG_CORRELATION_QUERY} {window}))", ), ): total = await _loki_count(session, loki_url, query) @@ -1675,6 +1757,71 @@ async def _log_loki_diagnostics(session: aiohttp.ClientSession, loki_url: str) - ) +async def _poll_tempo_for_logged_ids( + session: aiohttp.ClientSession, + tempo_url: str, + unique_ids: list[str], +) -> tuple[str | None, int, int, str | None]: + """Resolve one of ``unique_ids`` in Tempo, retrying until a deadline. + + Every id is tried on each pass, not just the first: one unexported trace + must not fail the check while correlation demonstrably works for another. + + The pass is then repeated until the shared poll window closes, because a + trace id reaches a log line the instant its span is created but only becomes + queryable after the exporter batches it, Tempo ingests it and its block is + searchable. A single pass therefore races that pipeline exactly the way the + metric checks used to race the export-plus-scrape pipeline, and it is fixed + the same way -- with METRIC_POLL_TIMEOUT_SEC and METRIC_POLL_INTERVAL_SEC, + the constants that already bound every other poll in this file, rather than + a second timeout of its own. + + Retrying does not weaken the assertion. The check still passes only on a + logged id that Tempo really returns spans for; what changes is that a + failure now means the id was absent for the whole window, which is a + confirmed absence rather than a snapshot taken at one moment. + + A Tempo request that FAILS is not the same as a trace that is absent, and + the two are reported differently. A 404 is absence and returns no spans, so + the next candidate is tried. Any other failure is remembered and polling + continues -- a transient blip mid-window should not fail a check that would + otherwise pass -- but if the window closes with nothing resolved, the last + failure is returned so the caller can say the query broke instead of + claiming the spans were never exported. Swallowing it would reproduce the + silent failure this change exists to remove. + + Args: + session: aiohttp client session. + tempo_url: Base URL for the Tempo API. + unique_ids: Candidate trace ids read from Loki, already deduplicated. + + Returns: + ``(trace_id, span_count, attempts, error)``. ``error`` is None unless a + Tempo request failed and nothing resolved; ``(None, 0, n, None)`` means + every id was genuinely absent for the whole window. + """ + deadline = time.monotonic() + METRIC_POLL_TIMEOUT_SEC + attempts = 0 + last_error: str | None = None + while True: + attempts += 1 + for candidate in unique_ids: + try: + spans = await _tempo_get_trace(session, tempo_url, candidate) + except Exception as exc: # noqa: BLE001 - a poll must not abort here + last_error = f"{type(exc).__name__}: {exc}" + continue + if spans: + # Resolved, so whatever failed earlier in the window did not + # matter -- do not report a stale error alongside a pass. + return candidate, len(spans), attempts, None + remaining = deadline - time.monotonic() + if remaining <= 0: + return None, 0, attempts, last_error + # Never sleep past the deadline, matching _poll_series_count. + await asyncio.sleep(min(METRIC_POLL_INTERVAL_SEC, remaining)) + + async def validate_log_trace_correlation( session: aiohttp.ClientSession, loki_url: str, @@ -1778,36 +1925,45 @@ async def validate_log_trace_correlation( ) ) else: - # Try every id found, not just the first: one unexported trace - # should not fail the check while correlation demonstrably works. - resolved: str | None = None - span_count = 0 unique_ids = list(dict.fromkeys(logged_ids)) - for candidate in unique_ids: - try: - spans = await _tempo_get_trace(session, tempo_url, candidate) - except Exception: # noqa: BLE001 - a 404 is "not found", not an error - continue - if spans: - resolved, span_count = candidate, len(spans) - break - + resolved, span_count, attempts, poll_error = ( + await _poll_tempo_for_logged_ids(session, tempo_url, unique_ids) + ) + if resolved: + message = ( + f"logged trace_id {resolved[:16]}... resolves to " + f"{span_count} spans in Tempo" + ) + elif poll_error: + # Distinct from the absence message below on purpose: "Tempo + # never answered" and "the spans were not exported" call for + # different investigations, and printing the second for the + # first sends the reader to the wrong subsystem. + message = ( + f"could not verify {len(unique_ids)} logged trace_id(s): " + f"Tempo queries failed over {METRIC_POLL_TIMEOUT_SEC:g}s " + f"({attempts} attempt(s)); last error was {poll_error}" + ) + else: + message = ( + f"none of {len(unique_ids)} logged trace_id(s) resolve in " + f"Tempo after {attempts} attempt(s) over " + f"{METRIC_POLL_TIMEOUT_SEC:g}s; the spans they name were " + "not exported" + ) report.add( CheckResult( name="log.trace_id_cross_reference", category="log", passed=resolved is not None, - message=( - f"logged trace_id {resolved[:16]}... resolves to " - f"{span_count} spans in Tempo" - if resolved - else f"none of {len(unique_ids)} logged trace_id(s) resolve in " - "Tempo; the spans they name were not exported" - ), + message=message, details={ "trace_id": resolved, "span_count": span_count, "candidates": len(unique_ids), + "poll_attempts": attempts, + "poll_timeout_sec": METRIC_POLL_TIMEOUT_SEC, + "poll_error": poll_error, }, ) ) diff --git a/docker/telemetry/workload/workload_orchestrator.py b/docker/telemetry/workload/workload_orchestrator.py index 5978c28e20..f17a33eef5 100755 --- a/docker/telemetry/workload/workload_orchestrator.py +++ b/docker/telemetry/workload/workload_orchestrator.py @@ -356,6 +356,15 @@ def _launch_phase_tasks( Each generator is given the phase duration plus SUBPROCESS_GRACE_SEC, so a wedged one is killed instead of stalling the phase. + Any report left at a path this phase is about to use is deleted first. + report_dir defaults to a fixed location and the filenames are derived from + the phase index and name, so consecutive runs of a profile reuse the same + paths. Without the delete, a generator that produced no report this run + left the previous run's file in place, and _collect_task_result read it as + this run's result — which also breaks the assumption evaluate_exit_gate + documents, that a crashed generator leaves its totals at 0. Afterwards a + present file always belongs to this run and a missing one is unambiguous. + Args: phase: Phase dict from the profile. endpoints: List of WebSocket endpoint URLs. @@ -374,6 +383,7 @@ def _launch_phase_tasks( rpc_cfg = phase.get("rpc") if rpc_cfg: rpc_out = report_dir / f"{prefix}-rpc.json" + rpc_out.unlink(missing_ok=True) cmd = _build_rpc_cmd(endpoints, rpc_cfg, duration, rpc_out) task = asyncio.create_task(run_subprocess(cmd, f"RPC [{name}]", timeout)) tasks.append(("rpc", rpc_out, task)) @@ -381,6 +391,7 @@ def _launch_phase_tasks( tx_cfg = phase.get("tx") if tx_cfg: tx_out = report_dir / f"{prefix}-tx.json" + tx_out.unlink(missing_ok=True) cmd = _build_tx_cmd(endpoints[0], tx_cfg, duration, tx_out) task = asyncio.create_task(run_subprocess(cmd, f"TX [{name}]", timeout)) tasks.append(("tx", tx_out, task)) @@ -583,7 +594,7 @@ def parse_args() -> argparse.Namespace: formatter_class=argparse.RawDescriptionHelpFormatter, epilog=""" Profiles: - full-validation Full 18-dashboard coverage (~5 min load + 1 min propagation) + full-validation Full 15-dashboard coverage (~5 min load + 1 min propagation) quick-smoke Fast CI smoke test (~30s load + 30s propagation) stress Heavy sustained load for benchmarking (~3.5 min + 1 min) diff --git a/docs/telemetry-runbook.md b/docs/telemetry-runbook.md index daa27ef0e2..bbcd0613b3 100644 --- a/docs/telemetry-runbook.md +++ b/docs/telemetry-runbook.md @@ -4757,27 +4757,48 @@ Key properties: `baseline-timings.json` obliges you to re-derive these bounds** — a value that moves into a different bucket gets a different `hi_next` — and `.github/scripts/telemetry/check_regression_bounds.py` fails CI if you do not. -- **A single flat bound cannot work here.** The gated quantiles span 0.078 ms to - 17 ms, so one figure is inert at the bottom of that range and trigger-happy at +- **A single flat bound cannot work here.** The gated quantiles span 0.006 ms to + 21 ms, so one figure is inert at the bottom of that range and trigger-happy at the top. The flat 10/15 ms span bound it replaced sat 1.15x to 2000x above the metric it guarded, and a 10x regression injected into each key in turn was caught on only 5 of 28. - **The detection floor is `hi_next / baseline`, so some keys are only weakly - guarded.** It ranges 2.02x to 9.42x over the current baseline; - `span.ledger.build.p50` is effectively not guarded at 9.4x. - `baselines/README.md` lists all nine weak keys and the ladder edges that would - fix them. + guarded.** It ranges 2.21x to 16.28x over the current baseline; + `job.acceptLedger.running.p95` is effectively not guarded at 16.3x, and is the + one gated key a 10x regression does not catch (it first fires at 16.28x; at 20x + the sweep catches 20 of 20). `baselines/README.md` lists all seven weak keys, + the limiting ladder step for each, and the edges that would fix them. +- **A baseline refresh can silently move sensitivity in either direction.** The + trip point is derived from the baseline, so a refresh that lands at the low end + of a metric's range tightens the gate and one that lands high loosens it. The + 2026-08-26 refresh took `job.acceptLedger.running.p95` from a 5.74x floor to + 16.28x — it does not fire on any observed run, so it stays gated, but the weak + floor is recorded rather than left to surprise someone. The same refresh put + three `p50` keys below the spread they need, and they are now excluded (below). + `baselines/README.md` carries the measurements. - **The bound covers quantization noise only, so a key whose run-to-run variance - exceeds it cannot be gated.** `span.ledger.validate.p95` and `.p99` are - excluded for exactly that reason — measured spreads of 5.9x and 66.8x across - four CI runs, both reaching past their trip points on healthy runs, because - the span's duration follows peer-validation arrival timing rather than code - speed. Widening their bounds would gate nothing, so they are listed in - `excluded_keys` in `regression-metrics.json` and `check_regression_bounds.py` - rule F keeps that exclusion honest. Before gating any key, check its observed - maximum across runs against `baseline + bound`; see `baselines/README.md`. + exceeds it cannot be gated. Five keys are excluded for that reason**, leaving + 20 gated. `span.ledger.validate.p95` and `.p99` came first — spreads of 5.9x + and 66.8x across four CI runs, both reaching past their trip points on healthy + runs, because the span's duration follows peer-validation arrival timing rather + than code speed. The 2026-08-26 refresh added `span.tx.apply.p50`, + `span.ledger.build.p50` and `span.consensus.ledger_close.p50`, whose observed + maxima sit 46.76x, 4.77x and 2.38x above their new trip points. That is the + same rule applied, not a new exception: the decisive evidence is that + `span.tx.apply.p50` read 0.7917 ms in the previous baseline and 0.00597 ms in + this one — 132x apart on the same workload — so whether the gate worked was + decided by where in its own distribution the captured run fell, not by the + code. All five share one shape: the observed maximum exceeds + `baseline + bound`, four of them because a low-bucket baseline yields a tiny + bound. Widening gates nothing and re-baselining until a run lands high is the + trap; **a multi-run baseline, or a spread measurement captured alongside it, is + what would let them be gated again** — not implemented, and the reason these + exclusions stand. They are listed with their measurements in `excluded_keys` in + `regression-metrics.json`, and `check_regression_bounds.py` rule F keeps each + entry honest. Before gating any key, check its observed maximum across runs + against `baseline + bound`; see `baselines/README.md`. - **For every currently gated metric the absolute bound decides; the percentage - bound does not.** Measured, the bound is 102%-842% of its own baseline, above + bound does not.** Measured, the bound is 121%-1528% of its own baseline, above both configured percentage bounds. This is _not_ a general property: the span ladder's top steps are only 1.25x-1.5x apart, so a baseline between about 2667-3000 ms or 3334-4000 ms gets an absolute bound worth under 50% of itself @@ -4866,6 +4887,23 @@ container as the main CI, so Conan and ccache hit the shared caches), and log-record counters, and Loki's entry counts for the stream selector with and without the line filter. The diagnostics are non-fatal by construction: each leg is isolated and a missing container or unreachable endpoint prints a note. + Those two Loki entry counts are `sum(count_over_time(...))`, and the `sum()` is + load-bearing: the `filelog` receiver leaves `message` and `timestamp` as + log-record attributes, Loki's OTLP path stores them as structured metadata, and + structured metadata joins a metric query's label set — so an unaggregated + `count_over_time` produces one series per log line and Loki answers `HTTP 400 +maximum number of series (500) reached`. Unaggregated, both legs printed + `unavailable` on runs `32877465763` and `32964262700` and the block + distinguished nothing. A rejected query now logs its HTTP status and Loki's own + plain-text explanation rather than a JSON-mimetype error. + `log.trace_id_cross_reference` polls Tempo for up to `METRIC_POLL_TIMEOUT_SEC` + before failing, so a logged id that Tempo has not yet indexed is retried rather + than reported absent. It also separates a failed Tempo query from a genuinely + absent trace: a 404 on `/api/traces/` is absence and moves to the next + candidate, while any other non-200 raises `TempoQueryError` and is reported as + "could not verify" rather than "not exported". Both Tempo helpers previously + passed an error body straight to `resp.json()`, so a JSON 5xx read as zero + spans or zero traces. `docker/telemetry/integration-test.sh` (which has its own `check_log_correlation()`) is still run by no workflow. - **Inputs**: only `run_benchmark` changes behaviour. `rpc_rate`, `rpc_duration`,