From 6e2b2da7728660d17c17dde7c0e475d28ea79c2a Mon Sep 17 00:00:00 2001 From: Pratik Mankawde <3397372+pratikmankawde@users.noreply.github.com> Date: Fri, 21 Aug 2026 12:46:56 +0100 Subject: [PATCH] fix(telemetry): resolve microsecond latencies below 100us The microsecond ladder's first edge was 100us, which sat ABOVE the mass of every instrument using it. Measured on devnet: 99.3% of job_queued_us samples, 92.5% of job_running_us and 90.4% of getobject_lookup_us fell in that first bucket. histogram_quantile then interpolated inside bucket 0 and returned `quantile / fraction_in_bucket_0 x first_edge` -- p75/p95/p99 of job_queued_us read 75.52/95.66/99.69us against a prediction of 75.53/95.67/99.70. Three-decimal agreement: those panels were reporting arithmetic on the bucket edge, not latency. The fix was already half-written. kSubMillisecondBoundaries had been parked in MetricsRegistry.cpp as [[maybe_unused]] with a comment noting exactly this problem for nodestore reads. Its edges are now folded into kMicrosecondBuckets rather than deleted, so the parked intent is carried forward: 1..1000us resolution where the mass is, upper edges unchanged so multi-second stalls stay measurable. Also moves the GetObject count and charge ladders into HistogramBuckets.h, so all five ladders have one owner and one set of invariant tests (29 now). Adds check_bucket_parity.py, wired into the existing OTel naming workflow. The C++ millisecond ladder and the collector's spanmetrics ladder are specified to agree over their shared range; they were identical when shipped, then the collector side alone was extended and nothing noticed for eleven phases. The check asserts containment rather than equality, because jobs outlive spans -- jobq_updatepaths averages ~60s, which no span approaches, so demanding equality would force a ceiling that censors it. Verified it rejects a missing collector edge, a bogus in-range edge, and a return to the 5s ceiling. ledger-data-sync's "Job Queue Wait p95 By Type" moves off the beast jobq_*_q_milliseconds pair onto job_queued_us filtered by job_type. Those beast metrics are ms-quantised at the source (Event rounds up to a whole millisecond), so 94-100% of their samples sat in the first bucket and no ladder change could fix them. Note the label values are camelCase (job_type="ledgerData"), not the lowercase metric-name fragments. Both histogram-fed alert thresholds re-validated and left unchanged, with the measured basis recorded so neither gets tuned against the old artefact: only 0.0022% of job_queued_us samples exceed the 1s threshold, and every edge bracketing the 1000ms ios_latency threshold survived the ladder change. Docs: the rpc_size "known issue -- tracked separately" notes in the runbook and 09-data-collection-reference are now resolved notes, the stale 10-edge span_duration bucket list is corrected to the collector's real 20, and the runbook gains a "Reading A Histogram Percentile" section covering both saturation traps and the expected discontinuity after a ladder change. --- .../scripts/telemetry/check_bucket_parity.py | 128 ++++++++++++++++++ .github/workflows/on-pr.yml | 1 + .../workflows/reusable-check-otel-naming.yml | 8 ++ .../09-data-collection-reference.md | 27 ++-- .../grafana/dashboards/ledger-data-sync.json | 16 +-- .../grafana/provisioning/alerting/rules.yaml | 15 ++ docs/telemetry-runbook.md | 64 +++++++-- include/xrpl/telemetry/HistogramBuckets.h | 65 +++++++++ .../libxrpl/telemetry/HistogramBuckets.cpp | 47 ++++++- src/xrpld/telemetry/MetricsRegistry.cpp | 80 ++--------- 10 files changed, 354 insertions(+), 97 deletions(-) create mode 100755 .github/scripts/telemetry/check_bucket_parity.py diff --git a/.github/scripts/telemetry/check_bucket_parity.py b/.github/scripts/telemetry/check_bucket_parity.py new file mode 100755 index 0000000000..4c723fb4c0 --- /dev/null +++ b/.github/scripts/telemetry/check_bucket_parity.py @@ -0,0 +1,128 @@ +#!/usr/bin/env python3 +"""Assert the C++ millisecond ladder agrees with the collector's spanmetrics ladder. + +The two are specified to match so a span-derived latency panel and a native +histogram panel can be read on the same scale. They *were* identical when first +shipped. Then the collector ladder alone was extended -- sub-millisecond edges +below 1ms and second-scale edges up to 30s -- and nothing checked the other +side, so the C++ ladder stayed capped at 5s. Every quantile above 5s then read +back as a flat 5000, because Prometheus returns the second-highest edge for a +quantile landing in the `+Inf` bucket. That looks like a measurement rather +than an error, which is why it survived for eleven phases. + +The rule is containment, not equality: + + * every representable collector edge MUST appear in the C++ ladder, so the + shared range reads identically; + * the C++ ladder MAY carry extra edges ABOVE the collector's highest edge, + because jobs outlive spans -- the updatepaths job type was measured + averaging ~60s, which no span approaches. Demanding equality would force a + ceiling that censors it, reintroducing the bug this guards against; + * collector edges below 1ms are expected to be ABSENT rather than missing: + beast::insight::Event rounds every duration up to a whole millisecond + before it reaches the histogram, so those edges could never collect a + sample. + +Exit 0 when the ladders agree, 1 with a diff when they do not. +""" + +import re +import sys +from pathlib import Path + +HEADER = Path("include/xrpl/telemetry/HistogramBuckets.h") +COLLECTOR = Path("docker/telemetry/otel-collector-config.yaml") + +# beast::insight::Event applies ceil, so anything below 1ms +# collapses onto the 1ms edge. +REPRESENTABLE_FLOOR_MS = 1.0 + +UNIT_TO_MS = {"ms": 1.0, "s": 1000.0} + + +def collector_edges_ms(): + """Parse the spanmetrics bucket list, normalising each edge to milliseconds.""" + text = COLLECTOR.read_text() + match = re.search(r"buckets:\s*\[(.*?)\]", text, re.S) + if not match: + sys.exit(f"{COLLECTOR}: no 'buckets:' list found") + + edges = [] + for raw in match.group(1).split(","): + token = raw.strip() + if not token: + continue + parsed = re.fullmatch(r"([0-9.]+)(ms|s)", token) + if not parsed: + sys.exit(f"{COLLECTOR}: cannot parse bucket edge {token!r}") + edges.append(float(parsed.group(1)) * UNIT_TO_MS[parsed.group(2)]) + return edges + + +def cpp_edges_ms(): + """Parse kMillisecondBuckets out of the header that owns every ladder.""" + text = HEADER.read_text() + match = re.search(r"kMillisecondBuckets\{(.*?)\};", text, re.S) + if not match: + sys.exit(f"{HEADER}: kMillisecondBuckets not found") + return [ + float(token.strip().replace("'", "")) + for token in match.group(1).split(",") + if token.strip() + ] + + +def main(): + collector = collector_edges_ms() + cpp = cpp_edges_ms() + required = [edge for edge in collector if edge >= REPRESENTABLE_FLOOR_MS] + if not required: + sys.exit(f"{COLLECTOR}: no edges at or above {REPRESENTABLE_FLOOR_MS} ms") + collector_top = max(required) + + missing = [edge for edge in required if edge not in cpp] + # An extra C++ edge inside the collector's range means the two scales + # disagree where they overlap. Above the collector's top it is a deliberate + # extension. + inside_range = [e for e in cpp if e not in required and e < collector_top] + + if not missing and not inside_range: + extensions = [e for e in cpp if e > collector_top] + summary = f"OK: all {len(required)} representable collector edges present" + if extensions: + pretty = ", ".join(f"{e:g}" for e in extensions) + summary += ( + f"; {len(extensions)} extension edge(s) above " + f"{collector_top:g} ms: [{pretty}]" + ) + print(summary) + return 0 + + print("Bucket ladder parity violated.", file=sys.stderr) + print( + f" collector (>= {REPRESENTABLE_FLOOR_MS:g} ms): " + f"{[f'{e:g}' for e in required]}", + file=sys.stderr, + ) + print( + f" HistogramBuckets.h : {[f'{e:g}' for e in cpp]}", file=sys.stderr + ) + for edge in missing: + print(f" MISSING from the C++ ladder: {edge:g} ms", file=sys.stderr) + for edge in inside_range: + print( + f" C++ edge {edge:g} ms lies inside the collector's range but is not " + "a collector edge -- add it to the collector or drop it here", + file=sys.stderr, + ) + print( + "\nThe two ladders must agree over their shared range. Extra C++ edges are\n" + "permitted only ABOVE the collector's highest edge. Change both sides, or\n" + "change the spec in OpenTelemetryPlan/Phase7_taskList.md.", + file=sys.stderr, + ) + return 1 + + +if __name__ == "__main__": + sys.exit(main()) diff --git a/.github/workflows/on-pr.yml b/.github/workflows/on-pr.yml index 9fd8b14b27..5135f45b43 100644 --- a/.github/workflows/on-pr.yml +++ b/.github/workflows/on-pr.yml @@ -72,6 +72,7 @@ jobs: .github/scripts/levelization/** .github/scripts/otel-naming/** .github/scripts/rename/** + .github/scripts/telemetry/** .github/workflows/reusable-check-levelization.yml .github/workflows/reusable-check-otel-naming.yml .github/workflows/reusable-check-rename.yml diff --git a/.github/workflows/reusable-check-otel-naming.yml b/.github/workflows/reusable-check-otel-naming.yml index 54cab30640..a37e7e1632 100644 --- a/.github/workflows/reusable-check-otel-naming.yml +++ b/.github/workflows/reusable-check-otel-naming.yml @@ -33,3 +33,11 @@ jobs: # it enforces each rule only when the layer it needs is present, so it # works whether telemetry changes land in one PR or several. run: python .github/scripts/otel-naming/check_otel_naming.py + - name: Check histogram bucket parity + # The C++ millisecond ladder and the collector's spanmetrics ladder are + # specified to agree over their shared range. They were identical when + # first shipped, then the collector side alone was extended and nothing + # noticed for eleven phases: native histograms stayed capped at 5s while + # spans reached 30s, so every quantile above 5s reported a flat 5000. + # Nothing but a check keeps two lists in step. + run: python .github/scripts/telemetry/check_bucket_parity.py diff --git a/OpenTelemetryPlan/09-data-collection-reference.md b/OpenTelemetryPlan/09-data-collection-reference.md index 3578774b37..fd0d8135f6 100644 --- a/OpenTelemetryPlan/09-data-collection-reference.md +++ b/OpenTelemetryPlan/09-data-collection-reference.md @@ -531,12 +531,12 @@ a destructor must not depend on still existing. A query that only groups by The OTel Collector's SpanMetrics connector automatically generates RED (Rate, Errors, Duration) metrics from every span. No custom metrics code in xrpld is needed. -| Prometheus Metric | Type | Description | -| ----------------------------------- | --------- | ------------------------------------------------------------------------------ | -| `span_calls_total` | Counter | Total span invocations | -| `span_duration_milliseconds_bucket` | Histogram | Latency distribution (buckets: 1, 5, 10, 25, 50, 100, 250, 500, 1000, 5000 ms) | -| `span_duration_milliseconds_count` | Histogram | Observation count | -| `span_duration_milliseconds_sum` | Histogram | Cumulative latency | +| Prometheus Metric | Type | Description | +| ----------------------------------- | --------- | ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | +| `span_calls_total` | Counter | Total span invocations | +| `span_duration_milliseconds_bucket` | Histogram | Latency distribution. Buckets come from the collector's spanmetrics config: 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. The sub-millisecond edges exist because most xrpld spans are far below 1 ms; without them every p95/p99 pinned to a constant 0.95 ms | +| `span_duration_milliseconds_count` | Histogram | Observation count | +| `span_duration_milliseconds_sum` | Histogram | Cumulative latency | **Standard labels on every metric**: `span_name`, `status_code`, `service_name`, `span_kind` @@ -684,13 +684,14 @@ prefix=xrpld Quantiles collected: 0th, 50th, 90th, 95th, 99th, 100th percentile. -\* **`rpc_size` instrument mismatch (known issue):** response size in bytes is -recorded through the millisecond-scaled event histogram (`makeEvent`), so it is -exported as `rpc_size_milliseconds_bucket` with time-scaled boundaries that top -out at 5000. Byte values above ~5 KB saturate in the last bucket, so the -percentiles are not true byte sizes. The _RPC & Pathfinding_ panel is flagged -accordingly. A dedicated byte-unit histogram is needed to fix this; tracked -separately. +\* **`rpc_size` now records bytes as bytes (fixed).** It used to go through the +millisecond-scaled event histogram and export as `rpc_size_milliseconds_bucket` +on a ladder topping out at 5000, so the 24.9% of responses larger than 5 kB all +landed in the last bucket and every percentile read back as a flat 5000 — a +plausible-looking constant rather than a byte size. `beast::insight::Event` now +declares a `Unit`, so this instrument is created with unit `By` and exports as +**`rpc_size_bytes_bucket`** on `kByteBuckets` (512 B to 1 MiB, placed from the +measured distribution). Queries and panels must use the new name. **Grafana dashboards**: _Node Health_ (`ios_latency`), _RPC & Pathfinding_ (`rpc_time`, `rpc_size`, `pathfind_*`) diff --git a/docker/telemetry/grafana/dashboards/ledger-data-sync.json b/docker/telemetry/grafana/dashboards/ledger-data-sync.json index 4eabe25f03..8f9e33efc5 100644 --- a/docker/telemetry/grafana/dashboards/ledger-data-sync.json +++ b/docker/telemetry/grafana/dashboards/ledger-data-sync.json @@ -1251,7 +1251,7 @@ }, { "title": "Job Queue Wait p95 By Type", - "description": "###### What this is:\n*95th-percentile time a job waits in the queue before a worker thread picks it up, for the sync-critical job types. This is the metric form of the 'ProcessLData wait: NNNNms' warnings in the debug log.*\n\n###### How it's computed:\n*histogram_quantile(0.95, rate(jobq__q_milliseconds_bucket[$__rate_interval])) for ledgerdata, acceptledger, fetchtxndata, transaction, advanceledger, ledgerrequest.*\n\n###### Reading it:\n*Queue wait should be single-digit to low-tens of ms. High ledgerdata/fetchtxndata wait = the node cannot process inbound ledger data fast enough.*\n\n###### Healthy range:\n*< ~50ms p95 per type on a healthy node.*\n\n###### Watch for:\n*ledgerdata or fetchtxndata q-wait spiking to seconds = worker threads are blocked (usually on NuDB reads - see the cause tier).*\n\n###### Keywords:\n- **Job queue / job type** *(per node)* \u2014 xrpld's worker-thread pool; every unit of background work is enqueued under a named job type.\n- **Deferred job** *(per node)* \u2014 a job held back because its type is already at its concurrency limit; the leading indicator of queue backpressure.\n\n###### Computation boundary:\n*Result: Per node \u2014 each series is one server's own value.*\n*Recorded in xrpld code as a native metric (beast::insight); the collector only forwards it; the Grafana query selects and aggregates it.*\n\n###### Source:\n[core/JobQueue.cpp](https://github.com/XRPLF/rippled/blob/develop/src/libxrpl/core/detail/JobQueue.cpp)\n\n###### Function:\n`JobQueue::getJson (per-type queue timing)`\n\n###### References:\n[Telemetry glossary](https://github.com/XRPLF/rippled/blob/develop/docs/telemetry-glossary.md#job-queue-job-type)", + "description": "###### What this is:\n*95th-percentile time a job waits in the queue before a worker thread picks it up, for the sync-critical job types. This is the metric form of the 'ProcessLData wait: NNNNms' warnings in the debug log.*\n\n###### How it's computed:\n*histogram_quantile(0.95, rate(job_queued_us_bucket{job_type=\"\"}[$__rate_interval])) for ledgerData, acceptLedger, fetchTxnData, transaction, advanceLedger, ledgerRequest. Reads the OTel-native microsecond instrument rather than the beast jobq_* pair: beast Events round every duration up to a whole millisecond, so 94-100% of their samples landed in the first bucket and every percentile was an interpolation inside it rather than a measurement.*\n\n###### Reading it:\n*Queue wait is normally tens to hundreds of microseconds. High ledgerData/fetchTxnData wait = the node cannot process inbound ledger data fast enough.*\n\n###### Healthy range:\n*< ~500us p95 per type on a healthy node; sustained milliseconds is already backpressure.*\n\n###### Watch for:\n*ledgerData or fetchTxnData q-wait spiking to seconds = worker threads are blocked (usually on NuDB reads - see the cause tier).*\n\n###### Keywords:\n- **Job queue / job type** *(per node)* \u2014 xrpld's worker-thread pool; every unit of background work is enqueued under a named job type.\n- **Deferred job** *(per node)* \u2014 a job held back because its type is already at its concurrency limit; the leading indicator of queue backpressure.\n\n###### Computation boundary:\n*Result: Per node \u2014 each series is one server's own value.*\n*Recorded in xrpld code by MetricsRegistry as an OTel-native histogram in microseconds; the collector only forwards it; the Grafana query selects and aggregates it.*\n\n###### Source:\n[core/JobQueue.cpp](https://github.com/XRPLF/rippled/blob/develop/src/libxrpl/core/detail/JobQueue.cpp)\n\n###### Function:\n`JobQueue::getJson (per-type queue timing)`\n\n###### References:\n[Telemetry glossary](https://github.com/XRPLF/rippled/blob/develop/docs/telemetry-glossary.md#job-queue-job-type)", "type": "timeseries", "gridPos": { "h": 10, @@ -1272,48 +1272,48 @@ "type": "prometheus", "uid": "${DS_PROMETHEUS}" }, - "expr": "label_replace(label_join(label_replace(histogram_quantile(0.95, sum by (le, service_instance_id, xrpl_branch, xrpl_node_role, xrpl_work_item) (rate(jobq_ledgerdata_q_milliseconds_bucket{service_instance_id=~\"$node\", deployment_environment=~\"$deployment_environment\", xrpl_network_type=~\"$xrpl_network_type\", service_name=~\"$service_name\", xrpl_work_item=~\"$xrpl_work_item\", xrpl_branch=~\"$xrpl_branch\", xrpl_node_role=~\"$xrpl_node_role\"}[$__rate_interval]))), \"series\", \"ledgerdata q-wait p95\", \"\", \"\"), \"xrpl_ident\", \", \", \"service_instance_id\", \"xrpl_branch\", \"xrpl_work_item\"), \"xrpl_ident\", \"[$1]\", \"xrpl_ident\", \"(?:, )*(.*[^, ])(?:, )*\")" + "expr": "label_replace(label_join(label_replace(histogram_quantile(0.95, sum by (le, service_instance_id, xrpl_branch, xrpl_node_role, xrpl_work_item) (rate(job_queued_us_bucket{job_type=\"ledgerData\", service_instance_id=~\"$node\", deployment_environment=~\"$deployment_environment\", xrpl_network_type=~\"$xrpl_network_type\", service_name=~\"$service_name\", xrpl_work_item=~\"$xrpl_work_item\", xrpl_branch=~\"$xrpl_branch\", xrpl_node_role=~\"$xrpl_node_role\"}[$__rate_interval]))), \"series\", \"ledgerData q-wait p95\", \"\", \"\"), \"xrpl_ident\", \", \", \"service_instance_id\", \"xrpl_branch\", \"xrpl_work_item\"), \"xrpl_ident\", \"[$1]\", \"xrpl_ident\", \"(?:, )*(.*[^, ])(?:, )*\")" }, { "datasource": { "type": "prometheus", "uid": "${DS_PROMETHEUS}" }, - "expr": "label_replace(label_join(label_replace(histogram_quantile(0.95, sum by (le, service_instance_id, xrpl_branch, xrpl_node_role, xrpl_work_item) (rate(jobq_acceptledger_q_milliseconds_bucket{service_instance_id=~\"$node\", deployment_environment=~\"$deployment_environment\", xrpl_network_type=~\"$xrpl_network_type\", service_name=~\"$service_name\", xrpl_work_item=~\"$xrpl_work_item\", xrpl_branch=~\"$xrpl_branch\", xrpl_node_role=~\"$xrpl_node_role\"}[$__rate_interval]))), \"series\", \"acceptledger q-wait p95\", \"\", \"\"), \"xrpl_ident\", \", \", \"service_instance_id\", \"xrpl_branch\", \"xrpl_work_item\"), \"xrpl_ident\", \"[$1]\", \"xrpl_ident\", \"(?:, )*(.*[^, ])(?:, )*\")" + "expr": "label_replace(label_join(label_replace(histogram_quantile(0.95, sum by (le, service_instance_id, xrpl_branch, xrpl_node_role, xrpl_work_item) (rate(job_queued_us_bucket{job_type=\"acceptLedger\", service_instance_id=~\"$node\", deployment_environment=~\"$deployment_environment\", xrpl_network_type=~\"$xrpl_network_type\", service_name=~\"$service_name\", xrpl_work_item=~\"$xrpl_work_item\", xrpl_branch=~\"$xrpl_branch\", xrpl_node_role=~\"$xrpl_node_role\"}[$__rate_interval]))), \"series\", \"acceptLedger q-wait p95\", \"\", \"\"), \"xrpl_ident\", \", \", \"service_instance_id\", \"xrpl_branch\", \"xrpl_work_item\"), \"xrpl_ident\", \"[$1]\", \"xrpl_ident\", \"(?:, )*(.*[^, ])(?:, )*\")" }, { "datasource": { "type": "prometheus", "uid": "${DS_PROMETHEUS}" }, - "expr": "label_replace(label_join(label_replace(histogram_quantile(0.95, sum by (le, service_instance_id, xrpl_branch, xrpl_node_role, xrpl_work_item) (rate(jobq_fetchtxndata_q_milliseconds_bucket{service_instance_id=~\"$node\", deployment_environment=~\"$deployment_environment\", xrpl_network_type=~\"$xrpl_network_type\", service_name=~\"$service_name\", xrpl_work_item=~\"$xrpl_work_item\", xrpl_branch=~\"$xrpl_branch\", xrpl_node_role=~\"$xrpl_node_role\"}[$__rate_interval]))), \"series\", \"fetchtxndata q-wait p95\", \"\", \"\"), \"xrpl_ident\", \", \", \"service_instance_id\", \"xrpl_branch\", \"xrpl_work_item\"), \"xrpl_ident\", \"[$1]\", \"xrpl_ident\", \"(?:, )*(.*[^, ])(?:, )*\")" + "expr": "label_replace(label_join(label_replace(histogram_quantile(0.95, sum by (le, service_instance_id, xrpl_branch, xrpl_node_role, xrpl_work_item) (rate(job_queued_us_bucket{job_type=\"fetchTxnData\", service_instance_id=~\"$node\", deployment_environment=~\"$deployment_environment\", xrpl_network_type=~\"$xrpl_network_type\", service_name=~\"$service_name\", xrpl_work_item=~\"$xrpl_work_item\", xrpl_branch=~\"$xrpl_branch\", xrpl_node_role=~\"$xrpl_node_role\"}[$__rate_interval]))), \"series\", \"fetchTxnData q-wait p95\", \"\", \"\"), \"xrpl_ident\", \", \", \"service_instance_id\", \"xrpl_branch\", \"xrpl_work_item\"), \"xrpl_ident\", \"[$1]\", \"xrpl_ident\", \"(?:, )*(.*[^, ])(?:, )*\")" }, { "datasource": { "type": "prometheus", "uid": "${DS_PROMETHEUS}" }, - "expr": "label_replace(label_join(label_replace(histogram_quantile(0.95, sum by (le, service_instance_id, xrpl_branch, xrpl_node_role, xrpl_work_item) (rate(jobq_transaction_q_milliseconds_bucket{service_instance_id=~\"$node\", deployment_environment=~\"$deployment_environment\", xrpl_network_type=~\"$xrpl_network_type\", service_name=~\"$service_name\", xrpl_work_item=~\"$xrpl_work_item\", xrpl_branch=~\"$xrpl_branch\", xrpl_node_role=~\"$xrpl_node_role\"}[$__rate_interval]))), \"series\", \"transaction q-wait p95\", \"\", \"\"), \"xrpl_ident\", \", \", \"service_instance_id\", \"xrpl_branch\", \"xrpl_work_item\"), \"xrpl_ident\", \"[$1]\", \"xrpl_ident\", \"(?:, )*(.*[^, ])(?:, )*\")" + "expr": "label_replace(label_join(label_replace(histogram_quantile(0.95, sum by (le, service_instance_id, xrpl_branch, xrpl_node_role, xrpl_work_item) (rate(job_queued_us_bucket{job_type=\"transaction\", service_instance_id=~\"$node\", deployment_environment=~\"$deployment_environment\", xrpl_network_type=~\"$xrpl_network_type\", service_name=~\"$service_name\", xrpl_work_item=~\"$xrpl_work_item\", xrpl_branch=~\"$xrpl_branch\", xrpl_node_role=~\"$xrpl_node_role\"}[$__rate_interval]))), \"series\", \"transaction q-wait p95\", \"\", \"\"), \"xrpl_ident\", \", \", \"service_instance_id\", \"xrpl_branch\", \"xrpl_work_item\"), \"xrpl_ident\", \"[$1]\", \"xrpl_ident\", \"(?:, )*(.*[^, ])(?:, )*\")" }, { "datasource": { "type": "prometheus", "uid": "${DS_PROMETHEUS}" }, - "expr": "label_replace(label_join(label_replace(histogram_quantile(0.95, sum by (le, service_instance_id, xrpl_branch, xrpl_node_role, xrpl_work_item) (rate(jobq_advanceledger_q_milliseconds_bucket{service_instance_id=~\"$node\", deployment_environment=~\"$deployment_environment\", xrpl_network_type=~\"$xrpl_network_type\", service_name=~\"$service_name\", xrpl_work_item=~\"$xrpl_work_item\", xrpl_branch=~\"$xrpl_branch\", xrpl_node_role=~\"$xrpl_node_role\"}[$__rate_interval]))), \"series\", \"advanceledger q-wait p95\", \"\", \"\"), \"xrpl_ident\", \", \", \"service_instance_id\", \"xrpl_branch\", \"xrpl_work_item\"), \"xrpl_ident\", \"[$1]\", \"xrpl_ident\", \"(?:, )*(.*[^, ])(?:, )*\")" + "expr": "label_replace(label_join(label_replace(histogram_quantile(0.95, sum by (le, service_instance_id, xrpl_branch, xrpl_node_role, xrpl_work_item) (rate(job_queued_us_bucket{job_type=\"advanceLedger\", service_instance_id=~\"$node\", deployment_environment=~\"$deployment_environment\", xrpl_network_type=~\"$xrpl_network_type\", service_name=~\"$service_name\", xrpl_work_item=~\"$xrpl_work_item\", xrpl_branch=~\"$xrpl_branch\", xrpl_node_role=~\"$xrpl_node_role\"}[$__rate_interval]))), \"series\", \"advanceLedger q-wait p95\", \"\", \"\"), \"xrpl_ident\", \", \", \"service_instance_id\", \"xrpl_branch\", \"xrpl_work_item\"), \"xrpl_ident\", \"[$1]\", \"xrpl_ident\", \"(?:, )*(.*[^, ])(?:, )*\")" }, { "datasource": { "type": "prometheus", "uid": "${DS_PROMETHEUS}" }, - "expr": "label_replace(label_join(label_replace(histogram_quantile(0.95, sum by (le, service_instance_id, xrpl_branch, xrpl_node_role, xrpl_work_item) (rate(jobq_ledgerrequest_q_milliseconds_bucket{service_instance_id=~\"$node\", deployment_environment=~\"$deployment_environment\", xrpl_network_type=~\"$xrpl_network_type\", service_name=~\"$service_name\", xrpl_work_item=~\"$xrpl_work_item\", xrpl_branch=~\"$xrpl_branch\", xrpl_node_role=~\"$xrpl_node_role\"}[$__rate_interval]))), \"series\", \"ledgerrequest q-wait p95\", \"\", \"\"), \"xrpl_ident\", \", \", \"service_instance_id\", \"xrpl_branch\", \"xrpl_work_item\"), \"xrpl_ident\", \"[$1]\", \"xrpl_ident\", \"(?:, )*(.*[^, ])(?:, )*\")" + "expr": "label_replace(label_join(label_replace(histogram_quantile(0.95, sum by (le, service_instance_id, xrpl_branch, xrpl_node_role, xrpl_work_item) (rate(job_queued_us_bucket{job_type=\"ledgerRequest\", service_instance_id=~\"$node\", deployment_environment=~\"$deployment_environment\", xrpl_network_type=~\"$xrpl_network_type\", service_name=~\"$service_name\", xrpl_work_item=~\"$xrpl_work_item\", xrpl_branch=~\"$xrpl_branch\", xrpl_node_role=~\"$xrpl_node_role\"}[$__rate_interval]))), \"series\", \"ledgerRequest q-wait p95\", \"\", \"\"), \"xrpl_ident\", \", \", \"service_instance_id\", \"xrpl_branch\", \"xrpl_work_item\"), \"xrpl_ident\", \"[$1]\", \"xrpl_ident\", \"(?:, )*(.*[^, ])(?:, )*\")" } ], "fieldConfig": { "defaults": { "displayName": "${__field.labels.series} ${__field.labels.xrpl_ident}", - "unit": "ms", + "unit": "µs", "custom": { "axisLabel": "p95 Wait (ms)", "spanNulls": 1800000, diff --git a/docker/telemetry/grafana/provisioning/alerting/rules.yaml b/docker/telemetry/grafana/provisioning/alerting/rules.yaml index 9746559b28..7d909074b2 100644 --- a/docker/telemetry/grafana/provisioning/alerting/rules.yaml +++ b/docker/telemetry/grafana/provisioning/alerting/rules.yaml @@ -480,6 +480,15 @@ groups: # p99 time a job waits in the queue before running. A sustained p99 # above 1s means the node is saturated and work is backing up. `le` must # stay inside the inner sum or histogram_quantile cannot interpolate. + # + # Threshold re-validated after the microsecond ladder was re-cut. Do NOT + # tune it down against a casual reading of this p99: before that change + # the ladder's first edge was 100us with 99.3% of samples beneath it, so + # p99 reported 99.7us -- the bucket edge scaled by the quantile, not a + # latency. Measured cumulative distribution: 99.26% of samples land + # within 100us, 99.969% within 5ms, 99.990% within 100ms, and only + # 0.0022% exceed 1s. So 1s sits about four orders of magnitude above the + # healthy p99 and fires only on genuine saturation, which is the intent. - uid: xrpld-jobqueue-latency-high title: JobQueueLatencyHigh condition: C @@ -544,6 +553,12 @@ groups: # first and explains the others. Measured p99-of-p95 is 37-49ms on # healthy nodes and 488-566ms on nodes that are actively flapping, so # 1000ms flags genuine degradation rather than the current baseline. + # + # Still valid after the millisecond ladder was extended: that change only + # ADDED edges above 5s (2s/3s/4s/10s/30s/60s/120s) and removed none, so + # every edge bracketing this threshold -- 25/50/100/250/500/1000ms -- is + # unchanged and the measurements above still hold. ios_latency's own mean + # is 12.9ms, far below the threshold. - uid: xrpld-nodestore-io-latency-high title: NodeStoreIOLatencyHigh condition: C diff --git a/docs/telemetry-runbook.md b/docs/telemetry-runbook.md index 3b903a784c..a95a0ab12e 100644 --- a/docs/telemetry-runbook.md +++ b/docs/telemetry-runbook.md @@ -2262,22 +2262,68 @@ Requires `trace_peer=1` in the `[telemetry]` config section. | ------------------------- | ---------- | ------------------------------------------------------------- | ----------- | | RPC Request Rate | stat | `rate(rpc_requests[5m])` | — | | RPC Response Time | timeseries | `histogram_quantile(0.95, rpc_time_milliseconds_bucket)` | — | -| RPC Response Size | timeseries | `histogram_quantile(0.95, rpc_size_milliseconds_bucket)` | — | +| RPC Response Size | timeseries | `histogram_quantile(0.95, rpc_size_bytes_bucket)` | — | | RPC Response Time Heatmap | heatmap | `rpc_time_milliseconds_bucket` | — | | Pathfinding Fast Duration | timeseries | `histogram_quantile(0.95, pathfind_fast_milliseconds_bucket)` | — | | Pathfinding Full Duration | timeseries | `histogram_quantile(0.95, pathfind_full_milliseconds_bucket)` | — | | Resource Warnings Rate | stat | `rate(warn_total[$__rate_interval])` | — | | Resource Drops Rate | stat | `rate(drop_total[$__rate_interval])` | — | -> **The `_milliseconds` suffix comes from the exporter, not from xrpld.** These -> histograms are created with unit `"ms"` -> ([OTelCollector.cpp:615](../src/libxrpl/beast/insight/OTelCollector.cpp#L615)), -> so the Prometheus exporter appends the unit to the family name — `rpc_time` -> becomes `rpc_time_milliseconds_bucket`. Querying the bare `rpc_time_bucket`, +> **The unit suffix comes from the exporter, not from xrpld.** Each histogram +> declares a unit, and the Prometheus exporter appends the unit's name to the +> family name — a `ms` instrument like `rpc_time` becomes +> `rpc_time_milliseconds_bucket`. Querying the bare `rpc_time_bucket`, > `ios_latency_bucket` or `pathfind_fast_bucket` returns no data and no error. -> **Known issue**: `rpc_size` counts bytes but shares the same `"ms"` histogram -> constructor, so it is exported as `rpc_size_milliseconds_bucket` — the suffix -> is wrong, the name is nonetheless the one to query. +> +> The unit an `Event` declares also selects its bucket ladder, because the +> histogram views match on unit. `rpc_size` measures bytes, so it declares +> `Unit::Bytes` and exports as **`rpc_size_bytes_bucket`** on the byte ladder. +> It used to share the `ms` constructor and export as +> `rpc_size_milliseconds_bucket` on a latency ladder — if you find that name in +> an old query or bookmark, it no longer exists. + +#### Reading A Histogram Percentile + +Two failure modes make a percentile panel lie, and neither looks like an error — +both produce a believable number. Check for them before trusting any p95/p99. + +**Saturated at the top.** If the quantile falls in the `+Inf` bucket, Prometheus +returns the **second-highest** bucket edge, not `+Inf`. A panel pinned to a round +number that happens to equal the ladder's top edge is the signature. Confirm by +comparing the top finite bucket against the total: + +```promql +1 - ( + sum(last_over_time(_bucket{le=""}[15m])) + / sum(last_over_time(_bucket{le="+Inf"}[15m])) +) +``` + +A non-trivial result means samples are being censored and the percentile is a +lower bound, not a measurement. + +**Saturated at the bottom.** If nearly every sample lands in the first bucket, +`histogram_quantile` interpolates _inside_ it and returns +`quantile / fraction_in_bucket_0 × first_edge`. The signature is a p75/p95/p99 +that sit in near-constant proportion to each other and to the first edge — for +example 75.5 / 95.7 / 99.7 against a 100 µs floor. Confirm with: + +```promql +sum(last_over_time(_bucket{le=""}[15m])) +/ sum(last_over_time(_bucket{le="+Inf"}[15m])) +``` + +Anything close to 1 means the panel is reporting arithmetic on the bucket edge. + +**After a ladder change, expect a discontinuity.** Existing series keep their old +`le` values, so a percentile panel shows a step at the restart that introduced +new edges. That break is the ladder changing, not an incident. + +Bucket edges for the native instruments live in one place — +[`include/xrpl/telemetry/HistogramBuckets.h`](../include/xrpl/telemetry/HistogramBuckets.h). +The millisecond ladder is required to contain every representable edge of the +collector's spanmetrics ladder; `.github/scripts/telemetry/check_bucket_parity.py` +enforces that in CI, because the two silently drifted once already. ### Span → Metric → Dashboard Summary diff --git a/include/xrpl/telemetry/HistogramBuckets.h b/include/xrpl/telemetry/HistogramBuckets.h index 381362034e..6a00417961 100644 --- a/include/xrpl/telemetry/HistogramBuckets.h +++ b/include/xrpl/telemetry/HistogramBuckets.h @@ -136,6 +136,68 @@ inline constexpr std::array kByteBuckets{ 262'144.0, 1'048'576.0}; +/** + * Bucket edges, in microseconds, for the OTel-native duration instruments + * created directly on MetricsRegistry: job queue wait and run times, RPC + * method latency, and GetObject lookup latency. + * + * The edges from 1 to 1000 us are the ones that matter most. An earlier + * version of this ladder started at 100 us, which sat ABOVE the mass of every + * instrument using it: 99.3% of job_queued_us samples, 92.5% of + * job_running_us and 90.4% of getobject_lookup_us fell in that first bucket. + * `histogram_quantile` then interpolated inside bucket 0 and returned the + * boundary scaled by the requested quantile -- p75/p95/p99 of job_queued_us + * read 75.5/95.7/99.7 us, which is arithmetic on the bucket edge, not a + * latency. A warm nodestore read is around 1.5 us, so single-microsecond + * resolution is not excessive here. + * + * The upper edges reach a minute so multi-second stalls stay measurable. The + * SDK's own default ladder stops at 10,000, which every one of these + * instruments exceeds during catch-up. + */ +inline constexpr std::array kMicrosecondBuckets{ + 1.0, + 2.0, + 5.0, + 10.0, + 25.0, + 50.0, + 100.0, + 250.0, + 500.0, + 1'000.0, + 5'000.0, + 25'000.0, + 100'000.0, + 500'000.0, + 1'000'000.0, + 5'000'000.0, + 10'000'000.0, + 30'000'000.0, + 60'000'000.0}; + +/** + * Bucket edges for the GetObject request object count. + * + * Counts run from 1 to the hard reply cap (kHardMaxReplyNodes, 12288). The + * honest sync path asks for at most 8 objects, so the low edges are + * fine-grained; the upper ones follow the charge size bands up to the cap. + * Because the top edge IS the hard cap, this ladder cannot saturate. + */ +inline constexpr std::array + kObjectCountBuckets{1.0, 2.0, 4.0, 8.0, 16.0, 64.0, 256.0, 1'024.0, 4'096.0, 12'288.0}; + +/** + * Bucket edges for the GetObject resource charge. + * + * Charges span 0 (the free tier) to roughly 99k for a full-size all-miss + * request. The edges bracket the two thresholds that decide a peer's fate -- + * the warning threshold at 5000 and the drop threshold at 25000 -- so a + * dashboard can show how close charges run to each. + */ +inline constexpr std::array + kChargeBuckets{0.0, 100.0, 500.0, 1'000.0, 5'000.0, 10'000.0, 25'000.0, 50'000.0, 100'000.0}; + /** * @brief Check that a ladder is strictly ascending and non-negative. * @@ -163,6 +225,9 @@ isAscendingNonNegative(std::span ladder) noexcept static_assert(isAscendingNonNegative(kMillisecondBuckets)); static_assert(isAscendingNonNegative(kByteBuckets)); +static_assert(isAscendingNonNegative(kMicrosecondBuckets)); +static_assert(isAscendingNonNegative(kObjectCountBuckets)); +static_assert(isAscendingNonNegative(kChargeBuckets)); /** * @brief Copy a ladder into the `std::vector` the OTel SDK wants. diff --git a/src/tests/libxrpl/telemetry/HistogramBuckets.cpp b/src/tests/libxrpl/telemetry/HistogramBuckets.cpp index 1eb013784e..f54a7ecde1 100644 --- a/src/tests/libxrpl/telemetry/HistogramBuckets.cpp +++ b/src/tests/libxrpl/telemetry/HistogramBuckets.cpp @@ -60,7 +60,52 @@ INSTANTIATE_TEST_SUITE_P( HistogramBucketsTest, ::testing::Values( std::span{kMillisecondBuckets}, - std::span{kByteBuckets})); + std::span{kByteBuckets}, + std::span{kMicrosecondBuckets}, + std::span{kObjectCountBuckets}, + std::span{kChargeBuckets})); + +TEST(HistogramBucketsRange, microsecondFloorLandsBelowTheMeasuredMass) +{ + // Measured: 99.3% of job_queued_us samples sat below the old 100 us floor, + // so p75/p95/p99 all interpolated inside bucket 0 and returned + // 75.5/95.7/99.7 us -- the boundary scaled by the requested quantile, + // not a latency. Warm nodestore reads are ~1.5 us, so the floor has to + // reach single microseconds and several edges must precede 100 us. + EXPECT_LE(kMicrosecondBuckets.front(), 1.0); + + auto const belowHundred = + std::ranges::count_if(kMicrosecondBuckets, [](double edge) { return edge < 100.0; }); + EXPECT_GE(belowHundred, 5) << "too little resolution below 100 us"; +} + +TEST(HistogramBucketsRange, microsecondCeilingStillReachesOneMinute) +{ + // Job waits and RPC latencies routinely exceed the SDK default ceiling of + // 10,000; multi-second stalls must stay measurable rather than censored. + EXPECT_EQ(kMicrosecondBuckets.back(), 60'000'000.0); +} + +TEST(HistogramBucketsRange, objectCountLadderCannotSaturate) +{ + // GetObject counts run 1..kHardMaxReplyNodes, so the top edge IS the hard + // cap and censoring is impossible by construction. + EXPECT_EQ(kObjectCountBuckets.front(), 1.0); + EXPECT_EQ(kObjectCountBuckets.back(), 12'288.0); +} + +TEST(HistogramBucketsRange, chargeLadderBracketsTheResourceThresholds) +{ + // The two edges that decide a peer's fate must be present so a dashboard + // can show how close charges run to each: warning at 5000, drop at 25000. + // A leading 0 separates the free tier from everything else. + EXPECT_EQ(kChargeBuckets.front(), 0.0); + for (double const threshold : {5'000.0, 25'000.0}) + { + EXPECT_NE(std::ranges::find(kChargeBuckets, threshold), kChargeBuckets.end()) + << threshold << " is a resource threshold and must be an edge"; + } +} // The validator must also REJECT. A predicate that only ever returns true // would let every ladder above pass while proving nothing. diff --git a/src/xrpld/telemetry/MetricsRegistry.cpp b/src/xrpld/telemetry/MetricsRegistry.cpp index 69aa120705..04c2670fab 100644 --- a/src/xrpld/telemetry/MetricsRegistry.cpp +++ b/src/xrpld/telemetry/MetricsRegistry.cpp @@ -63,6 +63,7 @@ #include #include #include +#include #include #include @@ -84,7 +85,6 @@ #include #include -#include #include #include #include @@ -119,66 +119,16 @@ constexpr char kRpcMethodDurationUs[] = "rpc_method_us"; constexpr char kJobTypeLabel[] = "job_type"; constexpr char kHandlerLabel[] = "handler"; -/** - * Bucket boundaries for microsecond-valued duration instruments. - * - * 100 µs, 500 µs, 1 ms, 5 ms, 10 ms, 25 ms, 50 ms, 100 ms, 250 ms, 500 ms, - * 1 s, 2.5 s, 5 s, 10 s, 30 s, 60 s. Covers sub-millisecond jobs through - * multi-second stalls without saturating. - */ -constexpr std::array kMicrosecondBoundaries{ - 100.0, - 500.0, - 1'000.0, - 5'000.0, - 10'000.0, - 25'000.0, - 50'000.0, - 100'000.0, - 250'000.0, - 500'000.0, - 1'000'000.0, - 2'500'000.0, - 5'000'000.0, - 10'000'000.0, - 30'000'000.0, - 60'000'000.0}; - -/** - * Bucket boundaries for latencies that are normally sub-millisecond. - * - * 1 µs, 2 µs, 5 µs, 10 µs, 25 µs, 50 µs, 100 µs, 250 µs, 500 µs, 1 ms, 5 ms, - * 25 ms. - * - * kMicrosecondBoundaries starts at 100 µs, which is above the entire range a - * healthy nodestore read occupies, so every warm read falls in its first - * bucket and the distribution reads as flat. These edges resolve the warm - * range instead, while still reaching far enough to show a cold tail against - * it. - * - * Currently unused: no sub-millisecond histogram instrument exists yet. The - * edges live here so the instrument that records nodestore read latency gets - * a ladder that fits it, rather than silently inheriting the wrong one. - */ -[[maybe_unused]] constexpr std::array kSubMillisecondBoundaries{ - 1.0, - 2.0, - 5.0, - 10.0, - 25.0, - 50.0, - 100.0, - 250.0, - 500.0, - 1'000.0, - 5'000.0, - 25'000.0}; - /** * Register an explicit-bucket histogram view. * * The SDK's default boundaries top out at 10,000, so any instrument whose - * values exceed that saturates and every quantile reads as the ceiling. + * values exceed that saturates and every quantile reads as the ceiling. The + * floor matters just as much and is easier to miss: a ladder whose first edge + * sits above the mass of the distribution makes every low quantile an + * interpolation inside bucket 0 -- a number derived from the bucket edge + * rather than from any sample. Both ends are chosen from measured + * distributions in HistogramBuckets.h. * * @param views The registry to add the view to. * @param name Instrument name to match (e.g. "job_running_us"). @@ -206,7 +156,7 @@ addHistogramView( * Register the microsecond-ladder view for a duration instrument. * * Job wait/run times and RPC latencies routinely exceed the SDK default - * ceiling, so they all share `kMicrosecondBoundaries`. + * ceiling, so they all share `buckets::kMicrosecondBuckets`. * * @param views The registry to add the view to. * @param name Instrument name to match. @@ -214,7 +164,10 @@ addHistogramView( void addMicrosecondHistogramView(metric_sdk::ViewRegistry& views, std::string const& name) { - addHistogramView(views, name, {kMicrosecondBoundaries.begin(), kMicrosecondBoundaries.end()}); + addHistogramView( + views, + name, + xrpl::telemetry::buckets::toVector(xrpl::telemetry::buckets::kMicrosecondBuckets)); } } // namespace @@ -352,18 +305,13 @@ MetricsRegistry::initExporterAndProvider( // asks for at most 8, so the low buckets are fine-grained and the upper // ones follow the charge size bands (64, 1024) up to the hard cap. addHistogramView( - *views, - kGetObjectRequestObjects, - {1.0, 2.0, 4.0, 8.0, 16.0, 64.0, 256.0, 1'024.0, 4'096.0, 12'288.0}); + *views, kGetObjectRequestObjects, buckets::toVector(buckets::kObjectCountBuckets)); // Charge values span 0 (free tier) to ~99k for a full-size all-miss // request. Boundaries bracket the resource thresholds that decide a // peer's fate -- kWarningThreshold (5000) and kDropThreshold (25000) -- // so a dashboard can show how close charges run to each. - addHistogramView( - *views, - kGetObjectCharge, - {0.0, 100.0, 500.0, 1'000.0, 5'000.0, 10'000.0, 25'000.0, 50'000.0, 100'000.0}); + addHistogramView(*views, kGetObjectCharge, buckets::toVector(buckets::kChargeBuckets)); // Create MeterProvider with resource, then attach the metric reader. provider_ = metric_sdk::MeterProviderFactory::Create(std::move(views), resourceAttrs);