diff --git a/docker/telemetry/workload/baselines/README.md b/docker/telemetry/workload/baselines/README.md index 75a75c2561..29f627deee 100644 --- a/docker/telemetry/workload/baselines/README.md +++ b/docker/telemetry/workload/baselines/README.md @@ -27,24 +27,35 @@ 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: 20 metrics gate, on a baseline captured 2026-08-26 +## Current state: 19 metrics gate, on a baseline captured 2026-09-10 -`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's 1 ms floor, 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 -stale-high baseline passes everything silently, so the entries had to be dropped rather than left -in place. They stay retrievable from this file's git history. +`baseline-timings.json` holds real captured values for the 19 keys the harness gates. Every value is +the **median of three clean CI runs** — `34495527952`, `34505215266` and `34507425933` — taken at +`a0385c53cb`, profile `full-validation`, window `3m`. The file records that provenance itself, in +its `source_runs` and `statistic` fields. + +The median of three is the point, not a detail. A single-run baseline is what disqualified five of +the six excluded keys below: one sample carries no information about spread, and the bound is +derived from that one sample alone. + +It replaced a capture taken 2026-08-26, before the account-funding race was fixed. Phases whose +funding silently failed submitted little or no traffic, so that capture recorded artificially low +ledger and transaction timings. Once funding worked, `span.ledger.build.p99` read 29.00 ms against +its 9.109 ms baseline and turned the gate red on a run whose 200 span and metric checks all passed +— which is why that key is now excluded. + +Two earlier generations stay retrievable from this file's git history: a 2026-08-24 capture, and +before it entries captured 2026-06-05 that were voided into a placeholder because they were captured +against the spanmetrics ladder's old 1 ms floor, 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 stale-high baseline +passes everything silently, so those entries had to be dropped rather than left in place. **A placeholder must not outlive one run.** CI stays green the whole time one stands, so an un-copied block is not a failure anyone will notice — it is a silent loss of regression coverage -that looks identical to a passing gate. Voiding a baseline is the one hand edit this file allows; -_setting_ one always comes from a printed CI block, per the "Refreshing the baseline" rule below. +that looks identical to a passing gate. Voiding a baseline is the one hand edit that needs no CI +block behind it. Setting one comes from a printed CI block, with a single documented exception — +combining several runs into a median, which nothing automates yet (see [Schema](#schema)). ## Absolute bounds are derived per metric, from the ladder @@ -61,8 +72,8 @@ fire. Firing needs the quantile to have moved at least two buckets up. A multipl _enclosing_ bucket's width cannot deliver this, because once the quantile crosses `hi` the interpolation happens across the **next** bucket, which on this ladder is up to 8x wider — `(0.5, 1]` is 0.5 ms wide and `(1, 5]` is 4 ms wide. The full derivation, both ladders, and a -per-key table of the arithmetic are in that file's `_absolute_bound_derivation` and -`_derivation_table`. +per-key table of the arithmetic are in that file's `_absolute_bound_derivation`, +`_bucket_note` (both ladders) and `_derivation_table`. Two earlier generations of this bound were wrong, in opposite directions: @@ -70,17 +81,24 @@ 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 | 19 / 20 keys | **0 / 20 keys** | +| `hi_next − baseline` (current) | per metric | **19 / 19 keys** | **0 / 19 keys** | -The first two rows were measured when 28 and 25 keys were gated; the current row was re-measured -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 +The first two rows were measured when 28 and 25 keys were gated, by injecting a 10x regression into +each gated key in turn against a real CI `timings.json`. The current row is **derived, not sampled**, +and holds for every key on the 2026-09-10 baseline. A key's detection floor is exactly +`trip point ÷ baseline`, because the gate fires when the reading exceeds the trip point and a `k`x +regression reads `k × baseline`. So a 10x regression is caught precisely when the floor is under 10x, +and the weakest floor on this baseline is 7.41x — see +[weakly guarded](#which-keys-are-only-weakly-guarded) below. + +That is a real improvement over the 2026-08-26 baseline, where `job.acceptLedger.running.p95` had a +16.28x floor and was the one key a 10x regression missed. Its baseline rose from 6142.9 us to +15967.7 us while `hi_next` stayed at 100000 us, which pulled its floor down to 6.26x. Note the +direction this can move in: floors are a property of where each baseline lands on the ladder, so a +refresh changes sensitivity without anything about the code changing. Re-derive this table on every +refresh. + +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 @@ -105,30 +123,34 @@ signature described below. ### Which keys are only weakly guarded 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.21x to 16.28x. Do **not** read these as guarded: +`hi_next / baseline`, so a baseline sitting just above an edge is guarded loosely. Over the +2026-09-10 baseline the floor ranges 2.00x to 7.41x. Do **not** read these six as guarded: -| 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 | +| key | baseline | fires at | floor | limiting ladder step | +| --------------------------------- | ---------- | --------- | ----- | -------------------- | +| `span.consensus.ledger_close.p95` | 0.6750 ms | 5 ms | 7.41x | 1 ms → 5 ms | +| `span.consensus.accept.p50` | 1.4364 ms | 10 ms | 6.96x | 5 ms → 10 ms | +| `job.acceptLedger.running.p95` | 15967.7 us | 100000 us | 6.26x | 25000 us → 100000 us | +| `span.rpc.ws_message.p95` | 0.8122 ms | 5 ms | 6.16x | 1 ms → 5 ms | +| `span.rpc.ws_message.p99` | 0.9873 ms | 5 ms | 5.06x | 1 ms → 5 ms | +| `span.tx.process.p99` | 0.9940 ms | 5 ms | 5.03x | 1 ms → 5 ms | -`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 +Four of the six are limited by the same `1 ms → 5 ms` step, which is where this ladder is coarsest +relative to how the spans actually behave. None of the six fires on any observed run, so all six +stay gated; 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. +`job.transaction.running.p95` and `span.tx.process.p95` were on this list against the 2026-08-26 +baseline, at 8.33x and 8.20x, and both dropped off it in the refresh — 2.65x and 2.00x now. +`span.tx.process.p95` is the tightest gated key on this baseline — 0.50 on baseline over trip point, +and 0.76 on the observed maximum across the three source runs — so it is the first to re-measure if +the gate reddens. The two ratios have different numerators; neither is the other. + `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 +[what all six excluded keys have in common](#what-all-six-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 @@ -165,13 +187,15 @@ exclusion at _quantile_ rather than _span_ granularity, which is why lists span names and `_quantiles` is shared across all of them, so removing two quantiles of one span cannot be expressed by deleting a name. -Measured across four CI runs: +Measured across four CI runs, against the baseline in force **when the two keys were excluded**. +The `p50` row is the only one still gated. Its baseline was 0.0779 ms then and is 0.0598 ms now, with +the same 0.25 ms trip point either way, so the argument is unchanged: -| key | baseline | trip point | observed min | observed max | spread | -| --------------------------------- | --------- | ---------- | ------------ | ------------ | ------ | -| `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 | +| key | baseline at exclusion | 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.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 | Both excluded quantiles reach past their trip point on an ordinary run, so CI reddened twice with no code change: run `32867433073` read `p95` = 0.7500 ms (+212%) and run `32862589645` read @@ -206,9 +230,9 @@ proves nothing; it is spread **relative to the trip point** that decides. And be 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 happened to three `p50` keys on this baseline, and **all three are 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): +That is what happened to three `p50` keys on the **2026-08-26** baseline, and **all three are +excluded** — this rule being applied, not a new exception. Measured across the three CI runs +`32862589645`, `32867433073` and `32964262700` (the last of which produced that baseline): | key | bound | trip point | observed max | max ÷ trip | spread | | --------------------------------- | --------- | ---------- | ------------ | ---------- | ------ | @@ -216,15 +240,15 @@ this rule being applied, not a new exception. Measured across the three CI runs | `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 +Before the exclusion, replaying **either** older run against that 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. +2026-08-24 baseline and **0.00597 ms** in the 2026-08-26 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. @@ -232,9 +256,12 @@ 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`. +19 gated keys sit between 0.14 and 0.50 of their **baseline** over their trip point, the tightest +being `span.tx.process.p95` at 0.50. That ratio is derivable from the two committed JSON files, so it +is checkable; a headroom figure against each key's observed maximum is not, because no per-run +`timings.json` is committed. -### What all five excluded keys have in common +### What all six excluded keys have in common | key | trip point | observed max | mechanism | | --------------------------------- | ---------- | ------------ | ------------------------------------- | @@ -243,19 +270,29 @@ lands favourably. A key that fails this test is never fixed by widening its boun | `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 | +| `span.ledger.build.p99` | 25 ms | 29.0000 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 +One invariant covers all six: **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 six 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 distance to the next edge up. The other two fail despite generous bounds: +`ledger.validate.p99` has 8.94 ms and a 66.8x spread that reaches 25.875 ms against a 10 ms trip +point, and `ledger.build.p99` has 16.056 ms and a 4.11x spread whose maximum is 1.16x its 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. +`span.ledger.build.p99` is the newest of the six and the clearest illustration of the rule, because +the previous baseline **hid** it: at 9.109 ms the same rule also gave a 25 ms trip point, and the key +read as gated only because both the capture and the comparison runs happened to land low. Ledger +construction keeps coverage through `span.ledger.build.p95`, whose baseline sits at 0.48 of its trip +point. + +**The follow-up that would restore coverage**, stated rather than left implied: a bound derived from +the ladder alone cannot support these keys, because it carries no information about spread. What +would let them be gated again is a bound sized against **observed variance** — a spread measurement +captured alongside the baseline, rather than the ladder distance only. The 2026-09-10 baseline is +already a median of three runs, which is the raw material for that; using the spread to size bounds +is the part that is not implemented, and it is the design change these six exclusions are waiting +on. ## Bootstrapping the baseline @@ -346,9 +383,11 @@ debug-level detail, enable it per partition **after** the baseline exists. "window": "3m", "git_sha": "", "profile": "", + "source_runs": [34495527952, 34505215266, 34507425933], + "statistic": "median of three clean full-validation runs", "capture": { - "declared": 20, - "captured": 20, + "declared": 19, + "captured": 19, "min_ratio": 0.5, "complete": true }, @@ -359,6 +398,21 @@ debug-level detail, enable it per partition **after** the baseline exists. } ``` +`source_runs` and `statistic` record how the numbers were arrived at, and the committed baseline +carries both. They matter because the bound-derivation rule reads the baseline as a single number: +if `statistic` says the values are a median of several runs, a reviewer knows the spread was +observable, and if it is absent the baseline came from one run and every key on it is exposed to the +single-run problem described under +[The general rule this exposed](#the-general-rule-this-exposed). Neither field is read by any +script; they are provenance, like `git_sha`. + +`capture_timings.py` emits neither field, and no script in this directory combines several runs, so +a multi-run baseline is currently assembled by hand and these two fields are how that is declared. +That is a gap, not a workflow: it sits outside the paste-from-CI rule the rest of this file +describes, so the median and the run ids are only as trustworthy as the PR that introduced them. +Automating the combination — and having it write both fields — is part of the multi-run baseline work +the exclusions are waiting on. + `capture` describes the capture that produced the file, not the metrics in it: `declared` is how many keys the surface asked for, `captured` how many came back with a value, `min_ratio` the bar they were judged against, and `complete` the verdict. It is a diff --git a/docker/telemetry/workload/benchmark.sh b/docker/telemetry/workload/benchmark.sh index 7035a2bc43..7847687fb9 100755 --- a/docker/telemetry/workload/benchmark.sh +++ b/docker/telemetry/workload/benchmark.sh @@ -86,6 +86,14 @@ PEER_PORT_BASE=51250 # Above run-full-validation.sh's 6006.. so both harnesses can share a box. WS_PORT_BASE=6020 +# Name stem of each node's directory: node i lives in $WORKDIR/$NODE_PREFIX-$i. +# Every node path and kill pattern below derives from it, and so does the +# service_instance_id the telemetry arm reports. The telemetry arm exports to the +# same endpoint the workload harness uses, so a stem that differs from that +# harness's is what keeps the two clusters apart in the backend. Deriving both +# from one value is what stops the directory and the reported id drifting. +NODE_PREFIX="bench-node" + # Head start the generators get before the sampler opens its window. # tx_submitter.py creates and funds eight accounts from genesis and then waits # for those payments to validate, so without a lead the first seconds of every @@ -148,6 +156,19 @@ done # Validate prerequisites. A missing binary or tool means no measurement can be # taken, which is "cannot measure", not "too slow". +# Validate the two numeric options before anything derives ports, loop counts or +# pid-count guards from them. --nodes 0 is the dangerous one: node_pids_csv then +# yields an empty list, awk reports 0 fields, and the "found N of NUM_NODES pids" +# guard compares 0 with 0 and passes, handing the sampler no pids at all. +case "$NUM_NODES" in + '' | *[!0-9]*) cannot_measure "--nodes must be a positive integer, got '$NUM_NODES'" ;; +esac +[ "$NUM_NODES" -ge 1 ] || cannot_measure "--nodes must be at least 1, got '$NUM_NODES'" +case "$DURATION" in + '' | *[!0-9]*) cannot_measure "--duration must be a positive integer, got '$DURATION'" ;; +esac +[ "$DURATION" -ge 1 ] || cannot_measure "--duration must be at least 1, got '$DURATION'" + [ -x "$XRPLD" ] || cannot_measure "xrpld not found at $XRPLD" command -v jq >/dev/null 2>&1 || cannot_measure "jq not found" command -v bc >/dev/null 2>&1 || cannot_measure "bc not found" @@ -189,7 +210,7 @@ start_cluster() { # Build per-node configs. for i in $(seq 1 "$NUM_NODES"); do - local node_dir="$WORKDIR/bench-node-$i" + local node_dir="$WORKDIR/$NODE_PREFIX-$i" mkdir -p "$node_dir/nudb" "$node_dir/db" || cannot_measure "Could not create node$i directories under $node_dir" @@ -227,7 +248,7 @@ start_cluster() { telemetry_section=" [telemetry] enabled=1 -service_instance_id=bench-node-${i} +service_instance_id=$NODE_PREFIX-${i} endpoint=http://localhost:4318/v1/traces exporter=otlp_http batch_size=512 @@ -251,10 +272,10 @@ endpoint=http://localhost:4318/v1/metrics" enabled=0" fi - # No `|| cannot_measure` here: a guard after `<"$node_dir/xrpld.cfg" <"$node_dir/xrpld.cfg" </dev/null || true fi done - # Belt and braces for a node whose pidfile is missing or stale. Matched on - # the per-node config path — the shape start_cluster launches nodes with - # (`--conf $WORKDIR/nodeN/xrpld.cfg`) — rather than on the workdir alone. - # The loose form killed anything whose command line merely mentioned the - # workdir, including a developer's `tail -f $WORKDIR/node1/debug.log`, and - # the EXIT trap now makes this run on every exit path. - pkill -f "$WORKDIR/node[0-9]+/xrpld\.cfg" 2>/dev/null || true + # Belt and braces for a node whose pidfile is missing or stale. Matched on the + # per-node config path start_cluster launches with, not the workdir alone: a + # workdir-only pattern would also match anything that merely mentions the + # tree, such as a developer's `tail -f` on a node's debug.log. + pkill -f "$WORKDIR/$NODE_PREFIX-[0-9]+/xrpld\.cfg" 2>/dev/null || true # Guarded on purpose. This runs as the EXIT trap, where any unguarded # failure makes `set -e` exit with that command's status and discard the @@ -384,12 +403,6 @@ stop_cluster() { return 0 } -# Reap the cluster on every exit path. Installed here rather than straight -# after argument parsing so the handler name always resolves. Without it, any -# failure between start_cluster and stop_cluster leaks the xrpld children -# along with their RPC ports (5020+) and peer ports (51250+). -trap 'stop_workload; stop_cluster' EXIT - # Build RPC ports CSV string. rpc_ports_csv() { local ports="" @@ -422,7 +435,7 @@ ws_endpoints() { node_pids_csv() { local i out="" pid for i in $(seq 1 "$NUM_NODES"); do - pid=$(cat "$WORKDIR/bench-node-$i/xrpld.pid" 2>/dev/null) || continue + pid=$(cat "$WORKDIR/$NODE_PREFIX-$i/xrpld.pid" 2>/dev/null) || continue [ -n "$pid" ] && out="$out,$pid" done printf '%s' "${out#,}" @@ -485,6 +498,14 @@ stop_workload() { return 0 } +# Reap the workload and the cluster on every exit path. Installed below both +# handlers, not after argument parsing: if the trap fires while either name is +# still undefined, errexit aborts the handler on "command not found" and the +# rest of it -- the cluster reap -- never runs. Without the trap, any failure +# between start_cluster and stop_cluster leaks the xrpld children along with +# their RPC ports (5020+) and peer ports (51250+). +trap 'stop_workload; stop_cluster' EXIT + collect_metrics() { local label="$1" local out_file="$2" @@ -548,26 +569,31 @@ INCONCLUSIVE="n/a" read_metric() { local file="$1" local key="$2" - jq -r ".$key // 0" "$file" + # jq exits 5 on malformed JSON and 2 on a missing file. Neither is one of + # this script's three documented codes, and a bare assignment would let it + # escape through errexit, so route both through cannot_measure. + jq -r ".$key // 0" "$file" 2>/dev/null || + cannot_measure "$file is not readable JSON — refusing to compare an unreadable run" } BASE_CPU=$(read_metric "$BASELINE_FILE" "cpu_pct_avg") TELE_CPU=$(read_metric "$TELEMETRY_FILE" "cpu_pct_avg") -CPU_DELTA=$(echo "scale=2; $TELE_CPU - $BASE_CPU" | bc 2>/dev/null || echo "0") +CPU_DELTA=$(echo "scale=2; $TELE_CPU - $BASE_CPU" | bc 2>/dev/null || echo "$INCONCLUSIVE") BASE_MEM=$(read_metric "$BASELINE_FILE" "memory_rss_mb_peak") TELE_MEM=$(read_metric "$TELEMETRY_FILE" "memory_rss_mb_peak") -MEM_DELTA=$(echo "scale=2; $TELE_MEM - $BASE_MEM" | bc 2>/dev/null || echo "0") +MEM_DELTA=$(echo "scale=2; $TELE_MEM - $BASE_MEM" | bc 2>/dev/null || echo "$INCONCLUSIVE") BASE_RPC=$(read_metric "$BASELINE_FILE" "rpc_p99_ms") TELE_RPC=$(read_metric "$TELEMETRY_FILE" "rpc_p99_ms") -RPC_DELTA=$(echo "scale=2; $TELE_RPC - $BASE_RPC" | bc 2>/dev/null || echo "0") +RPC_DELTA=$(echo "scale=2; $TELE_RPC - $BASE_RPC" | bc 2>/dev/null || echo "$INCONCLUSIVE") # Both impacts below are ratios of the baseline, so a non-positive baseline -# leaves them undefined. The collector writes tps=0 whenever no ledger -# advanced and read_metric defaults a missing key to 0, so this is a routine -# outcome rather than an edge case. Reporting it as "0% impact" would clear -# the threshold and hide a failed baseline run. +# leaves them undefined. Reporting that as "0% impact" would clear the +# threshold and hide a failed baseline run. The reachable case is not the +# collector's tps=0 placeholder -- that marks the run incomplete and stops it +# earlier -- but quantization: tps is printed to two decimals, so a barely +# advancing cluster yields "0.00" with the metrics still flagged complete. # # Both expressions scale by 100 before dividing. bc truncates at "scale" after # every operation, so dividing first would floor the ratio to 2 decimals and @@ -576,7 +602,7 @@ RPC_DELTA=$(echo "scale=2; $TELE_RPC - $BASE_RPC" | bc 2>/dev/null || echo "0") BASE_TPS=$(read_metric "$BASELINE_FILE" "tps") TELE_TPS=$(read_metric "$TELEMETRY_FILE" "tps") if [[ "$(echo "$BASE_TPS > 0" | bc 2>/dev/null)" = "1" ]]; then - TPS_IMPACT=$(echo "scale=2; ($BASE_TPS - $TELE_TPS) * 100 / $BASE_TPS" | bc 2>/dev/null || echo "0") + TPS_IMPACT=$(echo "scale=2; ($BASE_TPS - $TELE_TPS) * 100 / $BASE_TPS" | bc 2>/dev/null || echo "$INCONCLUSIVE") else TPS_IMPACT="$INCONCLUSIVE" fi @@ -584,7 +610,7 @@ fi BASE_CONS=$(read_metric "$BASELINE_FILE" "consensus_round_mean_ms") TELE_CONS=$(read_metric "$TELEMETRY_FILE" "consensus_round_mean_ms") if [[ "$(echo "$BASE_CONS > 0" | bc 2>/dev/null)" = "1" ]]; then - CONS_IMPACT=$(echo "scale=2; ($TELE_CONS - $BASE_CONS) * 100 / $BASE_CONS" | bc 2>/dev/null || echo "0") + CONS_IMPACT=$(echo "scale=2; ($TELE_CONS - $BASE_CONS) * 100 / $BASE_CONS" | bc 2>/dev/null || echo "$INCONCLUSIVE") else CONS_IMPACT="$INCONCLUSIVE" fi @@ -615,7 +641,7 @@ check_threshold() { # Unusable measurement. Counted as a failure so the exit gate fires: an # undefined result must never read as a pass. if [ "$actual" = "$INCONCLUSIVE" ]; then - fail "$name: INCONCLUSIVE — baseline was zero or missing" >&2 + fail "$name: INCONCLUSIVE — the baseline was zero or missing, or the arithmetic failed" >&2 FAIL_COUNT=$((FAIL_COUNT + 1)) INCONCLUSIVE_COUNT=$((INCONCLUSIVE_COUNT + 1)) printf -v "$result_var" 'INCONCLUSIVE' @@ -695,7 +721,14 @@ EOMD ok "Benchmark report written to $REPORT_FILE" cat "$REPORT_FILE" -# Exit with failure if any check failed. -if [ "$FAIL_COUNT" -gt 0 ]; then +# Exit per the code table at the top of this file. A breach and an unmeasurable +# row both have to fail the gate, but they are different codes: exit 1 promises +# every metric was measured, so a run carrying an INCONCLUSIVE row reports 2 +# instead. FAIL_COUNT includes the inconclusive rows, so subtract them to see +# whether any real threshold was exceeded. +if [ "$((FAIL_COUNT - INCONCLUSIVE_COUNT))" -gt 0 ]; then exit 1 +elif [ "$INCONCLUSIVE_COUNT" -gt 0 ]; then + fail "$INCONCLUSIVE_COUNT overhead row(s) could not be measured — reporting an infrastructure error, not a breach" >&2 + exit 2 fi diff --git a/docker/telemetry/workload/regression-metrics.json b/docker/telemetry/workload/regression-metrics.json index f68c3f027c..8035240430 100644 --- a/docker/telemetry/workload/regression-metrics.json +++ b/docker/telemetry/workload/regression-metrics.json @@ -2,7 +2,7 @@ "_description": "Metric surface for the OTel-driven regression gate. Each entry names a metric, the quantiles to capture, and how to query Prometheus. The comparator compares current run against baseline-timings.json under these exact keys.", "_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 \u2014 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:470 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 \u2014 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 \u2014 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 excludes three keys here, and it is a property of WHERE THE CAPTURED RUN LANDED rather than of the metric: the same span.tx.apply.p50 has read 0.7917 ms, mid-distribution, where the identical rule produces a 4.21 ms bound that absorbs 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_shape": "ALL SIX 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 excludes four of the six keys here, and it is a property of WHERE THE CAPTURED RUN LANDED rather than of the metric: the same span.tx.apply.p50 has read 0.7917 ms, mid-distribution, where the identical rule produces a 4.21 ms bound that absorbs 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 six 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_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.", "_key_format": "{category}.{name}.p{quantile} (e.g. span.tx.process.p99, job.transaction.queued.p95). Only the categories defined below are captured; there is no rpc_methods group, so no rpc.* key is produced or gated (FU-4).", "excluded_keys": { @@ -11,7 +11,7 @@ "span.ledger.build.p99": "Run-to-run variance exceeds the bound this ladder can derive, measured on the first three runs after the account-funding race was fixed. Baseline 8.944 ms (median of CI runs 34495527952, 34505215266, 34507425933) sits in (5, 10], so hi_next is 25 ms, the bound is 16.056 ms and the trip point is 25 ms. Across those three runs the value read 29.000, 7.060 and 8.944 ms -- a 4.11x spread, and the maximum is 1.16x the trip point, so a healthy run reddens CI. Run 34495527952 is that run: it turned the workload gate red on this key alone while all 200 span and metric checks passed and every phase reported 0 errors. Two corroborating details. First, its 29.000 ms reading is shared to the last digit with span.consensus.accept.p99 in the same run, which is the signature of histogram_quantile interpolating a thin tail inside one bucket rather than of ledger construction slowing down. Second, the previous baseline hid this: at 9.109 ms the same rule also gave a 25 ms trip point, and the key read as gated only because both the capture and the comparison runs happened to land low -- the 2026-08-26 capture predated the funding fix, so its phases submitted little or no traffic. Widening is not available: a bound tolerating 29.000 ms would be 20.06 ms and reach into the (25, 50] bucket, restoring exactly the single-crossing false positive the derivation rule exists to remove. Ledger construction is not left unguarded -- span.ledger.build.p95 stays gated and sits at 0.48 of its trip point. Do NOT re-gate this key by widening the bound; it needs a spread-aware baseline, or a finer ladder edge between 10 ms and 25 ms.", "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:1003, 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.", - "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.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 six. 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." }, "job_queue": { "_phases": ["queued", "running"], diff --git a/docker/telemetry/workload/regression-thresholds.json b/docker/telemetry/workload/regression-thresholds.json index 76c2b9850c..973b099831 100644 --- a/docker/telemetry/workload/regression-thresholds.json +++ b/docker/telemetry/workload/regression-thresholds.json @@ -1,5 +1,5 @@ { - "_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 is excluded from the gated surface entirely: its quantiles are the ladder floor times the quantile, so no bound can gate it. See _excluded_ledger_store in regression-metrics.json. REFRESHED 2026-09-10 from the median of CI runs 34495527952, 34505215266 and 34507425933, the first three runs with the account-funding race fixed. The 2026-08-26 baseline predated that fix, so the phases that lost their traffic captured artificially low ledger and transaction timings; job.transaction.queued.p95 and job.transaction.running.p95 could not be captured at all. Applying the observed-maximum test to the refreshed numbers leaves 19 of 20 keys between 0.17 and 0.76 of their trip points, and disqualifies span.ledger.build.p99 -- see excluded_keys in regression-metrics.json. span.tx.process.p95 is the tightest survivor at 0.76 and is the key to re-measure first if the gate reddens again.", + "_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.9940ms in bucket (0.5, 1], hi_next = 5, so its bound is 4.0060ms 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.0060 for 4.006030232040599, is rejected; _derivation_table below shows the arithmetic for each one. Measured over the committed 2026-09-10 baseline this rule yields a detection floor of 2.00x to 7.41x 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 EXCLUDED, all of them p50 (six keys are excluded in total; the other three are span.ledger.validate.p95, span.ledger.validate.p99 and span.ledger.build.p99): 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 2026-08-24 baseline and 0.00597ms in the 2026-08-26 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 the 2026-08-26 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. On the current 2026-09-10 baseline the 19 gated keys sit between 0.14 and 0.50 of baseline over trip point, the tightest being span.tx.process.p95 at 0.50. That ratio is derivable from this file and baseline-timings.json. A headroom figure against each key's OBSERVED MAXIMUM is not derivable here, because no per-run timings.json is committed -- so do not restate one without citing the run it came from. See _excluded_shape in regression-metrics.json for what the 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. On the current 2026-09-10 baseline the six weakest keys are span.consensus.ledger_close.p95 (baseline 0.6750ms, fires at 5ms, 7.41x), span.consensus.accept.p50 (1.4364ms, 10ms, 6.96x), job.acceptLedger.running.p95 (15967.74us, 100000us, 6.26x), span.rpc.ws_message.p95 (0.8122ms, 5ms, 6.16x), span.rpc.ws_message.p99 (0.9873ms, 5ms, 5.06x) and span.tx.process.p99 (0.9940ms, 5ms, 5.03x). Four of the six are limited by the 1ms\u21925ms step; the other two by 5ms\u219210ms (span.consensus.accept.p50) and 25000us\u2192100000us (job.acceptLedger.running.p95). None of the six fires on any observed run, so all six stay gated, but the weak floors are recorded here so they are visible rather than surprising. Because every floor is now under 10x, a 10x regression is caught on all 19 gated keys -- that is derived from the floors, not sampled. On the 2026-08-26 baseline job.acceptLedger.running.p95 had a 16.28x floor and was the one key 10x missed; its baseline rose 6142.86us to 15967.74us while hi_next stayed at 100000us, which pulled its floor to 6.26x. Sensitivity therefore moves with each refresh even when no code changes, so re-derive these floors whenever the baseline is refreshed. 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 is excluded from the gated surface entirely: its quantiles are the ladder floor times the quantile, so no bound can gate it. See _excluded_ledger_store in regression-metrics.json. REFRESHED 2026-09-10 from the median of CI runs 34495527952, 34505215266 and 34507425933, the first three runs with the account-funding race fixed. The 2026-08-26 baseline predated that fix, so the phases that lost their traffic captured artificially low ledger and transaction timings. Applying the observed-maximum test to the refreshed numbers leaves 19 of 20 keys between 0.17 and 0.76 of their trip points, and disqualifies span.ledger.build.p99 -- see excluded_keys in regression-metrics.json. span.tx.process.p95 is the tightest survivor at 0.76 and is the key to re-measure first if the gate reddens again.", "_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 floor is 0.01ms; a span baseline captured against a 1ms floor is void below 1ms \u2014 a p95 reading 0.95ms there is 0.95 \u00d7 that 1ms first edge, not a measurement. Do not assume a surviving span baseline is unaffected by ladder work: every span quantile below 1ms is affected. 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.", "_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 should not be oversold. 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). That false fire is NOT to be read as 'the intended signal that the override is missing' \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": { @@ -17,7 +17,7 @@ "span.tx.process": "p50 0.21390674968918655 in (0.1,0.25] -> hi_next 0.5 - baseline = 0.28609325031081345 | p95 0.49949970576841685 in (0.25,0.5] -> hi_next 1 - baseline = 0.5005002942315832 | p99 0.9939697679594013 in (0.5,1] -> hi_next 5 - baseline = 4.006030232040599" }, "_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.", - "_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. Do not reason from 'every step of both ladders is at least a factor of 2' -- that premise is false. The span ladder breaks it 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).", + "_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 on the 2026-09-10 baseline, (bound / baseline) ranges from 100.2% (span.tx.process.p95) to 640.7% (span.consensus.ledger_close.p95), all above the 50% and 5% percentage bounds configured here, and the minimum trip multiple of all 19 gated keys is set by the absolute bound. Re-measure these two extremes on every baseline refresh: both changed identity in the 2026-09-10 refresh. THIS IS NOT A GENERAL GUARANTEE. Do not reason from 'every step of both ladders is at least a factor of 2' -- that premise is false. The span ladder breaks it 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": { "job_queue": { "p95": { diff --git a/docker/telemetry/workload/run-full-validation.sh b/docker/telemetry/workload/run-full-validation.sh index 59c7b1b372..7a356fa85b 100755 --- a/docker/telemetry/workload/run-full-validation.sh +++ b/docker/telemetry/workload/run-full-validation.sh @@ -81,6 +81,13 @@ RPC_PORT_BASE=5005 WS_PORT_BASE=6006 PEER_PORT_BASE=51235 +# Node i lives in $WORKDIR/$NODE_PREFIX-$i, and every node path, kill pattern and +# log glob below derives from it. The directory name is also the node's identity: +# the collector stamps that segment as service.instance.id. If it and the +# [telemetry] service_instance_id below disagree, log lines get a node name no +# trace or metric shares. Sibling harness files pin their own stem. +NODE_PREFIX="validator" + # 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 parks the # poll loop for the rest of the run. The loops here count attempts, not seconds, @@ -217,8 +224,19 @@ while [ $# -gt 0 ]; do # Match the node config path, not the bare workdir: a plain # "$WORKDIR" pattern also matches any shell, editor or log tail # whose command line merely mentions that path. - pkill -f "$WORKDIR/node[0-9]+/xrpld\.cfg" 2>/dev/null || true - docker compose -f "$COMPOSE_FILE" down 2>/dev/null || true + # + # This is the only thing that stops the nodes. They are host + # processes, not containers, so the compose teardown below does not + # touch them. + pkill -f "$WORKDIR/$NODE_PREFIX-[0-9]+/xrpld\.cfg" 2>/dev/null || true + # pkill sends SIGTERM and a node keeps writing NuDB while it unwinds, + # so the rm below would race a live writer and fail with ENOTEMPTY. + # Same wait as the pre-run cleanup path. + sleep 2 + # -v also drops the named tempo-data volume. Without it the next + # run's Tempo starts with the previous run's traces still queryable, + # which a span assertion can be satisfied by. + docker compose -f "$COMPOSE_FILE" down -v 2>/dev/null || true # The collector bind-mounts $WORKDIR (see XRPLD_LOG_DIR below), so a # file left behind owned by a container uid makes this fail. Leaving # it in place would hand the next run stale node state, so say so @@ -256,8 +274,11 @@ ok "Prerequisites verified." # Cleanup previous run # --------------------------------------------------------------------------- log "Cleaning up previous run..." -# Narrowed for the same reason as the --cleanup branch above. -pkill -f "$WORKDIR/node[0-9]+/xrpld\.cfg" 2>/dev/null || true +# Matches the node config path, for the same reason as the --cleanup branch +# above. A node left over +# from a previous run still holds this run's RPC, WS and peer ports, so missing +# one here surfaces much later as a cluster that never reaches consensus. +pkill -f "$WORKDIR/$NODE_PREFIX-[0-9]+/xrpld\.cfg" 2>/dev/null || true sleep 2 rm -rf "$WORKDIR" || die "Could not remove the previous run's workdir $WORKDIR" mkdir -p "$WORKDIR" "$REPORT_DIR" || die "Could not create $WORKDIR and $REPORT_DIR" @@ -273,12 +294,15 @@ XRPLD_LOG_DIR="$WORKDIR" docker compose -f "$COMPOSE_FILE" up -d || log "Waiting for OTel Collector..." for attempt in $(seq 1 30); do - status=$(curl -so /dev/null -w '%{http_code}' --max-time "$CURL_MAX_TIME" http://localhost:4318/ 2>/dev/null || echo 000) + # The fallback must not sit inside the substitution: curl already prints 000 + # on a refused connection and then exits non-zero, so `|| echo 000` there + # appends a second 000 and the "not ready" test can never match. + status=$(curl -so /dev/null -w '%{http_code}' --max-time "$CURL_MAX_TIME" http://localhost:4318/ 2>/dev/null) || status=000 if [ "$status" != "000" ]; then ok "OTel Collector ready (attempt $attempt)" break fi - [ "$attempt" -eq 30 ] && die "OTel Collector not ready after 30s" + [ "$attempt" -eq 30 ] && die "OTel Collector not ready after 30 attempts" sleep 1 done @@ -288,7 +312,7 @@ for attempt in $(seq 1 30); do ok "Tempo ready (attempt $attempt)" break fi - [ "$attempt" -eq 30 ] && die "Tempo not ready after 30s" + [ "$attempt" -eq 30 ] && die "Tempo not ready after 30 attempts" sleep 1 done @@ -298,7 +322,7 @@ for attempt in $(seq 1 30); do ok "Prometheus ready (attempt $attempt)" break fi - [ "$attempt" -eq 30 ] && die "Prometheus not ready after 30s" + [ "$attempt" -eq 30 ] && die "Prometheus not ready after 30 attempts" sleep 1 done @@ -311,20 +335,20 @@ bash "$SCRIPT_DIR/generate-validator-keys.sh" "$XRPLD" "$NUM_NODES" "$WORKDIR" | die "generate-validator-keys.sh failed — no validator keys for the $NUM_NODES-node cluster" for i in $(seq 1 "$NUM_NODES"); do - NODE_DIR="$WORKDIR/validator-$i" - mkdir -p "$NODE_DIR/nudb" "$NODE_DIR/db" || die "Could not create node$i directories under $NODE_DIR" + NODE_DIR="$WORKDIR/$NODE_PREFIX-$i" + mkdir -p "$NODE_DIR/nudb" "$NODE_DIR/db" || die "Could not create $NODE_PREFIX-$i directories under $NODE_DIR" RPC_PORT=$((RPC_PORT_BASE + i - 1)) WS_PORT=$((WS_PORT_BASE + i - 1)) PEER_PORT=$((PEER_PORT_BASE + i - 1)) SEED=$(jq -r ".[$((i - 1))].seed" "$WORKDIR/validator-keys.json") || - die "Could not read node$i's seed from $WORKDIR/validator-keys.json" + die "Could not read $NODE_PREFIX-$i's seed from $WORKDIR/validator-keys.json" # jq prints the string "null" and exits 0 when the array is shorter than # NUM_NODES, so the exit status alone does not detect a short key file. An # unusable seed here is only visible ~200s later as a cluster that never # proposes, which names the wrong step. case "$SEED" in - "" | null) die "node$i has no seed in $WORKDIR/validator-keys.json — the file holds fewer than $NUM_NODES entries, or entry $((i - 1)) carries no seed" ;; + "" | null) die "$NODE_PREFIX-$i has no seed in $WORKDIR/validator-keys.json — the file holds fewer than $NUM_NODES entries, or entry $((i - 1)) carries no seed" ;; esac # Build ips_fixed. @@ -336,7 +360,7 @@ for i in $(seq 1 "$NUM_NODES"); do fi done - cat >"$NODE_DIR/xrpld.cfg" <"$NODE_DIR/xrpld.cfg" <"$NODE_DIR/xrpld.pid" || die "Could not write node$i's pid file $NODE_DIR/xrpld.pid" + echo $! >"$NODE_DIR/xrpld.pid" || die "Could not write $NODE_PREFIX-$i's pid file $NODE_DIR/xrpld.pid" log " Node $i: RPC=$RPC_PORT WS=$WS_PORT Peer=$PEER_PORT PID=$!" done @@ -478,17 +502,17 @@ node_running() { report_stopped_nodes() { local i pid status for i in $(seq 1 "$NUM_NODES"); do - pid=$(cat "$WORKDIR/validator-$i/xrpld.pid" 2>/dev/null || echo "") + pid=$(cat "$WORKDIR/$NODE_PREFIX-$i/xrpld.pid" 2>/dev/null || echo "") [ -n "$pid" ] || continue node_running "$pid" && continue status=0 wait "$pid" 2>/dev/null || status=$? - warn "node$i (pid $pid) is not running — wait status $status" - if [ -s "$WORKDIR/validator-$i/stdout.log" ]; then - warn "node$i last output:" - tail -n 15 "$WORKDIR/validator-$i/stdout.log" | sed 's/^/ /' >&2 + warn "$NODE_PREFIX-$i (pid $pid) is not running — wait status $status" + if [ -s "$WORKDIR/$NODE_PREFIX-$i/stdout.log" ]; then + warn "$NODE_PREFIX-$i last output:" + tail -n 15 "$WORKDIR/$NODE_PREFIX-$i/stdout.log" | sed 's/^/ /' >&2 else - warn "node$i wrote no stdout at all" + warn "$NODE_PREFIX-$i wrote no stdout at all" fi done } @@ -510,7 +534,7 @@ for attempt in $(seq 1 120); do # node is missing but not which one, which leaves nothing to grep # for in the artifacts. An empty state means the RPC port did not # answer at all, which usually means the process is gone. - laggards="$laggards node$i=${state:-unreachable}" + laggards="$laggards $NODE_PREFIX-$i=${state:-unreachable}" fi done if [ "$ready" -ge "$NUM_NODES" ]; then @@ -522,7 +546,7 @@ for attempt in $(seq 1 120); do # minutes of progress output. stopped=0 for n in $(seq 1 "$NUM_NODES"); do - p=$(cat "$WORKDIR/node$n/xrpld.pid" 2>/dev/null || echo "") + p=$(cat "$WORKDIR/$NODE_PREFIX-$n/xrpld.pid" 2>/dev/null || echo "") if [ -n "$p" ] && ! node_running "$p"; then stopped=$((stopped + 1)) fi @@ -548,7 +572,7 @@ for attempt in $(seq 1 120); do # is a no-op when nothing stopped, and it costs nothing to be sure. # Tolerated for the same reason as above. report_stopped_nodes || true - die "Consensus timeout — only $ready/$NUM_NODES nodes proposing after ${attempt}s. Not proposing:${laggards}. Check $WORKDIR/node*/debug.log and $WORKDIR/node*/stdout.log (a node that died before its log sink opened writes only the latter), then '$0 --cleanup'." + die "Consensus timeout — only $ready/$NUM_NODES nodes proposing after ${attempt} attempts. Not proposing:${laggards}. Check $WORKDIR/$NODE_PREFIX-*/debug.log and $WORKDIR/$NODE_PREFIX-*/stdout.log (a node that died before its log sink opened writes only the latter), then '$0 --cleanup'." fi printf "\r %d/%d nodes proposing..." "$ready" "$NUM_NODES" sleep 1 @@ -570,7 +594,7 @@ for attempt in $(seq 1 60); do # ledger_economy{metric="base_fee_xrp"} is only observed from a validated # ledger, and complete_ledgers stays absent while the range is empty. if [ "$attempt" -eq 60 ]; then - die "No validated ledger after ${attempt}s (last seq: $val_seq). Check $WORKDIR/node*/debug.log, then '$0 --cleanup'." + die "No validated ledger after ${attempt} attempts (last seq: $val_seq). Check $WORKDIR/$NODE_PREFIX-*/debug.log, then '$0 --cleanup'." fi sleep 1 done @@ -704,9 +728,9 @@ diag_node_logs() { local i log bytes total correlated sample echo " [leg 1/4 node] debug.log lines matching '$DIAG_TRACE_RE'" for i in $(seq 1 "$NUM_NODES"); do - log="$WORKDIR/validator-$i/debug.log" + log="$WORKDIR/$NODE_PREFIX-$i/debug.log" if [ ! -f "$log" ]; then - echo " node$i: no debug.log at $log — the node never opened its log sink" + echo " $NODE_PREFIX-$i: no debug.log at $log — the node never opened its log sink" continue fi bytes=$(wc -c <"$log" 2>/dev/null || echo 0) @@ -714,7 +738,7 @@ diag_node_logs() { # grep -c exits 1 on zero matches but still prints the count, so the # guard keeps the 0 rather than replacing it with an empty string. correlated=$(grep -cE "$DIAG_TRACE_RE" "$log" 2>/dev/null || true) - echo " node$i: bytes=$bytes lines=$total correlated=${correlated:-0}" + echo " $NODE_PREFIX-$i: bytes=$bytes lines=$total correlated=${correlated:-0}" # Severity mix from the '[partition:]SEV' token, which Logs::format() # writes as the 4th whitespace-separated field. Fixed key order so two # runs' output can be diffed directly. Lines whose 4th field is not a @@ -1076,7 +1100,7 @@ echo " xrpld nodes ($NUM_NODES) are running:" for i in $(seq 1 "$NUM_NODES"); do rpc=$((RPC_PORT_BASE + i - 1)) ws=$((WS_PORT_BASE + i - 1)) - pid=$(cat "$WORKDIR/validator-$i/xrpld.pid" 2>/dev/null || echo 'unknown') + pid=$(cat "$WORKDIR/$NODE_PREFIX-$i/xrpld.pid" 2>/dev/null || echo 'unknown') echo " Node $i: RPC=$rpc WS=$ws PID=$pid" done echo ""