ARCHIVE/rippled
1
0
Fork 0
mirror of https://github.com/XRPLF/rippled.git synced 2026-07-30 02:20:39 +00:00
Code Issues Packages Projects Releases Wiki Activity

docs(telemetry): document the sync bottleneck diagnosis

Browse Source 
Two different bottlenecks both present as the ledgerData job lane pinned
at its concurrency cap of 3, so lane occupancy diagnoses neither. One is
write-serialized (NuDB takes one global mutex per insert, so inserts
queue), the other is cold-read-bound on a populated store. Telling them
apart needs the storage-side signals, not the lane.

Adds to docs/telemetry-runbook.md a "Slow to reach full" procedure: a
Mermaid diagram of the two modes, a decision table keyed on whether
acquisitions are completing, the measured reference values from both
runs, and the deferral/timeout pair that fingerprints the disarmed
give-up path. States plainly that node_reads_hit is a found count rather
than a cache-hit rate, which is why a ~100% "hit rate" at 113 us per
read is the cold-read signature and not a contradiction.

Records honestly that the populated-store run was twice as fast despite
slower reads, so cold reads alone do not explain the long incident.

Adds reference rows for the 13 new nodestore_state label values and the
nodestore_read_us histogram to
OpenTelemetryPlan/09-data-collection-reference.md, in the authoritative
Phase 9 OTel SDK section alongside the existing NodeStore I/O table.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
This commit is contained in:
Pratik Mankawde
2026-07-28 12:19:22 +01:00
parent 51f6544f7b
commit 819abf8ee1
2 changed files with 365 additions and 0 deletions
Download Patch File Download Diff File Expand all files Collapse all files

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

@@ -1004,6 +1004,12 @@ 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 plus the
`nodestore_read_us` histogram — which separate a write-serialized stall from a
cold-read stall. See
[Sync Diagnosis Signals](#sync-diagnosis-signals-observable-gauge--nodestore_state)
and
[NodeStore Read Latency](#nodestore-read-latency-histogram--nodestore_read_us).
### New Grafana Dashboards (Phase 9)
@@ -1143,6 +1149,96 @@ via OTLP/HTTP to the OTel Collector and scraped by Prometheus.
| `nodestore_state{metric="write_load"}` | Gauge | `metric` | Current write load score |
| `nodestore_state{metric="read_queue"}` | Gauge | `metric` | Items in read prefetch queue |
> **`node_reads_hit` is a found count, not a cache-hit rate.** `fetchHitCount_`
> is incremented whenever the fetch returned an object
> (`src/libxrpl/nodestore/Database.cpp:246-255`), regardless of where it came
> from. The ratio against `node_reads_total` is therefore the fraction of fetches
> that **found** something, and can read ~100% while every fetch went to disk.
> Pair it with `read_mean_us` before drawing any conclusion — see
> [Slow to reach `full`](../docs/telemetry-runbook.md#slow-to-reach-full).
#### Sync Diagnosis Signals (Observable Gauge — `nodestore_state`)
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`).
| 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 |
**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.
- 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
zero is a meaningful reading.
**The pairs, not the individual counts, are diagnostic.** Deferrals rising while
timeouts stay flat means the give-up path is disarmed: a deferral re-arms the
timer without running its body, so the retry counter never advances and the
6-timeout give-up is unreachable. Sweep evictions rising while completions stay at
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`.
#### NodeStore Read Latency (Histogram — `nodestore_read_us`)
<!-- cspell:ignore ISTOGRAM -->
<!-- The all-caps macro name XRPL_METRIC_HISTOGRAM_RECORD trips cspell's
compound-word splitter, which emits the subword "ISTOGRAM"; ignore it here. -->
Recorded per fetch at `src/xrpld/app/main/NodeStoreScheduler.cpp` via
`XRPL_METRIC_HISTOGRAM_RECORD_LABELED`, not as a `MetricsRegistry` member. The
name, label keys, and all four label values are the `constexpr` constants in
`include/xrpl/telemetry/NodeStoreMetricNames.h`, shared with the bucket-view
registration for the same reason `GetObjectMetricNames.h` exists.
| Prometheus Metric | Type | Labels | Description |
| ------------------- | --------- | ------------------------------------------------------------- | --------------------------------------------- |
| `nodestore_read_us` | Histogram | `fetch_type="async"` \| `"sync"`, `found="true"` \| `"false"` | Per-fetch backend read latency (microseconds) |
**It gets its own bucket ladder, not the shared µs one.** Boundaries are
`1, 2, 5, 10, 25, 50, 100, 250, 500, 1000, 5000, 25000` microseconds
(`kSubMillisecondBoundaries`, registered by `addSubMillisecondHistogramView()`).
The shared `kMicrosecondBoundaries` ladder starts at 100 µs, above the entire
range a warm read occupies, so every warm read would fall in bucket 0 and the
distribution would read as flat — while still needing to reach far enough to show
a cold tail against it. That is a fifth view, alongside the four listed under
[GetObject Request Path](#getobject-request-path-synchronous-countershistograms).
**Why two labels rather than one series.** A slow `async` read delays prefetch; a
slow `sync` read blocks a caller outright. A `found=false` fetch can have to
consult every backend, so mixing it with hits blurs the distribution that matters.
Cardinality is fixed at four combinations. Per project convention, a panel using
these needs matching `fetch_type` and `found` template variables.
Zero is a recordable value — a fetch served from a warm page cache genuinely
rounds to 0 µs, and suppressing it would make the fastest reads invisible.
Negative elapsed values (clock anomalies) are dropped rather than passed to the
SDK, which would otherwise log a warning on every such call.
#### Cache Hit Rates & Sizes (Observable Gauge — `cache_metrics`)
| Prometheus Metric | Type | Labels | Description |
@@ -1363,8 +1459,31 @@ histogram_quantile(0.95, sum by (le) (rate(getobject_lookup_us_bucket[5m])))
# GetObject requests refused, by reason
sum by (reason) (rate(getobject_rejected_total[5m]))
# Write-path queueing: depth is fixed-point, divide by 100
nodestore_state{metric="nudb_writer_depth_x100"} / 100
# Read cost, and the found rate that qualifies it (NOT a cache-hit rate)
nodestore_state{metric="read_mean_us"}
# Are ledger acquisitions finishing at all? (per minute)
increase(nodestore_state{metric="acquire_completions"}[1m])
# Livelock fingerprint: deferrals climbing while timeouts stay flat
increase(nodestore_state{metric="acquire_deferrals"}[5m])
increase(nodestore_state{metric="acquire_timeouts"}[5m])
# Per-fetch read latency p99, split by the two dimensions that matter
histogram_quantile(0.99, sum by (le, fetch_type, found) (rate(nodestore_read_us_bucket[5m])))
```
> **Diagnostic procedure.** These signals exist to answer one question — why a
> node is slow to reach `full` — and the decision rule that uses them lives in
> [docs/telemetry-runbook.md § Slow to reach `full`](../docs/telemetry-runbook.md#slow-to-reach-full),
> with the measured reference values from both bottleneck modes. The short form:
> the `ledgerData` lane sitting at its concurrency cap is true in **both** modes,
> so it is never a diagnosis on its own.
### Phase 7+: External Dashboard Parity Metrics
> **Source**: [External Dashboard Parity Spec](./06-implementation-phases.md#appendix-external-dashboard-parity) — metrics inspired by the community [xrpl-validator-dashboard](https://github.com/realgrapedrop/xrpl-validator-dashboard).

246
docs/telemetry-runbook.md
View File

@@ -712,11 +712,57 @@ These gauges are exported via the OTel Metrics SDK `PeriodicMetricReader` (10s i
| `db_metrics{metric="historical_perminute"}` | MetricsRegistry.cpp | Historical ledger fetches per minute |
| `cache_metrics{metric="AL_size"}` | MetricsRegistry.cpp | AcceptedLedger cache size |
| `nodestore_state{metric="node_reads_duration_us"}` | MetricsRegistry.cpp | Cumulative read time (microseconds) |
| `nodestore_state{metric="node_writes_duration_us"}` | MetricsRegistry.cpp | Cumulative write time (microseconds) |
| `nodestore_state{metric="read_request_bundle"}` | MetricsRegistry.cpp | Read request bundle count |
| `nodestore_state{metric="read_threads_running"}` | MetricsRegistry.cpp | Active read threads |
| `nodestore_state{metric="read_threads_total"}` | MetricsRegistry.cpp | Total read threads configured |
| `rpc_in_flight_requests` | PerfLogImp.cpp | RPC requests currently executing (UpDownCounter) |
#### Sync Diagnosis Signals
More label values on the same `nodestore_state` gauge. They exist to separate the
two different reasons a node is slow to reach `full` — see
[Slow to reach `full`](#slow-to-reach-full). The `nudb_*` group is published only
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 |
`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.
#### NodeStore Read Latency Histogram
| Prometheus Metric | Kind | Labels | Description |
| ------------------- | --------- | ------------------------------------------------------------- | ----------------------------------- |
| `nodestore_read_us` | Histogram | `fetch_type` = `async` \| `sync`, `found` = `true` \| `false` | Per-fetch backend read latency (µs) |
Bucket edges are 1, 2, 5, 10, 25, 50, 100, 250, 500, 1000, 5000, 25000
microseconds — a dedicated sub-millisecond ladder, not the shared µs ladder the
job histograms use. The shared ladder starts at 100 µs, which is above the entire
range a warm read occupies, so every warm read would land in one bucket and the
distribution would read flat.
The two labels separate cases with different consequences. An `async` read that is
slow only delays prefetch; a `sync` read that is slow blocks a caller outright.
A `found=false` fetch can have to consult every backend, so mixing it with hits
blurs the distribution that matters.
#### Counters
| Prometheus Metric | Source | Description |
@@ -1468,6 +1514,206 @@ which a slowness-only metric cannot.
a rejection spike will _not_ show up as latency. Check the rejection counters
before concluding that traffic is normal.
### Slow to reach `full`
Use this when a node takes far longer than expected to sync. Two completely
different bottlenecks look identical from outside: in both, the `ledgerData` job
lane sits pinned at its concurrency cap of 3 with jobs waiting behind it.
**Lane occupancy on its own distinguishes nothing.** It is true in both cases, so
it is never a diagnosis. Two tuning experiments were spent before that was known —
do not repeat them. Read the storage-side signals below instead.
The two modes and the signal that separates them:
```mermaid
flowchart TB
L["`**ledgerData lane at cap 3**
jobs waiting behind it
TRUE IN BOTH MODES
diagnoses nothing`"]
L --> W["`**Mode W — write-bound**
fresh or empty store`"]
L --> R["`**Mode R — cold-read-bound**
populated store, cold pages`"]
W --> W1["`reads cheap and always miss
data comes from peers`"]
W1 --> W2["`cost is on the WRITE side
one global mutex per insert
so inserts queue`"]
W2 --> W3["`**Look at:** writer depth
above 1, insert mean well
above service time`"]
R --> R1["`no write contention
writer depth 1.00`"]
R1 --> R2["`reads pay disk latency
on every fetch —
found but cold`"]
R2 --> R3["`**Look at:** read mean and
peak high while the
found rate is near 100%`"]
style L fill:#7b3f00,color:#ffffff
style W fill:#1f4e79,color:#ffffff
style R fill:#4a148c,color:#ffffff
style W1 fill:#37474f,color:#ffffff
style W2 fill:#37474f,color:#ffffff
style W3 fill:#2d5016,color:#ffffff
style R1 fill:#37474f,color:#ffffff
style R2 fill:#37474f,color:#ffffff
style R3 fill:#2d5016,color:#ffffff
```
#### `node_reads_hit` is a found count, not a cache-hit rate
This is the most misleading signal on the board, so read it first.
`fetchHitCount_` is incremented whenever the fetch **returned an object**
(`src/libxrpl/nodestore/Database.cpp:246-255`) — not when a cache served it. So
`node_reads_hit / node_reads_total` is the fraction of fetches that **found**
something, and it can read ~100% while every one of those fetches went to disk.
A ~100% "hit rate" at 113 µs per read is therefore not a contradiction. It is the
cold-read signature: the data is on disk, found every time, and paid for every
time. A real devnet incident hung a client-handler node for 25 minutes in exactly
this state — 112.7 µs per read against 4.95 µs on a healthy peer, both reporting
~99.98%.
A node configured with `online_delete` runs `DatabaseRotatingImp`, which has **no
NodeObject cache** at all (0 `cache_` references in
`src/libxrpl/nodestore/DatabaseRotatingImp.cpp` versus 11 in
`DatabaseNodeImp.cpp`), so every fetch reaches the backend. That is why the
cold-read mode shows up on exactly those nodes.
#### The decision rule
**Procedure** — all of it assumes the `ledgerData` lane is already at its cap; if
it is not, this procedure does not apply.
1. Ask whether acquisitions are completing at all: read `acquire_completions` as a
rate over the window. That single answer picks which half of the table below
you are in.
2. Within that half, read the storage signal named in the row. The first row that
matches is the answer.
3. Confirm it against the measured reference points in the next section before
acting.
| Completions per minute | Storage signal | Root cause and next step |
| ---------------------- | ------------------------------------------- | -------------------------------------------------------------------------------------------------------------------------------------------- |
| Zero | Read time high **and** found rate near 100% | **Cold-read stall on a populated store.** The walk pays disk latency on data the node already has. Check store size and the sweep counters. |
| Zero | Anything else | **Look upstream of the write path.** Storage is not the constraint — the work is either not arriving or being discarded before it lands. |
| Continuing | Read time low **and** writer depth above 1 | **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. |
| Continuing | Anything else | **Genuinely disk-bound.** The device is the limit. This is the only branch where storage hardware is the right thing to change. |
Queries, scoped to one node as everywhere else in this runbook:
```promql
# Are acquisitions finishing? (per minute)
increase(nodestore_state{metric="acquire_completions", service_instance_id="$node"}[1m])
# Read cost and the found rate that qualifies it
nodestore_state{metric="read_mean_us", service_instance_id="$node"}
rate(nodestore_state{metric="node_reads_hit", service_instance_id="$node"}[5m])
/ rate(nodestore_state{metric="node_reads_total", service_instance_id="$node"}[5m])
# Write-side queueing: depth is fixed-point, divide by 100
nodestore_state{metric="nudb_writer_depth_x100", service_instance_id="$node"} / 100
nodestore_state{metric="nudb_insert_mean_us", service_instance_id="$node"}
# Read latency distribution, split by the two dimensions that matter
histogram_quantile(0.99, sum by (le, fetch_type, found) (rate(nodestore_read_us_bucket{service_instance_id="$node"}[5m])))
```
#### Measured reference points
Two runs on the same host, same build, differing only in the state of the store.
Use these as the shape to compare against, not as thresholds.
| Signal | Mode W: clean store | Mode R: populated store, cold pages |
| -------------------- | ------------------- | ----------------------------------- |
| Time to `full` | 510 s | 260 s |
| Read time, mean | 8.8 µs | 31.8 µs |
| Read time, peak | 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 |
What healthy looks like: read mean in the single-digit microseconds, writer depth
at 1.00, queueing near 0%, and `acquire_completions` advancing. Any one of a read
mean in the tens or hundreds of microseconds, 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%.
**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
here, so this is a property to observe and design around, not a bug to fix
locally. `nudb_writer_depth_x100` is the queue length at that mutex.
#### The deferral/timeout pair
Read these two together or not at all. The livelock fingerprint is **deferrals
rising while timeouts stay flat**.
A deferral happens when the acquisition timer job finds its lane already full. The
timer is re-armed but its **body does not run**, so the retry counter never
advances and the 6-timeout give-up becomes unreachable — the give-up path is
disarmed and the acquisition can never end on its own. Neither counter alone shows
this: deferrals rising looks like ordinary backpressure, and timeouts flat looks
like health. Only the divergence is diagnostic. See the counter documentation in
`src/xrpld/app/ledger/AcquireStats.h`.
Two more pairs from the same family:
- `acquire_sweep_evictions` rising while `acquire_completions` stays at zero →
partial work is being discarded and redone. The sweep drops any acquisition
idle for more than one minute
(`src/xrpld/app/ledger/detail/InboundLedgers.cpp:400`), taking whatever it had
built with it.
- `acquire_aborts_partial` rising → the expensive form of an abort, where partly
built maps were thrown away. `acquire_aborts` alone does not separate the cheap
case from this one.
#### Honest limits of this diagnosis
- **The populated-store run was twice as fast, not slower** — 260 s against 510 s,
despite reads being roughly 4× more expensive. Reusing local data beats fetching
from peers even when every read is cold. Slow cold reads therefore do **not**
on their own explain the 25-minute devnet incident.
- Something compounds it there. The most likely 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 not confirmed; treat it as the next thing to test, not as
the answer.
- 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.
- These gauges are sampled on the `MetricsRegistry` reader's 10 s cadence, while
the `jobq_*` lane gauges are sampled at 1 s by a different provider. Widen the
window when correlating them rather than reading a single scrape; see the caveat
under [Slow TMGetObjectByHash service](#slow-tmgetobjectbyhash-service).
- `read_mean_us` and `write_mean_us` are omitted rather than reported as zero when
nothing has been read or written yet, so an idle node legitimately shows no
series.
Existing panels that already carry part of this picture, on the _Ledger Data &
Sync_ dashboard: **NuDB Read Latency**, **NuDB Cache Hit Ratio** (the found rate
described above, under its historical name), **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.
### High memory usage
- Reduce trace volume with collector-side tail sampling (xrpld head sampling is