mirror of
https://github.com/XRPLF/rippled.git
synced 2026-08-21 14:20:56 +00:00
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.
This commit is contained in:
Pratik Mankawde
@@ -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_<type>_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=\"<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,
|
||||
|
||||
@@ -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
|
||||
|
||||
Reference in New Issue
Block a user