mirror of
https://github.com/XRPLF/rippled.git
synced 2026-08-21 22:30:57 +00:00
fix(telemetry): correct five signals that would have misled an operator
Found by reviewing what each metric actually measures, with attention to the derived and bucketed ones. All five could report healthy while the node was not, or the reverse. - The nodestore latency panel took rate() of a mean. The gauge already divides duration by count in code, so rating it produced a figure with no unit, and Prometheus discards a gauge's decreases, so a heavy back-fill read as roughly zero microseconds per operation. The cumulative duration totals are now exported alongside the means, and the panel divides the rate of the total by the rate of the count, which is the latency over the panel's own window rather than a since-boot average that flattens with uptime. - The DNS-resolve and outbound-dial histograms had no explicit buckets, so they inherited a ladder that stops at ten seconds while the dial timer is fifteen. Every timed-out dial fell in the overflow bucket and p95 read exactly ten seconds however bad it got. Both now have a ladder reaching thirty seconds with fifteen on its own boundary, so a timeout is distinguishable from merely slow. - The missing-node counts only cleared when a tree completed, so a timed-out or failed acquire left its last count latched. Since the gauge reports the maximum across everything still in the collection, and eviction waits on a grace period plus the sweep interval, a finished node reported as stuck for minutes. That inverts the one signal that separates stuck from slow. Cleared unconditionally on the terminal path instead. - A disabled quorum published a sentinel so large that, on a timeseries axis shared with the trusted-key count, it flattened the key line to the baseline and hid the outage it was meant to mark. The series is now omitted and a quorum_disabled flag carries the state. - Two panel descriptions claimed a one-second export cycle. The reader is configured for ten. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
This commit is contained in:
Pratik Mankawde
@@ -1680,7 +1680,7 @@ no panel (it is read in Tempo instead).
|
||||
| `overlay_dial_latency_ms` | histogram | `ConnectAttempt.cpp` — `ConnectAttempt::reportOutcome` | Outbound Dial Latency (p95) | Time from starting an outbound dial to its terminal outcome, successes and failures together. A p95 near the dial timeout means peers accept TCP but never finish the handshake. |
|
||||
| `handshake_negotiation_fail_total` (`reason`, 14 values incl. `wrong_network`, `invalid_network_id`, `clock_skew`, `self_connection`, `session_verify_failed`) | counter | `Handshake.cpp` — `throwNegotiationFailure` (from `verifyHandshake`) | Handshake Negotiation Failures by Reason | Peer handshakes rejected after TLS while checking network id, clock, keys and addresses. `reason` names the failing check. |
|
||||
| `unl_fetch_total` (`site` = configured UNL URI; `outcome` = the 9 `ListDisposition` strings `accepted` \| `expired` \| `same_sequence` \| `pending` \| `known_sequence` \| `unsupported_version` \| `untrusted` \| `stale` \| `invalid`, plus `fetch_error` \| `bad_status` \| `parse_error`) | counter | `ValidatorSite.cpp` — `ValidatorSite::reportFetchOutcome` | UNL Fetch Rate by Site & Outcome | Validator-list fetches per site. `accepted` is the only success; `same_sequence` and `known_sequence` are normal no-op refreshes; the three literals are transport or content faults. |
|
||||
| `unl_quorum` (`metric` = `trusted_keys` \| `quorum`) | observable gauge | `MetricsRegistry.cpp` — `registerUnlQuorumGauge` | UNL Trusted Keys vs Quorum; UNL Quorum Headroom | Trusted UNL key count against the validations a ledger needs. `trusted_keys` at or below `quorum` means the node can never declare a ledger validated. |
|
||||
| `unl_quorum` (`metric` = `trusted_keys` \| `quorum` \| `quorum_disabled`) | observable gauge | `MetricsRegistry.cpp` — `registerUnlQuorumGauge` | UNL Trusted Keys vs Quorum; UNL Quorum Headroom | Trusted UNL key count against the validations a ledger needs. `trusted_keys` at or below `quorum` means the node can never declare a ledger validated. |
|
||||
| `clock_close_offset_seconds` (`metric` = `offset`) | observable gauge | `MetricsRegistry.cpp` — `registerClockSkewGauge` | Clock Close Offset | Network close time offset from the local clock. Negative means the local clock runs ahead. `server_info` only surfaces `close_time_offset` at 60 s or more, so this gauge sees skew far earlier. |
|
||||
| `state_changes_total` (`from`, `to` = `disconnected` \| `connected` \| `syncing` \| `tracking` \| `full`) | counter | `NetworkOPs.cpp` — `NetworkOPsImp::setMode` | Mode Transitions by Edge | Operating-mode transitions keyed on the (`from`, `to`) edge. The edge is what separates a clean `disconnected`→`connected`→`syncing`→`tracking`→`full` climb from `full`→`connected` flapping; an unlabelled total cannot tell them apart. |
|
||||
| `sync_state` (`metric` = `initial_full_duration_us`) | observable gauge | `MetricsRegistry.cpp` — `registerSyncStateGauge` | Time to First FULL | Microseconds from process start to the first `full` transition, sourced from `NetworkOPs::getInitialSyncDurationUs()`. Stays 0 until `full` is reached, so a flat 0 is itself the "never synced" signal; once set it never changes. |
|
||||
@@ -1703,7 +1703,7 @@ no panel (it is read in Tempo instead).
|
||||
| `serve_refused_total` (`request` = `ledger` \| `txset` \| `object` \| `fetchpack`; `reason` = `sendq_full` \| `load_shed` \| `not_found` \| `no_map` \| `bad_type` \| `empty_reply`) | counter | `PeerImp.cpp` — `processLedgerRequest`, `onMessage(TMGetObjectByHash)`, `doFetchPack` | Ledger/Object Serve Refusals | Peer data requests this node declined to answer, split by what was asked for and why. This is the **supply side** of the sync exchange — what this node refuses to serve OTHERS — and nothing equivalent existed before, so a node shedding every ledger request looked identical to one being asked for nothing. `sendq_full` and `load_shed` are self-inflicted backpressure (the send queue at `Tuning::kDropSendQueue`, or the local fee track loaded, or too many pack jobs queued), while `not_found` is a genuine history gap and `no_map` / `bad_type` / `empty_reply` mean the request was answerable in principle but produced nothing to send. `fetchpack` is counted apart from `ledger` because a fetch pack is how a syncing peer catches up in bulk and its shed threshold is a different one. Emitted at most once per request — `empty_reply` is reported after the node loop, never inside it — and both labels are code literals, so cardinality is bounded at compile time. |
|
||||
| `amendment_block` (`metric` = `warned` \| `seconds_to_block`) | observable gauge | `MetricsRegistry.cpp` — `registerAmendmentBlockGauge` | Amendment Block Countdown; Amendment Warned | `warned` is 1 once an unsupported amendment has reached majority (`NetworkOPs::isAmendmentWarned()`, previously only an admin-only `server_info` warning). **`seconds_to_block` is the leading indicator:** seconds until that amendment activates, from `AmendmentTable::firstUnsupportedExpected()` against the network close time. It reads `-1` when nothing is pending — a distinct healthy value rather than a missing series, matching the sentinel `validator_health{metric="unl_expiry_days"}` already uses — and is clamped at 0 rather than going negative, because past-due means the block is imminent, not overdue by some amount worth charting; the subtraction is done in `std::int64_t` so a past-due activation cannot wrap. Amendment-blocked is a terminal sync blocker: the node stops validating and never resumes without a software upgrade. The existing `validator_health{metric="amendment_blocked"}` reports that state after the fact, when nothing can be done about it; this gauge is the window before it, which is the only actionable part. The blocking amendment's identity is deliberately **not** a label — the network can vote on an arbitrary 256-bit amendment id, not drawn from this build's known features, so an id label would be unbounded cardinality and would mint a permanent new series per amendment. The id is available in logs from `AmendmentTableImpl::doValidatedLedger` ("Unsupported amendment \<hash\> reached majority at ..."), correlated to this series by node and time. |
|
||||
| `ledger_jump_total` | counter | `NetworkOPs.cpp` — `NetworkOPsImp::switchLastClosedLedger` | Byzantine Ledger Jumps | Forced jumps of the last closed ledger onto a divergent chain: the node was told the network's LCL is not the one it built on and discarded its own chain tip to follow. Nothing equivalent existed — this was log-only ("JUMP last closed ledger to ..."), so a node repeatedly thrashing between chains left no time series to correlate against the rest of the sync pipeline. Any non-zero rate is abnormal by construction; repeated jumps are wrong-chain thrash, which points at the peer set and the configured network id rather than anywhere in the acquire pipeline. Deliberately unlabelled: the ledger hash and sequence would both be unbounded as label values, and the log line beside the emit already carries them. |
|
||||
| `nodestore_latency` (`metric` = `write_mean_us` \| `read_mean_us` \| `write_count` \| `read_count`) | observable gauge | `MetricsRegistry.cpp` — `registerNodeStoreLatencyGauge` | NodeStore Write vs Read Latency (us/op); NodeStore Operation Rate (writes vs reads) | Mean microseconds per node-store store and per fetch, with both operation counts so a panel can divide the two rates and read _interval_ latency instead of the since-boot average. **The write side is the new signal.** `storeDurationUs_` was declared in `Database.h` and never written, and no accessor existed, so no write-path latency was observable anywhere; the read total was already exposed as `nodestore_state{metric="node_reads_duration_us"}`. This is the fingerprint of the "a node with a large existing DB syncs slower than a fresh one" symptom, which is write-bound and therefore invisible in every read-side metric. Chosen as a gauge over a histogram deliberately: a histogram gives true percentiles but costs one `Record()` per node object on the store/fetch path, and a single ledger write walks thousands of SHAMap nodes — this gauge instead reads four existing atomics once per ~10 s tick and adds nothing to the hot path. Consequence: **p99 is not obtainable from this signal**, and a histogram added later would also need an explicit-bucket View (`addMicrosecondHistogramView`) because the SDK default buckets top out at 10,000. Distinct from the Ledger Data Sync dashboard's NuDB Read Latency panel, which divides two `nodestore_state` fields in PromQL: that panel has no write-duration input to divide, because the quantity did not exist. **Known gap:** `write_mean_us` is emitted only when the store-duration total is non-zero, and that total is fed by `Database::recordStoreDuration`, today called only from `Database::importInternal` (the `[import_db]` admin path). `Database::store()` is pure virtual and neither `DatabaseNodeImp::store` nor `DatabaseRotatingImp::store` times itself yet, so an ordinary node reports `write_count` with no `write_mean_us`. The mean is omitted rather than reported as 0 so the gap stays visible instead of reading as "writes are instantaneous". |
|
||||
| `nodestore_latency` (`metric` = `write_mean_us` \| `read_mean_us` \| `write_count` \| `read_count` \| `write_duration_us` \| `read_duration_us`) | observable gauge | `MetricsRegistry.cpp` — `registerNodeStoreLatencyGauge` | NodeStore Write vs Read Latency (us/op); NodeStore Operation Rate (writes vs reads) | Mean microseconds per node-store store and per fetch, with both operation counts so a panel can divide the two rates and read _interval_ latency instead of the since-boot average. **The write side is the new signal.** `storeDurationUs_` was declared in `Database.h` and never written, and no accessor existed, so no write-path latency was observable anywhere; the read total was already exposed as `nodestore_state{metric="node_reads_duration_us"}`. This is the fingerprint of the "a node with a large existing DB syncs slower than a fresh one" symptom, which is write-bound and therefore invisible in every read-side metric. Chosen as a gauge over a histogram deliberately: a histogram gives true percentiles but costs one `Record()` per node object on the store/fetch path, and a single ledger write walks thousands of SHAMap nodes — this gauge instead reads four existing atomics once per ~10 s tick and adds nothing to the hot path. Consequence: **p99 is not obtainable from this signal**, and a histogram added later would also need an explicit-bucket View (`addMicrosecondHistogramView`) because the SDK default buckets top out at 10,000. Distinct from the Ledger Data Sync dashboard's NuDB Read Latency panel, which divides two `nodestore_state` fields in PromQL: that panel has no write-duration input to divide, because the quantity did not exist. **Known gap:** `write_mean_us` is emitted only when the store-duration total is non-zero, and that total is fed by `Database::recordStoreDuration`, today called only from `Database::importInternal` (the `[import_db]` admin path). `Database::store()` is pure virtual and neither `DatabaseNodeImp::store` nor `DatabaseRotatingImp::store` times itself yet, so an ordinary node reports `write_count` with no `write_mean_us`. The mean is omitted rather than reported as 0 so the gap stays visible instead of reading as "writes are instantaneous". |
|
||||
| `ledger_replay_fallback_total` (`stage` = `skiplist` \| `delta`) | counter | `SkipListAcquire.cpp` / `LedgerDeltaAcquire.cpp` — `trigger` | Replay Fallback to Full Acquire (by stage) | A ledger-replay sub-task abandoning its shortcut and acquiring the whole ledger through `InboundLedger` instead, because too few connected peers support the `LedgerReplay` protocol feature. Both branches were debug-log-only, so a silently defeated replay optimisation left no metric at all — back-fill simply ran on the slower path with nothing to show why. Emitted once, on the transition into fallback, not at the acquire call, which re-runs on every later trigger. The `stage` label separates the skip-list acquire (which fetches the list of historical ledger hashes) from the per-ledger delta acquire, because they fail independently. |
|
||||
| `ledger_replay_outcome_total` (`outcome` = `success` \| `timeout` \| `build_failed` \| `parameter_failed`) | counter | `LedgerReplayTask.cpp` — `LedgerReplayTask::recordOutcome` | Replay Outcomes (by terminal state) | Terminal state of every ledger-replay task, one emit per task. Every terminal path previously only set an internal `complete_`/`failed_` flag and wrote a log line, so a replay that never succeeded was indistinguishable from one that was never attempted. The outcome names the layer at fault: `timeout` means the deltas never arrived (a peer-supply problem), `build_failed` means a delta would not apply to its parent, and `parameter_failed` means a peer served a skip list inconsistent with what the task asked for — the latter two are data faults, not slowness. Read with `ledger_replay_fallback_total`: fallbacks rising while successes stay flat is replay-based catch-up degrading to full-ledger acquisition. |
|
||||
| `ledger_quorum_publish` (`metric` = `trusted_validation_tally` \| `quorum_target`) | observable gauge | `MetricsRegistry.cpp` — `registerLedgerQuorumPublishGauge` | Trusted Validations vs Quorum Target | Trusted validations counted at the most recent pre-accept gate, beside the number that gate required. Snapshotted in `LedgerMaster::checkAccept` before the shortfall check, so a node that keeps failing the gate still reports both numbers — which is the whole point: the tally alone cannot say whether validations are accumulating toward quorum (slow, will finish) or plateaued below it (stuck). Read the sustained floor of the tally, not a single sample: each series is a snapshot of the last evaluation, and the first evaluation of each round runs before peer validations arrive, so a healthy node sawtooths. `quorum_target` is what the gate actually demanded, as opposed to `unl_quorum{metric="quorum"}` which is what the trusted list configures. When the trusted list disables quorum entirely (`getNeededValidations` returns `SIZE_MAX`) the target is reported as int64 max rather than wrapping to -1, so it reads far above any tally instead of inverting the comparison — the same sentinel handling as the `unl_quorum` gauge. |
|
||||
|
||||
@@ -1372,7 +1372,7 @@
|
||||
},
|
||||
{
|
||||
"title": "Job Queue Backlog and Deferred by Type",
|
||||
"description": "###### What this is:\n*Per-job-type queue depth, two series per type. Waiting is the whole backlog: every job enqueued for that type that has not started yet. Deferred is the subset of that backlog that is blocked specifically because the type is already running at its concurrency limit. Deferred is the leading indicator of backpressure, because JobQueue::addJob never rejects a job for queue pressure -- it returns success and defers instead, so a capped type under pressure produces no error and no dropped work. Without these the only evidence is latency, which appears after the harm is already done.*\n\n###### How it's computed:\n*Two targets, each the top 10 gauges by current value: jobq_<jobtype>_waiting and jobq_<jobtype>_deferred. JobQueue::collect snapshots both counters under the one lock that guards them, so the pair is read at the same instant and is directly comparable, then publishes them on the 1-second export cycle. Gauges exist only for non-special job types, so the 11 special types -- the ones declared with a limit of 0, which bypass the limit logic entirely and therefore never defer -- do not appear on either series.*\n\n###### Reading it:\n*Read the two together; the ratio is the diagnostic, not either value alone. Deferred is always a subset of waiting, because addRefCountedJob increments waiting for every job and deferred only for the ones that arrive while the type is at its limit. Waiting high with deferred at zero means the type has spare slots and the backlog is just arrival burstiness -- it will drain without intervention. Waiting high with deferred also high means the concurrency limit is the binding constraint, not the work. Both near zero is the normal state. These are depths, not rates: the value is how many jobs are queued right now. finishJob drains deferred one per completion, so a deferred line that stays elevated means arrivals are outpacing completions rather than one isolated burst. Only the 10 highest series per state are drawn, which on an idle node is arbitrary among the zeros and under load is exactly the types under pressure.*\n\n###### Healthy range:\n*Deferred zero on all types. Waiting near zero, with brief spikes during ledger close.*\n\n###### Watch for:\n*ledgerrequest deferred above zero: the 3-slot ledgerRequest queue is full, so TMGetLedger service to syncing peers is being delayed. Use LedgerReq Wait by Handler next to see which of its two producers is responsible. ledgerdata or fetchtxndata deferred: inbound ledger data cannot be absorbed fast enough, which is what makes validated ledger age grow. A waiting line that climbs steadily while deferred stays flat points at the worker pool or at slow jobs rather than at the limit. Note both are sampled once per export cycle, so a sub-second spike can be missed; a reading of zero is not proof that nothing was ever queued or deferred.*\n\n###### Keywords:\n- **Deferred job** *(per node)* — a job held back because its type is already at its concurrency limit; the leading indicator of queue backpressure.\n- **Concurrency limit** *(per node)* — the cap on how many jobs of one type may run at once; a type at its cap cannot start more work.\n- **Job queue / job type** *(per node)* — xrpld's worker-thread pool; every unit of background work is enqueued under a named job type.\n\n###### Computation boundary:\n*Result: Per node — 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::addRefCountedJob / JobQueue::collect`\n\n###### References:\n[Telemetry glossary](https://github.com/XRPLF/rippled/blob/develop/docs/telemetry-glossary.md#deferred-job)",
|
||||
"description": "###### What this is:\n*Per-job-type queue depth, two series per type. Waiting is the whole backlog: every job enqueued for that type that has not started yet. Deferred is the subset of that backlog that is blocked specifically because the type is already running at its concurrency limit. Deferred is the leading indicator of backpressure, because JobQueue::addJob never rejects a job for queue pressure -- it returns success and defers instead, so a capped type under pressure produces no error and no dropped work. Without these the only evidence is latency, which appears after the harm is already done.*\n\n###### How it's computed:\n*Two targets, each the top 10 gauges by current value: jobq_<jobtype>_waiting and jobq_<jobtype>_deferred. JobQueue::collect snapshots both counters under the one lock that guards them, so the pair is read at the same instant and is directly comparable, then publishes them on the 10-second export cycle. Gauges exist only for non-special job types, so the 11 special types -- the ones declared with a limit of 0, which bypass the limit logic entirely and therefore never defer -- do not appear on either series.*\n\n###### Reading it:\n*Read the two together; the ratio is the diagnostic, not either value alone. Deferred is always a subset of waiting, because addRefCountedJob increments waiting for every job and deferred only for the ones that arrive while the type is at its limit. Waiting high with deferred at zero means the type has spare slots and the backlog is just arrival burstiness -- it will drain without intervention. Waiting high with deferred also high means the concurrency limit is the binding constraint, not the work. Both near zero is the normal state. These are depths, not rates: the value is how many jobs are queued right now. finishJob drains deferred one per completion, so a deferred line that stays elevated means arrivals are outpacing completions rather than one isolated burst. Only the 10 highest series per state are drawn, which on an idle node is arbitrary among the zeros and under load is exactly the types under pressure.*\n\n###### Healthy range:\n*Deferred zero on all types. Waiting near zero, with brief spikes during ledger close.*\n\n###### Watch for:\n*ledgerrequest deferred above zero: the 3-slot ledgerRequest queue is full, so TMGetLedger service to syncing peers is being delayed. Use LedgerReq Wait by Handler next to see which of its two producers is responsible. ledgerdata or fetchtxndata deferred: inbound ledger data cannot be absorbed fast enough, which is what makes validated ledger age grow. A waiting line that climbs steadily while deferred stays flat points at the worker pool or at slow jobs rather than at the limit. Note both are sampled once per export cycle, so a sub-second spike can be missed; a reading of zero is not proof that nothing was ever queued or deferred.*\n\n###### Keywords:\n- **Deferred job** *(per node)* — a job held back because its type is already at its concurrency limit; the leading indicator of queue backpressure.\n- **Concurrency limit** *(per node)* — the cap on how many jobs of one type may run at once; a type at its cap cannot start more work.\n- **Job queue / job type** *(per node)* — xrpld's worker-thread pool; every unit of background work is enqueued under a named job type.\n\n###### Computation boundary:\n*Result: Per node — 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::addRefCountedJob / JobQueue::collect`\n\n###### References:\n[Telemetry glossary](https://github.com/XRPLF/rippled/blob/develop/docs/telemetry-glossary.md#deferred-job)",
|
||||
"type": "timeseries",
|
||||
"gridPos": {
|
||||
"h": 8,
|
||||
|
||||
@@ -3150,7 +3150,7 @@
|
||||
"type": "prometheus",
|
||||
"uid": "${DS_PROMETHEUS}"
|
||||
},
|
||||
"description": "###### What this is:\n*How many ledgers this node has fully validated but not yet published to its clients and subscribers.*\n\n###### How it's computed:\n*ledger_quorum_publish series publish_lag: the validated ledger sequence minus the published ledger sequence, floored at zero. The published sequence was never exported before, so this gap was not derivable from any other series.*\n\n###### Reading it:\n*Publishing trails validation by design, so a small lag that drains each round is normal. A lag that stays positive, or grows, means validation is healthy and the publish pipeline is not \u2014 a different fault from anything the quorum or acquire panels can show.*\n\n###### Healthy range:\n*0 to 1 ledger.*\n\n###### Watch for:\n*A monotonic climb: the publish loop is falling behind a chain tip the node already holds, so clients and subscriptions see stale data while the node itself is current. Read it with Worker Pool Saturation and the per-job-type jobq_<jobtype>_deferred gauges — a starved job queue is the usual cause. A flat 0 is only healthy on a node that is validating: on one that never has, the 0 means nothing has been validated to publish, so read Trusted Validations vs Quorum Target first.*\n\n###### Keywords:\n- **Publish lag** *(per node)* \u2014 validated ledgers not yet published to clients and subscribers, i.e. the gap between the validated and the published sequence.\n\n###### Computation boundary:\n*Result: Per node \u2014 each series is one server's own value.*\n*Computed in xrpld code (MetricsRegistry, OpenTelemetry SDK) and exported as a metric; the collector only forwards it; the Grafana query selects and aggregates it.*\n\n###### Source:\n[MetricsRegistry.cpp](https://github.com/XRPLF/rippled/blob/develop/src/xrpld/telemetry/MetricsRegistry.cpp)\n\n###### Function:\n`registerLedgerQuorumPublishGauge`\n\n###### References:\n[Ledger close and publication on xrpl.org](https://xrpl.org/docs/concepts/consensus-protocol) \u00b7 [Telemetry glossary](https://github.com/XRPLF/rippled/blob/develop/docs/telemetry-glossary.md#publish-lag)",
|
||||
"description": "###### What this is:\n*How many ledgers this node has fully validated but not yet published to its clients and subscribers.*\n\n###### How it's computed:\n*ledger_quorum_publish series publish_lag: the validated ledger sequence minus the published ledger sequence, floored at zero. The published sequence was never exported before, so this gap was not derivable from any other series.*\n\n###### Reading it:\n*Publishing trails validation by design, so a small lag that drains each round is normal. A lag that stays positive, or grows, means validation is healthy and the publish pipeline is not \u2014 a different fault from anything the quorum or acquire panels can show.*\n\n###### Healthy range:\n*0 to 1 ledger.*\n\n###### Watch for:\n*A monotonic climb: the publish loop is falling behind a chain tip the node already holds, so clients and subscriptions see stale data while the node itself is current. Read it with Worker Pool Saturation and the per-job-type jobq_<jobtype>_deferred gauges \u2014 a starved job queue is the usual cause. A flat 0 is only healthy on a node that is validating: on one that never has, the 0 means nothing has been validated to publish, so read Trusted Validations vs Quorum Target first.*\n\n###### Keywords:\n- **Publish lag** *(per node)* \u2014 validated ledgers not yet published to clients and subscribers, i.e. the gap between the validated and the published sequence.\n\n###### Computation boundary:\n*Result: Per node \u2014 each series is one server's own value.*\n*Computed in xrpld code (MetricsRegistry, OpenTelemetry SDK) and exported as a metric; the collector only forwards it; the Grafana query selects and aggregates it.*\n\n###### Source:\n[MetricsRegistry.cpp](https://github.com/XRPLF/rippled/blob/develop/src/xrpld/telemetry/MetricsRegistry.cpp)\n\n###### Function:\n`registerLedgerQuorumPublishGauge`\n\n###### References:\n[Ledger close and publication on xrpl.org](https://xrpl.org/docs/concepts/consensus-protocol) \u00b7 [Telemetry glossary](https://github.com/XRPLF/rippled/blob/develop/docs/telemetry-glossary.md#publish-lag)",
|
||||
"fieldConfig": {
|
||||
"defaults": {
|
||||
"color": {
|
||||
@@ -3914,7 +3914,7 @@
|
||||
"type": "prometheus",
|
||||
"uid": "${DS_PROMETHEUS}"
|
||||
},
|
||||
"expr": "label_replace(label_join(label_replace(sum by (service_instance_id, xrpl_branch, xrpl_work_item) (rate(nodestore_latency{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\", metric=\"write_mean_us\"}[$__rate_interval])) / clamp_min(sum by (service_instance_id, xrpl_branch, xrpl_work_item) (rate(nodestore_latency{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\", metric=\"write_count\"}[$__rate_interval])), 1), \"series\", \"Write us/op (interval)\", \"\", \"\"), \"xrpl_ident\", \", \", \"service_instance_id\", \"xrpl_branch\", \"xrpl_work_item\"), \"xrpl_ident\", \"[$1]\", \"xrpl_ident\", \"(?:, )*(.*[^, ])(?:, )*\")",
|
||||
"expr": "label_replace(label_join(label_replace(sum by (service_instance_id, xrpl_branch, xrpl_work_item) (rate(nodestore_latency{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\", metric=\"write_duration_us\"}[$__rate_interval])) / clamp_min(sum by (service_instance_id, xrpl_branch, xrpl_work_item) (rate(nodestore_latency{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\", metric=\"write_count\"}[$__rate_interval])), 1), \"series\", \"Write us/op (interval)\", \"\", \"\"), \"xrpl_ident\", \", \", \"service_instance_id\", \"xrpl_branch\", \"xrpl_work_item\"), \"xrpl_ident\", \"[$1]\", \"xrpl_ident\", \"(?:, )*(.*[^, ])(?:, )*\")",
|
||||
"refId": "A"
|
||||
},
|
||||
{
|
||||
@@ -3922,7 +3922,7 @@
|
||||
"type": "prometheus",
|
||||
"uid": "${DS_PROMETHEUS}"
|
||||
},
|
||||
"expr": "label_replace(label_join(label_replace(sum by (service_instance_id, xrpl_branch, xrpl_work_item) (rate(nodestore_latency{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\", metric=\"read_mean_us\"}[$__rate_interval])) / clamp_min(sum by (service_instance_id, xrpl_branch, xrpl_work_item) (rate(nodestore_latency{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\", metric=\"read_count\"}[$__rate_interval])), 1), \"series\", \"Read us/op (interval)\", \"\", \"\"), \"xrpl_ident\", \", \", \"service_instance_id\", \"xrpl_branch\", \"xrpl_work_item\"), \"xrpl_ident\", \"[$1]\", \"xrpl_ident\", \"(?:, )*(.*[^, ])(?:, )*\")",
|
||||
"expr": "label_replace(label_join(label_replace(sum by (service_instance_id, xrpl_branch, xrpl_work_item) (rate(nodestore_latency{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\", metric=\"read_duration_us\"}[$__rate_interval])) / clamp_min(sum by (service_instance_id, xrpl_branch, xrpl_work_item) (rate(nodestore_latency{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\", metric=\"read_count\"}[$__rate_interval])), 1), \"series\", \"Read us/op (interval)\", \"\", \"\"), \"xrpl_ident\", \", \", \"service_instance_id\", \"xrpl_branch\", \"xrpl_work_item\"), \"xrpl_ident\", \"[$1]\", \"xrpl_ident\", \"(?:, )*(.*[^, ])(?:, )*\")",
|
||||
"refId": "B"
|
||||
}
|
||||
],
|
||||
|
||||
@@ -5107,7 +5107,7 @@
|
||||
},
|
||||
{
|
||||
"title": "Job Queue Saturation (Running vs Limit)",
|
||||
"description": "###### What this is:\n*How close each concurrency-capped job type is to its ceiling. JobQueue enforces a per-type limit on how many jobs of that type may run at once, and the tight ones carry ledger-sync traffic: makeFetchPack 1, ledgerRequest 3, ledgerData 3, updatePaths 1, fetchTxnData 5. A type at its ceiling cannot start more work no matter how many workers are idle, so this is a different kind of limit from CPU or disk.*\n\n###### How it's computed:\n*Each jobq_<jobtype>_running gauge divided by that type's own limit from JobTypes.h, so every line shares one 0-to-1 axis. 1.0 means running equals the limit. Multiply a reading by the limit shown in its legend to recover the raw job count. JobQueue::collect snapshots all three per-type counters under the queue's own lock and publishes them after releasing it, on the 1-second export cycle.*\n\n###### Reading it:\n*Read the distance to 1.0, not the absolute height. Below 1.0 the type has spare slots and its queue wait is not the limit's fault. Touching 1.0 briefly is normal work. Sitting at 1.0 means the type is pinned at its ceiling and every further job of that type is being deferred rather than started, which is what turns into queue wait downstream. Because the limits differ, a raw count of 3 is saturation for ledgerRequest but only 60 percent for fetchTxnData; normalizing is what makes the lines comparable.*\n\n###### Healthy range:\n*Below 1.0, with brief touches under load.*\n\n###### Watch for:\n*A line flat at 1.0: that type is the binding constraint. ledgerRequest pinned means the 3 slots shared by RcvGetLedger and RcvGetObjByHash are full, so peer ledger and object requests are queueing behind each other; the Ledger Data and Sync dashboard splits that wait by handler and shows the matching deferred depth. ledgerData or fetchTxnData pinned means inbound ledger data cannot be absorbed and validated ledger age will grow. makeFetchPack or updatePaths pinned at their limit of 1 means a single long job is blocking the whole type. These are sampled gauges, so a line that never reaches 1.0 is not proof the type was never momentarily saturated.*\n\n###### Keywords:\n- **Job queue / job type** *(per node)* — xrpld's worker-thread pool; every unit of background work is enqueued under a named job type.\n- **Concurrency limit** *(per node)* — the cap on how many jobs of one type may run at once; a type at its cap cannot start more work.\n- **Deferred job** *(per node)* — 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 — 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::getNextJob (limit enforcement) / JobQueue::collect (publication)`\n\n###### References:\n[Telemetry glossary](https://github.com/XRPLF/rippled/blob/develop/docs/telemetry-glossary.md#concurrency-limit)",
|
||||
"description": "###### What this is:\n*How close each concurrency-capped job type is to its ceiling. JobQueue enforces a per-type limit on how many jobs of that type may run at once, and the tight ones carry ledger-sync traffic: makeFetchPack 1, ledgerRequest 3, ledgerData 3, updatePaths 1, fetchTxnData 5. A type at its ceiling cannot start more work no matter how many workers are idle, so this is a different kind of limit from CPU or disk.*\n\n###### How it's computed:\n*Each jobq_<jobtype>_running gauge divided by that type's own limit from JobTypes.h, so every line shares one 0-to-1 axis. 1.0 means running equals the limit. Multiply a reading by the limit shown in its legend to recover the raw job count. JobQueue::collect snapshots all three per-type counters under the queue's own lock and publishes them after releasing it, on the 10-second export cycle.*\n\n###### Reading it:\n*Read the distance to 1.0, not the absolute height. Below 1.0 the type has spare slots and its queue wait is not the limit's fault. Touching 1.0 briefly is normal work. Sitting at 1.0 means the type is pinned at its ceiling and every further job of that type is being deferred rather than started, which is what turns into queue wait downstream. Because the limits differ, a raw count of 3 is saturation for ledgerRequest but only 60 percent for fetchTxnData; normalizing is what makes the lines comparable.*\n\n###### Healthy range:\n*Below 1.0, with brief touches under load.*\n\n###### Watch for:\n*A line flat at 1.0: that type is the binding constraint. ledgerRequest pinned means the 3 slots shared by RcvGetLedger and RcvGetObjByHash are full, so peer ledger and object requests are queueing behind each other; the Ledger Data and Sync dashboard splits that wait by handler and shows the matching deferred depth. ledgerData or fetchTxnData pinned means inbound ledger data cannot be absorbed and validated ledger age will grow. makeFetchPack or updatePaths pinned at their limit of 1 means a single long job is blocking the whole type. These are sampled gauges, so a line that never reaches 1.0 is not proof the type was never momentarily saturated.*\n\n###### Keywords:\n- **Job queue / job type** *(per node)* — xrpld's worker-thread pool; every unit of background work is enqueued under a named job type.\n- **Concurrency limit** *(per node)* — the cap on how many jobs of one type may run at once; a type at its cap cannot start more work.\n- **Deferred job** *(per node)* — 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 — 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::getNextJob (limit enforcement) / JobQueue::collect (publication)`\n\n###### References:\n[Telemetry glossary](https://github.com/XRPLF/rippled/blob/develop/docs/telemetry-glossary.md#concurrency-limit)",
|
||||
"type": "timeseries",
|
||||
"gridPos": {
|
||||
"h": 8,
|
||||
|
||||
@@ -179,7 +179,10 @@
|
||||
"ledger_quorum_publish{metric=\"publish_lag\"}",
|
||||
"ledger_quorum_shortfall_total{stage=\"pre_accept\"}",
|
||||
"consensus_round_duration_ms_bucket",
|
||||
"consensus_round_duration_ms_count"
|
||||
"consensus_round_duration_ms_count",
|
||||
"nodestore_latency{metric=\"write_duration_us\"}",
|
||||
"nodestore_latency{metric=\"read_duration_us\"}",
|
||||
"unl_quorum{metric=\"quorum_disabled\"}"
|
||||
],
|
||||
"_acquire_note": "The four sync_acquire sub-series and shamap_cache_hit_rate are unconditional: both are observable gauges whose callbacks observe every series on each collection tick, so each is present even when the value is 0 (an idle node reports in_flight=0 and missing_state_nodes_max=0, and a cold cache reports a 0.0 hit rate). Absence, not a zero, is the regression. The three WP-A3 counters (sync_acquire_source_total, sync_addnode_total, sync_acquire_no_progress_total) are deliberately NOT asserted here: all three are emitted only from InboundLedger, which runs only when a node must fetch a ledger it lacks. expected_spans.json already marks the ledger.acquire span optional for exactly this reason (\"A healthy local cluster rarely back-fills history\"), and the metric validator has no per-metric optional flag, so listing them would fail the harness red on a healthy run. They are covered by exact-value unit tests in src/tests/libxrpl/telemetry/MetricMacros.cpp and by the ledger-sync-health panels; add them here only alongside a harness step that forces a real acquire (e.g. starting a node against an existing ledger history).",
|
||||
"_jobq_note": "The three jobq_saturation series are unconditional: it is an observable gauge whose callback observes all three fields on every collection tick, so each series exists even when the value is 0, and absence rather than a zero is the regression. worker_threads is asserted because it is the denominator of the dashboard saturation ratio, and it is always at least 1 (the JobQueue ctor gives standalone mode exactly one worker), so a zero or missing reading there means the accessor regressed rather than the node being idle. The per-job-type waiting/running/deferred counts are published separately by JobQueue::collect() as the beast::insight gauges jobq_<type>_waiting / _running / _deferred, which the collector translates; they are covered by the StatsD-derived groups, not here.",
|
||||
|
||||
@@ -225,6 +225,16 @@ private:
|
||||
void
|
||||
refreshMissingNodeCounts() noexcept;
|
||||
|
||||
/**
|
||||
* Zero the missing-node counts because this acquire has finished.
|
||||
*
|
||||
* Unconditional, so it also clears after a timeout or failure, where the
|
||||
* have-tree flags are never set and the flag-guarded refresh would leave a
|
||||
* stale non-zero count visible to the gauge.
|
||||
*/
|
||||
void
|
||||
clearMissingNodeCounts() noexcept;
|
||||
|
||||
/**
|
||||
* Fold one processed batch into the acquire totals and emit its telemetry.
|
||||
*
|
||||
|
||||
@@ -224,6 +224,20 @@ InboundLedger::refreshMissingNodeCounts() noexcept
|
||||
missingTxNodes_.store(0, std::memory_order_relaxed);
|
||||
}
|
||||
|
||||
void
|
||||
InboundLedger::clearMissingNodeCounts() noexcept
|
||||
{
|
||||
// Unconditional, unlike refreshMissingNodeCounts(): this runs when the
|
||||
// acquire is over, however it ended. A timed-out or failed acquire never
|
||||
// sets the have-tree flags, so the flag-guarded refresh above would leave
|
||||
// its last sweep count latched. The gauge maxes over every acquire still in
|
||||
// the collection, and eviction waits on a one-minute grace plus the sweep
|
||||
// interval, so a latched count would report a finished node as stuck for
|
||||
// minutes -- inverting the one signal that separates stuck from slow.
|
||||
missingStateNodes_.store(0, std::memory_order_relaxed);
|
||||
missingTxNodes_.store(0, std::memory_order_relaxed);
|
||||
}
|
||||
|
||||
std::size_t
|
||||
InboundLedger::getPeerCount() const
|
||||
{
|
||||
@@ -741,6 +755,10 @@ InboundLedger::done()
|
||||
signaled_ = true;
|
||||
touch();
|
||||
|
||||
// The acquire is over on every path through here, so the missing-node
|
||||
// counts must stop being reported. See clearMissingNodeCounts().
|
||||
clearMissingNodeCounts();
|
||||
|
||||
// Keep the span active as the ambient context across the outcome log so
|
||||
// that line carries the span's trace_id. The activation is non-owning;
|
||||
// acquireSpan_ still owns the span. It pops at the end of this block, while
|
||||
|
||||
@@ -475,6 +475,11 @@ inline constexpr char parseError[] = "parse_error";
|
||||
namespace unl_quorum {
|
||||
inline constexpr char trustedKeys[] = "trusted_keys";
|
||||
inline constexpr char quorum[] = "quorum";
|
||||
// 1 while the validator list has disabled quorum, 0 otherwise. Carries the
|
||||
// state that used to be encoded by publishing a sentinel value on `quorum`
|
||||
// itself: a number that large plotted on a shared axis flattens the
|
||||
// trusted-key line to the baseline, hiding the very failure it marked.
|
||||
inline constexpr char quorumDisabled[] = "quorum_disabled";
|
||||
} // namespace unl_quorum
|
||||
|
||||
/**
|
||||
@@ -595,6 +600,13 @@ inline constexpr char writeCount[] = "write_count";
|
||||
inline constexpr char readCount[] = "read_count";
|
||||
inline constexpr char writeMeanUs[] = "write_mean_us";
|
||||
inline constexpr char readMeanUs[] = "read_mean_us";
|
||||
// Cumulative microsecond totals. The means above are convenient to read at a
|
||||
// glance but cannot be rated: they are already a ratio, and a gauge of a ratio
|
||||
// has no meaningful derivative. Dividing the rate of these totals by the rate of
|
||||
// the matching count yields the latency over the panel's own window, which is
|
||||
// what a dashboard actually wants.
|
||||
inline constexpr char writeDurationUs[] = "write_duration_us";
|
||||
inline constexpr char readDurationUs[] = "read_duration_us";
|
||||
} // namespace nodestore_latency
|
||||
|
||||
/**
|
||||
|
||||
@@ -328,6 +328,22 @@ MetricsRegistry::initExporterAndProvider(std::string const& endpoint, std::strin
|
||||
// comes from the shared constant both sites use.
|
||||
addMicrosecondHistogramView(*views, kGetObjectLookupUs);
|
||||
|
||||
// Millisecond dial/resolve latencies. Both exceed the SDK default ceiling
|
||||
// of 10,000: the dial timer is 15 s, so without an explicit ladder every
|
||||
// timed-out dial lands in the overflow bucket and p95 reads exactly 10 s
|
||||
// however bad it gets. The 15 s boundary sits on its own so a timeout is
|
||||
// distinguishable from merely slow.
|
||||
addHistogramView(
|
||||
*views,
|
||||
metric::dnsResolveLatencyMs,
|
||||
{1.0, 5.0, 10.0, 25.0, 50.0, 100.0, 250.0, 500.0, 1'000.0, 2'500.0, 5'000.0, 10'000.0,
|
||||
15'000.0, 20'000.0, 30'000.0});
|
||||
addHistogramView(
|
||||
*views,
|
||||
metric::overlayDialLatencyMs,
|
||||
{1.0, 5.0, 10.0, 25.0, 50.0, 100.0, 250.0, 500.0, 1'000.0, 2'500.0, 5'000.0, 10'000.0,
|
||||
15'000.0, 20'000.0, 30'000.0});
|
||||
|
||||
// The remaining two GetObject histograms are not durations, so the
|
||||
// microsecond ladder above does not fit them. Both still need explicit
|
||||
// boundaries: the SDK default stops at 10,000 and both ranges exceed it.
|
||||
@@ -1662,11 +1678,16 @@ MetricsRegistry::registerUnlQuorumGauge()
|
||||
// instead: headroom then goes strongly negative, which is the
|
||||
// truthful signal.
|
||||
auto const quorum = validators.quorum();
|
||||
observe(
|
||||
lval::unl_quorum::quorum,
|
||||
quorum == std::numeric_limits<std::size_t>::max()
|
||||
? std::numeric_limits<int64_t>::max()
|
||||
: static_cast<int64_t>(quorum));
|
||||
// A disabled quorum omits the series rather than publishing a
|
||||
// sentinel. Both consumers of this gauge are timeseries panels
|
||||
// sharing one axis with trusted_keys, so a huge value would
|
||||
// flatten the key line to the baseline and hide the outage it
|
||||
// was meant to signal. The boolean below carries the state, and
|
||||
// a missing quorum line is itself the visible anomaly.
|
||||
bool const quorumDisabled = quorum == std::numeric_limits<std::size_t>::max();
|
||||
if (!quorumDisabled)
|
||||
observe(lval::unl_quorum::quorum, static_cast<int64_t>(quorum));
|
||||
observe(lval::unl_quorum::quorumDisabled, quorumDisabled ? 1 : 0);
|
||||
}
|
||||
catch (...) // NOLINT(bugprone-empty-catch)
|
||||
{
|
||||
@@ -2149,15 +2170,22 @@ MetricsRegistry::registerNodeStoreLatencyGauge()
|
||||
// is missing: a reported 0 us would claim writes are
|
||||
// instantaneous, which is worse than no reading at all.
|
||||
//
|
||||
// The numerator guard is load-bearing, not defensive.
|
||||
// Database::store() is pure virtual, so only the store paths
|
||||
// that call recordStoreDuration() contribute. Today that is
|
||||
// Database::importInternal (the [import_db] path). The two
|
||||
// concrete runtime databases -- DatabaseNodeImp::store and
|
||||
// DatabaseRotatingImp::store -- do not call it yet, so on an
|
||||
// ordinary node write_count climbs while the duration total
|
||||
// stays 0. Omitting the mean makes that a visible data gap
|
||||
// instead of a false "writes take 0 us" line on the panel.
|
||||
// The numerator guard covers the pre-first-write window only.
|
||||
// Both concrete databases time their backend write, so the
|
||||
// total advances on any ordinary node; before the first write
|
||||
// it is still 0, and omitting the mean then is better than
|
||||
// publishing a false "writes take 0 us".
|
||||
// The cumulative totals are observed unconditionally, so a
|
||||
// panel can divide rate(duration) by rate(count) and read the
|
||||
// latency over its own window rather than a since-boot average
|
||||
// that flattens as uptime grows.
|
||||
observe(
|
||||
lval::nodestore_latency::writeDurationUs,
|
||||
static_cast<int64_t>(storeDurationUs));
|
||||
observe(
|
||||
lval::nodestore_latency::readDurationUs,
|
||||
static_cast<int64_t>(fetchDurationUs));
|
||||
|
||||
if (storeCount > 0 && storeDurationUs > 0)
|
||||
{
|
||||
observe(
|
||||
|
||||
Reference in New Issue
Block a user