ARCHIVE/rippled
1
0
Fork 0
mirror of https://github.com/XRPLF/rippled.git synced 2026-07-29 18:10:34 +00:00
Code Issues Packages Projects Releases Wiki Activity

Merge branch 'pratik/otel-phase9-metric-gap-fill' into pratik/otel-phase10-workload-validation

Browse Source 
# Conflicts:
#	docs/telemetry-runbook.md
This commit is contained in:
Pratik Mankawde
2026-07-28 19:03:00 +01:00
parent 33299dc5f4 df4f600c43
commit fdfd44d832
7 changed files with 312 additions and 78 deletions
Download Patch File Download Diff File Expand all files Collapse all files

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

@@ -1014,8 +1014,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)
@@ -1207,37 +1208,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
@@ -1247,6 +1255,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 |
@@ -1479,10 +1505,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])
```

59
docker/telemetry/grafana/dashboards/ledger-data-sync.json
View File

@@ -1678,7 +1678,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,
@@ -1727,7 +1727,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,
@@ -1786,8 +1786,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,
@@ -1836,7 +1836,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,
@@ -1938,6 +1938,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,

163
docs/telemetry-runbook.md
View File

@@ -1542,25 +1542,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
@@ -2445,12 +2455,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:
@@ -2500,6 +2510,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
@@ -2513,25 +2528,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
@@ -2553,12 +2593,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
@@ -2570,6 +2621,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
@@ -2607,7 +2670,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.
@@ -2639,6 +2711,11 @@ Sync_ dashboard: **NuDB Read Latency**, **NuDB Read Found 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.
**NuDB Read Found Ratio** plots `node_reads_hit / node_reads_total`. That is the
found rate, not a cache hit ratio: the underlying counter increments whenever a
fetch returned an object, and a node with `online_delete` has no object cache at

2
include/xrpl/nodestore/WriteStats.h
View File

@@ -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;

72
src/tests/libxrpl/nodestore/NuDBFactory.cpp
View File

@@ -1,9 +1,11 @@
#include <xrpl/basics/ByteUtilities.h>
#include <xrpl/basics/scope.h>
#include <xrpl/beast/utility/Journal.h>
#include <xrpl/beast/utility/temp_dir.h>
#include <xrpl/config/BasicConfig.h>
#include <xrpl/nodestore/DummyScheduler.h>
#include <xrpl/nodestore/Manager.h>
#include <xrpl/nodestore/Types.h>
#include <xrpl/nodestore/WriteStats.h>
#include <gtest/gtest.h>
@@ -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<Batch> batches;
batches.reserve(kOverlapThreads);
for (auto t = 0uz; t < kOverlapThreads; ++t)
{
batches.push_back(createPredictableBatch(
kOverlapPerThread, 1000 + t + (static_cast<std::uint64_t>(round) * 100'000)));
}
std::latch start(static_cast<std::ptrdiff_t>(kOverlapThreads));
std::vector<std::thread> 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<std::ptrdiff_t>(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<std::uint64_t>(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.

4
src/xrpld/app/ledger/detail/InboundLedger.cpp
View File

@@ -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)

13
src/xrpld/app/ledger/detail/TimeoutCounter.h
View File

@@ -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: