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);