From 253cd0648987d5d823cb0b7dcaa2b1338bfcac43 Mon Sep 17 00:00:00 2001 From: Pratik Mankawde <3397372+pratikmankawde@users.noreply.github.com> Date: Tue, 28 Jul 2026 18:46:55 +0100 Subject: [PATCH 1/3] docs(telemetry): correct the three measurement defects in docs and dashboard Three measurement fixes landed with no doc or dashboard change, leaving text that is now false and one fix unusable from a dashboard. Deferrals and timeouts are recorded in TimeoutCounter, a base shared by five subclasses, so the all-lane pair could show the documented livelock fingerprint while ledger acquisition was healthy. The runbook procedure and the reference doc now name acquire_ledger_deferrals and acquire_ledger_timeouts and say why the all-lane pair misleads; a new panel plots the ledger-scoped pair as rates on one axis, since the divergence is the signal. The existing panel is retitled All Lanes and points at it. Writer mean depth is depthSum over depthSamples, not over insertCount, and the measured 1.60 came from the biased estimator, so it and the 37% queueing share derived from it are lower bounds rather than values. The reference table now marks them as such, and the decision rule is shown to survive the correction rather than depending on the exact figures. Completions were never counted for acquisitions satisfied from the local store, so the run that read zero across 510 seconds had in fact reached full. Every place that treated a zero as a symptom now says it only means something on a build that has the fix. Also corrects the sync-diagnosis label-value count from 13 to 15 and a stale source line range; the instrument count stays 35, because both new values multiplex onto the existing nodestore_state gauge. Co-Authored-By: Claude Opus 5 (1M context) --- .../09-data-collection-reference.md | 77 ++++++--- .../grafana/dashboards/ledger-data-sync.json | 59 ++++++- docs/telemetry-runbook.md | 163 +++++++++++++----- 3 files changed, 228 insertions(+), 71 deletions(-) diff --git a/OpenTelemetryPlan/09-data-collection-reference.md b/OpenTelemetryPlan/09-data-collection-reference.md index 086a8e21d8..ceb42980c9 100644 --- a/OpenTelemetryPlan/09-data-collection-reference.md +++ b/OpenTelemetryPlan/09-data-collection-reference.md @@ -1004,8 +1004,9 @@ repeated here: `_running` / `_deferred`). These travel the `beast::insight` pipeline, not the OTel SDK one, so they are documented in [§2.5](#25-per-job-type-queue-gauges). -- The sync-diagnosis signals — 13 further `nodestore_state` label values — which - separate a write-serialized stall from a cold-read stall. See +- The sync-diagnosis signals — 15 further `nodestore_state` label values (two + latency means, four `nudb_*`, nine `acquire_*`) — which separate a + write-serialized stall from a cold-read stall. See [Sync Diagnosis Signals](#sync-diagnosis-signals-observable-gauge--nodestore_state). ### New Grafana Dashboards (Phase 9) @@ -1174,37 +1175,44 @@ Further label values on the same instrument, added to separate the two bottlenecks that both present as the `ledgerData` job lane pinned at its concurrency cap. Observed in `MetricsRegistry::observeNodeStoreTotals()`, `observeWritePathDetail()`, and `observeAcquireStats()` -(`src/xrpld/telemetry/MetricsRegistry.cpp:830-894`). +(`src/xrpld/telemetry/MetricsRegistry.cpp:805-877`). -| Prometheus Metric | Type | Labels | Description | -| --------------------------------------------------- | ----- | -------- | -------------------------------------------------------- | -| `nodestore_state{metric="read_mean_us"}` | Gauge | `metric` | Mean time per backend read (microseconds) | -| `nodestore_state{metric="write_mean_us"}` | Gauge | `metric` | Mean time per backend write (microseconds) | -| `nodestore_state{metric="nudb_writers_in_flight"}` | Gauge | `metric` | Threads inside a NuDB insert at sample time | -| `nodestore_state{metric="nudb_writer_depth_x100"}` | Gauge | `metric` | Mean queue depth at the NuDB insert mutex, scaled ×100 | -| `nodestore_state{metric="nudb_insert_mean_us"}` | Gauge | `metric` | Mean NuDB insert time incl. queueing (microseconds) | -| `nodestore_state{metric="nudb_insert_max_us"}` | Gauge | `metric` | Slowest single NuDB insert observed (microseconds) | -| `nodestore_state{metric="acquire_deferrals"}` | Gauge | `metric` | Acquisition timer jobs skipped because the lane was full | -| `nodestore_state{metric="acquire_timeouts"}` | Gauge | `metric` | Acquisition timer bodies that ran and advanced retry | -| `nodestore_state{metric="acquire_give_ups"}` | Gauge | `metric` | Acquisitions that exhausted their retry budget | -| `nodestore_state{metric="acquire_aborts"}` | Gauge | `metric` | Acquisitions destroyed before finishing | -| `nodestore_state{metric="acquire_aborts_partial"}` | Gauge | `metric` | Subset of aborts that discarded partly built maps | -| `nodestore_state{metric="acquire_completions"}` | Gauge | `metric` | Acquisitions that finished successfully | -| `nodestore_state{metric="acquire_sweep_evictions"}` | Gauge | `metric` | Acquisitions evicted by the 1-minute sweep | +| Prometheus Metric | Type | Labels | Description | +| ---------------------------------------------------- | ----- | -------- | ------------------------------------------------------- | +| `nodestore_state{metric="read_mean_us"}` | Gauge | `metric` | Mean time per backend read (microseconds) | +| `nodestore_state{metric="write_mean_us"}` | Gauge | `metric` | Mean time per backend write (microseconds) | +| `nodestore_state{metric="nudb_writers_in_flight"}` | Gauge | `metric` | Threads inside a NuDB insert at sample time | +| `nodestore_state{metric="nudb_writer_depth_x100"}` | Gauge | `metric` | Mean queue depth at the NuDB insert mutex, scaled ×100 | +| `nodestore_state{metric="nudb_insert_mean_us"}` | Gauge | `metric` | Mean NuDB insert time incl. queueing (microseconds) | +| `nodestore_state{metric="nudb_insert_max_us"}` | Gauge | `metric` | Slowest single NuDB insert observed (microseconds) | +| `nodestore_state{metric="acquire_deferrals"}` | Gauge | `metric` | Timer jobs skipped because the lane was full, all lanes | +| `nodestore_state{metric="acquire_timeouts"}` | Gauge | `metric` | Timer bodies that ran and advanced retry, all lanes | +| `nodestore_state{metric="acquire_ledger_deferrals"}` | Gauge | `metric` | Deferrals from the `InboundLedger` lane alone | +| `nodestore_state{metric="acquire_ledger_timeouts"}` | Gauge | `metric` | Timeouts from the `InboundLedger` lane alone | +| `nodestore_state{metric="acquire_give_ups"}` | Gauge | `metric` | Acquisitions that exhausted their retry budget | +| `nodestore_state{metric="acquire_aborts"}` | Gauge | `metric` | Acquisitions destroyed before finishing | +| `nodestore_state{metric="acquire_aborts_partial"}` | Gauge | `metric` | Subset of aborts that discarded partly built maps | +| `nodestore_state{metric="acquire_completions"}` | Gauge | `metric` | Acquisitions that finished successfully | +| `nodestore_state{metric="acquire_sweep_evictions"}` | Gauge | `metric` | Acquisitions evicted by the 1-minute sweep | **Three properties to know before querying these.** - `nudb_writer_depth_x100` is fixed-point — divide by 100. The depth sits just above 1.0 even under load, because NuDB takes one global mutex per insert (`nudb/impl/basic_store.ipp:288`, a Conan dependency this repo does not patch). - An integral gauge would truncate 1.60 to 1 and lose the signal entirely. + An integral gauge would truncate 1.60 to 1 and lose the signal entirely. The + value is `WriteStats::depthSum / WriteStats::depthSamples`, both folded in when + an insert **enters** the critical section, so inserts still in flight count + toward the mean. It is not `depthSum / insertCount`: `insertCount` only rises at + insert exit, and dividing by it excluded exactly the deep, slow inserts and + biased the mean downward when queueing was worst. - The four `nudb_*` values are published **only when the writable backend is NuDB**. `observeWritePathDetail()` returns early when `getWriteStats()` is empty, so a memory or RocksDB backend omits them rather than reporting four zeros. Absent is not zero. - `read_mean_us` and `write_mean_us` are omitted when nothing has been read or written, so a dashboard shows a gap instead of a plausible wrong number. The - seven `acquire_*` counters are published unconditionally, because for a counter + nine `acquire_*` counters are published unconditionally, because for a counter zero is a meaningful reading. **The pairs, not the individual counts, are diagnostic.** Deferrals rising while @@ -1214,6 +1222,24 @@ timer without running its body, so the retry counter never advances and the zero means partial work is discarded and redone. Neither pattern is visible from one counter. Documented on the class at `src/xrpld/app/ledger/AcquireStats.h`. +**Compare the ledger-scoped pair, not the all-lane pair.** Deferrals and timeouts +are both recorded in `TimeoutCounter`, a base shared by five subclasses +(`InboundLedger`, `TransactionAcquire`, `LedgerReplayTask`, `LedgerDeltaAcquire`, +`SkipListAcquire`) with different job limits, so `acquire_deferrals` and +`acquire_timeouts` pool every lane — a saturated replay lane reproduces the +fingerprint while ledger acquisition is healthy. `acquire_ledger_deferrals` and +`acquire_ledger_timeouts` narrow both events to the `InboundLedger` lane via +`TimeoutCounter::isLedgerAcquisition()` and are the pair to compare. Both pairs +multiplex on the existing `metric` label, so no new instrument and no new +dashboard template variable is involved. + +`acquire_completions` counts an acquisition at **both** of its exits — `done()` +and the `init()` path that is satisfied entirely from the local store — behind an +idempotent latch, so it is exactly one per completion however the completion was +reached. Before that latch existed, local-store hits were uncounted and the gauge +could read zero on a node that was completing steadily; treat a zero on archived +data as uninformative unless the build is known to include the fix. + #### Cache Hit Rates & Sizes (Observable Gauge — `cache_metrics`) | Prometheus Metric | Type | Labels | Description | @@ -1446,10 +1472,15 @@ nodestore_state{metric="read_mean_us", service_instance_id=~"$node"} # Are ledger acquisitions finishing at all? (per minute) increase(nodestore_state{metric="acquire_completions", service_instance_id=~"$node"}[1m]) -# Livelock fingerprint, first half: deferrals climbing -increase(nodestore_state{metric="acquire_deferrals", service_instance_id=~"$node"}[5m]) +# Livelock fingerprint, first half: ledger-acquisition deferrals climbing +increase(nodestore_state{metric="acquire_ledger_deferrals", service_instance_id=~"$node"}[5m]) -# Livelock fingerprint, second half: timeouts staying flat while the above climbs +# Livelock fingerprint, second half: ledger-acquisition timeouts staying flat +increase(nodestore_state{metric="acquire_ledger_timeouts", service_instance_id=~"$node"}[5m]) + +# All-lane totals. Answers "is any TimeoutCounter lane deferring", not "is ledger +# acquisition deferring" -- do not read the fingerprint off this pair. +increase(nodestore_state{metric="acquire_deferrals", service_instance_id=~"$node"}[5m]) increase(nodestore_state{metric="acquire_timeouts", service_instance_id=~"$node"}[5m]) ``` diff --git a/docker/telemetry/grafana/dashboards/ledger-data-sync.json b/docker/telemetry/grafana/dashboards/ledger-data-sync.json index 894d6e9831..d04e4d3150 100644 --- a/docker/telemetry/grafana/dashboards/ledger-data-sync.json +++ b/docker/telemetry/grafana/dashboards/ledger-data-sync.json @@ -1683,7 +1683,7 @@ }, { "title": "NuDB Writer Queue Depth", - "description": "###### What this is:\n*How many writers are queued at NuDB's insert mutex. NuDB takes one global lock per insert, so concurrent writers do not overlap -- they line up. This panel is the confirming half of the read-latency discriminator: when reads are fast and the lane is still full, the queueing is here.*\n\n###### How it's computed:\n*Mean Depth is nodestore_state{metric=\"nudb_writer_depth_x100\"} divided by 100. The exported gauge is integral, so the mean is scaled by 100 at the source to keep the fractional part; dividing it back is what makes 1.60 readable instead of 1. In Flight is the instantaneous nudb_writers_in_flight sample.*\n\n###### Reading it:\n*Depth is a queue length, so 1.0 is the floor and means every insert found the lock free. Anything meaningfully above 1.0 means inserts are waiting on each other and the write path, not the disk, is setting the pace. In Flight is a point sample from the scrape instant and will look spikier than the mean; read the mean for the trend and In Flight for the peak.*\n\n###### Healthy range:\n*Mean depth at or just above 1.0, In Flight low.*\n\n###### Watch for:\n*Mean depth above 1 while read latency stays in single-digit microseconds -- that pair is the write-lock ceiling, and no amount of read tuning will move it. A measured run of this mode held depth at 1.60 with reads flat at 8-9 microseconds and reached its ceiling in 510 seconds while completing nothing. Depth at 1.0 with slow reads is the opposite mode; look at the read panel.*\n\n###### Source:\n[telemetry/MetricsRegistry.cpp](https://github.com/XRPLF/rippled/blob/develop/src/xrpld/telemetry/MetricsRegistry.cpp)\n\n###### Function:\n`MetricsRegistry::observeWritePathDetail`", + "description": "###### What this is:\n*How many writers are queued at NuDB's insert mutex. NuDB takes one global lock per insert, so concurrent writers do not overlap -- they line up. This panel is the confirming half of the read-latency discriminator: when reads are fast and the lane is still full, the queueing is here.*\n\n###### How it's computed:\n*Mean Depth is nodestore_state{metric=\"nudb_writer_depth_x100\"} divided by 100. At the source it is depthSum over depthSamples, both accumulated when an insert enters the critical section, so an insert still in flight is part of the mean. The exported gauge is integral, so the mean is scaled by 100 to keep the fractional part; dividing it back is what makes 1.60 readable instead of 1. In Flight is the instantaneous nudb_writers_in_flight sample.*\n\n###### Reading it:\n*Depth is a queue length, so 1.0 is the floor and means every insert found the lock free. Anything meaningfully above 1.0 means inserts are waiting on each other and the write path, not the disk, is setting the pace. In Flight is a point sample from the scrape instant and will look spikier than the mean; read the mean for the trend and In Flight for the peak.*\n\n###### Healthy range:\n*Mean depth at or just above 1.0, In Flight low.*\n\n###### Watch for:\n*Mean depth above 1 while read latency stays in single-digit microseconds -- that pair is the write-lock ceiling, and no amount of read tuning will move it. A measured run of this mode held depth at 1.60 with reads flat at 8-9 microseconds and took 510 seconds to reach full. That 1.60 came from a build whose sample count advanced at insert exit rather than entry, which biased the mean down, so treat it as a lower bound. The same run appeared to complete nothing, which was a separate counting defect, not a stalled node. Depth at 1.0 with slow reads is the opposite mode; look at the read panel.*\n\n###### Source:\n[telemetry/MetricsRegistry.cpp](https://github.com/XRPLF/rippled/blob/develop/src/xrpld/telemetry/MetricsRegistry.cpp)\n\n###### Function:\n`MetricsRegistry::observeWritePathDetail`", "type": "timeseries", "gridPos": { "h": 8, @@ -1732,7 +1732,7 @@ }, { "title": "NuDB Insert Time (Mean & Max)", - "description": "###### What this is:\n*Time spent inside a NuDB insert, mean and worst case, alongside the backend's overall mean write latency. Splits an insert's cost into the part that is real work and the part that is waiting for the global insert mutex.*\n\n###### How it's computed:\n*Insert Mean is nodestore_state{metric=\"nudb_insert_mean_us\"}, total insert microseconds over insert count. Insert Max is nudb_insert_max_us, a true running maximum rather than a quantile, so one bad insert is visible and never averaged away. Write Mean is the write_mean_us gauge for the whole backend write path.*\n\n###### Reading it:\n*Compare Insert Mean against the service time implied by Writer Queue Depth. Mean insert time above the unqueued service time is wait, and the gap is the fraction of every write spent queued rather than working. Insert Max far above Insert Mean means the distribution has a tail -- typically a bucket split or a commit -- which a mean alone hides.*\n\n###### Healthy range:\n*Insert Mean in the low tens of microseconds with Insert Max within roughly an order of magnitude of it.*\n\n###### Watch for:\n*A widening gap between Insert Mean and the service floor. In a measured write-lock-bound run the mean was 20 microseconds of which only 12.5 was service, leaving 7.5 -- 37 percent of every insert -- as pure queueing. That is the cost the writer-depth panel predicts, quantified. Insert Max climbing on its own without the mean moving is a tail problem, not a saturation problem.*\n\n###### Source:\n[telemetry/MetricsRegistry.cpp](https://github.com/XRPLF/rippled/blob/develop/src/xrpld/telemetry/MetricsRegistry.cpp)\n\n###### Function:\n`MetricsRegistry::observeWritePathDetail`", + "description": "###### What this is:\n*Time spent inside a NuDB insert, mean and worst case, alongside the backend's overall mean write latency. Splits an insert's cost into the part that is real work and the part that is waiting for the global insert mutex.*\n\n###### How it's computed:\n*Insert Mean is nodestore_state{metric=\"nudb_insert_mean_us\"}, total insert microseconds over insert count. Insert Max is nudb_insert_max_us, a true running maximum rather than a quantile, so one bad insert is visible and never averaged away. Write Mean is the write_mean_us gauge for the whole backend write path.*\n\n###### Reading it:\n*Compare Insert Mean against the service time implied by Writer Queue Depth. Mean insert time above the unqueued service time is wait, and the gap is the fraction of every write spent queued rather than working. Insert Max far above Insert Mean means the distribution has a tail -- typically a bucket split or a commit -- which a mean alone hides.*\n\n###### Healthy range:\n*Insert Mean in the low tens of microseconds with Insert Max within roughly an order of magnitude of it.*\n\n###### Watch for:\n*A widening gap between Insert Mean and the service floor. In a measured write-lock-bound run the mean was 20 microseconds of which only 12.5 was service, leaving 7.5 -- at least 37 percent of every insert -- as pure queueing. It is a floor rather than an exact figure because it is derived from a mean depth that the build of the day biased downward, and a larger depth implies a larger queueing share. That is the cost the writer-depth panel predicts, quantified. Insert Max climbing on its own without the mean moving is a tail problem, not a saturation problem.*\n\n###### Source:\n[telemetry/MetricsRegistry.cpp](https://github.com/XRPLF/rippled/blob/develop/src/xrpld/telemetry/MetricsRegistry.cpp)\n\n###### Function:\n`MetricsRegistry::observeWritePathDetail`", "type": "timeseries", "gridPos": { "h": 8, @@ -1791,8 +1791,8 @@ "id": 33 }, { - "title": "Acquire Deferrals vs Timeouts (Livelock Fingerprint)", - "description": "###### What this is:\n*The two counters that together identify an acquisition livelock. Deferrals count timer jobs that were skipped because the ledgerData lane was already at its limit. Timeouts count timer bodies that actually ran and advanced an acquisition's retry counter. Both series are on one panel deliberately: the signal is the divergence between them, and neither counter shows it alone.*\n\n###### How it's computed:\n*rate() over nodestore_state{metric=\"acquire_deferrals\"} and nodestore_state{metric=\"acquire_timeouts\"}. Both are cumulative counters, so the rate is the per-second event frequency and a restart shows as a gap rather than as a negative spike.*\n\n###### Reading it:\n*Deferrals rising while timeouts stay flat is the livelock fingerprint. Retry counts only advance when a timer body runs, so if every timer is being deferred instead, the retry budget never advances and the give-up path is effectively disarmed -- the acquisition can neither finish nor fail, and it holds its slot indefinitely. The two rates moving together is the benign case: the lane is busy but timers are still landing and acquisitions are still progressing toward either success or abandonment.*\n\n###### Healthy range:\n*Both near zero when synced. During catch-up, deferrals non-zero is expected, but timeouts should track rather than flatten.*\n\n###### Watch for:\n*A deferral rate that climbs while the timeout rate stays pinned. One measured stall recorded 5441 deferrals against 687 timeouts -- an eight-to-one ratio -- with zero completions over the same window. Cross-check Acquisition Progress: a flat completion rate confirms the acquisitions are stuck rather than merely slow.*\n\n###### Source:\n[app/ledger/InboundLedgers.cpp](https://github.com/XRPLF/rippled/blob/develop/src/xrpld/app/ledger/detail/InboundLedgers.cpp)\n\n###### Function:\n`InboundLedgers acquire retry timer / AcquireStats`", + "title": "Acquire Deferrals vs Timeouts (All Lanes)", + "description": "###### What this is:\n*The two counters that together identify an acquisition livelock, summed over every acquisition lane. Deferrals count timer jobs that were skipped because the lane was already at its limit. Timeouts count timer bodies that actually ran and advanced an acquisition's retry counter. Both series are on one panel deliberately: the signal is the divergence between them, and neither counter shows it alone. Both are recorded in TimeoutCounter, a base shared by five subclasses with different job limits, so this pair pools every lane -- read the ledger-scoped panel for a diagnosis and this one only to ask whether any lane is deferring.*\n\n###### How it's computed:\n*rate() over nodestore_state{metric=\"acquire_deferrals\"} and nodestore_state{metric=\"acquire_timeouts\"}. Both are cumulative counters, so the rate is the per-second event frequency and a restart shows as a gap rather than as a negative spike.*\n\n###### Reading it:\n*Deferrals rising while timeouts stay flat is the livelock fingerprint, but on this pair it does not say WHICH lane. Retry counts only advance when a timer body runs, so if every timer is being deferred instead, the retry budget never advances and the give-up path is effectively disarmed -- the acquisition can neither finish nor fail, and it holds its slot indefinitely. The two rates moving together is the benign case: the lane is busy but timers are still landing and acquisitions are still progressing toward either success or abandonment.*\n\n###### Healthy range:\n*Both near zero when synced. During catch-up, deferrals non-zero is expected, but timeouts should track rather than flatten.*\n\n###### Watch for:\n*A deferral rate that climbs while the timeout rate stays pinned -- then confirm on Ledger Acquire Deferrals vs Timeouts before calling it a ledger-acquisition stall, because a saturated replay lane produces the same shape here. One measured stall recorded 5441 deferrals against 687 timeouts -- an eight-to-one ratio -- but those were all-lane counts and cannot be attributed to ledger acquisition. Cross-check Acquisition Progress: a flat completion rate confirms the acquisitions are stuck rather than merely slow.*\n\n###### Source:\n[app/ledger/InboundLedgers.cpp](https://github.com/XRPLF/rippled/blob/develop/src/xrpld/app/ledger/detail/InboundLedgers.cpp)\n\n###### Function:\n`InboundLedgers acquire retry timer / AcquireStats`", "type": "timeseries", "gridPos": { "h": 8, @@ -1841,7 +1841,7 @@ }, { "title": "Acquisition Progress (Completions, Give-Ups & Aborts)", - "description": "###### What this is:\n*Whether ledger acquisitions are reaching an ending at all. Completions are acquisitions that finished with the data. Give-Ups are acquisitions that exhausted their retry budget. Aborts are acquisitions destroyed before either outcome. Together they are every way an acquisition can leave the system, so the sum going to zero while work is queued means nothing is leaving.*\n\n###### How it's computed:\n*rate() over the cumulative nodestore_state{metric=\"acquire_completions\"}, acquire_give_ups and acquire_aborts counters.*\n\n###### Reading it:\n*This panel is the outcome side of the deferral panel. A healthy catch-up shows a steady completion rate; a healthy failure shows give-ups. What should never happen is all three flat while the ledgerData lane is full, because that means acquisitions are occupying slots without ever resolving. Read this together with Deferrals vs Timeouts: deferrals climbing with completions at zero narrows the stall down to the retry path.*\n\n###### Healthy range:\n*Completion rate positive whenever ledgers are being acquired. Give-ups and aborts low.*\n\n###### Watch for:\n*Zero completions sustained while the lane is busy. A measured write-bound run recorded zero completions across 510 seconds; the comparable read-bound run still managed 8, which is the difference between slow and stuck. A rising give-up rate is less alarming than a flat one -- it at least means the retry budget is being consumed and slots are being returned.*\n\n###### Source:\n[app/ledger/InboundLedgers.cpp](https://github.com/XRPLF/rippled/blob/develop/src/xrpld/app/ledger/detail/InboundLedgers.cpp)\n\n###### Function:\n`InboundLedger completion / AcquireStats`", + "description": "###### What this is:\n*Whether ledger acquisitions are reaching an ending at all. Completions are acquisitions that finished with the data. Give-Ups are acquisitions that exhausted their retry budget. Aborts are acquisitions destroyed before either outcome. Together they are every way an acquisition can leave the system, so the sum going to zero while work is queued means nothing is leaving.*\n\n###### How it's computed:\n*rate() over the cumulative nodestore_state{metric=\"acquire_completions\"}, acquire_give_ups and acquire_aborts counters. Completions cover both ways an acquisition can finish: the normal done() path and the init() path satisfied entirely from the local store.*\n\n###### Reading it:\n*This panel is the outcome side of the deferral panel. A healthy catch-up shows a steady completion rate; a healthy failure shows give-ups. What should never happen is all three flat while the ledgerData lane is full, because that means acquisitions are occupying slots without ever resolving. Read this together with Deferrals vs Timeouts: deferrals climbing with completions at zero narrows the stall down to the retry path.*\n\n###### Healthy range:\n*Completion rate positive whenever ledgers are being acquired. Give-ups and aborts low.*\n\n###### Watch for:\n*Zero completions sustained while the lane is busy -- on a current build. A measured write-bound run recorded zero completions across 510 seconds, but that run predates the fix that counts acquisitions satisfied from the local store, which were previously never counted at all; the node did reach full, so the zero was the counter and not the node. Completions are now counted at both exits behind an idempotent latch, so a zero here means zero. A rising give-up rate is less alarming than a flat one -- it at least means the retry budget is being consumed and slots are being returned.*\n\n###### Source:\n[app/ledger/InboundLedgers.cpp](https://github.com/XRPLF/rippled/blob/develop/src/xrpld/app/ledger/detail/InboundLedgers.cpp)\n\n###### Function:\n`InboundLedger completion / AcquireStats`", "type": "timeseries", "gridPos": { "h": 8, @@ -1943,6 +1943,55 @@ "overrides": [] }, "id": 36 + }, + { + "title": "Ledger Acquire Deferrals vs Timeouts (Ledger Lane Only)", + "description": "###### What this is:\n*The deferral and timeout counters narrowed to ledger acquisition alone. The all-lane pair on the panel above sums every TimeoutCounter subclass -- inbound ledgers, transaction sets and the three ledger-replay tasks -- each with its own job limit, so a saturated replay lane reproduces the livelock shape while ledger acquisition is healthy. These two count the same events for the InboundLedger lane only, so a divergence here is about ledger acquisition and nothing else.*\n\n###### How it's computed:\n*rate() over nodestore_state{metric=\"acquire_ledger_deferrals\"} and nodestore_state{metric=\"acquire_ledger_timeouts\"}. Both are cumulative counters incremented only when the recording TimeoutCounter's job name is InboundLedger, so the rate is the per-second event frequency for that lane and a restart shows as a gap rather than a negative spike.*\n\n###### Reading it:\n*Same fingerprint as the all-lane panel, but trustworthy: deferrals rising while timeouts stay flat means ledger acquisition's retry budget is not advancing, so the give-up path cannot fire and an acquisition holds its slot without finishing or failing. The two rates moving together is benign -- the lane is busy but timers are landing. Read this panel first and treat the all-lane panel as context for whether some other lane is also under pressure.*\n\n###### Healthy range:\n*Both near zero when synced. During catch-up, deferrals non-zero is expected, but timeouts should track rather than flatten.*\n\n###### Watch for:\n*A ledger deferral rate that climbs while the ledger timeout rate stays pinned. Compare against the all-lane panel: if the all-lane pair diverges but these two do not, the stall is in another acquisition lane and ledger acquisition is not the problem. Cross-check Acquisition Progress -- a flat completion rate alongside a divergence here confirms the acquisitions are stuck rather than merely slow.*\n\n###### Source:\n[app/ledger/detail/TimeoutCounter.cpp](https://github.com/XRPLF/rippled/blob/develop/src/xrpld/app/ledger/detail/TimeoutCounter.cpp)\n\n###### Function:\n`TimeoutCounter::queueJob, TimeoutCounter::invokeOnTimer (via isLedgerAcquisition) / AcquireStats`", + "type": "timeseries", + "gridPos": { + "h": 8, + "w": 12, + "x": 0, + "y": 149 + }, + "options": { + "tooltip": { + "maxHeight": 600, + "mode": "multi", + "sort": "desc" + } + }, + "targets": [ + { + "datasource": { + "type": "prometheus", + "uid": "${DS_PROMETHEUS}" + }, + "expr": "label_replace(label_join(label_replace(rate(nodestore_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=\"acquire_ledger_deferrals\"}[$__rate_interval]), \"series\", \"Ledger Deferrals/s\", \"\", \"\"), \"xrpl_ident\", \", \", \"service_instance_id\", \"xrpl_branch\", \"xrpl_work_item\"), \"xrpl_ident\", \"[$1]\", \"xrpl_ident\", \"(?:, )*(.*[^, ])(?:, )*\")" + }, + { + "datasource": { + "type": "prometheus", + "uid": "${DS_PROMETHEUS}" + }, + "expr": "label_replace(label_join(label_replace(rate(nodestore_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=\"acquire_ledger_timeouts\"}[$__rate_interval]), \"series\", \"Ledger Timeouts/s\", \"\", \"\"), \"xrpl_ident\", \", \", \"service_instance_id\", \"xrpl_branch\", \"xrpl_work_item\"), \"xrpl_ident\", \"[$1]\", \"xrpl_ident\", \"(?:, )*(.*[^, ])(?:, )*\")" + } + ], + "fieldConfig": { + "defaults": { + "displayName": "${__field.labels.series} ${__field.labels.xrpl_ident}", + "unit": "ops", + "custom": { + "axisLabel": "Ledger Lane Events (Per Second)", + "spanNulls": 1800000, + "insertNulls": false, + "showPoints": "auto", + "pointSize": 3 + } + }, + "overrides": [] + }, + "id": 37 } ], "schemaVersion": 39, diff --git a/docs/telemetry-runbook.md b/docs/telemetry-runbook.md index 67d4eaa26a..aaee9385fe 100644 --- a/docs/telemetry-runbook.md +++ b/docs/telemetry-runbook.md @@ -726,25 +726,35 @@ two different reasons a node is slow to reach `full` — see when the writable backend is NuDB; a memory or RocksDB backend omits those four label values rather than reporting them as zero. -| Prometheus Metric | Source | Description | -| --------------------------------------------------- | ------------------- | -------------------------------------------------------- | -| `nodestore_state{metric="read_mean_us"}` | MetricsRegistry.cpp | Mean time per backend read (microseconds) | -| `nodestore_state{metric="write_mean_us"}` | MetricsRegistry.cpp | Mean time per backend write (microseconds) | -| `nodestore_state{metric="nudb_writers_in_flight"}` | MetricsRegistry.cpp | Threads inside a NuDB insert right now | -| `nodestore_state{metric="nudb_writer_depth_x100"}` | MetricsRegistry.cpp | Mean queue depth at the NuDB insert mutex, ×100 | -| `nodestore_state{metric="nudb_insert_mean_us"}` | MetricsRegistry.cpp | Mean NuDB insert time, queueing included (microseconds) | -| `nodestore_state{metric="nudb_insert_max_us"}` | MetricsRegistry.cpp | Slowest single NuDB insert seen (microseconds) | -| `nodestore_state{metric="acquire_deferrals"}` | MetricsRegistry.cpp | Acquisition timer jobs skipped because the lane was full | -| `nodestore_state{metric="acquire_timeouts"}` | MetricsRegistry.cpp | Acquisition timer bodies that ran and advanced retry | -| `nodestore_state{metric="acquire_give_ups"}` | MetricsRegistry.cpp | Acquisitions that exhausted their retry budget | -| `nodestore_state{metric="acquire_aborts"}` | MetricsRegistry.cpp | Acquisitions destroyed before finishing | -| `nodestore_state{metric="acquire_aborts_partial"}` | MetricsRegistry.cpp | Subset of aborts that discarded partly built maps | -| `nodestore_state{metric="acquire_completions"}` | MetricsRegistry.cpp | Acquisitions that finished successfully | -| `nodestore_state{metric="acquire_sweep_evictions"}` | MetricsRegistry.cpp | Acquisitions evicted by the 1-minute sweep | +| Prometheus Metric | Source | Description | +| ---------------------------------------------------- | ------------------- | ----------------------------------------------------------- | +| `nodestore_state{metric="read_mean_us"}` | MetricsRegistry.cpp | Mean time per backend read (microseconds) | +| `nodestore_state{metric="write_mean_us"}` | MetricsRegistry.cpp | Mean time per backend write (microseconds) | +| `nodestore_state{metric="nudb_writers_in_flight"}` | MetricsRegistry.cpp | Threads inside a NuDB insert right now | +| `nodestore_state{metric="nudb_writer_depth_x100"}` | MetricsRegistry.cpp | Mean queue depth at the NuDB insert mutex, ×100 | +| `nodestore_state{metric="nudb_insert_mean_us"}` | MetricsRegistry.cpp | Mean NuDB insert time, queueing included (microseconds) | +| `nodestore_state{metric="nudb_insert_max_us"}` | MetricsRegistry.cpp | Slowest single NuDB insert seen (microseconds) | +| `nodestore_state{metric="acquire_deferrals"}` | MetricsRegistry.cpp | Timer jobs skipped because the lane was full, **all lanes** | +| `nodestore_state{metric="acquire_timeouts"}` | MetricsRegistry.cpp | Timer bodies that ran and advanced retry, **all lanes** | +| `nodestore_state{metric="acquire_ledger_deferrals"}` | MetricsRegistry.cpp | Deferrals from ledger acquisition alone | +| `nodestore_state{metric="acquire_ledger_timeouts"}` | MetricsRegistry.cpp | Timeouts from ledger acquisition alone | +| `nodestore_state{metric="acquire_give_ups"}` | MetricsRegistry.cpp | Acquisitions that exhausted their retry budget | +| `nodestore_state{metric="acquire_aborts"}` | MetricsRegistry.cpp | Acquisitions destroyed before finishing | +| `nodestore_state{metric="acquire_aborts_partial"}` | MetricsRegistry.cpp | Subset of aborts that discarded partly built maps | +| `nodestore_state{metric="acquire_completions"}` | MetricsRegistry.cpp | Acquisitions that finished successfully | +| `nodestore_state{metric="acquire_sweep_evictions"}` | MetricsRegistry.cpp | Acquisitions evicted by the 1-minute sweep | `nudb_writer_depth_x100` is fixed-point: divide by 100 to read it. The depth sits just above 1.0 even under load, so an integer gauge would truncate the whole -signal away. +signal away. It is `depthSum / depthSamples`, both accumulated when an insert +**enters** the critical section, so an insert still in flight is part of the mean. + +`acquire_deferrals` and `acquire_timeouts` sum every `TimeoutCounter` subclass — +inbound ledgers, transaction sets and the three ledger-replay tasks — because both +are recorded in that shared base. They answer "is any lane deferring", not "is +ledger acquisition deferring". Use `acquire_ledger_deferrals` and +`acquire_ledger_timeouts` for the ledger-acquisition diagnosis; see +[The deferral/timeout pair](#the-deferraltimeout-pair). #### Counters @@ -1607,12 +1617,12 @@ question has no answer and only question 1 applies. Then read the answer off the pair: -| Reads | Write path | Root cause and next step | -| --------- | --------------- | -------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | -| Cheap | Depth ~1.00 | **Not a storage bottleneck.** Nothing is queueing at either side. Look outside storage: work is either not arriving from peers or being discarded before it lands. Check the deferral and sweep counters. | -| Cheap | Depth over ~1.2 | **Serialized write path.** The queue is at the backend's insert mutex, not at the device. Tuning the disk will not help; see the note below. This is the clean-store mode. | -| Expensive | Depth ~1.00 | Split on the **found rate**. At 50% or above, **cold reads on data the node already has** — the walk pays disk latency on objects it holds. Below 50%, **genuinely disk-bound on real misses**, and storage hardware is the right thing to change. | -| Expensive | Depth over ~1.2 | **Both paths queueing.** Rarer, and neither fix on its own will be enough. Treat the larger of the two costs as the lead. | +| Reads | Write path | Root cause and next step | +| --------- | --------------- | ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | +| Cheap | Depth ~1.00 | **Not a storage bottleneck.** Nothing is queueing at either side. Look outside storage: work is either not arriving from peers or being discarded before it lands. Check `acquire_ledger_deferrals` against `acquire_ledger_timeouts`, and the sweep counter. | +| Cheap | Depth over ~1.2 | **Serialized write path.** The queue is at the backend's insert mutex, not at the device. Tuning the disk will not help; see the note below. This is the clean-store mode. | +| Expensive | Depth ~1.00 | Split on the **found rate**. At 50% or above, **cold reads on data the node already has** — the walk pays disk latency on objects it holds. Below 50%, **genuinely disk-bound on real misses**, and storage hardware is the right thing to change. | +| Expensive | Depth over ~1.2 | **Both paths queueing.** Rarer, and neither fix on its own will be enough. Treat the larger of the two costs as the lead. | **Why the rule is shaped this way.** Three points about the thresholds, each learned from a dataset that an earlier version of this table got wrong: @@ -1662,6 +1672,11 @@ nodestore_state{metric="nudb_insert_mean_us", service_instance_id=~"$node"} # its own: a high found rate is normal and healthy on a populated store. rate(nodestore_state{metric="node_reads_hit", service_instance_id=~"$node"}[5m]) / rate(nodestore_state{metric="node_reads_total", service_instance_id=~"$node"}[5m]) + +# The deferral/timeout pair, scoped to ledger acquisition. Use these two, not +# the all-lane acquire_deferrals / acquire_timeouts -- see the pair section below. +increase(nodestore_state{metric="acquire_ledger_deferrals", service_instance_id=~"$node"}[5m]) +increase(nodestore_state{metric="acquire_ledger_timeouts", service_instance_id=~"$node"}[5m]) ``` #### Measured reference points @@ -1675,25 +1690,50 @@ largest value that gauge reached over the run, not a read-latency percentile. Th healthy peer — is **not** ours; it comes from an incident report supplied to this project and is kept separate for that reason. -| Signal | Mode W: clean store | Mode R: populated store, cold pages | -| ------------------------------ | ------------------- | ----------------------------------- | -| Time to `full` | 510 s | 260 s | -| `read_mean_us` | 8.8 µs | 31.8 µs | -| `read_mean_us`, highest sample | 9 µs | 223 µs | -| Found rate | 0.00 % | 88.3 % | -| Insert time, mean | 20.0 µs | 15.9 µs | -| Writer depth, mean | 1.60 | 1.00 | -| Queueing per insert | 37 % | 0 % | -| Deferrals over run | +5441 | +1845 | -| Timeouts over run | +687 | +399 | -| Completions over run | 0 | 8 | -| Sweep evictions | +127 | +38 | +**Three rows below were measured on a build that got them wrong.** Both runs +predate the measurement fixes, so read those rows as bounds rather than values: + +- **Completions** were only counted in `InboundLedger::done()`, so an acquisition + satisfied entirely from the local store — `init()` sets `complete_` and returns + without ever calling `done()` — was never counted. Mode W's `0` is therefore not + evidence that the node completed nothing; it reached `full`, which it could not + have done without completing acquisitions. The count is now taken at both exits + behind an idempotent latch, so on a current build a zero means zero. +- **Writer depth** was summed at insert entry but divided by a sample count that + only advanced at insert exit, so in-flight inserts — the deep, slow ones — + contributed depth to the numerator and nothing to the denominator. The mean was + biased **down**, worst exactly when queueing was worst. Mode W's 1.60 is a lower + bound on the true depth. +- **Queueing per insert** is derived from that depth, so its 37 % is a lower bound + too. See the derivation below. + +| Signal | Mode W: clean store | Mode R: populated store, cold pages | +| ------------------------------ | ------------------------ | ----------------------------------- | +| Time to `full` | 510 s | 260 s | +| `read_mean_us` | 8.8 µs | 31.8 µs | +| `read_mean_us`, highest sample | 9 µs | 223 µs | +| Found rate | 0.00 % | 88.3 % | +| Insert time, mean | 20.0 µs | 15.9 µs | +| Writer depth, mean | ≥ 1.60 (biased low) | 1.00 | +| Queueing per insert | ≥ 37 % (derived from ↑) | 0 % | +| Deferrals over run, all lanes | +5441 | +1845 | +| Timeouts over run, all lanes | +687 | +399 | +| Completions over run | 0 (under-counted, see ↑) | 8 (under-counted, see ↑) | +| Sweep evictions | +127 | +38 | Applying the decision rule: Mode W reads cheap (8.8 µs) with depth 1.60, so it is the serialized write path. Mode R reads expensive (31.8 µs mean, 223 µs peak) with depth 1.00 and a found rate well above 50%, so it is cold reads on data the node holds. The rule reaches both answers without the found rate deciding either mode on -its own. +its own — and both answers survive the corrected measurements, because a +depth-1.60 lower bound is still above the 1.2 threshold and Mode R's 1.00 is a +floor that cannot be biased below itself. + +The deferral and timeout rows are the **all-lane** counters, the only ones that +existed when these runs were taken. They cannot be attributed to ledger +acquisition; the eight-to-one ratio in Mode W is a whole-node figure. Re-measure +with `acquire_ledger_deferrals` / `acquire_ledger_timeouts` before quoting a ratio +as a ledger-acquisition fingerprint. **The reported incident, for contrast — not our measurement.** Figures from an incident report supplied to this project. No writer-depth data was captured, so the @@ -1715,12 +1755,23 @@ at 1.00, queueing near 0%, and `acquire_completions` advancing. Any one of a rea mean several times a warm read, a writer depth above ~1.2, or completions flat at zero is worth chasing. -**How the 37% is derived.** It is not measured directly — it comes from the two -gauges by Little's Law. With mean queue depth L and mean insert time W, the -service time is `S = W / L` and the queueing component is `W − S`. Mode W's -20.0 µs at depth 1.60 gives S = 12.5 µs, so 7.5 µs of every insert — 37% — is -spent waiting for the mutex rather than writing. Mode R's depth of exactly 1.00 -gives S = W and no queueing, which is why it shows 0%. +**Completions flat at zero only means something on a current build.** Until the +counter was moved to cover both exits, an acquisition served from the local store +was never counted, so a build predating that fix could read zero while completing +steadily. Check the build before treating a zero on archived data as a symptom. + +**How the 37% is derived, and why it is a lower bound.** It is not measured +directly — it comes from the two gauges by Little's Law. With mean queue depth L +and mean insert time W, the service time is `S = W / L` and the queueing component +is `W − S`. Mode W's 20.0 µs at depth 1.60 gives S = 12.5 µs, so 7.5 µs of every +insert — 37% — was spent waiting for the mutex rather than writing. + +That 37% is **not exact**: the L it was computed from came from the biased +estimator described above, which understated depth. A larger L gives a smaller S +and a larger `W − S`, so the true queueing share of Mode W was **at least** 37%. +Quote it as a floor. Mode R's depth of exactly 1.00 is unaffected — 1.00 is the +minimum a depth can be, so no bias can have pushed it there — which is why its 0% +stands as measured. **Why the write path serializes.** NuDB takes one global mutex per insert (`nudb/impl/basic_store.ipp:288`). It is a Conan dependency and is not patched @@ -1732,6 +1783,18 @@ locally. `nudb_writer_depth_x100` is the queue length at that mutex. Read these two together or not at all. The livelock fingerprint is **deferrals rising while timeouts stay flat**. +**Read the ledger-scoped pair, not the all-lane pair.** Both events are recorded in +`TimeoutCounter`, a base class shared by five subclasses — `InboundLedger`, +`TransactionAcquire`, `LedgerReplayTask`, `LedgerDeltaAcquire` and +`SkipListAcquire` — each with its own job limit. `acquire_deferrals` and +`acquire_timeouts` therefore pool every lane, so a replay lane sitting at its own +limit produces the fingerprint shape while ledger acquisition is perfectly healthy. +That is a false positive on a headline diagnosis. `acquire_ledger_deferrals` and +`acquire_ledger_timeouts` count the same two events for the `InboundLedger` lane +only (`src/xrpld/app/ledger/detail/TimeoutCounter.h`, `isLedgerAcquisition()`), and +they are the pair this procedure means. The all-lane totals remain useful for one +question only: whether _any_ lane is deferring. + A deferral happens when the acquisition timer job finds its lane's job count at or above the acquisition's own limit — 5 for `InboundLedger` (`src/xrpld/app/ledger/detail/InboundLedger.cpp:86`), compared against @@ -1769,7 +1832,16 @@ Two more pairs from the same family: candidate is a much larger store, where the walk takes long enough that the 1-minute sweep destroys partial work faster than it can complete — which is why the sweep and completion counters are in the table. **This is an unconfirmed - hypothesis.** Treat it as the next thing to test, not as the answer. + hypothesis.** Treat it as the next thing to test, not as the answer. It was also + partly suggested by Mode W's zero completions, which we now know was a counting + defect rather than a stalled node, so the hypothesis has lost one of its + supports and needs re-testing on a current build before it is pursued. +- **Three of the numbers above were measured with instruments that were since + corrected**: completions (missed local-store hits), writer depth (mean biased + low), and the deferral/timeout pair (pooled across five job lanes). The modes + and the decision rule are unaffected — each survives the correction, as noted + where it appears — but no figure in the reference table should be quoted as an + exact measurement without re-running on a build that has all three fixes. - The `nudb_*` label values are absent entirely on a non-NuDB writable backend. Absent is not zero — a missing series means "not applicable", so a panel showing a gap there is correct behaviour. @@ -1801,6 +1873,11 @@ Sync_ dashboard: **NuDB Read Latency**, **NuDB Cache Hit Ratio**, **NuDB Read Pressure**, and **Job Queue Backlog and Deferred by Type** for the lane occupancy that this procedure tells you to distrust on its own. +The pair this procedure asks for is on **Ledger Acquire Deferrals vs Timeouts +(Ledger Lane Only)**, in the _Sync Bottleneck Discrimination_ row. The adjacent +**Acquire Deferrals vs Timeouts (All Lanes)** plots the pooled totals; read it only +to see whether some other acquisition lane is also under pressure. + The **NuDB Cache Hit Ratio** title is wrong and has not been changed yet: the panel plots `node_reads_hit / node_reads_total`, which is the found rate described above, not a cache hit ratio. Read it as the found rate regardless of what the title says. From f42aa360a6d4e683508bfe104421122cff35763d Mon Sep 17 00:00:00 2001 From: Pratik Mankawde <3397372+pratikmankawde@users.noreply.github.com> Date: Tue, 28 Jul 2026 18:51:49 +0100 Subject: [PATCH 2/3] refactor(ledger): tie the lane predicate to the job name it matches The counters that attribute deferrals and timeouts to ledger acquisition compared a string literal in TimeoutCounter against a separate literal in InboundLedger. Renaming the job would have silently sent both metrics to zero: no build error, no failing test, and documentation that quietly became wrong. Both now use one shared constant. --- src/xrpld/app/ledger/detail/InboundLedger.cpp | 4 +++- src/xrpld/app/ledger/detail/TimeoutCounter.h | 13 ++++++++++++- 2 files changed, 15 insertions(+), 2 deletions(-) diff --git a/src/xrpld/app/ledger/detail/InboundLedger.cpp b/src/xrpld/app/ledger/detail/InboundLedger.cpp index 0f01b22b7b..7444d00b16 100644 --- a/src/xrpld/app/ledger/detail/InboundLedger.cpp +++ b/src/xrpld/app/ledger/detail/InboundLedger.cpp @@ -83,7 +83,9 @@ InboundLedger::InboundLedger( app, hash, kLedgerAcquireTimeout, - {.jobType = JtLedgerData, .jobName = "InboundLedger", .jobLimit = 5}, + {.jobType = JtLedgerData, + .jobName = TimeoutCounter::kLedgerAcquireJobName, + .jobLimit = 5}, app.getJournal("InboundLedger")) , clock_(clock) , seq_(seq) diff --git a/src/xrpld/app/ledger/detail/TimeoutCounter.h b/src/xrpld/app/ledger/detail/TimeoutCounter.h index bba22139be..ac8571ad14 100644 --- a/src/xrpld/app/ledger/detail/TimeoutCounter.h +++ b/src/xrpld/app/ledger/detail/TimeoutCounter.h @@ -54,6 +54,17 @@ namespace xrpl { class TimeoutCounter { public: + /** + * Job name of the ledger-acquisition lane. + * + * Shared with InboundLedger, which passes it as its job name, so the + * counters that attribute deferrals and timeouts to this lane compare + * against the same string the lane is registered under. Two independent + * literals would drift apart silently: the metrics would read zero with + * no build error and no failing test. + */ + static constexpr char kLedgerAcquireJobName[] = "InboundLedger"; + /** * Cancel the task by marking it as failed if the task is not done. * @note this function does not attempt to cancel the scheduled timer or @@ -153,7 +164,7 @@ protected: [[nodiscard]] bool isLedgerAcquisition() const { - return queueJobParameter_.jobName == "InboundLedger"; + return queueJobParameter_.jobName == kLedgerAcquireJobName; } private: From df4f600c4370112a27c77c03ba1dad14ed0705a0 Mon Sep 17 00:00:00 2001 From: Pratik Mankawde <3397372+pratikmankawde@users.noreply.github.com> Date: Tue, 28 Jul 2026 18:58:32 +0100 Subject: [PATCH 3/3] fix(test): remove the unbounded wait from the overlapping-insert round The round built each thread's batch inside the thread, before arriving at the latch, so a throw there left the remaining threads waiting on an arrival that never came -- the test hung instead of failing. A spawn loop that ended early did the same. Batches are now built before any thread starts, so nothing between spawn and arrival can throw, and a guard counts down the shortfall for threads that were never spawned before joining the ones that were. The depth accounting having moved to insert entry, depthSamples is now the denominator of the mean depth, so it gets its own assertions: equal to insertCount once every thread has been joined, and moving with the duplicate-key round. The overlap assertions are unchanged. Co-Authored-By: Claude Opus 5 (1M context) --- include/xrpl/nodestore/WriteStats.h | 2 +- src/tests/libxrpl/nodestore/NuDBFactory.cpp | 72 +++++++++++++++++++-- 2 files changed, 69 insertions(+), 5 deletions(-) diff --git a/include/xrpl/nodestore/WriteStats.h b/include/xrpl/nodestore/WriteStats.h index 11aafff0c9..c8f485d3d1 100644 --- a/include/xrpl/nodestore/WriteStats.h +++ b/include/xrpl/nodestore/WriteStats.h @@ -73,7 +73,7 @@ struct WriteStats /** * Summed writer depth observed at each insert. Divided by - * @ref insertCount this gives mean depth. + * @ref depthSamples this gives mean depth. */ std::uint64_t depthSum = 0; diff --git a/src/tests/libxrpl/nodestore/NuDBFactory.cpp b/src/tests/libxrpl/nodestore/NuDBFactory.cpp index 2658cd3fdf..5f9197df84 100644 --- a/src/tests/libxrpl/nodestore/NuDBFactory.cpp +++ b/src/tests/libxrpl/nodestore/NuDBFactory.cpp @@ -1,9 +1,11 @@ #include +#include #include #include #include #include #include +#include #include #include @@ -76,6 +78,24 @@ constexpr std::uint64_t kOverlapPerThread = 50; * doInsert() together rather than one after another; staggered starts are what * would let every insert run end to end and never overlap. * + * The latch is the whole point of the round, and it is also the one thing here + * that can hang the test binary rather than fail it. Two rules keep it safe: + * + * 1. Every batch is built before the first thread exists, so the only thing + * a thread does before arriving is arrive. Building a batch inside the + * thread allocates, so it can throw, and a thread that throws never + * arrives -- leaving the other seven blocked on the latch for good. + * 2. Spawning is guarded, so a thread that never starts still has its + * arrival accounted for. + * + * batches built here (may throw; no thread waiting yet) + * | + * v + * spawn 8 --> [ latch: 8 arrivals ] --> stores overlap --> join + * | ^ + * +-- spawn threw ---+ guard counts down the missing arrivals, + * then joins the threads already running + * * @param backend Backend to insert into. Must be open. * @param round Round index, mixed into the seeds so every round writes * fresh keys and no insert takes the duplicate short-circuit. @@ -83,20 +103,44 @@ constexpr std::uint64_t kOverlapPerThread = 50; void runOverlappingInsertRound(Backend& backend, int round) { + std::vector batches; + batches.reserve(kOverlapThreads); + for (auto t = 0uz; t < kOverlapThreads; ++t) + { + batches.push_back(createPredictableBatch( + kOverlapPerThread, 1000 + t + (static_cast(round) * 100'000))); + } + std::latch start(static_cast(kOverlapThreads)); std::vector threads; threads.reserve(kOverlapThreads); + + // Covers a spawn loop that ends early. The latch is built for the full set + // because a thread that has already arrived cannot be un-counted, so the + // shortfall is counted down instead of the latch being resized. Counting + // down comes before joining: a thread left waiting on the latch would never + // become joinable. + // + // Released once every thread exists, so the success path joins below rather + // than from a destructor -- join() can throw, and a destructor would turn + // that into a terminate. + ScopeExit releaseAndJoin([&] { + start.count_down(static_cast(kOverlapThreads - threads.size())); + for (auto& th : threads) + th.join(); + }); + for (auto t = 0uz; t < kOverlapThreads; ++t) { - threads.emplace_back([&backend, &start, t, round] { - auto const batch = createPredictableBatch( - kOverlapPerThread, 1000 + t + (static_cast(round) * 100'000)); + threads.emplace_back([&backend, &start, &batches, t] { start.arrive_and_wait(); - for (auto const& obj : batch) + for (auto const& obj : batches[t]) backend.store(obj); }); } + releaseAndJoin.release(); + for (auto& th : threads) th.join(); } @@ -330,6 +374,7 @@ TEST(NuDBFactory, write_stats_accumulate_per_insert) EXPECT_EQ(initial->insertTotalUs, 0u); EXPECT_EQ(initial->insertMaxUs, 0u); EXPECT_EQ(initial->depthSum, 0u); + EXPECT_EQ(initial->depthSamples, 0u); EXPECT_EQ(initial->concurrentWriters, 0u); // Exactly 10 inserts must be counted as 10, and depthSum must be 10 @@ -352,6 +397,11 @@ TEST(NuDBFactory, write_stats_accumulate_per_insert) FAIL() << "nudb must report write stats after inserts"; EXPECT_EQ(after->insertCount, kFirstBatch); EXPECT_EQ(after->depthSum, kFirstBatch); + // The denominator of the published mean depth. One sample per insert, so + // with the depth being 1 throughout, depthSum and depthSamples coincide + // here -- which is why this pair alone cannot tell a correct depthSum from + // a constant 1, and why the overlap test below exists. + EXPECT_EQ(after->depthSamples, kFirstBatch); EXPECT_GT(after->insertTotalUs, 0u); EXPECT_GT(after->insertMaxUs, 0u); // A maximum is never below the mean, so max * n >= sum. Catches a field @@ -376,6 +426,7 @@ TEST(NuDBFactory, write_stats_accumulate_per_insert) FAIL() << "nudb must report write stats after a second batch"; EXPECT_EQ(cumulative->insertCount, kFirstBatch + kSecondBatch); EXPECT_EQ(cumulative->depthSum, kFirstBatch + kSecondBatch); + EXPECT_EQ(cumulative->depthSamples, kFirstBatch + kSecondBatch); EXPECT_EQ(cumulative->concurrentWriters, 0u); // A running maximum never decreases. EXPECT_GE(cumulative->insertMaxUs, after->insertMaxUs); @@ -439,6 +490,10 @@ TEST(NuDBFactory, write_stats_count_duplicate_key_inserts) // rounds that stored new data would leave these equal. EXPECT_EQ(second->insertCount, first->insertCount + kBatchSize); EXPECT_EQ(second->depthSum, first->depthSum + kBatchSize); + // Sampled at entry, so the duplicate round is sampled whether or not it + // stores anything. An implementation that sampled only new data would + // leave this at the first round's figure and skew the mean. + EXPECT_EQ(second->depthSamples, first->depthSamples + kBatchSize); // The depth returned to zero, so the key_exists early return did not // leak a writer. EXPECT_EQ(second->concurrentWriters, 0u); @@ -505,6 +560,15 @@ TEST(NuDBFactory, write_stats_measure_depth_under_real_overlap) // under contention fails this. EXPECT_EQ(stats->insertCount, completedRounds * kOverlapThreads * kOverlapPerThread); + // A depth sample is taken when an insert starts and insertCount rises when + // one finishes, so the two populations differ only while an insert is in + // flight. Every thread has been joined here, so nothing is in flight and + // they must agree exactly. That is what licenses comparing depthSum against + // insertCount below, and it is an assertion in its own right: a depthSamples + // stuck at zero makes the published mean depth vanish rather than read + // wrong, because the metric is omitted when its denominator is zero. + EXPECT_EQ(stats->depthSamples, stats->insertCount); + // THE assertion this test exists for: strictly greater, so a depthSum fed // a constant 1 (or fed nothing, or fed insertCount's own delta) cannot // satisfy it however many rounds run.