From 8633df7a3eacebb0b32344fb55f0cf1bd5049bbd Mon Sep 17 00:00:00 2001 From: Pratik Mankawde <3397372+pratikmankawde@users.noreply.github.com> Date: Mon, 27 Jul 2026 16:39:09 +0100 Subject: [PATCH] feat(telemetry): expose the sweep-trim and rotation costs (WP-B5) 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) --- .cspell.config.yaml | 1 + .../scripts/levelization/results/ordering.txt | 1 + .../09-data-collection-reference.md | 30 +- .../dashboards/ledger-sync-health.json | 420 ++++++++++++++++++ .../telemetry/workload/expected_metrics.json | 6 +- docs/telemetry-glossary.md | 70 +++ docs/telemetry-runbook.md | 45 +- include/xrpl/basics/MallocTrim.h | 18 +- include/xrpl/nodestore/DatabaseRotating.h | 33 ++ .../nodestore/detail/DatabaseRotatingImp.h | 19 + include/xrpl/telemetry/GetObjectMetricNames.h | 4 - src/libxrpl/basics/MallocTrim.cpp | 147 +++--- src/libxrpl/nodestore/DatabaseRotatingImp.cpp | 6 + src/tests/libxrpl/basics/MallocTrim.cpp | 39 +- src/tests/libxrpl/telemetry/MetricMacros.cpp | 377 +++++++++++++++- src/xrpld/app/consensus/RCLConsensus.cpp | 3 - src/xrpld/app/main/Application.cpp | 75 +++- src/xrpld/app/misc/SHAMapStoreImp.cpp | 12 + src/xrpld/overlay/detail/ConnectAttempt.cpp | 3 - src/xrpld/overlay/detail/OverlayImpl.cpp | 3 - src/xrpld/overlay/detail/PeerImp.cpp | 3 - src/xrpld/telemetry/MetricMacros.h | 4 - src/xrpld/telemetry/MetricNames.h | 66 +++ src/xrpld/telemetry/MetricsRegistry.cpp | 119 ++++- src/xrpld/telemetry/MetricsRegistry.h | 9 + 25 files changed, 1402 insertions(+), 111 deletions(-) diff --git a/.cspell.config.yaml b/.cspell.config.yaml index 3a3a122e2f..f37bf48891 100644 --- a/.cspell.config.yaml +++ b/.cspell.config.yaml @@ -18,6 +18,7 @@ dictionaries: ignoreRegExpList: - /\b[rs][1-9A-HJ-NP-Za-km-z]{25,34}/g # addresses and seeds - /\bC[A-Z0-9]{15}/g # CTIDs + - /\bXRPL_METRIC_[A-Z_]+/g # telemetry macro names; the splitter emits subwords like ISTOGRAM - /\b(XRPL|BEAST)_[A-Z_0-9]+_H_INCLUDED+/g # include guards - /\b(XRPL|BEAST)_[A-Z_0-9]+_H+/g # include guards - /::[a-z:_]+/g # things from other namespaces diff --git a/.github/scripts/levelization/results/ordering.txt b/.github/scripts/levelization/results/ordering.txt index 92f14ed1ed..19b649dc37 100644 --- a/.github/scripts/levelization/results/ordering.txt +++ b/.github/scripts/levelization/results/ordering.txt @@ -200,6 +200,7 @@ tests.libxrpl > xrpl.basics tests.libxrpl > xrpl.config tests.libxrpl > xrpl.core tests.libxrpl > xrpld.app +tests.libxrpl > xrpld.consensus tests.libxrpl > xrpld.overlay tests.libxrpl > xrpld.peerfinder tests.libxrpl > xrpld.telemetry diff --git a/OpenTelemetryPlan/09-data-collection-reference.md b/OpenTelemetryPlan/09-data-collection-reference.md index 4adb9af535..6ac7a598ae 100644 --- a/OpenTelemetryPlan/09-data-collection-reference.md +++ b/OpenTelemetryPlan/09-data-collection-reference.md @@ -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). - + + 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 \ 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. diff --git a/docker/telemetry/grafana/dashboards/ledger-sync-health.json b/docker/telemetry/grafana/dashboards/ledger-sync-health.json index 7f45af7d7a..f9f629aa68 100644 --- a/docker/telemetry/grafana/dashboards/ledger-sync-health.json +++ b/docker/telemetry/grafana/dashboards/ledger-sync-health.json @@ -4233,6 +4233,426 @@ ], "title": "Replay Outcomes (by terminal state)", "type": "timeseries" + }, + { + "datasource": { + "type": "prometheus", + "uid": "${DS_PROMETHEUS}" + }, + "description": "###### What this is:\n*How long the heap trim that ends every cache sweep takes. The trim returns free heap pages to the kernel, and its cost scales with the resident heap \u2014 so this is the panel that shows a node with a large existing database paying a per-sweep penalty a fresh node never pays.*\n\n###### How it's computed:\n*p50 and p95 of the sweep_malloc_trim_us histogram. Recorded once per sweep, so the sample rate is one per sweep interval (10 s on a tiny node through 120 s on a huge one). The measurement used to run only at debug log level, so on an ordinary node there was no value at all.*\n\n###### Reading it:\n*Read the two lines together against the sweep interval. Sub-millisecond is free. Tens of milliseconds against a 10 s interval is still a small duty cycle but means the trim is walking a large heap, and it runs on the sweep job \u2014 so the cost lands on the job queue, not in the background.*\n\n###### Healthy range:\n*Under a millisecond on a warm node with a modest heap.*\n\n###### Watch for:\n*p95 climbing as the database grows, especially alongside a rising sweep-job queue wait. IMPORTANT LIMITATION: the fault counter beside this panel covers the trim call only. It proves the trim itself faults; it does NOT prove the trim causes the later faults taken as the caches refill. Correlate this duration against sweep-job queueing rather than concluding the trim caused a slow sync.*\n\n###### Keywords:\n- **Heap trim** *(per node)* \u2014 returning free heap pages from the allocator's arenas back to the kernel.\n- **Sweep interval** *(per node)* \u2014 how often the periodic cache sweep runs, set by node size.\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[Application.cpp](https://github.com/XRPLF/rippled/blob/develop/src/xrpld/app/main/Application.cpp)\n\n###### Function:\n`ApplicationImp::trimHeapAndRecord`\n\n###### References:\n[Telemetry glossary](https://github.com/XRPLF/rippled/blob/develop/docs/telemetry-glossary.md#heap-trim)", + "fieldConfig": { + "defaults": { + "color": { + "mode": "palette-classic" + }, + "custom": { + "axisBorderShow": false, + "axisCenteredZero": false, + "axisColorMode": "text", + "axisLabel": "Trim Duration", + "axisPlacement": "auto", + "barAlignment": 0, + "barWidthFactor": 0.6, + "drawStyle": "line", + "fillOpacity": 10, + "gradientMode": "none", + "hideFrom": { + "legend": false, + "tooltip": false, + "viz": false + }, + "insertNulls": false, + "lineInterpolation": "linear", + "lineWidth": 2, + "pointSize": 3, + "scaleDistribution": { + "type": "linear" + }, + "showPoints": "auto", + "showValues": false, + "spanNulls": 1800000, + "stacking": { + "group": "A", + "mode": "none" + }, + "thresholdsStyle": { + "mode": "off" + } + }, + "displayName": "${__field.labels.series} ${__field.labels.xrpl_ident}", + "thresholds": { + "mode": "absolute", + "steps": [ + { + "color": "green", + "value": null + } + ] + }, + "unit": "\u00b5s" + } + }, + "gridPos": { + "h": 12, + "w": 12, + "x": 0, + "y": 272 + }, + "id": 64, + "options": { + "annotations": { + "clustering": -1, + "multiLane": false + }, + "legend": { + "calcs": [], + "displayMode": "list", + "enableFacetedFilter": false, + "overflow": "ellipsis", + "placement": "bottom", + "showLegend": true + }, + "tooltip": { + "hideZeros": false, + "maxHeight": 600, + "mode": "multi", + "sort": "desc" + } + }, + "pluginVersion": "13.2.0-28926505616", + "targets": [ + { + "datasource": { + "type": "prometheus", + "uid": "${DS_PROMETHEUS}" + }, + "expr": "label_replace(label_join(label_replace(histogram_quantile(0.5, sum by (le, service_instance_id, xrpl_branch, xrpl_node_role) (rate(sweep_malloc_trim_us_bucket{service_instance_id=~\"$node\", deployment_environment=~\"$deployment_environment\", xrpl_network_type=~\"$xrpl_network_type\", service_name=~\"$service_name\", xrpl_work_item=~\"$xrpl_work_item\", xrpl_branch=~\"$xrpl_branch\", xrpl_node_role=~\"$xrpl_node_role\"}[$__rate_interval]))), \"series\", \"P50 Trim\", \"\", \"\"), \"xrpl_ident\", \", \", \"service_instance_id\", \"xrpl_branch\", \"xrpl_work_item\"), \"xrpl_ident\", \"[$1]\", \"xrpl_ident\", \"(?:, )*(.*[^, ])(?:, )*\")", + "refId": "A" + }, + { + "datasource": { + "type": "prometheus", + "uid": "${DS_PROMETHEUS}" + }, + "expr": "label_replace(label_join(label_replace(histogram_quantile(0.95, sum by (le, service_instance_id, xrpl_branch, xrpl_node_role) (rate(sweep_malloc_trim_us_bucket{service_instance_id=~\"$node\", deployment_environment=~\"$deployment_environment\", xrpl_network_type=~\"$xrpl_network_type\", service_name=~\"$service_name\", xrpl_work_item=~\"$xrpl_work_item\", xrpl_branch=~\"$xrpl_branch\", xrpl_node_role=~\"$xrpl_node_role\"}[$__rate_interval]))), \"series\", \"P95 Trim\", \"\", \"\"), \"xrpl_ident\", \", \", \"service_instance_id\", \"xrpl_branch\", \"xrpl_work_item\"), \"xrpl_ident\", \"[$1]\", \"xrpl_ident\", \"(?:, )*(.*[^, ])(?:, )*\")", + "refId": "B" + } + ], + "title": "Sweep Heap-Trim Duration (p50/p95)", + "type": "timeseries" + }, + { + "datasource": { + "type": "prometheus", + "uid": "${DS_PROMETHEUS}" + }, + "description": "###### What this is:\n*Two rates side by side: minor page faults taken inside the heap trim, and the resident memory the trim actually returned to the kernel. Together they say whether the trim is buying anything for what it costs.*\n\n###### How it's computed:\n*Rate of sweep_malloc_trim_minor_faults_total and of sweep_malloc_trim_reclaimed_kb_total. Both are cumulative counters exported per sweep, so the panel rates them rather than plotting the totals. Reclaim is published only when resident memory actually fell; a sweep during which another thread grew the heap contributes nothing rather than a negative amount.*\n\n###### Reading it:\n*Reclaim rate with a near-zero fault rate is a cheap, useful trim. A fault rate that moves with the reclaim rate means the pages are being handed back and immediately taken again, which is churn rather than savings.*\n\n###### Healthy range:\n*A reclaim rate that tracks cache turnover, with faults near zero.*\n\n###### Watch for:\n*Reclaim near zero while the trim duration panel shows real time being spent: the trim is walking the heap and freeing nothing, which is pure cost. IMPORTANT LIMITATION: the fault delta is scoped to the trim call, so it cannot show the re-fault cost paid later as the caches refill and touch the returned pages. That later cost is real but is NOT measured here; do not read a low fault rate as proof the trim was free.*\n\n###### Keywords:\n- **Minor page fault** *(per node)* \u2014 a memory access satisfied without disk I/O, by mapping a page the kernel already holds.\n- **Reclaimed resident memory** *(per node)* \u2014 resident kilobytes the allocator handed back to the kernel.\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[Application.cpp](https://github.com/XRPLF/rippled/blob/develop/src/xrpld/app/main/Application.cpp)\n\n###### Function:\n`ApplicationImp::trimHeapAndRecord`\n\n###### References:\n[Telemetry glossary](https://github.com/XRPLF/rippled/blob/develop/docs/telemetry-glossary.md#minor-page-fault)", + "fieldConfig": { + "defaults": { + "color": { + "mode": "palette-classic" + }, + "custom": { + "axisBorderShow": false, + "axisCenteredZero": false, + "axisColorMode": "text", + "axisLabel": "Faults & KB / Sec", + "axisPlacement": "auto", + "barAlignment": 0, + "barWidthFactor": 0.6, + "drawStyle": "line", + "fillOpacity": 10, + "gradientMode": "none", + "hideFrom": { + "legend": false, + "tooltip": false, + "viz": false + }, + "insertNulls": false, + "lineInterpolation": "linear", + "lineWidth": 2, + "pointSize": 3, + "scaleDistribution": { + "type": "linear" + }, + "showPoints": "auto", + "showValues": false, + "spanNulls": 1800000, + "stacking": { + "group": "A", + "mode": "none" + }, + "thresholdsStyle": { + "mode": "off" + } + }, + "displayName": "${__field.labels.series} ${__field.labels.xrpl_ident}", + "thresholds": { + "mode": "absolute", + "steps": [ + { + "color": "green", + "value": null + } + ] + }, + "unit": "cps" + } + }, + "gridPos": { + "h": 12, + "w": 12, + "x": 12, + "y": 272 + }, + "id": 65, + "options": { + "annotations": { + "clustering": -1, + "multiLane": false + }, + "legend": { + "calcs": [], + "displayMode": "list", + "enableFacetedFilter": false, + "overflow": "ellipsis", + "placement": "bottom", + "showLegend": true + }, + "tooltip": { + "hideZeros": false, + "maxHeight": 600, + "mode": "multi", + "sort": "desc" + } + }, + "pluginVersion": "13.2.0-28926505616", + "targets": [ + { + "datasource": { + "type": "prometheus", + "uid": "${DS_PROMETHEUS}" + }, + "expr": "label_replace(label_join(label_replace(sum by (service_instance_id, xrpl_branch, xrpl_work_item) (rate(sweep_malloc_trim_minor_faults_total{service_instance_id=~\"$node\", deployment_environment=~\"$deployment_environment\", xrpl_network_type=~\"$xrpl_network_type\", service_name=~\"$service_name\", xrpl_work_item=~\"$xrpl_work_item\", xrpl_branch=~\"$xrpl_branch\", xrpl_node_role=~\"$xrpl_node_role\"}[$__rate_interval])), \"series\", \"Minor Faults / Sec\", \"\", \"\"), \"xrpl_ident\", \", \", \"service_instance_id\", \"xrpl_branch\", \"xrpl_work_item\"), \"xrpl_ident\", \"[$1]\", \"xrpl_ident\", \"(?:, )*(.*[^, ])(?:, )*\")", + "refId": "A" + }, + { + "datasource": { + "type": "prometheus", + "uid": "${DS_PROMETHEUS}" + }, + "expr": "label_replace(label_join(label_replace(sum by (service_instance_id, xrpl_branch, xrpl_work_item) (rate(sweep_malloc_trim_reclaimed_kb_total{service_instance_id=~\"$node\", deployment_environment=~\"$deployment_environment\", xrpl_network_type=~\"$xrpl_network_type\", service_name=~\"$service_name\", xrpl_work_item=~\"$xrpl_work_item\", xrpl_branch=~\"$xrpl_branch\", xrpl_node_role=~\"$xrpl_node_role\"}[$__rate_interval])), \"series\", \"Reclaimed KB / Sec\", \"\", \"\"), \"xrpl_ident\", \", \", \"service_instance_id\", \"xrpl_branch\", \"xrpl_work_item\"), \"xrpl_ident\", \"[$1]\", \"xrpl_ident\", \"(?:, )*(.*[^, ])(?:, )*\")", + "refId": "B" + } + ], + "title": "Sweep Heap-Trim Faults & Reclaim Rate", + "type": "timeseries" + }, + { + "datasource": { + "type": "prometheus", + "uid": "${DS_PROMETHEUS}" + }, + "description": "###### What this is:\n*When an online-delete rotation is running, and the rate 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 \u2014 and it exists only on a populated, already-rotated database, which is why it never appears on a fresh node.*\n\n###### How it's computed:\n*rotation_state with metric=in_flight plotted raw (it is a 0/1 state flag), and metric=copy_forward \u2014 a cumulative write total \u2014 plotted as a rate. Both are read from the node store on each collection tick. The copy-forward count existed before as a log-only per-rotation tally that reset on every swap; the total behind this panel never resets, so it can be rated.*\n\n###### Reading it:\n*The two must move together: copy-forward writes should only appear while the window flag is 1. Read the write rate against the node-store write latency panel above \u2014 that is what tells extra rotation writes from a slow backend.*\n\n###### Healthy range:\n*Flag at 0 most of the time, rising to 1 briefly once per delete interval, with the write rate non-zero only inside those windows.*\n\n###### Watch for:\n*A copy-forward rate that is large enough to move node-store write latency: rotation is competing with sync I/O, which is the whole hypothesis this panel tests. Copy-forward writes while the flag reads 0 would mean the window flag leaked, not that rotation is cheap. NO SERIES AT ALL on either query means online_delete is not configured on this node, which is different from a rotation that costs nothing.*\n\n###### Keywords:\n- **Rotation window** *(per node)* \u2014 the interval during which an online-delete backend swap is in progress.\n- **Copy-forward write** *(per node)* \u2014 rewriting a node body from the backend about to be deleted into the one replacing it.\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`registerRotationStateGauge`\n\n###### References:\n[Telemetry glossary](https://github.com/XRPLF/rippled/blob/develop/docs/telemetry-glossary.md#rotation-window)", + "fieldConfig": { + "defaults": { + "color": { + "mode": "palette-classic" + }, + "custom": { + "axisBorderShow": false, + "axisCenteredZero": false, + "axisColorMode": "text", + "axisLabel": "State & Writes / Sec", + "axisPlacement": "auto", + "barAlignment": 0, + "barWidthFactor": 0.6, + "drawStyle": "line", + "fillOpacity": 10, + "gradientMode": "none", + "hideFrom": { + "legend": false, + "tooltip": false, + "viz": false + }, + "insertNulls": false, + "lineInterpolation": "linear", + "lineWidth": 2, + "pointSize": 3, + "scaleDistribution": { + "type": "linear" + }, + "showPoints": "auto", + "showValues": false, + "spanNulls": 1800000, + "stacking": { + "group": "A", + "mode": "none" + }, + "thresholdsStyle": { + "mode": "off" + } + }, + "displayName": "${__field.labels.series} ${__field.labels.xrpl_ident}", + "thresholds": { + "mode": "absolute", + "steps": [ + { + "color": "green", + "value": null + } + ] + }, + "unit": "cps" + } + }, + "gridPos": { + "h": 12, + "w": 12, + "x": 0, + "y": 284 + }, + "id": 66, + "options": { + "annotations": { + "clustering": -1, + "multiLane": false + }, + "legend": { + "calcs": [], + "displayMode": "list", + "enableFacetedFilter": false, + "overflow": "ellipsis", + "placement": "bottom", + "showLegend": true + }, + "tooltip": { + "hideZeros": false, + "maxHeight": 600, + "mode": "multi", + "sort": "desc" + } + }, + "pluginVersion": "13.2.0-28926505616", + "targets": [ + { + "datasource": { + "type": "prometheus", + "uid": "${DS_PROMETHEUS}" + }, + "expr": "label_replace(label_join(label_replace(sum by (service_instance_id, xrpl_branch, xrpl_work_item) (rotation_state{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=\"in_flight\"}), \"series\", \"Rotation In Flight (0/1)\", \"\", \"\"), \"xrpl_ident\", \", \", \"service_instance_id\", \"xrpl_branch\", \"xrpl_work_item\"), \"xrpl_ident\", \"[$1]\", \"xrpl_ident\", \"(?:, )*(.*[^, ])(?:, )*\")", + "refId": "A" + }, + { + "datasource": { + "type": "prometheus", + "uid": "${DS_PROMETHEUS}" + }, + "expr": "label_replace(label_join(label_replace(sum by (service_instance_id, xrpl_branch, xrpl_work_item) (rate(rotation_state{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=\"copy_forward\"}[$__rate_interval])), \"series\", \"Copy-Forward Writes / Sec\", \"\", \"\"), \"xrpl_ident\", \", \", \"service_instance_id\", \"xrpl_branch\", \"xrpl_work_item\"), \"xrpl_ident\", \"[$1]\", \"xrpl_ident\", \"(?:, )*(.*[^, ])(?:, )*\")", + "refId": "B" + } + ], + "title": "Online-Delete Rotation Window & Copy-Forward Writes", + "type": "timeseries" + }, + { + "datasource": { + "type": "prometheus", + "uid": "${DS_PROMETHEUS}" + }, + "description": "###### What this is:\n*Rate at which a rotation has to rescue a tree node that was missing from BOTH backends and rewrite it from memory. Each one is an extra write on top of the whole-state-map walk the rotation already performs.*\n\n###### How it's computed:\n*Rate of rotation_copy_node_restore_total. Incremented once per rescued node in the rotation's state-map walk, from a branch that was warn-log-only before, so the volume was invisible unless someone was reading logs.*\n\n###### Reading it:\n*Zero on a healthy node. Any sustained rate means clean nodes reachable from the validated state map have no on-disk copy left, because the backend holding them was removed by an earlier rotation and they were never rewritten.*\n\n###### Healthy range:\n*Flat at zero.*\n\n###### Watch for:\n*A non-zero rate is the signal that earlier rotations dropped data the current state map still needs: each rescue is a write that competes with sync I/O, and without the rescue the node would later surface as an unresolvable missing-node error. Read with the copy-forward panel \u2014 both are rotation-time writes, but this one also indicates prior data loss rather than merely cost. The node hash is deliberately not a label (unbounded cardinality); get it from the copyNode warning in Loki, correlated by node and time.*\n\n###### Keywords:\n- **Node re-store** *(per node)* \u2014 rewriting an in-memory tree node whose only on-disk copy was removed by an earlier rotation.\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[SHAMapStoreImp.cpp](https://github.com/XRPLF/rippled/blob/develop/src/xrpld/app/misc/SHAMapStoreImp.cpp)\n\n###### Function:\n`SHAMapStoreImp::copyNode`\n\n###### References:\n[Telemetry glossary](https://github.com/XRPLF/rippled/blob/develop/docs/telemetry-glossary.md#node-re-store)", + "fieldConfig": { + "defaults": { + "color": { + "mode": "palette-classic" + }, + "custom": { + "axisBorderShow": false, + "axisCenteredZero": false, + "axisColorMode": "text", + "axisLabel": "Re-Stores / Sec", + "axisPlacement": "auto", + "barAlignment": 0, + "barWidthFactor": 0.6, + "drawStyle": "line", + "fillOpacity": 10, + "gradientMode": "none", + "hideFrom": { + "legend": false, + "tooltip": false, + "viz": false + }, + "insertNulls": false, + "lineInterpolation": "linear", + "lineWidth": 2, + "pointSize": 3, + "scaleDistribution": { + "type": "linear" + }, + "showPoints": "auto", + "showValues": false, + "spanNulls": 1800000, + "stacking": { + "group": "A", + "mode": "none" + }, + "thresholdsStyle": { + "mode": "off" + } + }, + "displayName": "${__field.labels.series} ${__field.labels.xrpl_ident}", + "thresholds": { + "mode": "absolute", + "steps": [ + { + "color": "green", + "value": null + } + ] + }, + "unit": "ops" + } + }, + "gridPos": { + "h": 12, + "w": 12, + "x": 12, + "y": 284 + }, + "id": 67, + "options": { + "annotations": { + "clustering": -1, + "multiLane": false + }, + "legend": { + "calcs": [], + "displayMode": "list", + "enableFacetedFilter": false, + "overflow": "ellipsis", + "placement": "bottom", + "showLegend": true + }, + "tooltip": { + "hideZeros": false, + "maxHeight": 600, + "mode": "multi", + "sort": "desc" + } + }, + "pluginVersion": "13.2.0-28926505616", + "targets": [ + { + "datasource": { + "type": "prometheus", + "uid": "${DS_PROMETHEUS}" + }, + "expr": "label_replace(label_join(label_replace(sum by (service_instance_id, xrpl_branch, xrpl_work_item) (rate(rotation_copy_node_restore_total{service_instance_id=~\"$node\", deployment_environment=~\"$deployment_environment\", xrpl_network_type=~\"$xrpl_network_type\", service_name=~\"$service_name\", xrpl_work_item=~\"$xrpl_work_item\", xrpl_branch=~\"$xrpl_branch\", xrpl_node_role=~\"$xrpl_node_role\"}[$__rate_interval])), \"series\", \"Nodes Re-Stored / Sec\", \"\", \"\"), \"xrpl_ident\", \", \", \"service_instance_id\", \"xrpl_branch\", \"xrpl_work_item\"), \"xrpl_ident\", \"[$1]\", \"xrpl_ident\", \"(?:, )*(.*[^, ])(?:, )*\")", + "refId": "A" + } + ], + "title": "Rotation Node Re-Store Rate", + "type": "timeseries" } ], "title": "Back-fill & persistence", diff --git a/docker/telemetry/workload/expected_metrics.json b/docker/telemetry/workload/expected_metrics.json index 77236c89e5..8ace992723 100644 --- a/docker/telemetry/workload/expected_metrics.json +++ b/docker/telemetry/workload/expected_metrics.json @@ -182,7 +182,9 @@ "consensus_round_duration_ms_count", "nodestore_latency{metric=\"write_duration_us\"}", "nodestore_latency{metric=\"read_duration_us\"}", - "unl_quorum{metric=\"quorum_disabled\"}" + "unl_quorum{metric=\"quorum_disabled\"}", + "sweep_malloc_trim_us_bucket", + "sweep_malloc_trim_us_count" ], "_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__waiting / _running / _deferred, which the collector translates; they are covered by the StatsD-derived groups, not here.", @@ -191,6 +193,8 @@ "_a7_note": "WP-A7 adds three observable gauges and four counters. The 16 gauge sub-series (peer_ledger_supply, peerfinder_slot_census, amendment_block) are unconditional and asserted individually: each callback in MetricsRegistry.cpp calls observe() for every field on every collection tick with no early return between them, so the series exists whatever the value. That includes the two sentinel readings \u2014 a node whose peers have advertised nothing reports peer_ledger_supply{metric=\"supply_min_seq\"} = 0 meaning unknown, and a node with no pending amendment reports amendment_block{metric=\"seconds_to_block\"} = -1 meaning healthy. Absence, not the sentinel, is the regression. Of the four counters only peer_accept_total is asserted: run-full-validation.sh gives every node a [port_peer] on 0.0.0.0 and lists the other four nodes in [ips], so all 5 nodes dial each other and each one is also dialled, which means OverlayImpl::onHandoff runs and reports outcome=accepted (or slot_refused/no_slot on the duplicate half of each mutual dial) on every node. It is asserted bare rather than with an outcome= selector because which outcome a given node records depends on dial ordering, which the harness does not control. The other three counters are deliberately NOT asserted. peer_disconnect_total is emitted only from PeerImp::close, and a healthy 5-node localhost cluster holds its 4 fixed peers for the whole run: the timer-driven reasons need maxUnknownTime (600 s) or maxDivergedTime (300 s) to elapse (Config.h) while the full-validation profile totals well under that, and the shutdown reasons only fire during teardown, which happens in run-full-validation.sh after Step 5 has already scraped. serve_refused_total needs a peer to ask this node for a ledger, tx set or object it cannot serve \u2014 on a cluster where every node has the same complete history from genesis, getLedger()/getTxSet() succeed and the send queues never approach Tuning::kDropSendQueue. ledger_jump_total needs NetworkOPsImp::switchLastClosedLedger, reached only when consensus reports an LCL this node did not build on; a healthy 5-node cluster agrees every round, so it never jumps. The metric validator has no per-metric optional flag, so listing any of the three would fail the harness red on a healthy run \u2014 the same reasoning _acquire_note applies to the WP-A3 InboundLedger counters. All four counters are covered by exact-value unit tests in src/tests/libxrpl/telemetry/MetricMacros.cpp and rendered by the ledger-sync-health panels Peer Disconnects by Reason, Ledger/Object Serve Refusals and Byzantine Ledger Jumps. To make them assertable the harness would need a fault-injection step: kill one node mid-run and re-scrape before teardown (peer_disconnect_total, reason=read_error/graceful), request a ledger sequence outside the cluster's history or drive a node past its send-queue limit (serve_refused_total), and start a node on a divergent chain tip or partition the cluster and heal it (ledger_jump_total).", "_a6_note": "WP-A6 adds one observable gauge (nodestore_latency) and two counters (ledger_replay_fallback_total, ledger_replay_outcome_total). Only three of the four gauge sub-series are asserted. write_count and read_count are unconditional: the callback observes both on every collection tick with no early return before them, so a series exists whatever the value, and a node that has written nothing reports write_count=0 rather than dropping the series. read_mean_us is safe because any node that has opened a ledger has already fetched objects, so the fetch duration total is non-zero. write_mean_us is deliberately NOT asserted: the mean is emitted only when the store-duration total is non-zero, and that total is fed by Database::recordStoreDuration(), which today is called only from Database::importInternal -- the [import_db] admin path. Database::store() is pure virtual and the two concrete runtime overrides (DatabaseNodeImp::store, DatabaseRotatingImp::store) do not time themselves yet, so an ordinary harness node produces write_count but no write_mean_us. Asserting it would ship a permanently red CI check for a known, documented gap; the omission is the honest encoding of that gap. The two replay counters are likewise NOT asserted, for the same reason _acquire_note gives for the WP-A3 InboundLedger counters: both are emitted only from the ledger-replay path, which requires the [ledger_replay] config stanza AND a real historical back-fill against peers that support the LedgerReplay protocol feature. run-full-validation.sh starts a fresh local cluster with no history to back-fill, so no replay task is ever created and neither counter can produce a series. All three unasserted signals are covered by exact-value unit tests in src/tests/libxrpl/telemetry/MetricMacros.cpp and rendered by the ledger-sync-health panels NodeStore Write vs Read Latency, Replay Fallback to Full Acquire and Replay Outcomes. To make them assertable the harness would need to enable [ledger_replay] and start a node against an existing ledger history so it back-fills through the replay path, and to time the two concrete store overrides.", "_a5_note": "WP-A5 adds one observable gauge (ledger_quorum_publish) and one counter (ledger_quorum_shortfall_total). All four gauge sub-series are asserted and are unconditional: registerLedgerQuorumPublishGauge's callback in MetricsRegistry.cpp calls observe() for every field on every collection tick with no early return between them, and each accessor is a plain relaxed atomic load that always returns a value, so the series exists whatever the reading. That deliberately includes the three diagnostic zeros: a node that has never had a gate evaluated reports trusted_validation_tally=0 and quorum_target=0, one that has never fully validated reports time_to_first_validated_us=0, and one that is caught up reports publish_lag=0. Absence, not the zero, is the regression -- the same reasoning _sync_state_note gives for initial_full_duration_us. Note the sentinel: when the trusted list disables quorum entirely, getNeededValidations() returns SIZE_MAX and LedgerMaster reports quorum_target as int64 max rather than letting the cast wrap to -1, so the target reads far above any tally instead of inverting the comparison (the same fix as the unl_quorum gauge). ledger_quorum_shortfall_total IS asserted, which differs from the WP-A3/A6/A7 counters, and the reason is that this counter does not need a fault to fire. RCLConsensus::Adaptor::doAccept issues this node's own validation and then calls ledgerMaster_.consensusBuilt immediately (RCLConsensus.cpp), which calls checkAccept on the freshly built ledger (LedgerMaster.cpp) BEFORE the peers' validations for that same ledger have arrived. With the harness's 5 validators the quorum is max(ceil(5*0.8), ceil(5*0.6)) = 4 (ValidatorList::calculateQuorum), so that first evaluation of each round tallies short of 4 and takes the shortfall early return; the gate is then re-entered from RCLValidations handleNewValidation as each trusted validation arrives and eventually passes. A HEALTHY 5-node cluster therefore emits this counter every round, which is why it is safe to assert on a clean run -- unlike peer_disconnect_total or ledger_replay_fallback_total, it needs no fault injection, no [ledger_replay] stanza and no historical back-fill. The stage=\"pre_accept\" selector is asserted rather than the bare name so that the label dimension is proven to have reached Prometheus, matching the state_changes_total{from,to} pattern. Consequence for readers of the panels: a non-zero rate on Pre-Accept Quorum Shortfall Rate is NOT by itself a fault, and the panel description says so; the fault signature is that rate climbing well above the ledger-close rate while the tally on Trusted Validations vs Quorum Target stays flat below its target. If a future harness change makes the cluster single-node or standalone this assertion must move to a note: standalone_ short-circuits consensusBuilt before checkAccept, and getNeededValidations() returns 0 in standalone mode, so the gate can never report a shortfall.", + "_b5_sweep_note": "WP-B5 Suspect 3 (per-sweep malloc_trim) adds one histogram and two counters. Only the histogram is asserted, by its Prometheus _bucket and _count series because the bare instrument name is not a series. It is unconditional on any running node: ApplicationImp::start arms the sweep timer before the workload begins, the interval is SizedItem::SweepInterval (Config.cpp: 10 s at nodeSize 0 through 120 s at nodeSize 4), and the full-validation profile runs 270 s of workload before Step 5 scrapes -- so at least two sweeps complete even in the slowest case, and each one records exactly one sample. The measurement itself is now unconditional too: it used to sit inside `if (journal.debug())` in MallocTrim.cpp, so a node at ordinary log level measured nothing; that gate now covers only the JLOG. The two counters are deliberately NOT asserted. sweep_malloc_trim_minor_faults_total is emitted only when the trim's minor-fault delta is greater than zero, and a trim on the small heap of a fresh localhost node routinely faults zero times -- the emit site publishes nothing rather than a zero, because a zero-valued series would claim the trim was measured as free when the honest statement is that there was nothing to fault on. sweep_malloc_trim_reclaimed_kb_total is emitted only when resident memory actually FELL across the trim, which on a node whose caches are still filling frequently does not happen (glibc has nothing above the top of the heap to release, and mmap-backed allocations are returned on free regardless of trimming). The validator has no per-metric optional flag, so asserting either would ship a permanently red CI check for a healthy run. Both are covered by exact-value unit tests in src/tests/libxrpl/telemetry/MetricMacros.cpp -- including the skip paths -- and rendered by the ledger-sync-health panel Sweep Heap-Trim Faults & Reclaim Rate. To make them assertable the harness would need a node with a large enough resident heap for a trim to reclaim, e.g. starting against an existing populated database rather than from genesis.", + "_b5_rotation_note": "WP-B5 Suspect 4 (online_delete rotation extra writes) adds one observable gauge (rotation_state, sub-series in_flight and copy_forward) and one counter (rotation_copy_node_restore_total). NONE is asserted, because the 5-node localhost harness structurally CANNOT produce any of them -- this is a documented note rather than a check that would fail CI red. Two independent reasons. First, no rotation ever runs: xrpld-validator.cfg.template sets online_delete=256 and does not set advisory_delete, so SHAMapStoreImp's gate is validatedSeq >= lastRotated + 256 (SHAMapStoreImp.cpp), which needs 256 validated ledgers; at the network's several-seconds-per-ledger close rate that is on the order of 15-20 minutes, while the full-validation profile totals 270 s of workload before Step 5 scrapes. Second, even the in_flight flag needs a rotation to have started, and copy_forward additionally needs an ARCHIVE holding data that a fetch actually reads during the rotation window -- which requires a populated, already-rotated database, exactly the condition the hypothesis says is why this slowdown never appears on a fresh node. rotation_copy_node_restore_total is narrower still: it fires only for a clean tree node reachable from the validated state map whose sole on-disk copy was removed by an EARLIER rotation, so it needs at least two rotations plus real prior data loss. Note that rotation_state publishes no series at all when online_delete is not configured, by design: MetricsRegistry::registerRotationStateGauge dynamic_casts the node store to DatabaseRotating and returns early on failure, so an absent series means 'rotation is not configured' rather than the false 'rotation is free' a zero would report. All four signals are covered by exact-value unit tests in src/tests/libxrpl/telemetry/MetricMacros.cpp (including the not-configured and between-rotations cases) and rendered by the ledger-sync-health panels Online-Delete Rotation Window & Copy-Forward Writes and Rotation Node Re-Store Rate. To make them assertable the harness would need a step that starts a node against a pre-populated database that has already rotated at least once, or that lowers online_delete and advisory_delete far enough to force a rotation inside the run window and then re-scrapes before teardown.", "_round_histogram_note": "consensus_round_duration_ms is a native OTel histogram recorded once per consensus round in RCLConsensus, so it needs no collector configuration -- it rides the existing OTLP -> Prometheus path. It is asserted by its Prometheus _bucket and _count series because the bare instrument name is not a series. Both are unconditional on any running cluster: every node closes ledgers continuously, so a round completes within the harness window and the histogram is populated. Absence means the record site or the explicit-bucket view regressed, not that the node was idle. The instrument carries NO labels, so exactly one series exists per node and per bucket boundary." }, "grafana_dashboards": { diff --git a/docs/telemetry-glossary.md b/docs/telemetry-glossary.md index 491aa3da54..b3df34ccdc 100644 --- a/docs/telemetry-glossary.md +++ b/docs/telemetry-glossary.md @@ -744,6 +744,76 @@ How long the node store takes to persist one object. This is the cost that gover **See also:** [Node-store read latency](#node-store-read-latency) · [Node-store operation rate](#node-store-operation-rate) + + +### Heap trim + +Asking the memory allocator to return free pages from its own pools back to the operating system. The node does this at the end of every periodic cache sweep, because a sweep is exactly when a large amount of memory has just been released. The cost is not fixed: the allocator has to walk its pools to find what is returnable, so the work grows with how much memory the process is holding — which is why a node with a large existing database pays more for it, every sweep, than an empty one does. The pages handed back are not gone for good; the next access to that memory has to take them again, which is the reason a trim is a trade rather than a pure saving. + +**Scope:** per node — measured on and specific to this individual server. + +**See also:** [Minor page fault](#minor-page-fault) · [Reclaimed resident memory](#reclaimed-resident-memory) · [Sweep interval](#sweep-interval) + + + +### Minor page fault + +A memory access the operating system satisfies without touching a disk, by attaching a page it already had available. Cheap next to a disk read but not free, and taken in volume it becomes a real cost. Faults counted during a heap trim show the trim doing its own work of releasing memory. They deliberately say nothing about the faults paid afterwards, when caches refill and touch the memory that was given back — that later cost is the reason a trim can slow other work down, and counting the faults inside the trim does not capture it. Reading the figure as the total price of trimming overstates what was measured. + +**Scope:** per node — measured on and specific to this individual server. + +**See also:** [Heap trim](#heap-trim) · [Reclaimed resident memory](#reclaimed-resident-memory) + + + +### Reclaimed resident memory + +How much memory a heap trim actually handed back to the operating system, as opposed to how long it spent looking. This is what makes the trim's cost judgeable: time spent with memory returned is a trade, and time spent with nothing returned is pure loss. Only memory the allocator holds in its own pools can be returned at all, so a trim can legitimately reclaim nothing — and a reading of zero is a real answer rather than a missing one. Memory can also grow across a trim, when other threads allocate faster than it releases; that is reported as no reclaim rather than as a negative amount, since a running total cannot go backwards. + +**Scope:** per node — measured on and specific to this individual server. + +**See also:** [Heap trim](#heap-trim) · [Sweep interval](#sweep-interval) + + + +### Sweep interval + +How often the node runs its periodic pass over the in-memory caches, expiring what is stale. The period is chosen from the configured node size, so a larger node sweeps less often. It sets the cadence of everything the sweep does, including the heap trim at the end of it, and it is therefore the number against which any per-sweep cost has to be judged: the same expense is negligible at one interval and significant at another. The sweep runs as a queued job, so its cost is paid on a worker thread and competes with other work rather than happening in the background. + +**Scope:** per node — measured on and specific to this individual server. + +**See also:** [Heap trim](#heap-trim) · [Job queue occupancy](#job-queue-occupancy) + + + +### Rotation window + +The interval during which the node is swapping the pair of storage backends that make online deletion of old history possible. New data goes to one backend while the older one is kept for reading; on a swap the older one is discarded and a fresh one takes over. The window matters because it is the only time certain extra writes happen, so a cost seen inside it and a cost seen outside it have different explanations. A node that is not configured for online deletion has no window at all, which is a different situation from a window that costs nothing. + +**Scope:** per node — measured on and specific to this individual server. + +**See also:** [Copy-forward write](#copy-forward-write) · [Node re-store](#node-re-store) · [Node-store write latency](#node-store-write-latency) + + + +### Copy-forward write + +Rewriting a stored object out of the backend that is about to be discarded and into the one replacing it. An ordinary read would not write anything; this one must, because the copy it just read is about to be deleted and would otherwise survive only in memory. The volume scales with how much of the outgoing backend gets read during the swap, so it is a cost only a node that already holds history can incur — the reason this competes with catching up on a populated database and never appears on a fresh one. + +**Scope:** per node — measured on and specific to this individual server. + +**See also:** [Rotation window](#rotation-window) · [Node re-store](#node-re-store) + + + +### Node re-store + +Writing a tree node back to storage from memory because it could not be found in either storage backend. It signals more than cost. The node is still reachable from the current validated state, yet its only stored copy was in a backend an earlier swap discarded, and it was never rewritten because nothing had modified it. Rescuing it is an extra write, and skipping the rescue would leave the node unresolvable later. A sustained rate therefore reports two things at once: added write pressure now, and history quietly dropped by an earlier swap. + +**Scope:** per node — measured on and specific to this individual server. + +**See also:** [Rotation window](#rotation-window) · [Copy-forward write](#copy-forward-write) · [Missing SHAMap node](#missing-shamap-node) + ### Operating mode / server state diff --git a/docs/telemetry-runbook.md b/docs/telemetry-runbook.md index ef6dcffc36..c7ad89bb3d 100644 --- a/docs/telemetry-runbook.md +++ b/docs/telemetry-runbook.md @@ -2507,23 +2507,44 @@ 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. Expand the collapsed **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 | +| 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 | **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 -what tells cache pressure from a disk bottleneck. Two limits: these are **means, -not percentiles**, and `write_mean_us` is currently emitted only for the +what tells cache pressure from a disk bottleneck. The last four rows add the two +costs that are _specific_ to a node that already has data — the per-sweep heap +trim, whose price scales with the resident heap, and online-delete rotation, +whose extra writes need an archive to read from. Both are absent by construction +on a fresh node, which is what makes them candidate explanations for this branch's +symptom rather than general slowness. + +Three limits to respect here. The node-store numbers are **means, not +percentiles**, and `write_mean_us` is currently emitted only for the `[import_db]` admin import path — on an ordinary node `write_count` climbs with no `write_mean_us` line, which is a known instrumentation gap, not a healthy -zero. Detail: [Sync pipeline](#sync-pipeline--ordered-diagnosis) steps 9 and 14. +zero. And the trim's fault counter is scoped to the **trim call only**: it shows +that the trim itself faults, and it cannot show the faults paid later as the +caches refill and touch the pages the trim returned. That later re-fault cost is +the actual mechanism by which a trim would slow a sync, and no metric here +measures it — so correlate the trim **duration** against the sweep job's queue +wait, and do not present the fault rate as proof the trim caused a slow sync. +Detail: [Sync pipeline](#sync-pipeline--ordered-diagnosis) steps 9 and 14. #### Branch F — terminal: the node will stop validating for good diff --git a/include/xrpl/basics/MallocTrim.h b/include/xrpl/basics/MallocTrim.h index 2d0cf989ba..eb3244da10 100644 --- a/include/xrpl/basics/MallocTrim.h +++ b/include/xrpl/basics/MallocTrim.h @@ -8,7 +8,10 @@ namespace xrpl { -// cSpell:ignore ptmalloc +// cSpell:ignore ptmalloc statm +// "statm" is the /proc/self/statm filename the RSS readings come from; it is a +// kernel path, not prose, so it cannot be respelled. Same directive as the two +// MallocTrim .cpp files. // ----------------------------------------------------------------------------- // Allocator interaction note: @@ -66,6 +69,19 @@ struct MallocTrimReport * * @note Intended for use after operations that free significant memory (e.g., * cache sweeps, ledger cleanup, online delete). Consider rate limiting. + * + * @note Every report field is populated on every call, whatever the journal's + * severity. Only the diagnostic JLOG is severity-gated. Measuring costs + * about 6 us (two /proc/self/statm reads and two getrusage calls) against + * a trim that costs milliseconds on a large heap, so callers on a cold + * path -- the cache sweep is the intended one -- can record the numbers + * unconditionally. A caller on a hot path should not use this function at + * all rather than expect the measurement to disappear. + * + * @note `minfltDelta` covers the trim call ONLY. It shows that the trim itself + * faults; it does NOT capture the faults later taken when the caches + * refill and touch the pages the trim returned. Do not read it as the + * total cost of trimming. */ MallocTrimReport mallocTrim(std::string_view tag, beast::Journal journal); diff --git a/include/xrpl/nodestore/DatabaseRotating.h b/include/xrpl/nodestore/DatabaseRotating.h index 5381b5c435..6fec2fc6a3 100644 --- a/include/xrpl/nodestore/DatabaseRotating.h +++ b/include/xrpl/nodestore/DatabaseRotating.h @@ -5,6 +5,7 @@ #include #include +#include #include #include #include @@ -54,6 +55,38 @@ public: */ virtual void setRotationInFlight(bool inFlight) = 0; + + /** + * Whether an online-delete rotation is in progress right now. + * + * A rotation's extra writes only happen inside this window, so a panel + * reading the copy-forward total needs this to know when to expect it to + * move. Outside the window a flat total is correct, not a broken signal. + * + * @return true between the cache-freshen phase starting and rotate() + * completing. + */ + [[nodiscard]] virtual bool + isRotationInFlight() const = 0; + + /** + * Nodes copied forward from the archive backend into the writable one + * during rotation windows, since this process started. + * + * These are writes an ordinary fetch would not have performed: the archive + * is about to be deleted, so a body it served has to be rewritten to + * survive. The count therefore scales with how much of the archive is read + * during a rotation, which is why it appears only on a populated, + * already-rotated online_delete database. + * + * Cumulative for the lifetime of the process, deliberately: the per-rotation + * tally that `rotate()` logs is reset on every swap, and a counter that goes + * backwards cannot be rated. A panel takes the rate of this instead. + * + * @return Monotonic count of copy-forward writes. + */ + [[nodiscard]] virtual std::uint64_t + copyForwardTotal() const = 0; }; } // namespace xrpl::NodeStore diff --git a/include/xrpl/nodestore/detail/DatabaseRotatingImp.h b/include/xrpl/nodestore/detail/DatabaseRotatingImp.h index ecbe9a513d..abc2901d1a 100644 --- a/include/xrpl/nodestore/detail/DatabaseRotatingImp.h +++ b/include/xrpl/nodestore/detail/DatabaseRotatingImp.h @@ -73,6 +73,18 @@ public: void setRotationInFlight(bool inFlight) override; + [[nodiscard]] bool + isRotationInFlight() const override + { + return rotationInFlight_.load(std::memory_order_acquire); + } + + [[nodiscard]] std::uint64_t + copyForwardTotal() const override + { + return copyForwardTotal_.load(std::memory_order_relaxed); + } + private: std::shared_ptr writableBackend_; std::shared_ptr archiveBackend_; @@ -86,6 +98,13 @@ private: std::atomic rotationInFlight_{false}; std::atomic copyForwardCount_{0}; + // Same events as copyForwardCount_, but never reset. rotate() zeroes the + // per-rotation tally above to produce its one-line summary, which makes that + // counter unusable as a metric: a series that drops to 0 on every swap + // cannot be rated. This one only ever increases, so rate() over it reads + // correctly and the two uses do not fight over one variable. + std::atomic copyForwardTotal_{0}; + std::shared_ptr fetchNodeObject(uint256 const& hash, std::uint32_t, FetchReport& fetchReport, bool duplicate) override; diff --git a/include/xrpl/telemetry/GetObjectMetricNames.h b/include/xrpl/telemetry/GetObjectMetricNames.h index e2951a43d0..6df75182b8 100644 --- a/include/xrpl/telemetry/GetObjectMetricNames.h +++ b/include/xrpl/telemetry/GetObjectMetricNames.h @@ -1,9 +1,5 @@ #pragma once -// cspell:ignore ISTOGRAM -// The all-caps macro name XRPL_METRIC_HISTOGRAM_RECORD trips cspell's -// compound-word splitter, which emits the subword "ISTOGRAM"; ignore it here. - /** * Metric names, label keys, label values, and descriptions for the * `TMGetObjectByHash` request path. diff --git a/src/libxrpl/basics/MallocTrim.cpp b/src/libxrpl/basics/MallocTrim.cpp index 3831c8adae..e4b982afd9 100644 --- a/src/libxrpl/basics/MallocTrim.cpp +++ b/src/libxrpl/basics/MallocTrim.cpp @@ -15,7 +15,6 @@ #include #include -#include #include #include #include @@ -69,6 +68,73 @@ parseStatmRSSkB(std::string const& statm) return (resident * pageSize) / 1024; } +/** + * Read a whole /proc pseudo-file into a string. + * + * /proc files are frequently not seekable, so the contents are streamed rather + * than sized-then-read. + * + * @param path Absolute path of the pseudo-file. + * @return The file contents, or an empty string if it could not be opened. + */ +std::string +readProcFile(std::string const& path) +{ + std::ifstream ifs(path, std::ios::in | std::ios::binary); + if (!ifs.is_open()) + return {}; + + std::ostringstream oss; + oss << ifs.rdbuf(); + return oss.str(); +} + +/** + * Run malloc_trim and measure what it cost. + * + * Split out of mallocTrim() so the always-on measurement is one testable unit + * and the caller is left with only the logging decision. + * + * Measurement order brackets the trim as tightly as possible: the two RSS + * samples are outermost, the two fault samples inside them, and the clock pair + * innermost, so the reported duration contains the trim and nothing else. + * + * @param padBytes glibc trim padding, passed straight to ::malloc_trim. + * @return A fully populated report. Fields whose source syscall failed keep + * their -1 "not measured" sentinel. + */ +MallocTrimReport +measuredTrim(std::size_t padBytes) +{ + MallocTrimReport report; + report.supported = true; + + std::string const statmPath = "/proc/self/statm"; + + report.rssBeforeKB = detail::parseStatmRSSkB(readProcFile(statmPath)); + + struct rusage ru0{}; + bool const haveRu0 = getRusageThread(ru0); + + auto const t0 = std::chrono::steady_clock::now(); + report.trimResult = detail::mallocTrimWithPad(padBytes); + auto const t1 = std::chrono::steady_clock::now(); + + struct rusage ru1{}; + bool const haveRu1 = getRusageThread(ru1); + + report.rssAfterKB = detail::parseStatmRSSkB(readProcFile(statmPath)); + report.durationUs = std::chrono::duration_cast(t1 - t0); + + if (haveRu0 && haveRu1) + { + report.minfltDelta = ru1.ru_minflt - ru0.ru_minflt; + report.majfltDelta = ru1.ru_majflt - ru0.ru_majflt; + } + + return report; +} + #endif // __GLIBC__ && BOOST_OS_LINUX } // namespace detail @@ -88,70 +154,37 @@ mallocTrim(std::string_view tag, beast::Journal journal) // of RSS reduction and trim-latency stability without adding a tuning surface. static constexpr std::size_t kTrimPad = 0; - report.supported = true; + // The measurement is unconditional. It used to sit inside + // `if (journal.debug())`, which meant an ordinary node -- which does not run + // at debug level -- measured nothing, so the caller had no duration to + // record and the per-sweep trim cost was invisible in production, the one + // place it matters. + // + // Cost of measuring on every sweep, measured on this platform: two + // /proc/self/statm reads at ~2.8 us each and two getrusage(RUSAGE_THREAD) + // calls at ~0.17 us each, so about 6 us in total. The trim it brackets + // costs milliseconds on a large heap, and the sweep that calls it runs once + // per SizedItem::SweepInterval (10 s at the fastest, tiny-node setting). + // That is a duty cycle under 1e-6 percent, and under 1 percent of the + // measured operation, so nothing here is worth making conditional -- a + // debug-only RSS read would only reintroduce the blind spot it costs + // nothing to remove. + report = detail::measuredTrim(kTrimPad); + // Only the LOG stays gated: the string formatting is what an ordinary node + // genuinely should not pay for, and the numbers now reach the metrics + // pipeline through the return value instead. if (journal.debug()) { - auto readFile = [](std::string const& path) -> std::string { - std::ifstream ifs(path, std::ios::in | std::ios::binary); - if (!ifs.is_open()) - return {}; - - // /proc files are often not seekable; read as a stream. - std::ostringstream oss; - oss << ifs.rdbuf(); - return oss.str(); - }; - - std::string const tagStr{tag}; - std::string const statmPath = "/proc/self/statm"; - - auto const statmBefore = readFile(statmPath); - long const rssBeforeKB = detail::parseStatmRSSkB(statmBefore); - - struct rusage ru0{}; - bool const haveRu0 = getRusageThread(ru0); - - auto const t0 = std::chrono::steady_clock::now(); - - report.trimResult = detail::mallocTrimWithPad(kTrimPad); - - auto const t1 = std::chrono::steady_clock::now(); - - struct rusage ru1{}; - bool const haveRu1 = getRusageThread(ru1); - - auto const statmAfter = readFile(statmPath); - long const rssAfterKB = detail::parseStatmRSSkB(statmAfter); - - // Populate report fields - report.rssBeforeKB = rssBeforeKB; - report.rssAfterKB = rssAfterKB; - report.durationUs = std::chrono::duration_cast(t1 - t0); - - if (haveRu0 && haveRu1) - { - report.minfltDelta = ru1.ru_minflt - ru0.ru_minflt; - report.majfltDelta = ru1.ru_majflt - ru0.ru_majflt; - } - - std::int64_t const deltaKB = (rssBeforeKB < 0 || rssAfterKB < 0) - ? 0 - : (static_cast(rssAfterKB) - static_cast(rssBeforeKB)); - - JLOG(journal.debug()) << "malloc_trim tag=" << tagStr << " result=" << report.trimResult + JLOG(journal.debug()) << "malloc_trim tag=" << tag << " result=" << report.trimResult << " pad=" << kTrimPad << " bytes" - << " rss_before=" << rssBeforeKB << "kB" - << " rss_after=" << rssAfterKB << "kB" - << " delta=" << deltaKB << "kB" + << " rss_before=" << report.rssBeforeKB << "kB" + << " rss_after=" << report.rssAfterKB << "kB" + << " delta=" << report.deltaKB() << "kB" << " duration_us=" << report.durationUs.count() << " minflt_delta=" << report.minfltDelta << " majflt_delta=" << report.majfltDelta; } - else - { - report.trimResult = detail::mallocTrimWithPad(kTrimPad); - } #endif diff --git a/src/libxrpl/nodestore/DatabaseRotatingImp.cpp b/src/libxrpl/nodestore/DatabaseRotatingImp.cpp index d5a839eb56..9f0d68e54b 100644 --- a/src/libxrpl/nodestore/DatabaseRotatingImp.cpp +++ b/src/libxrpl/nodestore/DatabaseRotatingImp.cpp @@ -211,7 +211,13 @@ DatabaseRotatingImp::fetchNodeObject( if (duplicate || rotationInFlight_.load(std::memory_order_acquire)) { if (!duplicate) + { + // Two counters, one event: the per-rotation tally that + // rotate() resets for its log line, and the monotonic total + // the metrics gauge reads, which must never go backwards. copyForwardCount_.fetch_add(1, std::memory_order_relaxed); + copyForwardTotal_.fetch_add(1, std::memory_order_relaxed); + } writable->store(nodeObject); } } diff --git a/src/tests/libxrpl/basics/MallocTrim.cpp b/src/tests/libxrpl/basics/MallocTrim.cpp index 6ac8957f0e..02ab18f115 100644 --- a/src/tests/libxrpl/basics/MallocTrim.cpp +++ b/src/tests/libxrpl/basics/MallocTrim.cpp @@ -121,7 +121,12 @@ TEST(parseStatmRSSkB, standard_format) } #endif -TEST(mallocTrim, without_debug_logging) +// The measurement must NOT depend on the journal's severity. It used to sit +// inside `if (journal.debug())`, so an ordinary node -- which does not run at +// debug level -- measured nothing and the caller had no duration to record. +// This is the regression test for that: with a null sink (nothing is even +// loggable) every field must still be populated. +TEST(mallocTrim, measures_without_debug_logging) { beast::Journal const journal{beast::Journal::getNullSink()}; @@ -130,10 +135,29 @@ TEST(mallocTrim, without_debug_logging) #if defined(__GLIBC__) && BOOST_OS_LINUX EXPECT_EQ(report.supported, true); EXPECT_GE(report.trimResult, 0); - EXPECT_EQ(report.durationUs, std::chrono::microseconds{-1}); - EXPECT_EQ(report.minfltDelta, -1); - EXPECT_EQ(report.majfltDelta, -1); + + // The three measured fields are populated, NOT left at their -1 + // "not measured" sentinel. Asserting >= 0 rather than == a fixed number + // because these are real timings; the sentinel is what the test excludes. + EXPECT_GE(report.durationUs.count(), 0); + EXPECT_GE(report.minfltDelta, 0); + EXPECT_GE(report.majfltDelta, 0); + + // RSS is read on both sides of the trim, so both are real page counts. + // A live process always has resident pages, so these are strictly > 0. + EXPECT_GT(report.rssBeforeKB, 0); + EXPECT_GT(report.rssAfterKB, 0); + + // deltaKB() is now derived from two real readings rather than from the + // sentinel pair, so it is the genuine change: a trim never grows RSS by + // more than another thread could allocate concurrently, and this test is + // single-threaded, so the reading cannot be positive. + EXPECT_LE(report.deltaKB(), 0); + EXPECT_EQ(report.deltaKB(), report.rssAfterKB - report.rssBeforeKB); #else + // NEGATIVE PLATFORM PATH: not Linux/glibc, so there is no trim at all and + // every field must keep its sentinel. A zero here would falsely claim a + // free trim happened. EXPECT_EQ(report.supported, false); EXPECT_EQ(report.trimResult, -1); EXPECT_EQ(report.rssBeforeKB, -1); @@ -141,6 +165,7 @@ TEST(mallocTrim, without_debug_logging) EXPECT_EQ(report.durationUs, std::chrono::microseconds{-1}); EXPECT_EQ(report.minfltDelta, -1); EXPECT_EQ(report.majfltDelta, -1); + EXPECT_EQ(report.deltaKB(), 0); #endif } @@ -185,6 +210,12 @@ TEST(mallocTrim, with_debug_logging) EXPECT_GE(report.durationUs.count(), 0); EXPECT_GE(report.minfltDelta, 0); EXPECT_GE(report.majfltDelta, 0); + + // Same fields as the null-sink case above: raising the severity adds the + // log line and changes nothing about what is measured. The two tests + // together are what prove the severity no longer gates the measurement. + EXPECT_GT(report.rssBeforeKB, 0); + EXPECT_GT(report.rssAfterKB, 0); #else EXPECT_EQ(report.supported, false); EXPECT_EQ(report.trimResult, -1); diff --git a/src/tests/libxrpl/telemetry/MetricMacros.cpp b/src/tests/libxrpl/telemetry/MetricMacros.cpp index f418b8e271..50effe58b1 100644 --- a/src/tests/libxrpl/telemetry/MetricMacros.cpp +++ b/src/tests/libxrpl/telemetry/MetricMacros.cpp @@ -17,10 +17,6 @@ * MetricsRegistry.cpp is only compiled into this binary on the no-op path. */ -// cspell:ignore ISTOGRAM -// The all-caps macro name XRPL_METRIC_HISTOGRAM_RECORD trips cspell's -// compound-word splitter, which emits the subword "ISTOGRAM"; ignore it here. - #ifdef XRPL_ENABLE_TELEMETRY #include @@ -29,6 +25,7 @@ #include #include +#include #include #include @@ -2921,4 +2918,376 @@ TEST(MetricMacros, consensus_round_duration_emits_nothing_when_registry_disabled EXPECT_EQ(app.registry().meterCalls(), 0); } +// ----------------------------------------------------------------- +// WP-B5: per-sweep malloc_trim, and online_delete rotation writes +// +// Suspect 3. malloc_trim runs after EVERY cache sweep and its cost scales with +// the resident heap, so a node with a large existing database pays a per-sweep +// penalty a fresh one does not. The MallocTrimReport already carried every +// number; the emit site discarded it. +// +// Suspect 4. An online_delete rotation performs writes an ordinary fetch would +// not -- copy-forward from the doomed archive, plus copyNode re-stores -- which +// compete with sync I/O and only exist on a populated, already-rotated +// database. +// ----------------------------------------------------------------- + +// The three sweep instruments must stay three separate series carrying their own +// exact values, and the guards at the emit site must drop a reading that was +// never measured rather than publishing a zero for it. +// +// The 45000 us sample is above the SDK's 10,000 default top boundary on +// purpose: that is why MetricsRegistry registers the microsecond ladder for +// this instrument, and a 45 ms trim is exactly the large-heap case the signal +// exists to catch. The sum must carry the real value however it is bucketed. +TEST(MetricMacros, sweep_malloc_trim_records_exact_duration_faults_and_reclaim) +{ + CollectingProvider const provider; + FakeApp app; + wire(app, /*enabled=*/true, provider.meter()); + + // Mirrors ApplicationImp::trimHeapAndRecord for three sweeps: a cheap trim + // on a small heap, an expensive one on a large heap, and one that reclaimed + // nothing. Distinct values so a collapsed instrument cannot look correct. + struct Sweep + { + std::int64_t durationUs; + std::int64_t minfltDelta; + std::int64_t reclaimedKb; + }; + for (auto const& sweep : { + Sweep{.durationUs = 120, .minfltDelta = 3, .reclaimedKb = 512}, + Sweep{.durationUs = 45'000, .minfltDelta = 900, .reclaimedKb = 262'144}, + Sweep{.durationUs = 80, .minfltDelta = 0, .reclaimedKb = 0}, + }) + { + XRPL_METRIC_HISTOGRAM_RECORD( + app, + telemetry::metric::sweepMallocTrimUs, + "Duration of the malloc_trim call ending each cache sweep (microseconds)", + sweep.durationUs); + if (sweep.minfltDelta > 0) + { + XRPL_METRIC_COUNTER_ADD( + app, + telemetry::metric::sweepMallocTrimMinorFaultsTotal, + "Minor page faults taken inside the sweep's malloc_trim call", + static_cast(sweep.minfltDelta)); + } + if (sweep.reclaimedKb > 0) + { + XRPL_METRIC_COUNTER_ADD( + app, + telemetry::metric::sweepMallocTrimReclaimedKbTotal, + "Resident kilobytes returned to the OS by the sweep's malloc_trim", + static_cast(sweep.reclaimedKb)); + } + } + + auto const data = provider.collect(); + + // Histogram: all three sweeps recorded, including the one whose fault and + // reclaim readings were skipped -- a trim always has a duration. + auto const [count, sum] = histogramCountAndSum(data, "sweep_malloc_trim_us"); + EXPECT_EQ(count, 3u); + EXPECT_NEAR(sum, 45'200.0, 1e-9); + + // Counters: cumulative totals, so the panel can rate() them. The zero-value + // third sweep contributed to neither. + EXPECT_EQ( + counterValue(data, "sweep_malloc_trim_minor_faults_total", otel_sdk::PointAttributes{}), + 903); + EXPECT_EQ( + counterValue(data, "sweep_malloc_trim_reclaimed_kb_total", otel_sdk::PointAttributes{}), + 262'656); + + // All three are unlabelled: one series each, per node. A label here would be + // unbounded (there is no bounded dimension a sweep varies over) and the + // dashboard reads one line per node instead. + ASSERT_EQ(data.at("sweep_malloc_trim_us").size(), 1u); + EXPECT_TRUE(data.at("sweep_malloc_trim_us").begin()->first.empty()); + ASSERT_EQ(data.at("sweep_malloc_trim_minor_faults_total").size(), 1u); + EXPECT_TRUE(data.at("sweep_malloc_trim_minor_faults_total").begin()->first.empty()); + ASSERT_EQ(data.at("sweep_malloc_trim_reclaimed_kb_total").size(), 1u); + EXPECT_TRUE(data.at("sweep_malloc_trim_reclaimed_kb_total").begin()->first.empty()); + + // Exactly the three instruments, so neither counter absorbed the other's + // adds and the histogram did not spawn a sibling. + EXPECT_EQ(data.size(), 3u); +} + +// EDGE CASE: nothing was measured. On a non-glibc platform mallocTrim() returns +// a report whose fields are all at their -1 sentinel, and the emit site's +// guards must publish NO series for it. A zero-valued series would claim the +// trim was instantaneous and reclaimed nothing, which is a different (and +// false) statement from "this platform has no trim". +// +// A FRESH provider, because the reader is cumulative: a second collect() on the +// provider used above would still show the earlier series and the absence +// assertions could not fail. +TEST(MetricMacros, sweep_malloc_trim_publishes_nothing_when_unmeasured) +{ + CollectingProvider const provider; + FakeApp app; + wire(app, /*enabled=*/true, provider.meter()); + + // The sentinel report, exactly as MallocTrimReport default-constructs it. + MallocTrimReport const unsupported; + ASSERT_FALSE(unsupported.supported); + ASSERT_EQ(unsupported.durationUs.count(), -1); + ASSERT_EQ(unsupported.minfltDelta, -1); + ASSERT_EQ(unsupported.deltaKB(), 0); + + // trimHeapAndRecord's first guard: an unsupported report emits nothing at + // all, so the three statements below are never reached on such a platform. + if (unsupported.supported) + { + if (unsupported.durationUs.count() >= 0) + { + XRPL_METRIC_HISTOGRAM_RECORD( + app, + telemetry::metric::sweepMallocTrimUs, + "Duration of the malloc_trim call ending each cache sweep (microseconds)", + unsupported.durationUs.count()); + } + } + + auto const data = provider.collect(); + + // State: not one of the three series exists. + EXPECT_EQ(data.count("sweep_malloc_trim_us"), 0u); + EXPECT_EQ(data.count("sweep_malloc_trim_minor_faults_total"), 0u); + EXPECT_EQ(data.count("sweep_malloc_trim_reclaimed_kb_total"), 0u); + EXPECT_EQ(data.size(), 0u); +} + +// EDGE CASE: RSS GREW across the trim, because another thread allocated faster +// than the trim released. deltaKB() is then positive, and the reclaimed counter +// must skip it -- a counter cannot decrease, and there is no such thing as +// reclaiming a negative number of kilobytes. The duration is still recorded, +// because the trim did happen and did cost time. +TEST(MetricMacros, sweep_malloc_trim_skips_reclaim_when_rss_grew) +{ + CollectingProvider const provider; + FakeApp app; + wire(app, /*enabled=*/true, provider.meter()); + + // A report whose after-RSS is ABOVE its before-RSS. + MallocTrimReport grew; + grew.supported = true; + grew.trimResult = 1; + grew.rssBeforeKB = 1'000'000; + grew.rssAfterKB = 1'000'800; + grew.durationUs = std::chrono::microseconds{9'000}; + grew.minfltDelta = 11; + + // Cause: the sign convention is after-minus-before, so growth is positive + // and a naive negation would add 800 to a "reclaimed" total. + ASSERT_EQ(grew.deltaKB(), 800); + + XRPL_METRIC_HISTOGRAM_RECORD( + app, + telemetry::metric::sweepMallocTrimUs, + "Duration of the malloc_trim call ending each cache sweep (microseconds)", + grew.durationUs.count()); + XRPL_METRIC_COUNTER_ADD( + app, + telemetry::metric::sweepMallocTrimMinorFaultsTotal, + "Minor page faults taken inside the sweep's malloc_trim call", + static_cast(grew.minfltDelta)); + if (auto const deltaKB = grew.deltaKB(); deltaKB < 0) + { + XRPL_METRIC_COUNTER_ADD( + app, + telemetry::metric::sweepMallocTrimReclaimedKbTotal, + "Resident kilobytes returned to the OS by the sweep's malloc_trim", + static_cast(-deltaKB)); + } + + auto const data = provider.collect(); + + // The duration and the faults are real and are recorded. + auto const [count, sum] = histogramCountAndSum(data, "sweep_malloc_trim_us"); + EXPECT_EQ(count, 1u); + EXPECT_NEAR(sum, 9'000.0, 1e-9); + EXPECT_EQ( + counterValue(data, "sweep_malloc_trim_minor_faults_total", otel_sdk::PointAttributes{}), + 11); + + // NEGATIVE: the reclaim counter has no series at all. Absence, not a zero + // and emphatically not 800. + EXPECT_EQ(data.count("sweep_malloc_trim_reclaimed_kb_total"), 0u); + EXPECT_EQ(data.size(), 2u); +} + +// rotation_state is polled from the node store, so the production callback in +// MetricsRegistry::registerRotationStateGauge cannot be linked into this +// binary. The derivation it performs is asserted here against the same two +// inputs, mirroring how nodestore_latency is tested above. +TEST(MetricMacros, rotation_state_gauge_observes_in_flight_window_and_copy_forward_total) +{ + // Each scenario gets a FRESH provider: the reader is cumulative, so a + // series observed once would persist into the next collect() and the + // "no rotating store means no series" assertion below could not fail. + struct RotationState + { + bool isRotating; + std::uint64_t copyForwardTotal; + bool hasRotatingStore; + }; + + auto collectWith = [](RotationState& state) { + CollectingProvider const provider; + auto gauge = provider.meter()->CreateInt64ObservableGauge( + telemetry::metric::rotationState, + "Online-delete rotation state and copy-forward write total"); + gauge->AddCallback( + [](opentelemetry::metrics::ObserverResult result, void* state) { + auto const* self = static_cast(state); + // The production dynamic_cast: a node without online_delete has + // a non-rotating store and publishes nothing. + if (!self->hasRotatingStore) + return; + auto observe = [&](char const* field, std::int64_t value) { + opentelemetry::nostd::get>>(result) + ->Observe(value, {{telemetry::label::metric, field}}); + }; + observe( + telemetry::lval::rotation_state::inFlight, + static_cast(self->isRotating ? 1 : 0)); + observe( + telemetry::lval::rotation_state::copyForward, + static_cast(self->copyForwardTotal)); + }, + &state); + return provider.collect(); + }; + + // A rotation is running and has already forced 4096 copy-forward writes: + // the shape an operator should see, and the one that explains sync I/O + // contention on a populated online_delete database. + RotationState state{.isRotating = true, .copyForwardTotal = 4096, .hasRotatingStore = true}; + auto const rotating = collectWith(state); + + ASSERT_EQ(rotating.at("rotation_state").size(), 2u); + EXPECT_EQ(gaugeValue(rotating, "rotation_state", attrs("metric", "in_flight")), 1); + EXPECT_EQ(gaugeValue(rotating, "rotation_state", attrs("metric", "copy_forward")), 4096); + + // Single fixed-cardinality label group, keyed exactly `metric`. + auto const& firstKey = rotating.at("rotation_state").begin()->first; + ASSERT_EQ(firstKey.size(), 1u); + EXPECT_EQ(firstKey.begin()->first, "metric"); + + // Between rotations: in_flight drops to 0 while the total HOLDS its value. + // That combination is the whole point of pairing them -- the extra writes + // are not happening now, but they did, and the total must not reset (a + // counter that drops cannot be rated). + state = RotationState{.isRotating = false, .copyForwardTotal = 4096, .hasRotatingStore = true}; + auto const idle = collectWith(state); + + EXPECT_EQ(gaugeValue(idle, "rotation_state", attrs("metric", "in_flight")), 0); + EXPECT_EQ(gaugeValue(idle, "rotation_state", attrs("metric", "copy_forward")), 4096); + // Both series still exist while idle: a zero in_flight is a real reading, + // and absence would be the regression. + EXPECT_EQ(idle.at("rotation_state").size(), 2u); + + // EDGE CASE: a fresh node that has online_delete configured but has never + // rotated. Both readings are 0 and BOTH series still exist -- 0 copy-forward + // writes is the healthy answer to "what did rotation cost", not missing data. + state = RotationState{.isRotating = false, .copyForwardTotal = 0, .hasRotatingStore = true}; + auto const neverRotated = collectWith(state); + + EXPECT_EQ(gaugeValue(neverRotated, "rotation_state", attrs("metric", "in_flight")), 0); + EXPECT_EQ(gaugeValue(neverRotated, "rotation_state", attrs("metric", "copy_forward")), 0); + EXPECT_EQ(neverRotated.at("rotation_state").size(), 2u); + + // NEGATIVE: no rotating store at all -- online_delete is not configured, so + // the node store is a DatabaseNodeImp and the cast fails. NO series is + // published, deliberately: an absent series means "rotation is not + // configured", which a zero would misreport as "rotation is free". + state = RotationState{.isRotating = false, .copyForwardTotal = 0, .hasRotatingStore = false}; + auto const notConfigured = collectWith(state); + + EXPECT_EQ(notConfigured.count("rotation_state"), 0u); + EXPECT_EQ(notConfigured.size(), 0u); +} + +// The copyNode re-store counter: one increment per node rescued from neither +// backend, on ONE unlabelled series. The node hash must never become a label -- +// it is unbounded runtime data and would mint one series per rescued node. +TEST(MetricMacros, rotation_copy_node_restore_accumulates_on_one_unlabelled_series) +{ + CollectingProvider const provider; + FakeApp app; + wire(app, /*enabled=*/true, provider.meter()); + + // Seven rescued nodes across one rotation's state-map walk. + for (int i = 0; i < 7; ++i) + { + XRPL_METRIC_COUNTER_INC( + app, + telemetry::metric::rotationCopyNodeRestoreTotal, + "Nodes re-stored during rotation because they were missing from both backends"); + } + + auto const data = provider.collect(); + + ASSERT_EQ(data.at("rotation_copy_node_restore_total").size(), 1u); + EXPECT_EQ( + counterValue(data, "rotation_copy_node_restore_total", otel_sdk::PointAttributes{}), 7); + + // The single series carries NO labels, which is what bounds its cardinality + // to one per node however many distinct hashes were rescued. + EXPECT_TRUE(data.at("rotation_copy_node_restore_total").begin()->first.empty()); + + // The rotation gauge is a separate instrument, so the counter cannot inflate + // the copy-forward total: they measure two different extra writes. + EXPECT_EQ(data.count("rotation_state"), 0u); + EXPECT_EQ(data.size(), 1u); +} + +// RUNTIME-DISABLED no-op proof for all four WP-B5 push instruments. With the +// registry disabled nothing is emitted -- total absence, not zero-valued series +// -- and no macro ever asks for a meter. +TEST(MetricMacros, sweep_and_rotation_metrics_emit_nothing_when_registry_disabled) +{ + CollectingProvider const provider; + FakeApp app; + wire(app, /*enabled=*/false, provider.meter()); + + XRPL_METRIC_HISTOGRAM_RECORD( + app, + telemetry::metric::sweepMallocTrimUs, + "Duration of the malloc_trim call ending each cache sweep (microseconds)", + 45'000); + XRPL_METRIC_COUNTER_ADD( + app, + telemetry::metric::sweepMallocTrimMinorFaultsTotal, + "Minor page faults taken inside the sweep's malloc_trim call", + 900); + XRPL_METRIC_COUNTER_ADD( + app, + telemetry::metric::sweepMallocTrimReclaimedKbTotal, + "Resident kilobytes returned to the OS by the sweep's malloc_trim", + 262'144); + XRPL_METRIC_COUNTER_INC( + app, + telemetry::metric::rotationCopyNodeRestoreTotal, + "Nodes re-stored during rotation because they were missing from both backends"); + + auto const data = provider.collect(); + + // State: no series under any of the four names, and nothing else leaked in. + EXPECT_EQ(data.count("sweep_malloc_trim_us"), 0u); + EXPECT_EQ(data.count("sweep_malloc_trim_minor_faults_total"), 0u); + EXPECT_EQ(data.count("sweep_malloc_trim_reclaimed_kb_total"), 0u); + EXPECT_EQ(data.count("rotation_copy_node_restore_total"), 0u); + EXPECT_EQ(data.size(), 0u); + + // Cause, not just state: the isEnabled() gate short-circuited before any + // macro asked for a meter, so no instrument was ever created. + EXPECT_EQ(app.registry().meterCalls(), 0); +} + #endif // XRPL_ENABLE_TELEMETRY diff --git a/src/xrpld/app/consensus/RCLConsensus.cpp b/src/xrpld/app/consensus/RCLConsensus.cpp index aaf7e17c83..de58c0961c 100644 --- a/src/xrpld/app/consensus/RCLConsensus.cpp +++ b/src/xrpld/app/consensus/RCLConsensus.cpp @@ -1,6 +1,3 @@ -// cspell:ignore ISTOGRAM -// The all-caps macro name XRPL_METRIC_HISTOGRAM_RECORD trips cspell's -// compound-word splitter, which emits the subword "ISTOGRAM"; ignore it here. #include diff --git a/src/xrpld/app/main/Application.cpp b/src/xrpld/app/main/Application.cpp index 3f083a932d..359652334e 100644 --- a/src/xrpld/app/main/Application.cpp +++ b/src/xrpld/app/main/Application.cpp @@ -1,3 +1,4 @@ + #include #include @@ -38,6 +39,8 @@ #include #include #include +#include +#include #include #include @@ -1131,12 +1134,82 @@ public: << "; size after: " << cachedSLEs_.size(); } - mallocTrim("doSweep", journal_); + trimHeapAndRecord(); // Set timer to do another sweep later. setSweepTimer(); } + /** + * Return free heap pages to the OS at the end of a sweep, and record what + * that cost. + * + * Split out of doSweep() so the metric emit site is one small unit rather + * than a further three statements on an already-long function. + * + * Why this is instrumented: `malloc_trim` runs after EVERY cache sweep, and + * its cost scales with the resident heap, so a node with a large existing + * database pays a per-sweep penalty a fresh one does not -- the leading + * explanation for "an existing database syncs slower than an empty one" on + * glibc. The report used to be discarded here, so none of it was visible. + * + * doSweep() -> trimHeapAndRecord() -> mallocTrim() + * | | + * | MallocTrimReport (duration, + * | minor faults, RSS before/after) + * v + * 3 OTel instruments + * + * Cost: one histogram Record and two counter Adds per sweep, at a cadence + * of SizedItem::SweepInterval (10-120 s), so this is free. + * + * @note The minor-fault count covers the trim call only. It cannot show the + * faults taken later, as the caches refill and touch the pages the + * trim handed back -- see the runbook branch for how to read it. + */ + void + trimHeapAndRecord() + { + MallocTrimReport const report = mallocTrim("doSweep", journal_); + + // Nothing was measured: not Linux/glibc, so there is no trim to report + // and a zero would falsely claim a free one. + if (!report.supported) + return; + + if (report.durationUs.count() >= 0) + { + XRPL_METRIC_HISTOGRAM_RECORD( + *this, + telemetry::metric::sweepMallocTrimUs, + "Duration of the malloc_trim call ending each cache sweep (microseconds)", + report.durationUs.count()); + } + + if (report.minfltDelta > 0) + { + XRPL_METRIC_COUNTER_ADD( + *this, + telemetry::metric::sweepMallocTrimMinorFaultsTotal, + "Minor page faults taken inside the sweep's malloc_trim call", + static_cast(report.minfltDelta)); + } + + // deltaKB() is after-minus-before, so a successful trim is NEGATIVE. + // Publish the reclaimed amount as a positive cumulative total and drop + // the case where RSS grew across the call (another thread allocating + // faster than the trim released): a counter cannot go down, and "grew" + // is not a reclaim of a negative size. + if (auto const deltaKB = report.deltaKB(); deltaKB < 0) + { + XRPL_METRIC_COUNTER_ADD( + *this, + telemetry::metric::sweepMallocTrimReclaimedKbTotal, + "Resident kilobytes returned to the OS by the sweep's malloc_trim", + static_cast(-deltaKB)); + } + } + LedgerIndex getMaxDisallowedLedger() override { diff --git a/src/xrpld/app/misc/SHAMapStoreImp.cpp b/src/xrpld/app/misc/SHAMapStoreImp.cpp index 9b5f412fc5..591e1d67a2 100644 --- a/src/xrpld/app/misc/SHAMapStoreImp.cpp +++ b/src/xrpld/app/misc/SHAMapStoreImp.cpp @@ -4,6 +4,8 @@ #include #include #include +#include +#include #include #include @@ -273,6 +275,16 @@ SHAMapStoreImp::copyNode(std::uint64_t& nodeCount, SHAMapTreeNode const& node) dbRotating_->store(NodeObjectType::AccountNode, std::move(s.modData()), hash, 0); JLOG(journal_.warn()) << "copyNode: re-stored node missing from both backends, hash=" << hash << " type=" << static_cast(node.getType()); + // One extra write per rescued node, on top of the whole-state-map walk + // the rotation already performs. Rotation-time writes compete with sync + // I/O, and this branch was warn-log-only, so the volume was invisible + // unless an operator was reading logs. The node hash is deliberately NOT + // a label: it is unbounded runtime data and would mint one series per + // node. Correlate a spike against the log line by node and time. + XRPL_METRIC_COUNTER_INC( + app_, + telemetry::metric::rotationCopyNodeRestoreTotal, + "Nodes re-stored during rotation because they were missing from both backends"); } if ((++nodeCount % checkHealthInterval_) == 0u) { diff --git a/src/xrpld/overlay/detail/ConnectAttempt.cpp b/src/xrpld/overlay/detail/ConnectAttempt.cpp index 6b3877b079..6b2cf914ef 100644 --- a/src/xrpld/overlay/detail/ConnectAttempt.cpp +++ b/src/xrpld/overlay/detail/ConnectAttempt.cpp @@ -1,6 +1,3 @@ -// cspell:ignore ISTOGRAM -// The all-caps macro name XRPL_METRIC_HISTOGRAM_RECORD trips cspell's -// compound-word splitter, which emits the subword "ISTOGRAM"; ignore it here. #include diff --git a/src/xrpld/overlay/detail/OverlayImpl.cpp b/src/xrpld/overlay/detail/OverlayImpl.cpp index 6a1a2760bd..f800d15cfa 100644 --- a/src/xrpld/overlay/detail/OverlayImpl.cpp +++ b/src/xrpld/overlay/detail/OverlayImpl.cpp @@ -1,6 +1,3 @@ -// cspell:ignore ISTOGRAM -// The all-caps macro name XRPL_METRIC_HISTOGRAM_RECORD trips cspell's -// compound-word splitter, which emits the subword "ISTOGRAM"; ignore it here. #include diff --git a/src/xrpld/overlay/detail/PeerImp.cpp b/src/xrpld/overlay/detail/PeerImp.cpp index bc7f44e2bd..7082a24b11 100644 --- a/src/xrpld/overlay/detail/PeerImp.cpp +++ b/src/xrpld/overlay/detail/PeerImp.cpp @@ -1,6 +1,3 @@ -// cspell:ignore ISTOGRAM -// The all-caps macro name XRPL_METRIC_HISTOGRAM_RECORD trips cspell's -// compound-word splitter, which emits the subword "ISTOGRAM"; ignore it here. #include diff --git a/src/xrpld/telemetry/MetricMacros.h b/src/xrpld/telemetry/MetricMacros.h index 6bea92d8e3..0390a44167 100644 --- a/src/xrpld/telemetry/MetricMacros.h +++ b/src/xrpld/telemetry/MetricMacros.h @@ -1,9 +1,5 @@ #pragma once -// cspell:ignore ISTOGRAM -// The all-caps macro name XRPL_METRIC_HISTOGRAM_RECORD trips cspell's -// compound-word splitter, which emits the subword "ISTOGRAM"; ignore it here. - /** * Call-site OTel metric macros. * diff --git a/src/xrpld/telemetry/MetricNames.h b/src/xrpld/telemetry/MetricNames.h index ff86727998..331a18a19b 100644 --- a/src/xrpld/telemetry/MetricNames.h +++ b/src/xrpld/telemetry/MetricNames.h @@ -268,6 +268,58 @@ inline constexpr char nodestoreLatency[] = "nodestore_latency"; */ inline constexpr char consensusRoundDurationMs[] = "consensus_round_duration_ms"; +// ===== Sweep: what the periodic cache sweep costs ============================ +// +// The sweep runs every `SizedItem::SweepInterval` seconds (10 s on a tiny node +// through 120 s on a huge one), so these three emit sites are cold: one +// histogram Record and two counter Adds per sweep is free at that cadence. + +/** + * Wall-clock duration of the `malloc_trim` call that ends every cache sweep. + * + * The cost of returning free heap pages to the kernel scales with the resident + * heap, so this is the signal that a node with a large existing database pays a + * per-sweep penalty a fresh node does not. + */ +inline constexpr char sweepMallocTrimUs[] = "sweep_malloc_trim_us"; +/** + * Minor page faults taken *inside* the `malloc_trim` call. + * + * Cumulative, so `rate()` gives faults/sec. Scoped to the trim call only -- see + * the limitation noted on the runbook branch: this proves the trim itself + * faults, not that the trim causes later faults as the caches refill. + */ +inline constexpr char sweepMallocTrimMinorFaultsTotal[] = "sweep_malloc_trim_minor_faults_total"; +/** + * Resident kilobytes the trim actually returned to the kernel. + * + * Cumulative and clamped at zero per sweep: a trim that reclaimed nothing, or + * during which another thread grew the heap faster than the trim shrank it, + * contributes 0 rather than a negative amount. + */ +inline constexpr char sweepMallocTrimReclaimedKbTotal[] = "sweep_malloc_trim_reclaimed_kb_total"; + +// ===== Rotation: the extra writes an online_delete rotation performs ========= + +/** + * Nodes re-stored by `copyNode` because they were missing from both backends. + * + * The genuinely unmeasured extra write of a rotation: a clean node reachable + * from the validated state map whose only on-disk copy lived in a backend an + * earlier rotation removed. Was warn-log-only. + */ +inline constexpr char rotationCopyNodeRestoreTotal[] = "rotation_copy_node_restore_total"; +/** + * Rotation state: whether one is running, and the copy-forward write total. + * + * A gauge, not a counter, because the two readings are polled from the node + * store rather than pushed: `in_flight` is current state and `copy_forward` is a + * cumulative total the nodestore already keeps. Observed from the existing + * `registerNodeStoreGauge` callback, which is how everything else reads the node + * store from xrpld without libxrpl having to know about telemetry. + */ +inline constexpr char rotationState[] = "rotation_state"; + // ===== Pre-existing instruments pulled in by the family ratchet ============== // // These predate the sync-diagnostics work. They are declared here because the @@ -592,6 +644,20 @@ inline constexpr char warned[] = "warned"; inline constexpr char secondsToBlock[] = "seconds_to_block"; } // namespace amendment_block +/** + * `rotation_state` sub-metrics: is a rotation running, and how many extra + * writes have rotations caused. + * + * Read together: a `copy_forward` total that climbs while `in_flight` is 1 is + * the rotation doing its extra writes, which is the expected shape. The same + * total climbing while `in_flight` is 0 would mean the flag leaked, not that + * rotation is cheap. + */ +namespace rotation_state { +inline constexpr char inFlight[] = "in_flight"; +inline constexpr char copyForward[] = "copy_forward"; +} // namespace rotation_state + /** * `nodestore_latency` sub-metrics: mean latency per direction, with counts. */ diff --git a/src/xrpld/telemetry/MetricsRegistry.cpp b/src/xrpld/telemetry/MetricsRegistry.cpp index aba181ea50..c62f07a690 100644 --- a/src/xrpld/telemetry/MetricsRegistry.cpp +++ b/src/xrpld/telemetry/MetricsRegistry.cpp @@ -1,6 +1,3 @@ -// cspell:ignore ISTOGRAM -// The all-caps macro name XRPL_METRIC_HISTOGRAM_RECORD trips cspell's -// compound-word splitter, which emits the subword "ISTOGRAM"; ignore it here. /** * MetricsRegistry implementation — OpenTelemetry metric instruments for xrpld. @@ -47,6 +44,7 @@ #include #include #include +#include #include #include #include @@ -328,6 +326,19 @@ MetricsRegistry::initExporterAndProvider(std::string const& endpoint, std::strin // comes from the shared constant both sites use. addMicrosecondHistogramView(*views, kGetObjectLookupUs); + // Sweep malloc_trim duration. Shares the microsecond ladder rather than + // getting a bespoke one, and the ladder is what makes it readable: a trim on + // a small heap lands in the tens-of-microseconds buckets, while a trim on a + // multi-gigabyte resident heap runs well past 10 ms -- which is exactly the + // large-existing-database case this signal exists to catch. With the SDK + // default ceiling of 10,000 every one of those would collapse into the + // overflow bucket and p95 would read exactly 10 ms however bad it got. The + // shared ladder's upper reaches (25 ms, 50 ms, 100 ms, 250 ms, 500 ms, 1 s + // and beyond) resolve those, and its lower reaches (100 us, 500 us) resolve + // the healthy fresh-node case, so a per-instrument ladder would add a second + // thing to maintain for no extra resolution. + addMicrosecondHistogramView(*views, metric::sweepMallocTrimUs); + // 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 @@ -336,13 +347,39 @@ MetricsRegistry::initExporterAndProvider(std::string const& endpoint, std::strin 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}); + {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}); + {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 @@ -635,6 +672,7 @@ MetricsRegistry::registerAsyncGauges() registerObjectCountGauge(); registerLoadFactorGauge(); registerNodeStoreGauge(); + registerRotationStateGauge(); registerServerInfoGauge(); registerBuildInfoGauge(); registerCompleteLedgersGauge(); @@ -967,6 +1005,70 @@ MetricsRegistry::registerNodeStoreGauge() this); } +void +MetricsRegistry::registerRotationStateGauge() +{ + // --- Sync diagnostics: what an online_delete rotation costs --- + // A rotation performs writes an ordinary fetch would not: the archive + // backend is about to be deleted, so any node body it serves during the + // rotation window has to be rewritten into the writable backend to survive. + // That work scales with the archive, competes with sync I/O, and appears + // ONLY on a populated, already-rotated online_delete database -- which is + // why it never shows up on a fresh node and why it was never measured. The + // count existed as copyForwardCount_ but was log-only and reset per + // rotation. + // + // Polled from the node store rather than pushed, matching + // registerNodeStoreGauge above: DatabaseRotatingImp lives in libxrpl and + // cannot include xrpld/telemetry, so the counters are read through the + // DatabaseRotating accessors on each collection tick instead. + rotationStateGauge_ = meter_->CreateInt64ObservableGauge( + metric::rotationState, "Online-delete rotation state and copy-forward write total"); + rotationStateGauge_->AddCallback( + [](opentelemetry::metrics::ObserverResult result, void* state) { + auto* self = static_cast(state); + if (self->callbacksDetached_.load(std::memory_order_acquire)) + return; + auto& app = self->app_; + + try + { + // Only a rotating store has a rotation to report. On a node + // without online_delete the node store is a DatabaseNodeImp, so + // the cast fails and NO series is published -- deliberately, so + // that an absent series means "rotation is not configured" + // rather than a zero that would read as "rotation is free". + auto* rotating = dynamic_cast(&app.getNodeStore()); + if (rotating == nullptr) + return; + + auto observe = [&](char const* field, int64_t value) { + opentelemetry::nostd::get>>(result) + ->Observe(value, {{label::metric, field}}); + }; + + // The window the extra writes happen in. A panel needs this to + // know when the copy-forward total is expected to move. + observe( + lval::rotation_state::inFlight, + static_cast(rotating->isRotationInFlight() ? 1 : 0)); + + // Monotonic, so the panel takes rate() over it. The per-rotation + // tally that rotate() logs is reset on every swap and is + // therefore unusable here. + observe( + lval::rotation_state::copyForward, + static_cast(rotating->copyForwardTotal())); + } + catch (...) // NOLINT(bugprone-empty-catch) + { + // Silently skip if services are not yet ready. + } + }, + this); +} + void MetricsRegistry::registerServerInfoGauge() { @@ -2183,8 +2285,7 @@ MetricsRegistry::registerNodeStoreLatencyGauge() lval::nodestore_latency::writeDurationUs, static_cast(storeDurationUs)); observe( - lval::nodestore_latency::readDurationUs, - static_cast(fetchDurationUs)); + lval::nodestore_latency::readDurationUs, static_cast(fetchDurationUs)); if (storeCount > 0 && storeDurationUs > 0) { diff --git a/src/xrpld/telemetry/MetricsRegistry.h b/src/xrpld/telemetry/MetricsRegistry.h index ff07fdd10c..accfc02040 100644 --- a/src/xrpld/telemetry/MetricsRegistry.h +++ b/src/xrpld/telemetry/MetricsRegistry.h @@ -645,6 +645,13 @@ private: * Observable gauges for NodeStore write_load and read_queue. */ opentelemetry::nostd::shared_ptr nodeStoreGauge_; + /** + * Observable gauge for online-delete rotation state and its copy-forward + * write total. Publishes nothing on a node without `online_delete`, where + * the node store is not a rotating one. + */ + opentelemetry::nostd::shared_ptr + rotationStateGauge_; /** * Observable gauge for server-level health metrics (state, uptime, peers, etc.). */ @@ -872,6 +879,8 @@ private: void registerNodeStoreGauge(); // Task 9.1 void + registerRotationStateGauge(); // Sync diagnostics: online_delete rotation + void registerServerInfoGauge(); // Task 9.7a void registerBuildInfoGauge(); // Task 9.7b