ARCHIVE/rippled
1
0
Fork 0
mirror of https://github.com/XRPLF/rippled.git synced 2026-08-21 22:30:57 +00:00
Code Issues Packages Projects Releases Wiki Activity

feat(telemetry): expose the sweep-trim and rotation costs (WP-B5)

Browse Source 
Two suspects from the 3.3.0 slowdown investigation had no signal. Both were
already computing the numbers and throwing them away, so this exposes them
rather than adding measurement.

Per-sweep heap trim. The trim runs after every cache sweep, and its cost
scales with resident heap, so it is the leading explanation for a node with
a populated database syncing slower than a fresh one. The report already
carried duration, fault deltas and reclaimed pages, but the whole
measurement sat behind a debug-journal check, so an ordinary node measured
nothing, and the call site discarded the result. The measurement now always
runs and only the log line stays gated. Records trim duration, minor faults
and reclaimed kilobytes. Measured cost of the always-on path is about six
microseconds per sweep against a trim costing milliseconds, at a cadence of
ten to a hundred and twenty seconds.

Honest limit, stated in the runbook: the fault delta spans only the trim
call, so it shows the trim itself faulting but not the faults that follow as
caches refill. The duration is the signal to correlate against sweep-job
queueing.

Rotation writes. Rotation copies archive-served reads forward and re-stores
nodes missing from both backends, both of which compete with sync I/O and
only happen on a populated online_delete database. The copy-forward count
existed but was reset by the rotation's own log line, so a metric reading it
would drop to zero on every swap; a never-reset total sits beside it now.
The re-store count was not measured at all. Rotation duration is
deliberately not recorded: the health throttle sleeps at eight points inside
the sequence and dominates exactly when the node is unhealthy, so the number
would conflate work with waiting.

Nothing added for the other two suspects. Get-object serving is already
covered by the handler label, the lookup histogram and the deferred and
saturation gauges; peer churn by the disconnect-reason counter.

Also replaces nine per-file cspell ignores with one ignoreRegExpList entry
for the telemetry macro names, and picks up the levelization baseline for the
consensus span-name test.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
This commit is contained in:
Pratik Mankawde
2026-07-27 16:39:09 +01:00
parent 371f10934e
commit 8633df7a3e
25 changed files with 1402 additions and 111 deletions
Download Patch File Download Diff File Expand all files Collapse all files

30
OpenTelemetryPlan/09-data-collection-reference.md
View File

@@ -1668,9 +1668,11 @@ panel that renders it. Panel names are verbatim `ledger-sync-health` panel
titles unless another board is named explicitly, and `n/a` means the signal has
no panel (it is read in Tempo instead).
<!-- cspell:ignore txset -->
<!-- cspell:ignore txset statm -->
<!-- "txset" is a label value emitted verbatim by serve_refused_total; it is
the code literal, not prose, so it cannot be respelled here. -->
the code literal, not prose, so it cannot be respelled here. "statm" is the
/proc/self/statm kernel path the heap-trim RSS readings are taken from, so
it likewise cannot be respelled. -->
| Signal | Type | Emit site | Panel | Meaning |
| ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | ------------------ | -------------------------------------------------------------------------------------------------------- | -------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | -------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- |
@@ -1704,6 +1706,11 @@ no panel (it is read in Tempo instead).
| `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` \| `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". |
| `sweep_malloc_trim_us` | histogram | `Application.cpp` — `ApplicationImp::trimHeapAndRecord` | Sweep Heap-Trim Duration (p50/p95) | Wall-clock duration of the `malloc_trim` call that ends every cache sweep. **This is the leading explanation for "a node with a large existing DB syncs slower than a fresh one" on glibc:** the trim runs after EVERY sweep, its cost scales with the resident heap, and the pages it hands back must be re-faulted as the caches refill. The numbers all already existed on `MallocTrimReport`, but were unreachable twice over — the whole measurement block sat inside `if (journal.debug())` in `MallocTrim.cpp`, so an ordinary node at default log level measured nothing, and the return value was then discarded at the call site. The gate now covers only the `JLOG`; measuring costs about 6 µs (two `/proc/self/statm` reads at ~2.8 µs and two `getrusage` calls at ~0.17 µs) against a trim that costs milliseconds on a large heap, at a cadence of `SizedItem::SweepInterval` (10-120 s by node size) — a duty cycle below 1e-6 %, so keeping the RSS read debug-only would only have preserved the blind spot. Needs an explicit-bucket View (`addMicrosecondHistogramView`) because a trim on a multi-gigabyte heap runs well past the SDK default ceiling of 10,000, which would collapse exactly the slow trims this signal exists to catch into one saturated bucket. |
| `sweep_malloc_trim_minor_faults_total` | counter | `Application.cpp` — `ApplicationImp::trimHeapAndRecord` | Sweep Heap-Trim Faults & Reclaim Rate | Minor page faults taken _inside_ the trim call, from the `getrusage(RUSAGE_THREAD)` delta the report already carried. **Honest limitation, and it must not be over-claimed:** the delta is scoped to the trim call only, so it proves the trim itself faults — it does NOT prove the trim causes the faults taken later, as the caches refill and touch the pages the trim returned. That later re-fault cost is the actual mechanism the hypothesis proposes and it is NOT measured by this counter. Read the duration against sweep-job queueing rather than treating this number as the total cost of trimming. Emitted only when the delta is above zero: a trim that faulted nothing publishes no series, because a zero would read as "measured, and free" when the honest statement is that there was nothing to fault on. |
| `sweep_malloc_trim_reclaimed_kb_total` | counter | `Application.cpp` — `ApplicationImp::trimHeapAndRecord` | Sweep Heap-Trim Faults & Reclaim Rate | Resident kilobytes the trim actually returned to the kernel, so the cost above can be judged against what it bought. Cumulative and sign-corrected: `MallocTrimReport::deltaKB()` is after-minus-before, so a successful trim is NEGATIVE and the emit site publishes its magnitude. A sweep across which RSS GREW — another thread allocating faster than the trim released — is dropped rather than negated, because a counter cannot decrease and there is no reclaim of a negative size. Zero reclaim beside a non-zero duration is the worst reading: the trim is walking the heap and freeing nothing, which is pure cost. |
| `rotation_state` (`metric` = `in_flight` \| `copy_forward`) | observable gauge | `MetricsRegistry.cpp` — `registerRotationStateGauge` | Online-Delete Rotation Window & Copy-Forward Writes | The online-delete rotation window, and the running total of the extra writes it forces. A rotation rewrites into the new backend any node body the doomed archive serves, which is I/O an ordinary fetch would never perform and which scales with the archive — so it appears only on a populated, already-rotated database, which is precisely why it never shows on a fresh node. `copy_forward` comes from `DatabaseRotatingImp::copyForwardCount_`, which existed but was log-only AND reset by `rotate()` on every swap; a series that drops to zero per rotation cannot be rated, so a second never-reset total was added beside it and this gauge reads that. `in_flight` is exposed because the extra writes only happen inside that window, so a panel needs to know when to expect the total to move; the same total climbing while the flag reads 0 would mean the flag leaked, not that rotation is cheap. Polled rather than pushed because `DatabaseRotatingImp` is libxrpl and cannot include `xrpld/telemetry` — the two readings are taken through new `DatabaseRotating` accessors from the same collection tick pattern `registerNodeStoreGauge` already uses. **Publishes NO series when `online_delete` is not configured** (the `dynamic_cast` to `DatabaseRotating` fails and the callback returns early), deliberately: an absent series means "rotation is not configured", which a zero would misreport as "rotation is free". Rotation _duration_ is deliberately not recorded — see the note below the table. |
| `rotation_copy_node_restore_total` | counter | `SHAMapStoreImp.cpp` — `SHAMapStoreImp::copyNode` | Rotation Node Re-Store Rate | Nodes the rotation had to rescue because they were present in NEITHER backend, re-stored from the in-memory state map. The genuinely unmeasured rotation write: each is an extra store on top of the whole-state-map walk the rotation already performs, and the branch was warn-log-only, so the volume was invisible unless someone was reading logs. A non-zero rate says more than cost — it says an earlier rotation removed the only on-disk copy of a clean node (`cowid == 0`, so `flushDirty` skips it) that the current validated state map still reaches, and without the rescue it would later surface as an unresolvable `SHAMapMissingNode`. The node hash is deliberately not a label: it is unbounded runtime data that would mint one series per rescued node. Correlate a spike with the `copyNode` warning line in Loki, by node and time. |
| `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. |
@@ -1720,3 +1727,22 @@ no panel (it is read in Tempo instead).
| `txset.acquire` span (`outcome`, `txset_hash`, `duration_ms`, `timeouts`, `peer_count`) | span | `TransactionAcquire.cpp` — `TransactionAcquire::finalizeAcquireSpan` | Tx-Set Acquire Outcomes; Tx-Set Acquire Duration (p95) | One attempt to fetch the transaction set a consensus proposal referenced but this node did not hold. `TransactionAcquire` had **zero** telemetry of any kind before this, so a consensus round stalled waiting on a set was indistinguishable from an idle one. The sibling of `ledger.acquire`: same `TimeoutCounter` base, same trigger/onTimer/takeNodes shape, and the same `trace_ledger` flag so the two halves of a stuck sync cannot be enabled apart. `outcome` is `complete` \| `failed` \| `timeout` \| `abandoned`, stamped on both exits (`done()`, and the destructor when the round sweep in `InboundTransactions::newRound` drops a set that never arrived) by one idempotent finalizer. `timeout` is distinct from `failed` because the exhausted-budget path sets the terminal `failed_` flag too — that flag is how the timer loop stops — so the outcome rule checks the timeout first or every timeout would read as a data fault. `txset_hash` identifies WHICH set stalled and stays span-only: one metric series per consensus round would be unbounded. |
| `ledger.serve` span (`object_type`, `outcome`, `served_nodes`, `peer_id`, `ledger_seq`) | span | `PeerImp.cpp` — `PeerImp::processLedgerRequest` (the `JtLedgerReq` worker) | Ledger Serve Rate by Object Type | This node answering a peer's `TMGetLedger` request — the **supply side** of the sync exchange, and the trace-level companion to the existing `serve_refused_total` counter. The whole serve path had no span, so how long this node takes to answer, and whether it answered at all, was unobservable. A fresh trace root, because the request arrives from the wire on a shared worker whose ambient span is unrelated. `object_type` (`header` \| `tx` \| `as` \| `txset`) and `outcome` (`complete` \| `partial` \| `refused`) are both derived by shared rules in `LedgerSpanNames.h` rather than named per branch, which is what stops the eight exits of `processLedgerRequest` disagreeing about one request. `outcome` is derived from the reply itself — `served_nodes` is the reply's own node count and is 0 on all seven refusal paths — so nothing is accumulated and no work is added to the per-node assembly loop. `partial` means the reply hit `Tuning::kSoftMaxReplyNodes`, so the peer must make another round trip. |
| `peer.dial` span (`outcome`, `remote_endpoint`, `duration_ms`) | span | `ConnectAttempt.cpp` — `ConnectAttempt::reportOutcome` | Outbound Dial Outcomes (span-derived, per attempt) | One outbound connect attempt, as a per-attempt timeline rather than a rate. The trace-level companion to `overlay_connect_total` / `overlay_dial_latency_ms`: it carries the same five `outcome` values, set from the same `reportOutcome` funnel, so span and counter cannot disagree, and the funnel's existing first-call-wins guard makes the span exactly-once for free. What it adds is `remote_endpoint` — WHICH peer — which the counter deliberately cannot carry, because one series per peer address would be unbounded cardinality; it is a dedicated Tempo span column instead. A fresh trace root: a dial is the first thing a starting node does, so there is nothing to parent it to. An attempt torn down mid-dial by shutdown ends its span in the destructor with no `outcome`, which is the honest record of "never concluded" rather than a dropped span. |
### Why rotation duration is not recorded
An obvious fifth rotation signal would be how long a rotation takes, and it is
deliberately absent. `SHAMapStoreImp::run` calls `healthWait()` at eight points
inside the rotation sequence, and `healthWait()` blocks in
`std::this_thread::sleep_for(recoveryWaitTime_)` for as long as the node is not
`FULL` or its validated ledger is older than the age threshold. A wall-clock
duration spanning the rotation would therefore add a deliberate throttle to real
work and report the sum as one number — and the throttle dominates precisely
when the node is unhealthy, which is when the number would be read.
Subtracting the sleep is not clean either: the waits are interleaved with the
work at eight sites, and instrumenting each interval separately would mean eight
new emit points inside a sequence whose control flow already has several early
returns. The two signals in the table answer the question rotation duration was
wanted for — how much extra I/O did rotation cause — directly and without that
ambiguity, so the duration is left unmeasured rather than published as a number
that conflates work with throttling.