From 819abf8ee11a2713276dcf1ef585cb427fa02396 Mon Sep 17 00:00:00 2001 From: Pratik Mankawde <3397372+pratikmankawde@users.noreply.github.com> Date: Tue, 28 Jul 2026 12:19:22 +0100 Subject: [PATCH] docs(telemetry): document the sync bottleneck diagnosis 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) --- .../09-data-collection-reference.md | 119 +++++++++ docs/telemetry-runbook.md | 246 ++++++++++++++++++ 2 files changed, 365 insertions(+) diff --git a/OpenTelemetryPlan/09-data-collection-reference.md b/OpenTelemetryPlan/09-data-collection-reference.md index f511b0f161..bf9df83a77 100644 --- a/OpenTelemetryPlan/09-data-collection-reference.md +++ b/OpenTelemetryPlan/09-data-collection-reference.md @@ -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`) + + + + +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). diff --git a/docs/telemetry-runbook.md b/docs/telemetry-runbook.md index ebeb4eeaab..6128a7dd37 100644 --- a/docs/telemetry-runbook.md +++ b/docs/telemetry-runbook.md @@ -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