diff --git a/OpenTelemetryPlan/06-implementation-phases.md b/OpenTelemetryPlan/06-implementation-phases.md index f1991d5f19..8ed289cb73 100644 --- a/OpenTelemetryPlan/06-implementation-phases.md +++ b/OpenTelemetryPlan/06-implementation-phases.md @@ -919,7 +919,7 @@ Alert Rules from External Dashboard**. ## 6.8.3 Phase 10: Synthetic Workload Generation & Telemetry Validation (Weeks 16-17) -> **Status**: Implemented on this branch — `docker/telemetry/workload/` (24 +> **Status**: Implemented on this branch — `docker/telemetry/workload/` (25 > files) and `.github/workflows/telemetry-validation.yml` are present here. > Upstream branches do not carry them, so the exit criteria below only hold from > `pratik/otel-phase10-workload-validation` onward. @@ -1003,7 +1003,7 @@ flowchart LR - **Transaction submitter and RPC load generator** both use xrpld's native WebSocket command format (`{"command": ...}`) — not JSON-RPC format. Response data lives inside `"result"` with `"status"` at the top level. - **Node config** requires `[signing_support] true` for server-side signing, and `[ips]` (not `[ips_fixed]`) to ensure peer connections count in `peer_finder_active_*` metrics. -- **Metric validation** uses the Prometheus `/api/v1/series` endpoint (not instant queries) to avoid false negatives from stale StatsD gauges. Every metric in `expected_metrics.json` must have > 0 series. +- **Metric validation** uses the Prometheus `/api/v1/series` endpoint (not instant queries) which polls for late-populating series and ignores Prometheus's staleness horizon. Every metric in `expected_metrics.json` must have > 0 series. - **Gauge visibility**: the harness sets `[insight] server=otel` (`run-full-validation.sh`), so `beast::insight` gauges become OTel observable gauges whose callback is invoked on every collection cycle. A gauge that sits at 0 and never changes (e.g. `jobq_job_count`) therefore still reports, and `/api/v1/series` sees it. - **I/O latency fix**: `io_latency_sampler` emits unconditionally on first sample, then applies the 10 ms threshold. This ensures `ios_latency` is registered in Prometheus even in low-load CI environments. - **tx.receive span**: attribute keys are bare, not dotted — `suppressed` and `tx_status` (`TxSpanNames.h:71,75`). `suppressed` is set on both outcomes (`false` on the accepted path, `true` when the HashRouter suppresses), but `tx_status` is set **only** on the reject/known-bad/dropped paths, so it is absent on a successful receive. Assert on the attribute, not on span status. @@ -1070,15 +1070,16 @@ See [Phase10_taskList.md](./Phase10_taskList.md) for the per-task breakdown. ### CI Deliverable (Task 10.6) The Phase 10 CI entry point is `.github/workflows/telemetry-validation.yml` -(367 lines, on the Phase 10 branch). It runs three jobs — `linux-image-tag`, +(on the Phase 10 branch). It runs three jobs — `linux-image-tag`, `build-xrpld`, `validate-telemetry` — and is triggered by `workflow_dispatch` -plus `push` on `pratik/otel-phase*`, `feature/otel-*` and -`feature/telemetry-*`. **There is no cron schedule**, so nothing runs this -workflow on a timer. +plus any `push` that touches one of the `paths` globs below. **There is no +branch filter**: GitHub ANDs `branches` with `paths`, so a branch glob would +decide validation by what a branch is called rather than by what it changed. +**There is no cron schedule**, so nothing runs this workflow on a timer. > **Fixed — the `push` trigger's `paths` filter now covers the C++ telemetry -> sources.** The branch filter is only half the trigger; `push` also carries a -> `paths` filter, and it previously read: +> sources.** The `push` trigger carries a `paths` filter, and it previously +> read: > > ```yaml > paths: @@ -1092,14 +1093,14 @@ workflow on a timer. > `include/xrpl/basics/Telemetry*.h` nor `src/xrpld/app/misc/Telemetry*` exists. > The telemetry code lives in `src/xrpld/telemetry/**` (9 files, including > `MetricsRegistry.cpp`), `src/libxrpl/telemetry/**` (7 files) and -> `include/xrpl/telemetry/**` (10 files), none of which were listed. +> `include/xrpl/telemetry/**` (13 files), none of which were listed. > Consequence at the time: a pure C++ telemetry change — new instrument, > renamed metric, changed span attribute — never triggered this workflow on > push; only edits under `docker/telemetry/**` or to the workflow file itself > did. > -> The two dead globs have been replaced with the three real module directories, -> so the filter now reads: +> The two dead globs have been replaced with the real module directories, the +> name-constant headers and the checkers, so the filter now reads: > > ```yaml > paths: @@ -1107,15 +1108,22 @@ workflow on a timer. > - "docker/telemetry/**" > - "include/xrpl/telemetry/**" > - "src/libxrpl/telemetry/**" -> - "src/libxrpl/beast/insight/**" > - "src/xrpld/telemetry/**" +> - "include/xrpl/beast/insight/**" +> - "src/libxrpl/beast/insight/**" +> - "**/*SpanNames.h" +> - "**/*MetricNames.h" +> - "src/tests/libxrpl/telemetry/**" +> - ".github/scripts/otel-naming/**" +> - ".github/scripts/telemetry/**" > ``` > > `src/libxrpl/beast/insight/**` is included because it holds `OTelCollector.cpp`, -> the `beast::insight` OTLP export path the harness depends on. Residual gap: the -> instrumented call sites scattered through `src/xrpld/app/` are not listed, so a -> change that only adds or moves a span at a call site does not trigger the -> workflow on push. Those are reachable by manual dispatch. +> the `beast::insight` OTLP export path the harness depends on. The `*SpanNames.h` +> and `*MetricNames.h` globs cover the name constants wherever they sit, including +> under `src/xrpld/app/`. Residual gap: an instrumented call site that adds or +> moves a span without touching a name header does not trigger the workflow on +> push. Those are reachable by manual dispatch. > **Caveat — four inert inputs (documented, not wired).** The workflow declares > five `workflow_dispatch` inputs, but only `run_benchmark` changes behaviour. diff --git a/docker/telemetry/workload/README.md b/docker/telemetry/workload/README.md index 5a212022b4..07c3bacb0a 100644 --- a/docker/telemetry/workload/README.md +++ b/docker/telemetry/workload/README.md @@ -213,9 +213,9 @@ python3 tx_submitter.py --endpoint ws://localhost:6006 \ Automated validation that all expected telemetry data exists. Every metric in `expected_metrics.json` is required — if it doesn't fire, the validation fails. Spans are required unless the entry carries `"optional": true`. -- **Span validation**: All span types from `expected_spans.json` with required attributes and parent-child hierarchies. Entries marked `"optional": true` only fire under traffic the harness may not produce (HTTP/JSON-RPC client, gRPC client, path-finding RPC — see [Pathfinding is not exercised](#pathfinding-is-not-exercised) — missing-ledger fetch, mode transitions); their absence is recorded as a passing skip, not a failure. +- **Span validation**: All span types from `expected_spans.json` with required attributes and parent-child hierarchies. The 16 entries marked `"optional": true` are the ones the harness cannot guarantee: no gRPC client, no path-finding RPC (see [Pathfinding is not exercised](#pathfinding-is-not-exercised)), no missing-ledger fetch, no mode transition, no WebSocket handshake, and the six `txq.*` spans only when fee escalation puts something in the queue. `rpc.http_request` and `rpc.process` are marked optional because the generator drives WebSocket rather than HTTP. Their absence is recorded as a passing skip, not a failure. - **Metric validation**: All metrics from `expected_metrics.json` — SpanMetrics, `beast::insight` gauges/counters/histograms, `MetricsRegistry` OTLP metrics. Every listed metric must have > 0 series. Uses the Prometheus `/api/v1/series` endpoint (not instant queries), polled until the metric appears or the poll window elapses, so a late-populating or quiet series is not a false negative. -- **Log-trace correlation**: trace_id/span_id in Loki logs (requires Loki). The two checks are `log.trace_id_present` and `log.trace_id_cross_reference`, and they exist only when `--skip-loki` is **not** passed — `run_validation()` builds them inside an `if not skip_loki` branch, so with the flag they are absent from the report rather than reported as skipped. **CI always passes `--skip-loki`, so these two are never exercised there** — see [CI Integration](#ci-integration). +- **Log-trace correlation**: trace_id/span_id in Loki logs (requires Loki). The two checks are `log.trace_id_present` and `log.trace_id_cross_reference`, and they exist only when `--skip-loki` is **not** passed — `run_validation()` builds them inside an `if not skip_loki` branch, so with the flag they are absent from the report rather than reported as skipped. The workflow passes no `--skip-loki`, so both checks are built and gated on every CI run — see [CI Integration](#ci-integration). - **Dashboard validation**: Every dashboard uid listed under `grafana_dashboards.uids` in `expected_metrics.json` loads with panels. That list currently covers **all 15** dashboards provisioned in `docker/telemetry/grafana/dashboards/`. Note the scope of this check: it asks the Grafana API whether the dashboard exists and returns a panel count — it does **not** run the panels' queries, so a dashboard can pass here while individual panels render empty. ```bash @@ -359,7 +359,7 @@ from the running nodes, and writes them as JSON. `benchmark.sh` calls it once per leg; it is rarely run by hand. ```bash -./collect_system_metrics.sh 5020,5021,5022 300 /tmp/metrics.json +./collect_system_metrics.sh 5020,5021,5022 300 /tmp/metrics.json [pids_csv] ``` Processes are selected by matching `argv[0]`'s basename against the daemon @@ -370,8 +370,12 @@ string, are not sampled — including them diluted the CPU average and attributed a foreign process's RSS to the node. `ps -C xrpld` is not usable for this: xrpld renames itself, so its `comm` is `xrpld-main`. -Selection covers the whole host, so a second xrpld from another checkout is -sampled as well. Benchmark on a machine running one cluster only. +A fourth argument narrows selection to an explicit pid list, and `benchmark.sh` +always passes its own nodes' pids. It has to: `run-full-validation.sh` leaves its +five validation nodes running while the benchmark's three start, so host-wide +selection would average eight processes in both arms and report the largest of +them as the RSS peak. Without the argument the scope is still the whole host, so +a second xrpld from another checkout is sampled as well. The output carries a `metrics_complete` flag. It is `false` when any measurement source came back empty — no matching process, no successful RPC @@ -433,7 +437,7 @@ Categories: The validation runs as a GitHub Actions workflow (`.github/workflows/telemetry-validation.yml`): -- Triggered manually (`workflow_dispatch`) or on pushes to telemetry branches. There is no cron schedule. +- Triggered manually (`workflow_dispatch`), or by any push touching the workflow's `paths` globs. There is no branch filter and no cron schedule. - Builds xrpld, starts the full stack, runs load, validates - Uploads reports as artifacts (and node logs when validation did not succeed) - Writes the validation summary and the regression-gate summary to the workflow **Step Summary** (`$GITHUB_STEP_SUMMARY`). It does **not** comment on the PR — the workflow declares no `permissions:` block and calls no GitHub API, so read the summary on the run page. @@ -446,10 +450,10 @@ them again — load shape comes entirely from `--profile` and ### Log-trace correlation in CI -The workflow no longer passes `--skip-loki`, so `log.trace_id_present` and +The workflow passes no `--skip-loki`, so `log.trace_id_present` and `log.trace_id_cross_reference` are constructed and gated on every CI run. A green -`Telemetry Validation` is now evidence that log lines carry trace context and -that a logged trace id resolves to an exported trace. `integration-test.sh` has +`Telemetry Validation` is evidence that log lines carry trace context and that a +logged trace id resolves to an exported trace. `integration-test.sh` has its own `check_log_correlation()`, but no workflow runs that script. Correlation depends on four independent legs, and a failed check on its own names @@ -515,8 +519,8 @@ Re-run it after any change to log formatting, span activation, the collector's **Why.** Pathfinding is disabled on every node this harness starts, so those calls could only ever fail: - `src/xrpld/core/detail/Config.cpp:725-726` sets `pathSearchMax = 0` whenever a `[validation_seed]` or `[validator_token]` section is present — "by default, validators don't have pathfinding enabled". -- `run-full-validation.sh:308` writes `[validation_seed]` into every generated node cfg, and that script carries no `[path_search]`, `[path_search_fast]` or `[path_search_max]` section to put the default back. -- `src/xrpld/rpc/handlers/orderbook/RipplePathFind.cpp:48-49` therefore returns `rpcNOT_SUPPORTED`; `PathFind.cpp:39` does the same for `path_find`. +- `run-full-validation.sh` writes `[validation_seed]` into every generated node cfg, and that script carries no `[path_search]`, `[path_search_fast]` or `[path_search_max]` section to put the default back. +- `src/xrpld/rpc/handlers/orderbook/RipplePathFind.cpp:59-60` therefore returns `RpcNotSupported`; `PathFind.cpp:50-51` does the same for `path_find`. **Why the refusals would not be harmless.** They are not silent. `pathfind.request` is opened at `RipplePathFind.cpp:35`, **above** that guard, so a refused call still exports a span, and the enclosing `rpc.command.ripple_path_find` span carries `rpc_status=error`. At a 3% weight that is a steady ~3% error floor in `span_calls_total{status_code="STATUS_CODE_ERROR"}` — a figure that reads as an xrpld error rate and is not one. **An error-rate threshold derived from a harness run that does issue path-finding load is measuring the harness, not xrpld.** diff --git a/docker/telemetry/workload/baselines/README.md b/docker/telemetry/workload/baselines/README.md index 684e7e640d..75a75c2561 100644 --- a/docker/telemetry/workload/baselines/README.md +++ b/docker/telemetry/workload/baselines/README.md @@ -142,7 +142,7 @@ needs a finer low-end ladder **as well as** a spread-aware baseline. `0.005` / `0.0095` / `0.0099` ms, which is `0.5` / `0.95` / `0.99 × 0.01` ms — the ladder's first edge times the quantile, the signature of every sample landing in the first bucket. Those numbers are interpolation arithmetic on the bucket floor, not latencies. It is physically plausible: -[`LedgerMaster.cpp:463`](../../../../src/xrpld/app/ledger/detail/LedgerMaster.cpp#L463) wraps an +[`LedgerMaster.cpp:470`](../../../../src/xrpld/app/ledger/detail/LedgerMaster.cpp#L470) wraps an in-memory `ledgerHistory_.insert`, which completes in single-digit microseconds. While all the mass stays under 10 us the reported quantile cannot move materially, so **no @@ -180,7 +180,7 @@ while the other quantile stayed well inside its bound in the same run — the si not of a regression. The mechanism is arrival timing, not slow code. The span opens only once a quorum-completing -validation arrives ([`LedgerMaster.cpp:987`](../../../../src/xrpld/app/ledger/detail/LedgerMaster.cpp#L987), +validation arrives ([`LedgerMaster.cpp:1003`](../../../../src/xrpld/app/ledger/detail/LedgerMaster.cpp#L1003), inside `checkAccept`, past the `tvc < minVal` early return) and wraps the promotion work that follows — `setValidated`, `setFull`, `setValidLedger`, `pendSaveValidated`. Its duration therefore tracks when peer validations arrive in a 5-node cluster and what promotion then schedules, so a @@ -323,7 +323,7 @@ each node's `[rpc_startup]` stanza. Logging is **synchronous**, and several of t spans contain log statements, so the configured level is part of the measurement: - `ledger.build` contains [`BuildLedger.cpp:81`](../../../../src/xrpld/app/ledger/detail/BuildLedger.cpp#L81) (debug). -- `consensus.accept` contains [RCLConsensus.cpp:655/663/686](../../../../src/xrpld/app/consensus/RCLConsensus.cpp#L663) (debug) — `:663` logs **once per transaction** in the canonical set. +- `consensus.accept` contains [RCLConsensus.cpp:683/687/698/715](../../../../src/xrpld/app/consensus/RCLConsensus.cpp#L715) (debug) — `:715` logs **once per transaction** in the canonical set. - `tx.apply` and the other `spans.names` entries in [`../regression-metrics.json`](../regression-metrics.json) are affected the same way. Raising the level admits more of those statements and inflates the p50/p95/p99 of the very @@ -415,7 +415,7 @@ the first produces metrics that look gated in the report but are not. `rpc.process` is deliberately absent from the `spans.names` list in `regression-metrics.json`, so no `span.rpc.process.*` key appears in this baseline. The span is created only in `ServerHandler::processRequest()` -(`src/xrpld/rpc/detail/ServerHandler.cpp:705`), which is reached only from the +(`src/xrpld/rpc/detail/ServerHandler.cpp:718`), which is reached only from the HTTP/JSON-RPC session path. The harness load generator is WebSocket-only and that path never calls `processRequest`, so the span is never emitted under any workload profile here — `expected_spans.json` marks it `"optional": true` for diff --git a/docker/telemetry/workload/expected_metrics.json b/docker/telemetry/workload/expected_metrics.json index 1c0534c750..34a4b55fad 100644 --- a/docker/telemetry/workload/expected_metrics.json +++ b/docker/telemetry/workload/expected_metrics.json @@ -199,7 +199,7 @@ "not_asserted": { "description": "Emitted-and-dashboarded metrics deliberately left unasserted because they are workload-gated or defect-gated: the harness workload cannot guarantee they appear, and a check that fails on a healthy run is worse than no check. This group has no \"metrics\" key, so validate_telemetry.py skips it (validate_metrics iterates category_data.get(\"metrics\", [])). Promote an entry into an asserted group only after the workload is changed to guarantee it.", "metrics_excluded": { - "rpc_method_errored_total": "MetricsRegistry.cpp:332-333, push counter. 'Errored' here means a thrown C++ exception, not an error status in the JSON reply: the only caller is PerfLogImp.cpp:409 under 'if (!finish)', reached only through PerfLogImp::rpcError (PerfLogImp.h:150-153), whose only call site is the catch (std::exception&) handler in RPCHandler.cpp:213. An RPC that returns an error status normally still takes the rpcFinish path at RPCHandler.cpp:190 and increments rpc_method_finished_total. That distinction mattered here while the generator still issued ripple_path_find: those calls were in fact refused — pathfinding is off on every harness node, so doRipplePathFind returns rpcNOT_SUPPORTED (see pathfind_fast_milliseconds below) — and it would have been easy to conclude from that alone that this counter must fire. It does not, because a refusal is a normal return, not a throw. The harness issues no path-finding command at all, so the question is moot here, but the distinction is kept on record because it is the one that decides this entry. Nothing in rpc_load_generator.py's remaining server_info / fee / account / ledger / tx / DEX mix is expected to throw either, so no series may ever be created.", + "rpc_method_errored_total": "MetricsRegistry.cpp:332-333, push counter. 'Errored' here means a thrown C++ exception, not an error status in the JSON reply: the only caller is PerfLogImp.cpp:409 under 'if (!finish)', reached only through PerfLogImp::rpcError (PerfLogImp.h:150-153), whose only call site is the catch (std::exception&) handler in RPCHandler.cpp:213. An RPC that returns an error status normally still takes the rpcFinish path at RPCHandler.cpp:190 and increments rpc_method_finished_total. That distinction mattered here while the generator still issued ripple_path_find: those calls were in fact refused — pathfinding is off on every harness node, so doRipplePathFind returns RpcNotSupported (see pathfind_fast_milliseconds below) — and it would have been easy to conclude from that alone that this counter must fire. It does not, because a refusal is a normal return, not a throw. The harness issues no path-finding command at all, so the question is moot here, but the distinction is kept on record because it is the one that decides this entry. Nothing in rpc_load_generator.py's remaining server_info / fee / account / ledger / tx / DEX mix is expected to throw either, so no series may ever be created.", "ledger_history_mismatch_total": "MetricsRegistry.cpp:377, incremented only from LedgerHistory.cpp:332 on a built-vs-validated ledger mismatch. On a healthy run it never fires — asserting it would mean asserting a defect.", "txq_expired_total": "MetricsRegistry.cpp:379, incremented only at TxQ.cpp:1428 when a queued tx expires past its LastLedgerSequence. CI does run a txq-burst phase (workload-profiles.json:41, 30 s of single-type Payment at 60 TPS), but that does not guarantee sustained fee escalation followed by expiry: a run in which every other check passed still exposed only txq_metrics and no txq_expired_total.", "txq_dropped_total": "MetricsRegistry.cpp:381, incremented only at TxQ.cpp:1302 / :1347 on queue-full admission refusal. Same reason as txq_expired_total.", @@ -210,8 +210,8 @@ "getobject_charge": "GetObjectMetricNames.h:105, PeerImp.cpp:2931. Same gate.", "rpc_size_bytes": "ServerHandler.cpp:191, group('rpc')->makeEvent('size', Unit::Bytes). The OTLP Prometheus exporter derives the metric-name suffix from the declared unit, so a byte unit yields rpc_size_bytes. The Unit::Bytes declaration itself landed earlier, in 76c9051203; what 24094e427b changed was the exporter finally consuming it, replacing a hardcoded CreateDoubleHistogram(name, 'Duration in ms', 'ms') with otelUnitDescription(unit)/otelUnitCode(unit), and that is what renamed the series off rpc_size_milliseconds and the millisecond bucket ladder. Neither name was ever recorded here, so the harness could confirm neither the rename nor a regression back onto that ladder. Notified from ServerHandler::processRequest:1133, the HTTP JSON-RPC path — it computes an HTTP status and appends a trailing newline — and the load generators are WebSocket-only, the same gate regression-metrics.json:4 records for rpc.process, so only the harness's handful of HTTP health polls reach it. Real coverage needs an HTTP JSON-RPC phase in rpc_load_generator.py; that is a workload change rather than a harness correction, and is deliberately out of scope here.", "rpc_time_milliseconds": "ServerHandler.cpp:192, group('rpc')->makeEvent('time') with the default millisecond unit. Notified from ServerHandler::processRequest:1129, the same HTTP JSON-RPC call site as rpc_size_bytes and behind the same WebSocket-only gate.", - "pathfind_fast_milliseconds": "PathRequestManager.h:35, makeEvent('pathfind_fast') with the default millisecond unit, so the exported form is the pathfind_fast_milliseconds_bucket/_count/_sum triple and there is no bare series — the same convention io_latency and rpc_method_us follow, and rpc-pathfinding queries the _bucket. THE OPERATIVE BLOCKER IS THE CONFIG, NOT THE CALL GRAPH: pathfinding is disabled outright on every harness node, so no PathRequest is ever constructed and no pathfind_* histogram can exist. Config.cpp:725-726 sets pathSearchMax to 0 whenever a [validation_seed] or [validator_token] section is present ('By default, validators don't have pathfinding enabled'); run-full-validation.sh writes [validation_seed] into every generated node cfg (:308) and contains no [path_search], [path_search_fast] or [path_search_max] section to put it back (grep count 0 for path_search in that file — the only [path_search*] sections in docker/telemetry/ are in xrpld-telemetry.cfg and xrpld-telemetry-mainnet.cfg, neither of which the harness uses); and doRipplePathFind returns rpcNOT_SUPPORTED at RipplePathFind.cpp:48-49, before context.loadType is set and before any branch on the ledger parameter. That config gate alone would keep the metric absent even if the generator did issue the command, because every such call is refused at the front door; and the generator issues no path-finding RPC in the first place. Two independent reasons. Read that first: the structural argument below is correct and matters if pathfinding is ever enabled, but it is not why the metric is missing today. STRUCTURAL ARGUMENT (verified, applies once pathSearchMax is non-zero): reportFast's only caller is PathRequest.cpp:852, inside the 'if (fast && quickReply_ == {})' branch of PathRequest::doUpdate. The only doUpdate call that passes fast=true is in PathRequest::doCreate (PathRequest.cpp:259), guarded by '!hasCompletion()'. Both ripple_path_find entry points construct the PathRequest with a completion function, so hasCompletion() (:161-164) is true and the fast pass is skipped: with no ledger specified doRipplePathFind goes to makeLegacyPathRequest, which passes the coroutine-post lambda (RipplePathFind.cpp:140-160); with a ledger specified it goes to doLegacyPathRequest, which passes an empty-body but non-null lambda (PathRequestManager.cpp:317). Only the path_find streaming subscription reaches reportFast, because makePathRequest builds the request from a subscriber with no completion (PathRequestManager.cpp:261). The load generator has never used path_find: it fires one request per send and awaits one reply, which a streaming subscription does not fit. Covering this metric therefore needs both a [path_search_max] override (or a non-validator node) in run-full-validation.sh and a path_find subscription phase in the generator. Both are harness/workload changes and out of scope here. Grafana Cloud shows zero series in 180 days on the devnet nodes, consistent with those nodes receiving no pathfinding RPC.", - "pathfind_full_milliseconds": "PathRequestManager.h:36, makeEvent('pathfind_full'); same histogram naming as pathfind_fast_milliseconds above. Notified from reportFull (:87-90) via PathRequest.cpp:857, the 'else if (!fast && fullReply_ == {})' branch. Blocked by exactly the same config gate as pathfind_fast_milliseconds, and the probability of emission under the harness workload is zero, not low: pathSearchMax is 0 on every harness node (Config.cpp:725-726 plus the [validation_seed] section at run-full-validation.sh:308, with no [path_search*] override anywhere in that file), so doRipplePathFind returns rpcNOT_SUPPORTED at RipplePathFind.cpp:48-49 and no PathRequest object is ever constructed for reportFull to fire from. An earlier revision of this entry described the path as reachable-but-probabilistic — emitting one ledger close behind the request via PathRequestManager::updateAll's one-shot branch (PathRequestManager.cpp:160-166) — and prescribed sending an explicit ledger_index from the generator so doLegacyPathRequest would call doUpdate(cache, false) synchronously (PathRequestManager.cpp:321). Both halves were wrong. The probability is zero rather than merely unreliable, and the prescribed remedy cannot work at all, because the pathSearchMax guard fires before the ledger parameter is read: adding ledger_index changes nothing while pathfinding is off. The generator also issues no path-finding RPC, so covering this metric needs a [path_search_max] override (or a non-validator node) in run-full-validation.sh AND path-finding load added — a harness-topology plus workload change, out of scope here. The workload README section 'Pathfinding is not exercised' holds the recipe. Grafana Cloud shows zero series in 180 days on the devnet nodes, consistent with those nodes receiving no pathfinding RPC rather than with a broken exporter.", + "pathfind_fast_milliseconds": "PathRequestManager.h:35, makeEvent('pathfind_fast') with the default millisecond unit, so the exported form is the pathfind_fast_milliseconds_bucket/_count/_sum triple and there is no bare series — the same convention io_latency and rpc_method_us follow, and rpc-pathfinding queries the _bucket. THE OPERATIVE BLOCKER IS THE CONFIG, NOT THE CALL GRAPH: pathfinding is disabled outright on every harness node, so no PathRequest is ever constructed and no pathfind_* histogram can exist. Config.cpp:725-726 sets pathSearchMax to 0 whenever a [validation_seed] or [validator_token] section is present ('By default, validators don't have pathfinding enabled'); run-full-validation.sh writes [validation_seed] into every generated node cfg and contains no [path_search], [path_search_fast] or [path_search_max] section to put it back (grep count 0 for path_search in that file — the only [path_search*] sections in docker/telemetry/ are in xrpld-telemetry.cfg and xrpld-telemetry-mainnet.cfg, neither of which the harness uses); and doRipplePathFind returns RpcNotSupported at RipplePathFind.cpp:59-60, before context.loadType is set and before any branch on the ledger parameter. That config gate alone would keep the metric absent even if the generator did issue the command, because every such call is refused at the front door; and the generator issues no path-finding RPC in the first place. Two independent reasons. Read that first: the structural argument below is correct and matters if pathfinding is ever enabled, but it is not why the metric is missing today. STRUCTURAL ARGUMENT (verified, applies once pathSearchMax is non-zero): reportFast's only caller is PathRequest.cpp:852, inside the 'if (fast && quickReply_ == {})' branch of PathRequest::doUpdate. The only doUpdate call that passes fast=true is in PathRequest::doCreate (PathRequest.cpp:259), guarded by '!hasCompletion()'. Both ripple_path_find entry points construct the PathRequest with a completion function, so hasCompletion() (:161-164) is true and the fast pass is skipped: with no ledger specified doRipplePathFind goes to makeLegacyPathRequest, which passes the coroutine-post lambda (RipplePathFind.cpp:140-160); with a ledger specified it goes to doLegacyPathRequest, which passes an empty-body but non-null lambda (PathRequestManager.cpp:317). Only the path_find streaming subscription reaches reportFast, because makePathRequest builds the request from a subscriber with no completion (PathRequestManager.cpp:261). The load generator has never used path_find: it fires one request per send and awaits one reply, which a streaming subscription does not fit. Covering this metric therefore needs both a [path_search_max] override (or a non-validator node) in run-full-validation.sh and a path_find subscription phase in the generator. Both are harness/workload changes and out of scope here. Grafana Cloud shows zero series in 180 days on the devnet nodes, consistent with those nodes receiving no pathfinding RPC.", + "pathfind_full_milliseconds": "PathRequestManager.h:36, makeEvent('pathfind_full'); same histogram naming as pathfind_fast_milliseconds above. Notified from reportFull (:87-90) via PathRequest.cpp:857, the 'else if (!fast && fullReply_ == {})' branch. Blocked by exactly the same config gate as pathfind_fast_milliseconds, and the probability of emission under the harness workload is zero, not low: pathSearchMax is 0 on every harness node (Config.cpp:725-726 plus the [validation_seed] section run-full-validation.sh writes, with no [path_search*] override anywhere in that file), so doRipplePathFind returns RpcNotSupported at RipplePathFind.cpp:59-60 and no PathRequest object is ever constructed for reportFull to fire from. An earlier revision of this entry described the path as reachable-but-probabilistic — emitting one ledger close behind the request via PathRequestManager::updateAll's one-shot branch (PathRequestManager.cpp:160-166) — and prescribed sending an explicit ledger_index from the generator so doLegacyPathRequest would call doUpdate(cache, false) synchronously (PathRequestManager.cpp:321). Both halves were wrong. The probability is zero rather than merely unreliable, and the prescribed remedy cannot work at all, because the pathSearchMax guard fires before the ledger parameter is read: adding ledger_index changes nothing while pathfinding is off. The generator also issues no path-finding RPC, so covering this metric needs a [path_search_max] override (or a non-validator node) in run-full-validation.sh AND path-finding load added — a harness-topology plus workload change, out of scope here. The workload README section 'Pathfinding is not exercised' holds the recipe. Grafana Cloud shows zero series in 180 days on the devnet nodes, consistent with those nodes receiving no pathfinding RPC rather than with a broken exporter.", "warn_total": "include/xrpl/resource/detail/Logic.h:41, makeMeter('warn'). makeMeter maps to CreateUInt64Counter (OTelCollector.cpp:878-881 -> :773-777), so the Prometheus exporter appends _total; the meter is created on the bare collector with no group, hence the unprefixed name. Incremented only at Logic.h:481, inside the 'if (notify)' branch reached when a consumer's balance crosses kWarningThreshold. A cooperating 5-node cluster plus a rate-limited load generator never charges a consumer that far, and Grafana Cloud confirms zero series in 180 days. Recorded explicitly because this was briefly mis-diagnosed as a phantom metric: the rpc-pathfinding panel that queries it is correct, and renders empty only because the condition has not occurred.", "drop_total": "include/xrpl/resource/detail/Logic.h:42, makeMeter('drop'); same CreateUInt64Counter mapping and same _total suffix as warn_total. Incremented only at Logic.h:505, when a consumer's balance is at or above kDropThreshold and the connection is dropped. Grafana Cloud shows 2 live series, so unlike warn_total this one does fire in the wild — but only on a genuinely abusive consumer, which the harness deliberately does not create, so it is condition-gated all the same. Its rpc-pathfinding panel is likewise correct rather than phantom.", "jobq_*_milliseconds, jobq_*_q_milliseconds": "This key is a pattern rather than a literal metric name — unlike every other entry in this map it stands for a whole family, one pair per job type. Created per job type in JobTypeData.h:97-98 from info.name() and info.name() + kSuffixQueued ('_q'), so the exported names are jobq__milliseconds and jobq__q_milliseconds with the job type lowercased by formatName. Which job types appear depends on which jobs a run happens to schedule, so no individual name is guaranteed. They are also rounded up to a whole millisecond at source (Event.h:47-51 applies ceil to a millisecond value type), which is why 6e2b2da772 moved the ledger-data-sync q-wait panels off jobq__q_milliseconds_bucket onto job_queued_us_bucket — they are poor assertion targets regardless." diff --git a/docker/telemetry/workload/expected_spans.json b/docker/telemetry/workload/expected_spans.json index 3309bf86cb..375c29be22 100644 --- a/docker/telemetry/workload/expected_spans.json +++ b/docker/telemetry/workload/expected_spans.json @@ -25,7 +25,7 @@ "required_attributes": [], "config_flag": "trace_rpc", "optional": true, - "note": "HTTP-only. Created solely in ServerHandler::processRequest() (ServerHandler.cpp:705), which is reached only from processSession(Session, coro) (ServerHandler.cpp:646) — the HTTP/JSON-RPC path that roots rpc.http_request at ServerHandler.cpp:640-641. The WebSocket path (processSession(WSSession, coro, jv), ServerHandler.cpp:467) never calls processRequest, so this span never appears under a WebSocket request. It does still appear under this harness, 5 traces on a normal run, because run-full-validation.sh polls each node over HTTP with curl (:449, :502) and those requests take the HTTP path. Note that the harness does speak HTTP: a reader concluding this span is unreachable here would go looking for a way to add HTTP traffic that already exists." + "note": "HTTP-only. Created solely in ServerHandler::processRequest() (ServerHandler.cpp:718), which is reached only from processSession(Session, coro) (ServerHandler.cpp:646) — the HTTP/JSON-RPC path that roots rpc.http_request at ServerHandler.cpp:640-641. The WebSocket path (processSession(WSSession, coro, jv), ServerHandler.cpp:467) never calls processRequest, so this span never appears under a WebSocket request. It does still appear under this harness, 5 traces on a normal run, because run-full-validation.sh polls each node over HTTP with curl (:449, :502) and those requests take the HTTP path. Note that the harness does speak HTTP: a reader concluding this span is unreachable here would go looking for a way to add HTTP traffic that already exists." }, { "name": "rpc.command.*", @@ -242,7 +242,7 @@ "resolution_direction" ], "config_flag": "trace_consensus", - "note": "Also carries close_time_correct, close_resolution_ms, consensus_state, proposing, round_time_ms, tx_count. Emits a tx.included span EVENT per transaction in the accepted set (RCLConsensus.cpp:666, with a tx_id attribute), which validate_telemetry.py cannot assert (no event support)." + "note": "Also carries close_time_correct, close_resolution_ms, consensus_state, proposing, round_time_ms, tx_count. Emits a tx.included span EVENT per transaction in the accepted set (RCLConsensus.cpp:720, with a tx_id attribute), which validate_telemetry.py cannot assert (no event support)." }, { "name": "consensus.validation.send", @@ -353,7 +353,7 @@ "required_attributes": ["pathfind_fast"], "config_flag": "trace_rpc", "optional": true, - "note": "Created by PathRequest::doUpdate (PathRequest.cpp:749-750), which the harness never reaches: pathfinding is disabled on every harness node, so no PathRequest is ever constructed. Config.cpp:725-726 sets pathSearchMax to 0 when a [validation_seed] or [validator_token] section is present, run-full-validation.sh writes [validation_seed] for every node (:308) and has no [path_search*] override, and doRipplePathFind then returns rpcNOT_SUPPORTED at RipplePathFind.cpp:48-49 — above the request-construction branches and below the pathfind.request span guard at :35. Liquidity is not the reason and never was: the call is refused before any path search is attempted, so the outcome does not depend on what the ledger holds. There is a second, independent reason: the harness sends no path-finding RPC at all, since rpc_load_generator.py carries no ripple_path_find weight. Enabling this span therefore needs BOTH a [path_search_max] override (or a non-validator node) in run-full-validation.sh AND the load restored — see the workload README section 'Pathfinding is not exercised'." + "note": "Created by PathRequest::doUpdate (PathRequest.cpp:749-750), which the harness never reaches: pathfinding is disabled on every harness node, so no PathRequest is ever constructed. Config.cpp:725-726 sets pathSearchMax to 0 when a [validation_seed] or [validator_token] section is present, run-full-validation.sh writes [validation_seed] for every node and has no [path_search*] override, and doRipplePathFind then returns RpcNotSupported at RipplePathFind.cpp:59-60 — above the request-construction branches and below the pathfind.request span guard at :35. Liquidity is not the reason and never was: the call is refused before any path search is attempted, so the outcome does not depend on what the ledger holds. There is a second, independent reason: the harness sends no path-finding RPC at all, since rpc_load_generator.py carries no ripple_path_find weight. Enabling this span therefore needs BOTH a [path_search_max] override (or a non-validator node) in run-full-validation.sh AND the load restored — see the workload README section 'Pathfinding is not exercised'." }, { "name": "pathfind.discover", @@ -371,7 +371,7 @@ "required_attributes": ["pathfind_ledger_index", "pathfind_num_requests"], "config_flag": "trace_rpc", "optional": true, - "note": "Async recomputation at ledger close. PathRequestManager::updateAll emits the span only when requests_ is non-empty (PathRequestManager.cpp:88-95), so it needs a live path_find subscription. On the harness requests_ can never become non-empty at all: the only two insertPathRequest call sites are makePathRequest (:268) and makeLegacyPathRequest (:296), and both handlers return rpcNOT_SUPPORTED first because pathfinding is disabled on every node (PathFind.cpp:39, RipplePathFind.cpp:48; see the pathfind.compute entry above for the config chain)." + "note": "Async recomputation at ledger close. PathRequestManager::updateAll emits the span only when requests_ is non-empty (PathRequestManager.cpp:88-95), so it needs a live path_find subscription. On the harness requests_ can never become non-empty at all: the only two insertPathRequest call sites are makePathRequest (:268) and makeLegacyPathRequest (:296), and both handlers return RpcNotSupported first because pathfinding is disabled on every node (PathFind.cpp:50-51, RipplePathFind.cpp:59; see the pathfind.compute entry above for the config chain)." }, { "name": "grpc.*", @@ -389,7 +389,7 @@ "child": "rpc.process", "description": "WebSocket message contains processing span", "skip": true, - "skip_reason": "This relationship does not exist in the code: rpc.process is created only in ServerHandler::processRequest() (ServerHandler.cpp:705), reached only from processSession(Session, coro) (ServerHandler.cpp:646) — the HTTP/JSON-RPC path. The WebSocket path (processSession(WSSession, coro, jv), ServerHandler.cpp:467) never calls processRequest, so rpc.process is never emitted at all under the WebSocket-only harness. The earlier diagnosis (cross-thread context loss needing a C++ fix) was wrong: rpc.ws_message is a deliberate freshRoot (ServerHandler.cpp:473-474) so each WS message is its own trace rather than nesting under a span leaked on a reused coroutine worker. Nothing to fix." + "skip_reason": "This relationship does not exist in the code: rpc.process is created only in ServerHandler::processRequest() (ServerHandler.cpp:718), reached only from processSession(Session, coro) (ServerHandler.cpp:646) — the HTTP/JSON-RPC path. The WebSocket path (processSession(WSSession, coro, jv), ServerHandler.cpp:467) never calls processRequest, so rpc.process is never emitted at all under the WebSocket-only harness. The earlier diagnosis (cross-thread context loss needing a C++ fix) was wrong: rpc.ws_message is a deliberate freshRoot (ServerHandler.cpp:473-474) so each WS message is its own trace rather than nesting under a span leaked on a reused coroutine worker. Nothing to fix." }, { "parent": "rpc.ws_message", @@ -421,7 +421,7 @@ "child": "pathfind.compute", "description": "Pathfind request contains the compute sub-span", "skip": true, - "skip_reason": "Real relationship (pathfind.compute is created inside PathRequest::doUpdate at PathRequest.cpp:749-750, under the pathfind.request scope), but the child never exists on the harness because pathfinding is disabled on every node: Config.cpp:725-726 zeroes pathSearchMax whenever a [validation_seed] or [validator_token] section is present, run-full-validation.sh writes [validation_seed] for all five nodes (:308) with no [path_search*] override, and doRipplePathFind returns rpcNOT_SUPPORTED at RipplePathFind.cpp:48-49 before constructing a PathRequest. The parent would appear anyway if the RPC were issued, because its ScopedSpanGuard is created at RipplePathFind.cpp:35, above that guard; but rpc_load_generator.py carries no ripple_path_find weight, so not even the parent appears and both ends of this relationship are absent. Liquidity has nothing to do with it — the earlier 'no liquidity, returns before computing' reason was wrong, because no path search is attempted at all. Asserting this relationship needs the load restored AND a [path_search_max] override (or a non-validator node) in run-full-validation.sh." + "skip_reason": "Real relationship (pathfind.compute is created inside PathRequest::doUpdate at PathRequest.cpp:749-750, under the pathfind.request scope), but the child never exists on the harness because pathfinding is disabled on every node: Config.cpp:725-726 zeroes pathSearchMax whenever a [validation_seed] or [validator_token] section is present, run-full-validation.sh writes [validation_seed] for all five nodes with no [path_search*] override, and doRipplePathFind returns RpcNotSupported at RipplePathFind.cpp:59-60 before constructing a PathRequest. The parent would appear anyway if the RPC were issued, because its ScopedSpanGuard is created at RipplePathFind.cpp:35, above that guard; but rpc_load_generator.py carries no ripple_path_find weight, so not even the parent appears and both ends of this relationship are absent. Liquidity has nothing to do with it — the earlier 'no liquidity, returns before computing' reason was wrong, because no path search is attempted at all. Asserting this relationship needs the load restored AND a [path_search_max] override (or a non-validator node) in run-full-validation.sh." }, { "parent": "rpc.command.*", @@ -436,7 +436,7 @@ "child": "pathfind.discover", "description": "The path computation contains the discovery pass.", "skip": true, - "skip_reason": "Real relationship with BOTH ends absent, for the reason given in full on the pathfind.compute entry above: pathfinding is disabled on every harness node because Config.cpp:725-726 zeroes pathSearchMax whenever a [validation_seed] section is present, run-full-validation.sh writes one for all five nodes (:308) with no [path_search_max] override, so doRipplePathFind returns rpcNOT_SUPPORTED before any PathRequest is constructed -- and the harness sends no path-finding RPC at all either. Asserting this needs both blockers lifted, which is a workload and node-config change rather than a harness one. Listed here so that the pathfinding family is fully accounted for rather than partly silent.", + "skip_reason": "Real relationship with BOTH ends absent, for the reason given in full on the pathfind.compute entry above: pathfinding is disabled on every harness node because Config.cpp:725-726 zeroes pathSearchMax whenever a [validation_seed] section is present, run-full-validation.sh writes one for all five nodes with no [path_search_max] override, so doRipplePathFind returns RpcNotSupported before any PathRequest is constructed -- and the harness sends no path-finding RPC at all either. Asserting this needs both blockers lifted, which is a workload and node-config change rather than a harness one. Listed here so that the pathfinding family is fully accounted for rather than partly silent.", "added": "Closes the declared-but-unlisted gap" }, diff --git a/docker/telemetry/workload/regression-metrics.json b/docker/telemetry/workload/regression-metrics.json index d53396e755..70508085ad 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.", "_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_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_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: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 — 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 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_keys": { @@ -10,7 +10,7 @@ "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." + "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." }, "spans": { "_query_template": "histogram_quantile({quantile}, sum by (le) (rate(span_duration_milliseconds_bucket{span_name=\"{name}\"}[{window}])))", diff --git a/docs/telemetry-runbook.md b/docs/telemetry-runbook.md index f881049dcd..2d85f4e99f 100644 --- a/docs/telemetry-runbook.md +++ b/docs/telemetry-runbook.md @@ -2853,7 +2853,7 @@ With all four satisfied, `info` is the minimum level at which the `log.trace_id_ `debug` does correlate strictly more: it additionally brings in [`BuildLedger.cpp:81`](../src/xrpld/app/ledger/detail/BuildLedger.cpp#L81) (inside the `ledger.build` `ScopedSpanGuard` at [:55](../src/xrpld/app/ledger/detail/BuildLedger.cpp#L55), once per ledger close) and [`RPCHandler.cpp:188`](../src/xrpld/rpc/detail/RPCHandler.cpp#L188) (inside the `rpc.command.*` `ScopedSpanGuard` at [:168](../src/xrpld/rpc/detail/RPCHandler.cpp#L168), once per RPC command), giving broader multi-subsystem coverage. -But raising the **base** level to `debug` puts synchronous log I/O inside `ledger.build`, `consensus.accept` (including [RCLConsensus.cpp:663](../src/xrpld/app/consensus/RCLConsensus.cpp#L663), which logs **per transaction**) and `tx.apply` — precisely the spans whose p50/p95/p99 latencies `regression-metrics.json` gates. A baseline captured at `debug` bakes that log I/O into the latency numbers permanently, turning the regression gate into a measurement of its own configuration. +But raising the **base** level to `debug` puts synchronous log I/O inside `ledger.build`, `consensus.accept` (including [RCLConsensus.cpp:715](../src/xrpld/app/consensus/RCLConsensus.cpp#L715), which logs **per transaction**) and `tx.apply` — precisely the spans whose p50/p95/p99 latencies `regression-metrics.json` gates. A baseline captured at `debug` bakes that log I/O into the latency numbers permanently, turning the regression gate into a measurement of its own configuration. So if you need the broader coverage, enable it **per partition** rather than globally, and only **after** a baseline has been captured at the harness's normal level: