From 55276d1e8486a3cda7e4729c85adec1f481b2dd2 Mon Sep 17 00:00:00 2001 From: Pratik Mankawde <3397372+pratikmankawde@users.noreply.github.com> Date: Wed, 12 Aug 2026 17:28:03 +0100 Subject: [PATCH] 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. --- docs/telemetry-runbook.md | 98 ++++++++++++++++++++++++--------------- 1 file changed, 61 insertions(+), 37 deletions(-) diff --git a/docs/telemetry-runbook.md b/docs/telemetry-runbook.md index 64376ff7eb..e8eea7bfe0 100644 --- a/docs/telemetry-runbook.md +++ b/docs/telemetry-runbook.md @@ -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.