mirror of
https://github.com/XRPLF/rippled.git
synced 2026-08-21 22:30:57 +00:00
docs(telemetry): correct rotation-window scope and add p99 round guidance
Two runbook readings were misleading in ways that hid a real devnet issue.
The Online-Delete Rotation Window row said a healthy node shows the flag
"briefly 1 once per delete interval". That is true but not sufficient:
rotation_state{metric="in_flight"} is set immediately before
freshenCaches() and cleared by RotationExposureGuard on scope exit, so it
brackets only the freshen/swap phase. Measured on devnet-otel-usw2-01/02
with online_delete=256 and ~47.4M state nodes, the flag averaged
0.159/0.135 over 9 h while the node was inside a rotation ~93% of wall
clock, because the dominant visitNodes copy phase (median 651 s of an
~785 s cycle) emits nothing. The row read healthy on a rotation-bound
node. Add a scope note with the log triplet that does measure occupancy.
The Consensus Round Duration panel gained a p99 series, so retitle both
references and say when to read it: at ~19 rounds/min a single stalled
round is one sample in several hundred, so p95 stays at the normal close
time and can dip. An 11.4 s round measured p99 13400 ms while p95 read
3400 ms against a 2900-3787 ms baseline.
Instrumenting the copy phase is tracked in RIPD-7144; the underlying
rotation defects in RIPD-7720.
This commit is contained in:
Pratik Mankawde
@@ -3261,21 +3261,21 @@ are separated only by the stash-depth and per-type deferred gauges. Detail:
|
||||
_Time to First FULL_ has a value, or the node flaps between `full` and
|
||||
`connected`.
|
||||
|
||||
| Look at | Healthy | Unhealthy | Conclude |
|
||||
| ------------------------------------------------------------------------------ | ------------------------------- | ---------------------------------------------------------- | ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- |
|
||||
| _Publish Lag (validated minus published)_ | flat at 0 or 1 | positive and growing | validation is healthy and the **publish pipeline is not** — the node is current while its clients see stale data. Local processing fault: go to the job-queue and stall panels |
|
||||
| | | flat at 0 on a node that never validated | not healthy, merely empty — read _Trusted Validations vs Quorum Target_ first |
|
||||
| _Server Stall_ + _Server Stall Event Rate_ | both zero | large seconds, **flat** event rate | one long unresolved stall; past 600 s the server deliberately fails |
|
||||
| | | small seconds, **rising** event rate | repeated short stalls — periodic work (sweeps, large writes), not one stuck operation |
|
||||
| _Mode Transitions by Edge_ | each climb edge roughly once | repeated `full`→`connected` paired with `connected`→`full` | flapping: reaching `full` and losing it. Sends you to the stall panels or to branch B's clock and quorum panels — those are what drop a node out of `full` |
|
||||
| _Consensus Round Duration (p50/p95)_ + _Consensus Round Duration Distribution_ | band steady | band drifting up, or a second high band | rounds are taking longer; read against _Tx-Set Acquire Duration (p95)_ (rounds waiting on data) and _Trusted Validations vs Quorum Target_ (validations arriving too late) |
|
||||
| | | p95 climbing, p50 flat | a minority of rounds stall — the early form of a second band |
|
||||
| | | both rising together | the network is slowing, not this node. Compare another node via `$node` first |
|
||||
| _Tx-Set Acquire Outcomes_ + _Tx-Set Acquire Duration (p95)_ (row 9) | flat at zero, or all `complete` | `timeout`/`abandoned` climbing | proposed sets never complete — rounds wait on data, not on agreement. This is the consensus path, not history back-fill |
|
||||
| | | `complete` p95 approaching the round interval | sets arrive but so late they delay their own round; the outcome rate cannot show this because they succeed |
|
||||
| _Replay Fallback to Full Acquire (by stage)_ (row 8) | flat | any sustained rate | too few peers support the `LedgerReplay` feature, so every historical ledger is fetched whole. Nothing fails — the optimisation is simply gone, which is why it is easy to miss. `stage` names the sub-task: `skiplist` or `delta` |
|
||||
| _Replay Outcomes (by terminal state)_ (row 8) | `success` climbing | `timeout` climbing | deltas never arrived — treat as peer supply, read with branch C |
|
||||
| | | `build_failed`/`parameter_failed` | **data** faults from the serving peers, not slowness — the peer set is suspect |
|
||||
| Look at | Healthy | Unhealthy | Conclude |
|
||||
| ---------------------------------------------------------------------------------- | ------------------------------- | ---------------------------------------------------------- | ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- |
|
||||
| _Publish Lag (validated minus published)_ | flat at 0 or 1 | positive and growing | validation is healthy and the **publish pipeline is not** — the node is current while its clients see stale data. Local processing fault: go to the job-queue and stall panels |
|
||||
| | | flat at 0 on a node that never validated | not healthy, merely empty — read _Trusted Validations vs Quorum Target_ first |
|
||||
| _Server Stall_ + _Server Stall Event Rate_ | both zero | large seconds, **flat** event rate | one long unresolved stall; past 600 s the server deliberately fails |
|
||||
| | | small seconds, **rising** event rate | repeated short stalls — periodic work (sweeps, large writes), not one stuck operation |
|
||||
| _Mode Transitions by Edge_ | each climb edge roughly once | repeated `full`→`connected` paired with `connected`→`full` | flapping: reaching `full` and losing it. Sends you to the stall panels or to branch B's clock and quorum panels — those are what drop a node out of `full` |
|
||||
| _Consensus Round Duration (p50/p95/p99)_ + _Consensus Round Duration Distribution_ | band steady | band drifting up, or a second high band | rounds are taking longer; read against _Tx-Set Acquire Duration (p95)_ (rounds waiting on data) and _Trusted Validations vs Quorum Target_ (validations arriving too late) |
|
||||
| | | p95 climbing, p50 flat | a minority of rounds stall — the early form of a second band |
|
||||
| | | both rising together | the network is slowing, not this node. Compare another node via `$node` first |
|
||||
| _Tx-Set Acquire Outcomes_ + _Tx-Set Acquire Duration (p95)_ (row 9) | flat at zero, or all `complete` | `timeout`/`abandoned` climbing | proposed sets never complete — rounds wait on data, not on agreement. This is the consensus path, not history back-fill |
|
||||
| | | `complete` p95 approaching the round interval | sets arrive but so late they delay their own round; the outcome rate cannot show this because they succeed |
|
||||
| _Replay Fallback to Full Acquire (by stage)_ (row 8) | flat | any sustained rate | too few peers support the `LedgerReplay` feature, so every historical ledger is fetched whole. Nothing fails — the optimisation is simply gone, which is why it is easy to miss. `stage` names the sub-task: `skiplist` or `delta` |
|
||||
| _Replay Outcomes (by terminal state)_ (row 8) | `success` climbing | `timeout` climbing | deltas never arrived — treat as peer supply, read with branch C |
|
||||
| | | `build_failed`/`parameter_failed` | **data** faults from the serving peers, not slowness — the peer set is suspect |
|
||||
|
||||
**Conclusion:** the pipeline works; something behind it is not keeping up.
|
||||
Publish lag and stalls are local, round duration is often network-wide, and
|
||||
@@ -3289,23 +3289,36 @@ The specific symptom: a node with history starts and is slower than the same nod
|
||||
was when empty. Back-fill is **write**-bound, so no read-side panel shows it.
|
||||
Read the **Back-fill & persistence** row.
|
||||
|
||||
| Look at | Healthy | Unhealthy | Conclude |
|
||||
| ----------------------------------------------------------- | ------------------------------------------------------------------------- | --------------------------------------------------------------- | -------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- |
|
||||
| _NodeStore Write vs Read Latency (us/op)_ | write line flat and low | write line rising during back-fill | the backend cannot absorb writes. Adding peers will not help — check storage IOPS, the `[node_db]` backend and whether online-delete/rotation competes with the back-fill |
|
||||
| | | read line far above write | the read path is the cost; read with the cache-hit panel below |
|
||||
| _NodeStore Operation Rate (writes vs reads)_ | write rate non-zero while behind | write rate zero while still behind the network | nothing is being persisted — the stall is **upstream** of the node store. Go to branch C; storage is not the problem |
|
||||
| _SHAMap TreeNode Cache Hit Rate_ | rising as the cache warms | persistently low | the working set does not fit the cache, or re-acquisition churns it, so every tree walk pays disk latency |
|
||||
| _Acquire Source (local vs network)_ | `local` dominant on a warm node | sustained `network` on a range the node should hold | the local store is not retaining data |
|
||||
| paired with _NuDB Cache Hit Ratio_ (Ledger Data Sync board) | both healthy | low on both | disk-bound sync |
|
||||
| | | low here, NuDB healthy | cache pressure alone — this is the pairing that explains the whole symptom |
|
||||
| _Sweep Heap-Trim Duration (p50/p95)_ | sub-millisecond | tens of milliseconds and rising with database size | the per-sweep heap trim is walking a large resident heap. It runs **on the sweep job**, so the cost lands on the job queue, not in the background — read it next to the sweep job's queue wait |
|
||||
| | | flat and low while the symptom persists | the trim is not the cause; the remaining rows in this branch are |
|
||||
| _Sweep Heap-Trim Faults & Reclaim Rate_ | reclaim rate tracking cache turnover, faults near zero | reclaim near zero while the duration panel shows real time | the trim is walking the heap and freeing nothing — pure cost, and the clearest case for tuning the sweep interval up |
|
||||
| | | fault rate moving with the reclaim rate | pages are being handed back and immediately taken again. **Do not over-read this:** the fault delta covers the trim call only, so it shows the trim faulting — it does NOT prove the trim caused the later faults as caches refill. That is the mechanism, but it is not what this counter measures |
|
||||
| _Online-Delete Rotation Window & Copy-Forward Writes_ | flag briefly 1 once per delete interval, writes only inside those windows | copy-forward rate large enough to move node-store write latency | rotation is competing with sync I/O — the extra writes exist only on a populated, already-rotated database, which is why the symptom is specific to an existing one |
|
||||
| | | no series at all on either query | `online_delete` is not configured on this node, which is **not** the same as rotation costing nothing — rule the whole rotation hypothesis out and move on |
|
||||
| | | copy-forward writes while the flag reads 0 | the window flag leaked; treat the rate as unattributed rather than concluding rotation is cheap |
|
||||
| _Rotation Node Re-Store Rate_ | flat at zero | any sustained rate | an earlier rotation removed the only on-disk copy of clean nodes the current state map still reaches. Two consequences: each rescue is an extra write competing with sync, and without it the node would later hit an unresolvable missing-node error. Get the hashes from the `copyNode` warning in Loki — they are deliberately not labels |
|
||||
| Look at | Healthy | Unhealthy | Conclude |
|
||||
| ----------------------------------------------------------- | --------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | --------------------------------------------------------------- | -------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- |
|
||||
| _NodeStore Write vs Read Latency (us/op)_ | write line flat and low | write line rising during back-fill | the backend cannot absorb writes. Adding peers will not help — check storage IOPS, the `[node_db]` backend and whether online-delete/rotation competes with the back-fill |
|
||||
| | | read line far above write | the read path is the cost; read with the cache-hit panel below |
|
||||
| _NodeStore Operation Rate (writes vs reads)_ | write rate non-zero while behind | write rate zero while still behind the network | nothing is being persisted — the stall is **upstream** of the node store. Go to branch C; storage is not the problem |
|
||||
| _SHAMap TreeNode Cache Hit Rate_ | rising as the cache warms | persistently low | the working set does not fit the cache, or re-acquisition churns it, so every tree walk pays disk latency |
|
||||
| _Acquire Source (local vs network)_ | `local` dominant on a warm node | sustained `network` on a range the node should hold | the local store is not retaining data |
|
||||
| paired with _NuDB Cache Hit Ratio_ (Ledger Data Sync board) | both healthy | low on both | disk-bound sync |
|
||||
| | | low here, NuDB healthy | cache pressure alone — this is the pairing that explains the whole symptom |
|
||||
| _Sweep Heap-Trim Duration (p50/p95)_ | sub-millisecond | tens of milliseconds and rising with database size | the per-sweep heap trim is walking a large resident heap. It runs **on the sweep job**, so the cost lands on the job queue, not in the background — read it next to the sweep job's queue wait |
|
||||
| | | flat and low while the symptom persists | the trim is not the cause; the remaining rows in this branch are |
|
||||
| _Sweep Heap-Trim Faults & Reclaim Rate_ | reclaim rate tracking cache turnover, faults near zero | reclaim near zero while the duration panel shows real time | the trim is walking the heap and freeing nothing — pure cost, and the clearest case for tuning the sweep interval up |
|
||||
| | | fault rate moving with the reclaim rate | pages are being handed back and immediately taken again. **Do not over-read this:** the fault delta covers the trim call only, so it shows the trim faulting — it does NOT prove the trim caused the later faults as caches refill. That is the mechanism, but it is not what this counter measures |
|
||||
| _Online-Delete Rotation Window & Copy-Forward Writes_ | flag briefly 1 once per delete interval, writes only inside those windows (but see the scope note below the table — the flag does **not** measure total rotation occupancy) | copy-forward rate large enough to move node-store write latency | rotation is competing with sync I/O — the extra writes exist only on a populated, already-rotated database, which is why the symptom is specific to an existing one |
|
||||
| | | no series at all on either query | `online_delete` is not configured on this node, which is **not** the same as rotation costing nothing — rule the whole rotation hypothesis out and move on |
|
||||
| | | copy-forward writes while the flag reads 0 | the window flag leaked; treat the rate as unattributed rather than concluding rotation is cheap |
|
||||
| _Rotation Node Re-Store Rate_ | flat at zero | any sustained rate | an earlier rotation removed the only on-disk copy of clean nodes the current state map still reaches. Two consequences: each rescue is an extra write competing with sync, and without it the node would later hit an unresolvable missing-node error. Get the hashes from the `copyNode` warning in Loki — they are deliberately not labels |
|
||||
|
||||
> **Scope of the rotation-window flag.** `rotation_state{metric="in_flight"}` is
|
||||
> set immediately before `freshenCaches()` and cleared by `RotationExposureGuard`
|
||||
> on scope exit, so it brackets only the freshen/swap phase — deliberately, since
|
||||
> its purpose is the copy-forward exposure window. It therefore **cannot** tell
|
||||
> you whether rotation is saturating the node. Measured on
|
||||
> `devnet-otel-usw2-01/02` (`online_delete=256`, ~47.4M state nodes): the flag
|
||||
> averaged 0.159 / 0.135 over 9 h while the node was actually inside a rotation
|
||||
> ~93% of wall clock, because the dominant `visitNodes` copy phase (median 651 s
|
||||
> of an ~785 s cycle) emits no signal at all. Read at face value the row above
|
||||
> says "healthy" on a node that is rotation-bound. Until the copy phase is
|
||||
> instrumented (RIPD-7144), the only way to measure occupancy is the
|
||||
> `rotating validatedSeq` / `copied ledger` / `new backend` log triplet.
|
||||
|
||||
**Conclusion:** the tree-node cache sits one layer **above** the node store, so a
|
||||
miss here is what produces a node-store read there; reading the two together is
|
||||
@@ -3687,9 +3700,9 @@ panel it reads.
|
||||
this node declining (load, capacity, or a duplicate), while
|
||||
`protocol_mismatch`, `bad_cookie` and `handshake_error` point at the
|
||||
peer or at a network-id mismatch.
|
||||
Then read _Peer Disconnects by Reason_ (`peer_disconnect_total`, by
|
||||
`reason` and `direction`). One disconnect count cannot separate the two
|
||||
causes; the label can:
|
||||
Then read _Peer Disconnects (Count By Reason & Direction)_
|
||||
(`peer_disconnect_total`, by `reason` and `direction`). One disconnect
|
||||
count cannot separate the two causes; the label can:
|
||||
- `large_sendq`, `charge_resources` — **our fault.** This node could not
|
||||
keep up with what it owed the peer, or charged it past the resource
|
||||
limit, so it shed the connection as backpressure. The fix is local
|
||||
@@ -3700,7 +3713,12 @@ panel it reads.
|
||||
- `graceful`, `shutdown`, `stopping` — normal churn and clean teardown,
|
||||
not faults. A run dominated by these is healthy.
|
||||
Use `direction` to tell churn in the peers this node dials from churn
|
||||
in the peers that dial it.
|
||||
in the peers that dial it. That panel is a total over the dashboard
|
||||
window, so it says how much of each reason but not when. For the
|
||||
time-shaped view — which reason spiked, and whether it coincides with a
|
||||
stall — use _Peer Disconnect Rate_ and _Peer Disconnects By Reason &
|
||||
Direction_ on the **Peer Quality** dashboard, which read the same
|
||||
counter as a rate and as a per-interval increase.
|
||||
Finally, the mirror-image question: _Ledger/Object Serve Refusals_
|
||||
(`serve_refused_total`, by `request` and `reason`) is what **this node
|
||||
refuses to serve OTHERS**. It does not explain this node's own sync, but
|
||||
@@ -3997,7 +4015,7 @@ panel it reads.
|
||||
|
||||
18. **Are consensus rounds themselves slowing down?**
|
||||
Panels _Consensus Round Duration Distribution_ (heatmap) and _Consensus
|
||||
Round Duration (p50/p95)_ (`consensus_round_duration_ms`). A round that
|
||||
Round Duration (p50/p95/p99)_ (`consensus_round_duration_ms`). A round that
|
||||
used to take 3-4 s and now takes 12 delays every ledger behind it, and
|
||||
until now this was only a span attribute — answering it fleet-wide meant
|
||||
raw trace queries. Being a native metric it is also **never sampled**,
|
||||
@@ -4007,6 +4025,12 @@ panel it reads.
|
||||
Duration (p95)_ (step 16 — rounds waiting on data rather than on
|
||||
agreement) and _Trusted Validations vs Quorum Target_ (step 13 —
|
||||
validations arriving too late to close the round).
|
||||
- **A single stalled round** — read **p99**, not p50/p95. At the devnet rate
|
||||
of ~19 rounds/min one long round is a single sample in several hundred, so
|
||||
p95 stays at the normal close time and can even dip. Measured on
|
||||
`devnet-otel-usw2-01`: an 11.4 s round showed as p99 13400 ms while p95
|
||||
read 3400 ms, indistinguishable from its 2900-3787 ms baseline. The
|
||||
heatmap shows the same outlier as one faint high-bucket cell.
|
||||
- **P95 climbing while P50 stays flat** — a minority of rounds stall. This
|
||||
is the early form of what the heatmap later shows as a second band.
|
||||
- **Both rising together** — the whole network is slowing, not this node.
|
||||
|
||||
Reference in New Issue
Block a user