From 7ef8c07cf99f5a4098a176e31da9e75fd7719b1a Mon Sep 17 00:00:00 2001 From: Pratik Mankawde <3397372+pratikmankawde@users.noreply.github.com> Date: Tue, 28 Jul 2026 15:46:24 +0100 Subject: [PATCH 1/4] Rename nudb_bytes metric to stored_object_bytes The nudb_bytes label value on the storage_detail gauge named something the code never measured. It observes Database::getStoreSize(), which returns the storeSz_ accumulator: the cumulative payload bytes of objects this process handed to the NodeStore. That is not a NuDB file size. It excludes NuDB's keys, bucket padding and log, and it resets with the process while the files on disk do not. The name caused two concrete errors. It invited sizing the store on disk from a number that cannot do it, and it invited a write-amplification ratio against node_written_bytes -- which reads the same accessor at MetricsRegistry.cpp:836, so that ratio is a constant 1.0 and measures nothing. The nudb_ prefix was wrong too. storeSz_ is written only by Database::storeStats(), called from DatabaseNodeImp, DatabaseRotatingImp and Database itself. No backend code touches it, so the value reads the same on RocksDB. That distinguishes it from the real nudb_* family (nudb_writers_in_flight and friends), which come from getWriteStats() and are absent entirely on a non-NuDB backend. stored_object_bytes says what the value is and claims nothing about the filesystem. Docs already described the value correctly; they keep that explanation and now also record the old name, so a query pinned to it can be traced. Neither Backend nor Database exposes an on-disk size accessor and none was added -- no metric reports the store's on-disk size today. Updates the node-health panel title, description and PromQL, and the four docs that name the label value. Co-Authored-By: Claude Opus 5 (1M context) --- OpenTelemetryPlan/06-implementation-phases.md | 22 ++++++++------- .../09-data-collection-reference.md | 27 +++++++++++-------- OpenTelemetryPlan/Phase7_taskList.md | 21 ++++++++------- .../grafana/dashboards/node-health.json | 6 ++--- docs/telemetry-runbook.md | 8 +++--- src/xrpld/telemetry/MetricsRegistry.cpp | 18 ++++++++----- 6 files changed, 60 insertions(+), 42 deletions(-) diff --git a/OpenTelemetryPlan/06-implementation-phases.md b/OpenTelemetryPlan/06-implementation-phases.md index 536f906a47..ef311643f7 100644 --- a/OpenTelemetryPlan/06-implementation-phases.md +++ b/OpenTelemetryPlan/06-implementation-phases.md @@ -1680,18 +1680,22 @@ xrpld's `OperatingMode` enum maps 0-4 (DISCONNECTED through FULL). The external **Task 7.13: Storage Detail Observable Gauge** -| Gauge Name | Label `metric=` | Type | Source | -| ---------------------- | --------------- | ----- | ---------------------------------------------------- | -| `xrpld_storage_detail` | `nudb_bytes` | int64 | `Database::getStoreSize()` — cumulative object bytes | +| Gauge Name | Label `metric=` | Type | Source | +| ---------------------- | --------------------- | ----- | ---------------------------------------------------- | +| `xrpld_storage_detail` | `stored_object_bytes` | int64 | `Database::getStoreSize()` — cumulative object bytes | -Despite the name, this is not a filesystem measurement. `getStoreSize()` sums the -object payloads this process has written, so it excludes NuDB's keys, bucket padding -and log, and it resets with the process while the files on disk do not. It is the -same accessor `node_written_bytes` uses, so the two series are equal by construction -and any write-amplification ratio built from the pair is a constant 1.0. There is no +This is not a filesystem measurement. `getStoreSize()` sums the object payloads this +process has written, so it excludes NuDB's keys, bucket padding and log, and it +resets with the process while the files on disk do not. It is the same accessor +`node_written_bytes` uses, so the two series are equal by construction and any +write-amplification ratio built from the pair is a constant 1.0. There is no file-size accessor on `Backend` or `Database`, so no metric reports the store's on-disk size today. +The label value was `nudb_bytes` through Phase 8 and was renamed in Phase 9: the +value is read from `Database`, not from the NuDB backend, so a backend prefix +misdescribed it and the old name implied an on-disk size it never reported. + **File**: `src/xrpld/telemetry/MetricsRegistry.cpp` **Exit Criteria**: @@ -1847,7 +1851,7 @@ Add checks to `validate_telemetry.py` for all new span attributes and metrics. | `xrpld_ledgers_closed_total` | | `xrpld_validations_sent_total` | | `xrpld_state_changes_total` | -| `xrpld_storage_detail{metric="nudb_bytes"}` | +| `xrpld_storage_detail{metric="stored_object_bytes"}` | **New dashboard load checks (~3)**: diff --git a/OpenTelemetryPlan/09-data-collection-reference.md b/OpenTelemetryPlan/09-data-collection-reference.md index b24e4a5a82..3a05e4cf35 100644 --- a/OpenTelemetryPlan/09-data-collection-reference.md +++ b/OpenTelemetryPlan/09-data-collection-reference.md @@ -1565,18 +1565,23 @@ State value encoding: 0=disconnected, 1=connected, 2=syncing, 3=tracking, 4=full #### Storage Detail (Observable Gauge — `storage_detail`) -| Prometheus Metric | Type | Labels | Description | -| ------------------------------------- | ----- | -------- | ---------------------------------------------------------- | -| `storage_detail{metric="nudb_bytes"}` | Int64 | `metric` | Cumulative object-payload bytes written (not on-disk size) | +| Prometheus Metric | Type | Labels | Description | +| ---------------------------------------------- | ----- | -------- | ---------------------------------------------------------- | +| `storage_detail{metric="stored_object_bytes"}` | Int64 | `metric` | Cumulative object-payload bytes written (not on-disk size) | -> **`nudb_bytes` is not a file size, despite the name.** It observes -> `getStoreSize()` (`src/xrpld/telemetry/MetricsRegistry.cpp:1507`), which sums the -> object payloads this process has written. It therefore excludes NuDB's keys, -> bucket padding and log, and it resets when the process restarts while the files -> on disk do not. `node_written_bytes` on the `nodestore_state` gauge calls the same -> accessor (`MetricsRegistry.cpp:836`), so the two series are equal by construction -> and any write-amplification ratio built from the pair is a constant 1.0. To size -> the store on disk, stat the backend's files; no metric reports it today. +> **`stored_object_bytes` is not a file size.** It observes `getStoreSize()` +> (`src/xrpld/telemetry/MetricsRegistry.cpp:1511`), which sums the object payloads +> this process has written. It therefore excludes NuDB's keys, bucket padding and +> log, and it resets when the process restarts while the files on disk do not. +> `node_written_bytes` on the `nodestore_state` gauge calls the same accessor +> (`MetricsRegistry.cpp:836`), so the two series are equal by construction and any +> write-amplification ratio built from the pair is a constant 1.0. To size the store +> on disk, stat the backend's files; no metric reports it today. +> +> This label value was called `nudb_bytes` before Phase 9. The value comes from +> `node_store::Database`, not from the NuDB backend, so it reads the same on +> RocksDB and carries no backend prefix. Queries and dashboards pinned to the old +> name return no data. #### Synchronous Counters (Phase 7+) diff --git a/OpenTelemetryPlan/Phase7_taskList.md b/OpenTelemetryPlan/Phase7_taskList.md index d7ce34b7b8..e22c4b37c9 100644 --- a/OpenTelemetryPlan/Phase7_taskList.md +++ b/OpenTelemetryPlan/Phase7_taskList.md @@ -482,22 +482,25 @@ validatorParticipationGauge_ = meter_->CreateInt64ObservableGauge( > **Source**: [External Dashboard Parity](./06-implementation-phases.md#appendix-external-dashboard-parity) -**Objective**: Export NuDB-specific stored-bytes total and initial sync duration. +**Objective**: Export the NodeStore stored-bytes total and initial sync duration. **Gauge label values**: | Gauge Name | Label `metric=` | Type | Source | | ---------------------- | ------------------------------- | ------ | ---------------------------------------------------- | -| `xrpld_storage_detail` | `nudb_bytes` | int64 | `Database::getStoreSize()` — cumulative object bytes | +| `xrpld_storage_detail` | `stored_object_bytes` | int64 | `Database::getStoreSize()` — cumulative object bytes | | `xrpld_sync_info` | `initial_sync_duration_seconds` | double | Time from start to first FULL | -Despite the name, `nudb_bytes` is not a file size. `getStoreSize()` sums the object -payloads this process has written, so it excludes NuDB's keys, bucket padding and -log, and it resets when the process restarts while the files on disk do not. It is -the same accessor `node_written_bytes` uses, so the two series are equal by -construction and any write-amplification ratio built from the pair is a constant 1.0. -Neither `Backend` nor `Database` exposes a file-size accessor, so no metric reports -the store's on-disk size today. +`stored_object_bytes` is not a file size. `getStoreSize()` sums the object payloads +this process has written, so it excludes NuDB's keys, bucket padding and log, and it +resets when the process restarts while the files on disk do not. It is the same +accessor `node_written_bytes` uses, so the two series are equal by construction and +any write-amplification ratio built from the pair is a constant 1.0. Neither +`Backend` nor `Database` exposes a file-size accessor, so no metric reports the +store's on-disk size today. + +This label value was `nudb_bytes` when Phase 7 shipped it and was renamed in Phase 9, +because the value comes from `Database` rather than the NuDB backend. **Key modified files**: `src/xrpld/telemetry/MetricsRegistry.h/.cpp` diff --git a/docker/telemetry/grafana/dashboards/node-health.json b/docker/telemetry/grafana/dashboards/node-health.json index 61379e639e..327f222543 100644 --- a/docker/telemetry/grafana/dashboards/node-health.json +++ b/docker/telemetry/grafana/dashboards/node-health.json @@ -1347,8 +1347,8 @@ } }, { - "title": "NuDB Stored Bytes", - "description": "###### What this is:\n*Cumulative object-payload bytes this process has written to the NuDB object-store back end. Despite the metric name, this is not the size of the store on disk.*\n\n###### How it's computed:\n*Current value of the nudb_bytes gauge, plotted over time. It observes getStoreSize(), the same accessor node_written_bytes uses, so the two series are equal and their ratio is a constant 1.0 rather than a write-amplification measure.*\n\n###### Reading it:\n*A smoothly growing line is normal; the slope is the write rate. It excludes NuDB's keys, bucket padding and log, and it restarts from zero with the process while the files on disk do not.*\n\n###### Healthy range:\n*Gradual growth consistent with ledger data being stored.*\n\n###### Watch for:\n*A sudden jump in growth rate can indicate runaway storage or an unexpected back-fill. Do not use this panel to size the store on disk or to plan disk capacity; no metric reports on-disk size today, so check the filesystem directly.*\n\n###### Source:\n[MetricsRegistry.cpp](https://github.com/XRPLF/rippled/blob/develop/src/xrpld/telemetry/MetricsRegistry.cpp)\n\n###### Function:\n`registerStorageDetailGauge`", + "title": "Stored Object Bytes", + "description": "###### What this is:\n*Cumulative object-payload bytes this process has written to the NodeStore object-store back end. This is not the size of the store on disk.*\n\n###### How it's computed:\n*Current value of the stored_object_bytes gauge, plotted over time. It observes getStoreSize(), the same accessor node_written_bytes uses, so the two series are equal and their ratio is a constant 1.0 rather than a write-amplification measure.*\n\n###### Reading it:\n*A smoothly growing line is normal; the slope is the write rate. It excludes NuDB's keys, bucket padding and log, and it restarts from zero with the process while the files on disk do not.*\n\n###### Healthy range:\n*Gradual growth consistent with ledger data being stored.*\n\n###### Watch for:\n*A sudden jump in growth rate can indicate runaway storage or an unexpected back-fill. Do not use this panel to size the store on disk or to plan disk capacity; no metric reports on-disk size today, so check the filesystem directly.*\n\n###### Source:\n[MetricsRegistry.cpp](https://github.com/XRPLF/rippled/blob/develop/src/xrpld/telemetry/MetricsRegistry.cpp)\n\n###### Function:\n`registerStorageDetailGauge`", "type": "timeseries", "gridPos": { "h": 8, @@ -1368,7 +1368,7 @@ "datasource": { "type": "prometheus" }, - "expr": "label_replace(storage_detail{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=\"nudb_bytes\"}, \"series\", \"NuDB Stored Bytes\", \"\", \"\")" + "expr": "label_replace(storage_detail{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=\"stored_object_bytes\"}, \"series\", \"Stored Object Bytes\", \"\", \"\")" } ], "fieldConfig": { diff --git a/docs/telemetry-runbook.md b/docs/telemetry-runbook.md index 6bf79a81dc..a97fda2a68 100644 --- a/docs/telemetry-runbook.md +++ b/docs/telemetry-runbook.md @@ -1803,11 +1803,13 @@ Two more pairs from the same family: quantity, the larger of the recorded load and the pending batch size (`src/libxrpl/nodestore/BatchWriter.cpp:47-53`), so it is a batch-queue length rather than a thread count. -- **`nudb_bytes` is not the size of the store on disk**, despite the name. It reports - the cumulative object-payload bytes this process has written — the same value as +- **`stored_object_bytes` is not the size of the store on disk.** It reports the + cumulative object-payload bytes this process has written — the same value as `node_written_bytes`, from the same accessor — so it excludes keys, padding and the log, and it resets with the process. A ratio of the two is a constant 1.0 and - measures nothing. + measures nothing. This label value was called `nudb_bytes` before Phase 9; it + comes from `node_store::Database` rather than the NuDB backend, so it is not part + of the `nudb_*` family above and reads the same on RocksDB. - 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 diff --git a/src/xrpld/telemetry/MetricsRegistry.cpp b/src/xrpld/telemetry/MetricsRegistry.cpp index fbdd6edcbd..bef7ec8f2d 100644 --- a/src/xrpld/telemetry/MetricsRegistry.cpp +++ b/src/xrpld/telemetry/MetricsRegistry.cpp @@ -1472,7 +1472,8 @@ MetricsRegistry::registerStorageDetailGauge() // --- Task 7.13: Storage detail gauges --- // Reports the cumulative payload bytes handed to the NodeStore. See the // note at the observe() call below: this is logical bytes stored, not - // on-disk file size, because no accessor for the latter exists. + // on-disk file size, because no accessor for the latter exists. The label + // value names it that way so it is not read as a filesystem measurement. storageDetailGauge_ = meter_->CreateInt64ObservableGauge("storage_detail", "Storage detail metrics"); storageDetailGauge_->AddCallback( @@ -1490,11 +1491,13 @@ MetricsRegistry::registerStorageDetailGauge() ->Observe(value, {{"metric", name}}); }; - // Cumulative payload bytes handed to the NodeStore -- NOT - // on-disk file size, despite the name. getStoreSize() sums - // the object payloads this process has written, so it - // excludes NuDB's keys, bucket padding and log, and it - // resets with the process while the files do not. + // Cumulative payload bytes handed to the NodeStore. This is + // not an on-disk file size: getStoreSize() sums the object + // payloads this process has written, so it excludes NuDB's + // keys, bucket padding and log, and it resets with the + // process while the files do not. The value comes from + // Database, not from any backend, so it carries no nudb_ + // prefix -- it reads the same on RocksDB. // // This is the same call node_written_bytes makes on the // nodestore_state gauge, so the two series are equal by @@ -1504,7 +1507,8 @@ MetricsRegistry::registerStorageDetailGauge() // computing one would mean stat()ing the backend's files // from the reader thread, which needs a new Backend method // rather than a change at this call site. - observe("nudb_bytes", static_cast(app.getNodeStore().getStoreSize())); + observe( + "stored_object_bytes", static_cast(app.getNodeStore().getStoreSize())); } catch (...) // NOLINT(bugprone-empty-catch) { From 9f92a938e51d107136a24fc498a3a662c91f08a9 Mon Sep 17 00:00:00 2001 From: Pratik Mankawde <3397372+pratikmankawde@users.noreply.github.com> Date: Tue, 28 Jul 2026 16:08:56 +0100 Subject: [PATCH 2/4] test(telemetry): assert the nodestore_state labels and pin writer depth The 22 metric label values on the nodestore_state gauge were asserted nowhere, and the depthSum assertions could not tell the real fetch_add(depth) from a fetch_add(1) that would silently zero every derived queueing time. Make the four observe* helpers and their ObserveFn sink public rather than private, so the seam the header already claimed is actually reachable. All four are static and read only their arguments, so this exposes no object state; a friend declaration would have granted access to every private member instead. The assertions live in the existing Beast nodestore suite because src/test compiles into xrpld, which contains MetricsRegistry.cpp, while xrpl_tests deliberately does not when telemetry is enabled. Each helper now has its exact emitted label set asserted, so a typo in any literal fails instead of silently producing a disjoint series, and each derived mean is asserted ABSENT on a fresh store -- a refactor to value_or(0) would draw a believable flat zero on a latency axis and otherwise pass everything. Replace the concurrent write-stats test with one that forces genuine overlap through a latch. NuDB holds one global mutex for the whole insert and doInsert reads the depth before entering it, so a blocked thread records a depth of at least 2; asserting depthSum strictly exceeds insertCount therefore cannot be satisfied by a constant 1. The old bounds admitted that bug at their floor. Also: cover the std::nullopt branch on the two backends that exist in every build, bound the store-duration accumulator by the wall clock, drop four assertions that cannot fail, and correct two comments that claimed coverage the tests do not have -- the duplicate-key test is not the throwing path, because nudb reports key_exists without throwing, and no test drives NodeStoreScheduler::onFetch. --- .../scripts/levelization/results/ordering.txt | 2 + src/test/nodestore/DatabaseConfig_test.cpp | 513 ++++++++++++++++-- src/tests/libxrpl/nodestore/Backend.cpp | 50 ++ src/tests/libxrpl/nodestore/Database.cpp | 15 +- src/tests/libxrpl/nodestore/NuDBFactory.cpp | 206 +++++-- .../libxrpl/telemetry/MetricsRegistry.cpp | 3 +- .../telemetry/NodeStoreMetricNames.cpp | 28 +- src/xrpld/telemetry/MetricsRegistry.h | 112 ++-- 8 files changed, 795 insertions(+), 134 deletions(-) diff --git a/.github/scripts/levelization/results/ordering.txt b/.github/scripts/levelization/results/ordering.txt index 494fbc25e3..d9c4f24ecf 100644 --- a/.github/scripts/levelization/results/ordering.txt +++ b/.github/scripts/levelization/results/ordering.txt @@ -138,7 +138,9 @@ test.nodestore > test.jtx test.nodestore > test.unit_test test.nodestore > xrpl.basics test.nodestore > xrpl.config +test.nodestore > xrpld.app test.nodestore > xrpld.core +test.nodestore > xrpld.telemetry test.nodestore > xrpl.nodestore test.nodestore > xrpl.rdb test.overlay > test.jtx diff --git a/src/test/nodestore/DatabaseConfig_test.cpp b/src/test/nodestore/DatabaseConfig_test.cpp index 5c9b2cf0d6..b8392daaa8 100644 --- a/src/test/nodestore/DatabaseConfig_test.cpp +++ b/src/test/nodestore/DatabaseConfig_test.cpp @@ -4,6 +4,13 @@ #include #include +#ifdef XRPL_ENABLE_TELEMETRY +// The four nodestore_state gauge helpers under test, plus the counter type one +// of them reads. Both live in xrpld and are only declared in a +// telemetry-enabled build, so the include is guarded like its uses below. +#include +#include +#endif #include #include @@ -21,16 +28,21 @@ #include #include #include +#include #include #include #include +#include +#include #include #include -#include #include +#include +#include #include #include +#include namespace xrpl::node_store { @@ -624,12 +636,6 @@ public: std::is_same_v().getFetchSize()), std::uint64_t>, "getFetchSize must be 64-bit"); - // A 64-bit counter must be able to represent the byte totals a - // long-lived node reaches. 32 bits cannot. - static_assert( - std::numeric_limits::max() > std::numeric_limits::max(), - "64-bit counters must exceed the 32-bit ceiling"); - DummyScheduler scheduler; beast::TempDir const nodeDb; @@ -725,11 +731,24 @@ public: constexpr std::uint64_t kNumStored = 32; auto const stored = createPredictableBatch(static_cast(kNumStored), 4321); BEAST_EXPECT(stored.size() == kNumStored); + + auto const writesBegan = std::chrono::steady_clock::now(); storeBatch(*db, stored); + auto const wallClockUs = + static_cast(std::chrono::duration_cast( + std::chrono::steady_clock::now() - writesBegan) + .count()); BEAST_EXPECT(db->getStoreCount() == kNumStored); BEAST_EXPECT(db->getStoreDurationUs() > 0); + // Bounded above by the wall-clock span of the loop that produced it. + // The accumulator only ever sums the backend calls made inside that + // span, so it cannot exceed it. Without this bound the `> 0` above + // would also pass for an accumulator adding a fixed constant per + // insert instead of the measured time. + BEAST_EXPECT(db->getStoreDurationUs() <= wallClockUs); + // Writes must leave the read accumulator alone. This also proves the // read accessor does not report the write member. BEAST_EXPECT(db->getFetchDurationUs() == 0); @@ -765,6 +784,47 @@ public: //-------------------------------------------------------------------------- + /** + * Build a rotating nudb database over two fresh directories. + * + * @param scheduler Scheduler the database keeps a reference to; it must + * outlive the returned database. + * @param writableDir Directory for the writable backend. + * @param archiveDir Directory for the archive backend. + * @return The rotating database, or nullptr if either backend failed. + */ + std::unique_ptr + makeRotatingDatabase( + Scheduler& scheduler, + beast::TempDir const& writableDir, + beast::TempDir const& archiveDir) + { + Section writableParams; + writableParams.set(Keys::kType, "nudb"); + writableParams.set(Keys::kPath, writableDir.path()); + + Section archiveParams; + archiveParams.set(Keys::kType, "nudb"); + archiveParams.set(Keys::kPath, archiveDir.path()); + + std::shared_ptr writableBackend = + Manager::instance().makeBackend(writableParams, megabytes(4), scheduler, journal_); + std::shared_ptr archiveBackend = + Manager::instance().makeBackend(archiveParams, megabytes(4), scheduler, journal_); + if (!writableBackend || !archiveBackend) + return nullptr; + writableBackend->open(); + archiveBackend->open(); + + return std::make_unique( + scheduler, + 2, + std::move(writableBackend), + std::move(archiveBackend), + writableParams, + journal_); + } + /** * Verify the rotating database records its write duration too. * @@ -783,35 +843,14 @@ public: beast::TempDir const writableDir; beast::TempDir const archiveDir; - Section writableParams; - writableParams.set(Keys::kType, "nudb"); - writableParams.set(Keys::kPath, writableDir.path()); - - Section archiveParams; - archiveParams.set(Keys::kType, "nudb"); - archiveParams.set(Keys::kPath, archiveDir.path()); - - std::shared_ptr writableBackend = - Manager::instance().makeBackend(writableParams, megabytes(4), scheduler, journal_); - std::shared_ptr archiveBackend = - Manager::instance().makeBackend(archiveParams, megabytes(4), scheduler, journal_); - if (!BEAST_EXPECT(writableBackend) || !BEAST_EXPECT(archiveBackend)) + auto rotating = makeRotatingDatabase(scheduler, writableDir, archiveDir); + if (!BEAST_EXPECT(rotating)) return; - writableBackend->open(); - archiveBackend->open(); - - DatabaseRotatingImp rotating( - scheduler, - 2, - std::move(writableBackend), - std::move(archiveBackend), - writableParams, - journal_); // The private fetchNodeObject override hides the public base overload, // so exercise the rotating store through the Database interface, which // is also how production callers reach it. - Database& db = rotating; + Database& db = *rotating; // A fresh rotating database has done no work either. BEAST_EXPECT(db.getStoreCount() == 0); @@ -855,6 +894,405 @@ public: BEAST_EXPECT(db.getStoreDurationUs() == storeDurationAfterWrites); } + //-------------------------------------------------------------------------- + +#ifdef XRPL_ENABLE_TELEMETRY + + /** + * Recording sink for the nodestore_state gauge helpers. + * + * The helpers take an ObserveFn rather than the OTel observer result + * precisely so a test can hand them somewhere else to put a name and a + * number. Emissions are kept in order, not merged into a map, so a label + * published twice is visible instead of silently overwriting itself. + */ + struct MetricSink + { + /** + * Every (metric label, value) pair published, in emission order. + */ + std::vector> emitted; + + /** + * Return a sink callable that appends into @ref emitted. + */ + telemetry::MetricsRegistry::ObserveFn + fn() + { + return + [this](char const* name, std::int64_t value) { emitted.emplace_back(name, value); }; + } + + /** + * Return every published label, sorted, for set comparison. + */ + [[nodiscard]] std::vector + names() const + { + std::vector out; + out.reserve(emitted.size()); + for (auto const& entry : emitted) + out.push_back(entry.first); + std::ranges::sort(out); + return out; + } + + /** + * Return the value published for @p name, or std::nullopt when the + * label was not published at all. + * + * Absence and zero must stay distinguishable: a mean over no samples + * is deliberately omitted, while a counter at zero is published. + * + * @param name Metric label to look up. + */ + [[nodiscard]] std::optional + value(std::string const& name) const + { + auto const it = std::ranges::find_if( + emitted, [&name](auto const& entry) { return entry.first == name; }); + if (it == emitted.end()) + return std::nullopt; + return it->second; + } + }; + + /** + * Build a nudb database with a non-default read-thread count and bundle. + * + * Both are set away from their defaults so the read-queue labels pin real + * forwarding rather than agreeing with a default by accident. + * + * @param dir Directory the store lives in. + * @param scheduler Scheduler the database keeps a reference to; it must + * outlive the returned database. + * @param readThreads Read threads to request. + * @return The database, or nullptr on failure. + */ + std::unique_ptr + makeMeasuredDatabase(beast::TempDir const& dir, Scheduler& scheduler, int readThreads) + { + Section params; + params.set(Keys::kType, "nudb"); + params.set(Keys::kPath, dir.path()); + params.set(Keys::kRqBundle, "7"); + + return Manager::instance().makeDatabase( + megabytes(4), scheduler, readThreads, params, journal_); + } + + /** + * Verify the exact `metric` label set observeNodeStoreTotals() publishes, + * and that each derived mean is OMITTED rather than reported as zero + * before there is anything to average. + * + * The 22 label values on this gauge are the change's entire user-visible + * surface. A one-character typo in any of them produces a silently + * disjoint Prometheus series: the metric still exports, the dashboard + * panel goes blank, and nothing else fails. + */ + void + testNodeStoreTotalLabels() + { + testcase("nodestore_state totals labels"); + + DummyScheduler scheduler; + beast::TempDir const nodeDb; + Section nodeParams; + nodeParams.set(Keys::kType, "nudb"); + nodeParams.set(Keys::kPath, nodeDb.path()); + + std::unique_ptr db = + Manager::instance().makeDatabase(megabytes(4), scheduler, 2, nodeParams, journal_); + if (!BEAST_EXPECT(db)) + return; + + // Fresh store: the eight unconditional labels are published, each at + // exactly zero, and NEITHER mean appears. + MetricSink fresh; + telemetry::MetricsRegistry::observeNodeStoreTotals(*db, fresh.fn()); + + std::vector const kFreshLabels{ + "node_read_bytes", + "node_reads_duration_us", + "node_reads_hit", + "node_reads_total", + "node_writes", + "node_writes_duration_us", + "node_written_bytes", + "write_load"}; + BEAST_EXPECT(fresh.names() == kFreshLabels); + // No label published twice; a map-based sink would have hidden that. + BEAST_EXPECT(fresh.emitted.size() == kFreshLabels.size()); + + for (auto const& label : kFreshLabels) + BEAST_EXPECT(fresh.value(label) == std::int64_t{0}); + + // THE omission assertion. A refactor to `mean.value_or(0)` publishes + // these as a believable flat zero on a latency axis; absence is the + // only honest answer before anything has been read or written. + BEAST_EXPECT(!fresh.value("read_mean_us").has_value()); + BEAST_EXPECT(!fresh.value("write_mean_us").has_value()); + + testNodeStoreMeanLabels(*db); + } + + /** + * Verify both derived means appear once there is work to average, and + * that each is the quotient of its OWN published numerator and + * denominator. + * + * @param db Database to drive; must be freshly created. + */ + void + testNodeStoreMeanLabels(Database& db) + { + // Reads and writes are given deliberately different counts, so a mean + // wired to the wrong accessor pair -- the adjacent-call-site copy-paste + // risk -- cannot land on the right number. + constexpr std::uint64_t kNumStored = 32; + constexpr std::uint64_t kNumMissing = 8; + auto const stored = createPredictableBatch(static_cast(kNumStored), 24680); + storeBatch(db, stored); + + // Fetch each stored object twice, plus a batch of misses, so the read + // count is 2*32 + 8 = 72 against a write count of 32. + for (int pass = 0; pass < 2; ++pass) + { + for (auto const& object : stored) + BEAST_EXPECT(db.fetchNodeObject(object->getHash(), 0) != nullptr); + } + auto const missing = createPredictableBatch(static_cast(kNumMissing), 13579); + for (auto const& object : missing) + BEAST_EXPECT(db.fetchNodeObject(object->getHash(), 0) == nullptr); + + MetricSink busy; + telemetry::MetricsRegistry::observeNodeStoreTotals(db, busy.fn()); + + // Ten labels now: the eight above plus both means. + BEAST_EXPECT(busy.emitted.size() == 10); + BEAST_EXPECT(busy.value("read_mean_us").has_value()); + BEAST_EXPECT(busy.value("write_mean_us").has_value()); + + // Exact counts, so the denominators below are pinned independently. + BEAST_EXPECT(busy.value("node_writes") == std::int64_t{kNumStored}); + BEAST_EXPECT(busy.value("node_reads_total") == std::int64_t{2 * kNumStored + kNumMissing}); + BEAST_EXPECT(busy.value("node_reads_hit") == std::int64_t{2 * kNumStored}); + // The two denominators differ, which is what makes the cross-checks + // below able to catch a swapped accessor pair. + BEAST_EXPECT(busy.value("node_reads_total") != busy.value("node_writes")); + + // Each mean is the truncating quotient of two OTHER published labels, + // so this ties the three together without restating the helper's own + // expression. read_mean_us fed the store pair fails it. + auto const quotient = [](std::optional total, + std::optional count) { + return (total && count && *count != 0) ? std::optional{*total / *count} + : std::nullopt; + }; + BEAST_EXPECT( + busy.value("read_mean_us") == + quotient(busy.value("node_reads_duration_us"), busy.value("node_reads_total"))); + BEAST_EXPECT( + busy.value("write_mean_us") == + quotient(busy.value("node_writes_duration_us"), busy.value("node_writes"))); + } + + /** + * Verify observeWritePathDetail() publishes its four NuDB labels only for + * a measuring backend, and omits the two derived means until an insert + * has happened. + */ + void + testWritePathDetailLabels() + { + testcase("nodestore_state write-path labels"); + + DummyScheduler scheduler; + + // Negative path first: a backend that does not measure its writes must + // publish NOTHING. Zeros here would read as a perfectly idle write + // path on a node whose write path is simply not instrumented. + { + beast::TempDir const memDb; + Section memParams; + memParams.set(Keys::kType, "memory"); + memParams.set(Keys::kPath, memDb.path()); + + std::unique_ptr mem = + Manager::instance().makeDatabase(megabytes(4), scheduler, 2, memParams, journal_); + if (!BEAST_EXPECT(mem)) + return; + + auto const batch = createPredictableBatch(8, 111); + storeBatch(*mem, batch); + + MetricSink sink; + telemetry::MetricsRegistry::observeWritePathDetail(*mem, sink.fn()); + // Cause as well as state: the store really was written to, so the + // emptiness is the std::nullopt branch and not an idle database. + BEAST_EXPECT(sink.emitted.empty()); + BEAST_EXPECT(mem->getStoreCount() == 8); + } + + beast::TempDir const nodeDb; + Section nodeParams; + nodeParams.set(Keys::kType, "nudb"); + nodeParams.set(Keys::kPath, nodeDb.path()); + + std::unique_ptr db = + Manager::instance().makeDatabase(megabytes(4), scheduler, 2, nodeParams, journal_); + if (!BEAST_EXPECT(db)) + return; + + // Measuring backend, nothing written yet: the two instantaneous + // values are published at zero while the two means are omitted. This + // pins the deliberate asymmetry -- zero is meaningful for a gauge and + // meaningless for a mean. + MetricSink fresh; + telemetry::MetricsRegistry::observeWritePathDetail(*db, fresh.fn()); + std::vector const kFreshLabels{"nudb_insert_max_us", "nudb_writers_in_flight"}; + BEAST_EXPECT(fresh.names() == kFreshLabels); + BEAST_EXPECT(fresh.value("nudb_writers_in_flight") == std::int64_t{0}); + BEAST_EXPECT(fresh.value("nudb_insert_max_us") == std::int64_t{0}); + BEAST_EXPECT(!fresh.value("nudb_insert_mean_us").has_value()); + BEAST_EXPECT(!fresh.value("nudb_writer_depth_x100").has_value()); + + constexpr std::uint64_t kNumStored = 16; + auto const stored = createPredictableBatch(static_cast(kNumStored), 97531); + storeBatch(*db, stored); + + MetricSink busy; + telemetry::MetricsRegistry::observeWritePathDetail(*db, busy.fn()); + std::vector const kBusyLabels{ + "nudb_insert_max_us", + "nudb_insert_mean_us", + "nudb_writer_depth_x100", + "nudb_writers_in_flight"}; + BEAST_EXPECT(busy.names() == kBusyLabels); + BEAST_EXPECT(busy.emitted.size() == kBusyLabels.size()); + + // Writers all returned, so the live gauge is back to exactly zero + // while the cumulative maximum stayed up. + BEAST_EXPECT(busy.value("nudb_writers_in_flight") == std::int64_t{0}); + + // One writing thread, so mean depth is exactly 1.00 and the x100 + // fixed-point form must read exactly 100. This is the assertion that + // catches the scale being dropped (it would read 1) or applied twice + // (10000) -- either of which makes the dashboard's divide-by-100 wrong + // by two orders of magnitude. + BEAST_EXPECT(busy.value("nudb_writer_depth_x100") == std::int64_t{100}); + } + + /** + * Verify the seven acquire_* labels, published unconditionally, and each + * wired to its own counter. + * + * Every expected value below is distinct, so a getter cross-wired to a + * neighbouring counter cannot produce the right number anywhere. + */ + void + testAcquireStatLabels() + { + testcase("nodestore_state acquisition labels"); + + std::vector const kLabels{ + "acquire_aborts", + "acquire_aborts_partial", + "acquire_completions", + "acquire_deferrals", + "acquire_give_ups", + "acquire_sweep_evictions", + "acquire_timeouts"}; + + // A quiet node publishes all seven at zero. Unlike a mean, zero is the + // meaningful "no such event yet" reading for a counter, so omitting + // these would lose the ability to see that nothing happened. + AcquireStats quiet; + MetricSink fresh; + telemetry::MetricsRegistry::observeAcquireStats(quiet, fresh.fn()); + BEAST_EXPECT(fresh.names() == kLabels); + BEAST_EXPECT(fresh.emitted.size() == kLabels.size()); + for (auto const& label : kLabels) + BEAST_EXPECT(fresh.value(label) == std::int64_t{0}); + + // Distinct counts per event, and aborts recorded both with and + // without partial work so the subset relationship is exercised: 5 + // aborts of which 2 discarded partly built maps. + AcquireStats busy; + for (int i = 0; i < 3; ++i) + busy.recordDeferral(); + for (int i = 0; i < 7; ++i) + busy.recordTimeout(); + busy.recordGiveUp(); + for (int i = 0; i < 2; ++i) + busy.recordAbort(true); + for (int i = 0; i < 3; ++i) + busy.recordAbort(false); + for (int i = 0; i < 11; ++i) + busy.recordCompletion(); + for (int i = 0; i < 13; ++i) + busy.recordSweepEviction(); + + MetricSink sink; + telemetry::MetricsRegistry::observeAcquireStats(busy, sink.fn()); + BEAST_EXPECT(sink.names() == kLabels); + BEAST_EXPECT(sink.value("acquire_deferrals") == std::int64_t{3}); + BEAST_EXPECT(sink.value("acquire_timeouts") == std::int64_t{7}); + BEAST_EXPECT(sink.value("acquire_give_ups") == std::int64_t{1}); + BEAST_EXPECT(sink.value("acquire_aborts") == std::int64_t{5}); + BEAST_EXPECT(sink.value("acquire_aborts_partial") == std::int64_t{2}); + BEAST_EXPECT(sink.value("acquire_completions") == std::int64_t{11}); + BEAST_EXPECT(sink.value("acquire_sweep_evictions") == std::int64_t{13}); + } + + /** + * Verify the four read-queue labels and that the two configured values + * are forwarded rather than defaulted. + */ + void + testReadQueueLabels() + { + testcase("nodestore_state read-queue labels"); + + DummyScheduler scheduler; + beast::TempDir const nodeDb; + // Three read threads and a bundle of 7, neither of which is the + // default (the bundle default is 4), so a helper reading the wrong + // JSON member cannot agree by coincidence. + auto db = makeMeasuredDatabase(nodeDb, scheduler, 3); + if (!BEAST_EXPECT(db)) + return; + + MetricSink sink; + telemetry::MetricsRegistry::observeReadQueue(*db, sink.fn()); + + std::vector const kLabels{ + "read_queue", "read_request_bundle", "read_threads_running", "read_threads_total"}; + BEAST_EXPECT(sink.names() == kLabels); + BEAST_EXPECT(sink.emitted.size() == kLabels.size()); + + // Nothing has been queued for asynchronous read. + BEAST_EXPECT(sink.value("read_queue") == std::int64_t{0}); + // Both configured values, exactly as requested. read_request_bundle is + // the one that would silently read 4 if the helper looked up the wrong + // JSON member, since 4 is the default. + BEAST_EXPECT(sink.value("read_threads_total") == std::int64_t{3}); + BEAST_EXPECT(sink.value("read_request_bundle") == std::int64_t{7}); + // The running count races with the read threads parking themselves, so + // only its bounds are assertable: present, non-negative, and never + // above the total. Compared as unwrapped values, since comparing two + // optionals would also pass with both absent. + auto const running = sink.value("read_threads_running"); + if (BEAST_EXPECT(running.has_value())) + { + BEAST_EXPECT(*running >= 0); + BEAST_EXPECT(*running <= 3); + } + } + +#endif // XRPL_ENABLE_TELEMETRY + void run() override { @@ -864,6 +1302,19 @@ public: testRotatingDurationAccessors(); +#ifdef XRPL_ENABLE_TELEMETRY + // The four gauge helpers are declared and defined only in a + // telemetry-enabled build, so their label assertions are guarded the + // same way. + testNodeStoreTotalLabels(); + + testWritePathDetailLabels(); + + testAcquireStatLabels(); + + testReadQueueLabels(); +#endif + testConfig(); } }; diff --git a/src/tests/libxrpl/nodestore/Backend.cpp b/src/tests/libxrpl/nodestore/Backend.cpp index cc1d515621..c1f5b95e84 100644 --- a/src/tests/libxrpl/nodestore/Backend.cpp +++ b/src/tests/libxrpl/nodestore/Backend.cpp @@ -204,4 +204,54 @@ INSTANTIATE_TEST_SUITE_P( ::testing::ValuesIn(backendTypes()), [](::testing::TestParamInfo const& info) { return info.param; }); +// The std::nullopt default on the base class, exercised directly on the two +// backends that always exist in every build -- unlike rocksdb, which the +// parameterized suite above only reaches when XRPL_ROCKSDB_AVAILABLE. +// +// Why absence and not zeros: the exporter skips the whole nudb_* label group +// when getWriteStats() is empty (MetricsRegistry.cpp observeWritePathDetail +// returns early). If the base class returned a default-constructed WriteStats +// instead, every non-NuDB node would publish nudb_writers_in_flight=0 and +// nudb_insert_max_us=0 -- a perfectly idle write path, on a node whose write +// path is simply not instrumented. Each assertion below fails against that +// change. +TEST(BackendWriteStats, non_measuring_backends_report_absence_not_zeros) +{ + for (auto const& type : {std::string{"memory"}, std::string{"none"}}) + { + SCOPED_TRACE("type=" + type); + + DummyScheduler scheduler; + beast::Journal const journal{TestSink::instance()}; + beast::TempDir const tempDir; + + Section params; + params.set("type", type); + params.set("path", tempDir.path()); + + auto backend = Manager::instance().makeBackend(params, megabytes(4), scheduler, journal); + ASSERT_TRUE(backend); + backend->open(); + + // Absent before any write. + EXPECT_FALSE(backend->getWriteStats().has_value()); + + // Still absent after real writes. Cause, not just state: the + // backend has genuinely been used, so the absence is the base-class + // default and not an unopened backend. + beast::xor_shift_engine rng(kSeedValue); + auto const batch = createPredictableBatch(16, rng()); + storeBatch(*backend, batch); + EXPECT_FALSE(backend->getWriteStats().has_value()); + + // These backends queue nothing, so their own write load stays 0. The + // pairing matters: absent stats plus a 0 load is what tells the + // exporter "not measured", whereas present stats reading 0 would mean + // "measured, and idle". + EXPECT_EQ(backend->getWriteLoad(), 0); + + backend->close(); + } +} + } // namespace xrpl::node_store diff --git a/src/tests/libxrpl/nodestore/Database.cpp b/src/tests/libxrpl/nodestore/Database.cpp index 298c906a23..2f89442815 100644 --- a/src/tests/libxrpl/nodestore/Database.cpp +++ b/src/tests/libxrpl/nodestore/Database.cpp @@ -253,12 +253,23 @@ TEST_P(NodeStoreDatabaseTest, write_stats_forwarded_from_backend) ASSERT_TRUE(after.has_value()); EXPECT_EQ(after->insertCount, batch_.size()); // One writer thread, so the depth recorded at each insert is exactly 1. + // This catches a depth accumulator fed the wrong quantity (insertCount's + // running value, or the elapsed microseconds), but it CANNOT catch one fed + // a constant 1, because here the real depth is 1. That case needs genuine + // overlap and is covered by NuDBFactory.cpp's + // write_stats_measure_depth_under_real_overlap. EXPECT_EQ(after->depthSum, batch_.size()); // No writer is left in flight once the calls have returned. EXPECT_EQ(after->concurrentWriters, 0u); + // Same live depth through the other accessor on the same object, so the + // two cannot drift onto different fields. + EXPECT_EQ(db->getWriteLoad(), 0); EXPECT_GT(after->insertTotalUs, 0u); - // A maximum is never below the mean, which fails if the field held the - // minimum or the first sample instead of a running maximum. + // max * n >= sum. Catches a field holding the running MINIMUM, since + // min * n <= sum with equality only when every sample is identical. + // Degenerates when the samples do not vary; the unconditional guarantee + // that the field is a maximum is the non-decreasing check in + // NuDBFactory.cpp's write_stats_accumulate_per_insert. EXPECT_GE(after->insertMaxUs * after->insertCount, after->insertTotalUs); } diff --git a/src/tests/libxrpl/nodestore/NuDBFactory.cpp b/src/tests/libxrpl/nodestore/NuDBFactory.cpp index 1153aa3749..2658cd3fdf 100644 --- a/src/tests/libxrpl/nodestore/NuDBFactory.cpp +++ b/src/tests/libxrpl/nodestore/NuDBFactory.cpp @@ -4,6 +4,7 @@ #include #include #include +#include #include #include @@ -14,7 +15,9 @@ #include #include #include +#include #include +#include #include #include #include @@ -56,6 +59,48 @@ runRoundTrip(Section const& params, std::size_t expectedBlocksize) EXPECT_EQ(batch, copy); } +/** + * Threads used by the overlapping-insert round below. + */ +constexpr std::uint64_t kOverlapThreads = 8; + +/** + * Inserts each of those threads performs per round. + */ +constexpr std::uint64_t kOverlapPerThread = 50; + +/** + * Run one round of deliberately overlapping inserts against @p backend. + * + * All kOverlapThreads threads are released from a single latch, so they reach + * doInsert() together rather than one after another; staggered starts are what + * would let every insert run end to end and never overlap. + * + * @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. + */ +void +runOverlappingInsertRound(Backend& backend, int round) +{ + std::latch start(static_cast(kOverlapThreads)); + + std::vector threads; + threads.reserve(kOverlapThreads); + for (auto t = 0uz; t < kOverlapThreads; ++t) + { + threads.emplace_back([&backend, &start, t, round] { + auto const batch = createPredictableBatch( + kOverlapPerThread, 1000 + t + (static_cast(round) * 100'000)); + start.arrive_and_wait(); + for (auto const& obj : batch) + backend.store(obj); + }); + } + for (auto& th : threads) + th.join(); +} + } // namespace TEST(NuDBFactory, default_block_size) @@ -290,6 +335,14 @@ TEST(NuDBFactory, write_stats_accumulate_per_insert) // Exactly 10 inserts must be counted as 10, and depthSum must be 10 // because a single-threaded caller is always the only writer, so the // depth recorded at each insert is exactly 1. + // + // What this pins and what it cannot: on one thread depthSum == insertCount + // catches an accumulator fed the wrong quantity -- fed insertCount it + // would read 1+2+...+n, and fed the elapsed time it would read the + // microseconds. It does NOT catch depthSum being fed a constant 1, which + // is indistinguishable here because the real depth IS 1. That bug is the + // one that would silently zero every derived wait time, and it is caught + // by write_stats_measure_depth_under_real_overlap below. constexpr std::uint64_t kFirstBatch = 10; auto const batch = createPredictableBatch(kFirstBatch, 12345); storeBatch(*backend, batch); @@ -301,11 +354,12 @@ TEST(NuDBFactory, write_stats_accumulate_per_insert) EXPECT_EQ(after->depthSum, kFirstBatch); EXPECT_GT(after->insertTotalUs, 0u); EXPECT_GT(after->insertMaxUs, 0u); - // The largest single insert cannot exceed the sum of all of them. - EXPECT_LE(after->insertMaxUs, after->insertTotalUs); - // A maximum is never below the mean. This fails if the field were - // holding the minimum, or the first or last sample, instead of the - // running maximum. + // A maximum is never below the mean, so max * n >= sum. Catches a field + // fed the running MINIMUM: min * n <= sum, with equality only when every + // sample is identical, so any variation at all makes the two orderings + // exclusive. It does not discriminate when the samples happen not to + // vary; the running-maximum property is pinned unconditionally by the + // non-decreasing check after the second batch below. EXPECT_GE(after->insertMaxUs * after->insertCount, after->insertTotalUs); // No writer remains in flight once the calls have returned. EXPECT_EQ(after->concurrentWriters, 0u); @@ -334,6 +388,22 @@ TEST(NuDBFactory, write_stats_accumulate_per_insert) // Negative path: NuDB reports key_exists for a duplicate key and doInsert // deliberately does not treat that as an error. The accounting must still // run, and in particular the depth must come back down. +// +// What this does NOT cover, stated plainly because a comment claiming absent +// coverage is worse than none: this is not the throwing path. nudb::insert() +// sets error::key_exists and RETURNS (nudb/impl/basic_store.ipp:294, :307, +// :329), and doInsert() filters exactly that code out before it would throw +// (NuDBFactory.cpp:283), so a duplicate key takes the identical non-throwing +// control flow as a fresh key. It reaches the ScopeExit guard by the same +// route the happy path does. +// +// The throwing path -- where the guard is the only reason the depth comes +// back down -- is not reachable from a unit test: it needs nudb::insert() to +// fail with something other than key_exists (an I/O or allocation failure +// inside the library), which cannot be induced through the Backend interface +// without a fault-injection seam that does not exist. Its RAII contract is +// covered generically instead: src/tests/libxrpl/basics/scope.cpp:34-45 proves +// ScopeExit runs its function during unwinding. TEST(NuDBFactory, write_stats_count_duplicate_key_inserts) { beast::TempDir const tempDir; @@ -353,6 +423,7 @@ TEST(NuDBFactory, write_stats_count_duplicate_key_inserts) if (!first.has_value()) FAIL() << "nudb must report write stats"; ASSERT_EQ(first->insertCount, kBatchSize); + ASSERT_EQ(first->depthSum, kBatchSize); // Re-storing the identical batch writes nothing new, but each call is // still an insert attempt that entered and left the backend. @@ -361,16 +432,40 @@ TEST(NuDBFactory, write_stats_count_duplicate_key_inserts) auto const second = backend->getWriteStats(); if (!second.has_value()) FAIL() << "nudb must report write stats after re-storing"; - EXPECT_EQ(second->insertCount, kBatchSize * 2); - EXPECT_EQ(second->depthSum, kBatchSize * 2); - // The depth returned to zero, so the early-return error path did not + // The duplicate round is counted, so a key_exists early return is not + // skipping the accounting. Written as the first snapshot plus the batch + // size rather than as one product, because the two sides must differ by + // exactly the second round: an implementation that counted only the + // rounds that stored new data would leave these equal. + EXPECT_EQ(second->insertCount, first->insertCount + kBatchSize); + EXPECT_EQ(second->depthSum, first->depthSum + kBatchSize); + // The depth returned to zero, so the key_exists early return did not // leak a writer. EXPECT_EQ(second->concurrentWriters, 0u); + EXPECT_EQ(backend->getWriteLoad(), 0); backend->close(); } -TEST(NuDBFactory, write_stats_observe_concurrent_writers) +// depthSum is the L in Little's Law: mean depth L and mean insert time W give +// service time S = W / L, and the queuing time the whole diagnosis rests on is +// W - S. If depthSum were fed a constant 1 instead of the observed depth then +// L would read exactly 1.0, S would equal W, and every derived wait would read +// 0 -- a stalled write path indistinguishable from a healthy one, with nothing +// on any dashboard looking wrong. +// +// A single-threaded test cannot see that bug, because there the real depth IS +// 1. This test forces genuine overlap so the correct implementation records a +// depth above 1 and the constant-1 implementation cannot. +// +// Why the overlap is reachable and not merely hoped for: NuDB takes one global +// mutex for the entire insert, and doInsert() reads the depth BEFORE entering +// it. So while one thread is inside an insert, every other thread that reaches +// doInsert() records a depth of at least 2 and then blocks. All threads are +// released from one latch, and the round is retried until the overlap is +// observed -- so a constant-1 implementation exhausts every round and fails, +// while the real one satisfies it as soon as any two inserts overlap. +TEST(NuDBFactory, write_stats_measure_depth_under_real_overlap) { beast::TempDir const tempDir; auto const params = makeSection(tempDir.path()); @@ -381,36 +476,57 @@ TEST(NuDBFactory, write_stats_observe_concurrent_writers) ASSERT_TRUE(backend); backend->open(); - // Four threads insert distinct objects concurrently. The exact peak - // depth is racy, but two invariants are not: every insert is counted, - // and depthSum is at least insertCount because depth is >= 1 per - // insert. - constexpr std::uint64_t kThreads = 4; - constexpr std::uint64_t kPerThread = 50; + // Bounded so a genuine regression fails instead of hanging. Each round + // runs kOverlapThreads * kOverlapPerThread inserts through one global + // mutex, so one round already gives the correct implementation many + // chances to overlap. + constexpr int kMaxRounds = 20; - std::vector threads; - threads.reserve(kThreads); - for (auto t = 0uz; t < kThreads; ++t) + std::uint64_t completedRounds = 0; + std::optional stats; + + for (auto round = 0; round < kMaxRounds; ++round) { - threads.emplace_back([&backend, t] { - auto const batch = createPredictableBatch(kPerThread, 1000 + t); - for (auto const& obj : batch) - backend->store(obj); - }); - } - for (auto& th : threads) - th.join(); + runOverlappingInsertRound(*backend, round); + ++completedRounds; + + stats = backend->getWriteStats(); + if (!stats.has_value()) + FAIL() << "nudb must report write stats after concurrent inserts"; + + if (stats->depthSum > stats->insertCount) + break; + } - auto const stats = backend->getWriteStats(); if (!stats.has_value()) - FAIL() << "nudb must report write stats after concurrent inserts"; - EXPECT_EQ(stats->insertCount, kThreads * kPerThread); - EXPECT_GE(stats->depthSum, stats->insertCount); + FAIL() << "no round produced write stats"; + + // Every insert of every round is counted exactly once. A lost increment + // under contention fails this. + EXPECT_EQ(stats->insertCount, completedRounds * kOverlapThreads * kOverlapPerThread); + + // 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. + EXPECT_GT(stats->depthSum, stats->insertCount) + << "depthSum must record the observed depth, not a constant 1; rounds run=" + << completedRounds; + + // Upper bound with teeth: at most kThreads writers can be inside an + // insert at once, so no single insert can observe a depth above kThreads. + // A missing fetch_sub in recordInsert() would let the gauge climb once + // per insert, giving a depthSum near insertCount squared over two -- + // vastly over this bound at these counts. + EXPECT_LE(stats->depthSum, stats->insertCount * kOverlapThreads); + + // State plus cause: the gauge is back to exactly zero, so every one of + // the increments taken above was matched by its decrement. Exactly 0 and + // not "small": a single leaked writer strands getWriteLoad() nonzero for + // the life of the process, which gates history acquisition. EXPECT_EQ(stats->concurrentWriters, 0u); + EXPECT_EQ(backend->getWriteLoad(), 0); + EXPECT_GT(stats->insertMaxUs, 0u); - // Depth cannot exceed the number of threads that could be inside the - // insert at once, so the mean depth is bounded by kThreads. - EXPECT_LE(stats->depthSum, stats->insertCount * kThreads); backend->close(); } @@ -431,15 +547,29 @@ TEST(NuDBFactory, write_load_reports_writer_depth) // After writes complete the depth returns to 0 rather than staying // elevated, because this is an instantaneous gauge and not a counter. + // Exactly 0 and not merely small: were getWriteLoad() to return one of + // the cumulative fields instead of the live depth -- insertCount would + // read 5 here, insertTotalUs some microsecond total -- this fails. auto const batch = createPredictableBatch(5, 777); storeBatch(*backend, batch); EXPECT_EQ(backend->getWriteLoad(), 0); - // The value must stay far below the history-acquisition cutoff that - // LedgerMaster applies (kMaxWriteLoadAcquire), or history acquisition - // would silently stop. Depth is bounded by the writing threads. - constexpr int kMaxWriteLoadAcquire = 8192; - EXPECT_LT(backend->getWriteLoad(), kMaxWriteLoadAcquire); + // Same value as the write-stats snapshot reports, since both read the one + // depth atomic. Catches the two accessors drifting onto different fields. + auto const stats = backend->getWriteStats(); + if (!stats.has_value()) + FAIL() << "nudb must report write stats"; + EXPECT_EQ(static_cast(backend->getWriteLoad()), stats->concurrentWriters); + // The cumulative fields did move, so the 0 above is the gauge being + // instantaneous and not the backend having done nothing. + EXPECT_EQ(stats->insertCount, 5u); + + // NOTE. LedgerMaster gates history acquisition on getWriteLoad() staying + // below kMaxWriteLoadAcquire (8192), declared static constexpr inside + // src/xrpld/app/ledger/detail/LedgerMaster.cpp and so unreachable from + // this binary. Depth is bounded by the number of writing threads, which + // cannot approach that figure, so the coupling is recorded here rather + // than asserted against a literal copy of the constant that could drift. backend->close(); } diff --git a/src/tests/libxrpl/telemetry/MetricsRegistry.cpp b/src/tests/libxrpl/telemetry/MetricsRegistry.cpp index 490d622ab1..f21ddfe831 100644 --- a/src/tests/libxrpl/telemetry/MetricsRegistry.cpp +++ b/src/tests/libxrpl/telemetry/MetricsRegistry.cpp @@ -411,7 +411,8 @@ TEST(MetricsRegistryScaledMean, default_scale_is_one) { // The two-argument form is the latency case and must not scale silently; // if the default were 100 every published latency would be 100x wrong. - EXPECT_EQ(Registry::scaledMean(360, 8), Registry::scaledMean(360, 8, 1)); + // 360/8 is 45 by hand -- an independent literal, not a restatement of the + // implementation. A default of 100 would read 4500 here. EXPECT_EQ(Registry::scaledMean(360, 8), 45); } diff --git a/src/tests/libxrpl/telemetry/NodeStoreMetricNames.cpp b/src/tests/libxrpl/telemetry/NodeStoreMetricNames.cpp index 0c558ef252..22f1bebeb6 100644 --- a/src/tests/libxrpl/telemetry/NodeStoreMetricNames.cpp +++ b/src/tests/libxrpl/telemetry/NodeStoreMetricNames.cpp @@ -25,9 +25,26 @@ * into this binary on the no-op path (see src/tests/libxrpl/CMakeLists.txt). * What is testable here is everything that decides *what* gets recorded: the * instrument name, the two label values, the negative-value guard, and the - * bucket ladder the value is filed into. The remaining step -- that - * Database::fetchNodeObject actually reaches onFetch -- is covered by the - * existing nodestore suites, which already exercise that call path. + * bucket ladder the value is filed into. + * + * KNOWN GAP, stated plainly. Two separate steps remain unverified by any test: + * + * - That NodeStoreScheduler::onFetch() calls the histogram macro at all, with + * report.elapsed.count() and those two labels. `NodeStoreScheduler` appears + * in exactly one test file, src/test/app/SHAMapStore_test.cpp, and only as a + * construction site that asserts nothing about onFetch. The nodestore + * suites use DummyScheduler or a test-local CapturingScheduler, neither of + * which is NodeStoreScheduler, so they do NOT cover this call path. + * - That the recorded value has sub-millisecond resolution end to end. That + * half IS covered, in src/tests/libxrpl/nodestore/Database.cpp's + * sub_millisecond_fetch_latency_is_reported, which drives a real store + * through a capturing Scheduler and asserts the reported microsecond total + * equals the nodestore's own accumulator exactly. + * + * Closing the first gap needs an integration test under src/test/ with a live + * jtx::Env and an in-memory metric reader attached to the running + * MetricsRegistry; that is larger than this file's scope and is deliberately + * deferred rather than claimed. */ #include @@ -84,7 +101,6 @@ TEST(NodeStoreMetricNames, instrument_name_is_the_exact_shared_literal) // dashboard query and the reference doc must change with it, so the exact // string is asserted rather than merely its shape. EXPECT_EQ(std::string_view{kNodeStoreReadUs}, "nodestore_read_us"); - EXPECT_EQ(std::string_view{kNodeStoreReadUs}.size(), 17u); // No `xrpld_` prefix: verified against the live metric surface, where 0 of // 537 exported names carry one. A prefix here would make this the only @@ -160,10 +176,6 @@ TEST(NodeStoreMetricNames, latency_guard_admits_zero_and_refuses_negatives) EXPECT_TRUE(shouldRecordFetchLatency(9)); EXPECT_TRUE(shouldRecordFetchLatency(250)); EXPECT_TRUE(shouldRecordFetchLatency(30'000)); - - // The boundary is exactly at zero, not near it. - EXPECT_TRUE(shouldRecordFetchLatency(0)); - EXPECT_FALSE(shouldRecordFetchLatency(-1)); } // --------------------------------------------------------------------------- diff --git a/src/xrpld/telemetry/MetricsRegistry.h b/src/xrpld/telemetry/MetricsRegistry.h index d6dab25e12..6c10cdafc6 100644 --- a/src/xrpld/telemetry/MetricsRegistry.h +++ b/src/xrpld/telemetry/MetricsRegistry.h @@ -50,7 +50,7 @@ * +-- CountedObject counts * +-- Load factor breakdown * +-- NodeStore I/O gauges (totals, derived means, NuDB write queue, - * ledger-acquisition stall counters) + * ledger-acquisition stall counters) * +-- Server info (state, uptime, peers, consensus) * +-- Build info (version label) * +-- Complete ledger ranges (start/end pairs) @@ -612,6 +612,59 @@ public: { return meter_; } + + /** + * Sink handed to the nodestore_state gauge helpers below. + * + * Every value they publish multiplexes onto the single `nodestore_state` + * gauge through its `metric` label, so the helpers need no access to the + * OTel observer result -- just somewhere to put a name and a number. + */ + using ObserveFn = std::function; + + /** + * Observe the NodeStore I/O totals and the means derived from them. + * + * @param db NodeStore to read the counters from. + * @param observe Sink for one `metric`-labelled value. + */ + static void + observeNodeStoreTotals(node_store::Database& db, ObserveFn const& observe); + + /** + * Observe the backend write-path detail, when the backend measures it. + * + * Publishes nothing for a backend whose getWriteStats() is std::nullopt, + * which is every backend except NuDB. Absent labels let a reader tell + * "not measured" from "measured, and idle"; zeros would read as a + * perfectly idle write path. + * + * @param db NodeStore whose writable backend is sampled. + * @param observe Sink for one `metric`-labelled value. + */ + static void + observeWritePathDetail(node_store::Database const& db, ObserveFn const& observe); + + /** + * Observe the ledger-acquisition progress and stall counters. + * + * @param stats Process-wide acquisition counters. + * @param observe Sink for one `metric`-labelled value. + */ + static void + observeAcquireStats(AcquireStats const& stats, ObserveFn const& observe); + + /** + * Observe the read queue depth and the read thread-pool counts. + * + * These four have no accessor on Database, so its JSON counters object + * is still the only way to reach them. + * + * @param db NodeStore to read the JSON counters from. + * @param observe Sink for one `metric`-labelled value. + */ + static void + observeReadQueue(node_store::Database& db, ObserveFn const& observe); #endif private: @@ -894,60 +947,11 @@ private: void registerNodeStoreGauge(); // Task 9.1 - /** - * Sink handed to the registerNodeStoreGauge() helpers below. - * - * Every value they publish multiplexes onto the single `nodestore_state` - * gauge through its `metric` label, so the helpers need no access to the - * OTel observer result -- just somewhere to put a name and a number. - * That also makes each helper directly unit-testable by passing a - * recording sink, which the real observer result is not. - */ - using ObserveFn = std::function; + // The four nodestore_state helpers and their ObserveFn sink are public + // (above), so a test can drive each one with a recording sink and assert + // the exact `metric` label values it publishes. They read only their + // arguments, so exposing them widens no state. - /** - * Observe the NodeStore I/O totals and the means derived from them. - * - * @param db NodeStore to read the counters from. - * @param observe Sink for one `metric`-labelled value. - */ - static void - observeNodeStoreTotals(node_store::Database& db, ObserveFn const& observe); - - /** - * Observe the backend write-path detail, when the backend measures it. - * - * Publishes nothing for a backend whose getWriteStats() is std::nullopt, - * which is every backend except NuDB. Absent labels let a reader tell - * "not measured" from "measured, and idle"; zeros would read as a - * perfectly idle write path. - * - * @param db NodeStore whose writable backend is sampled. - * @param observe Sink for one `metric`-labelled value. - */ - static void - observeWritePathDetail(node_store::Database const& db, ObserveFn const& observe); - - /** - * Observe the ledger-acquisition progress and stall counters. - * - * @param stats Process-wide acquisition counters. - * @param observe Sink for one `metric`-labelled value. - */ - static void - observeAcquireStats(AcquireStats const& stats, ObserveFn const& observe); - - /** - * Observe the read queue depth and the read thread-pool counts. - * - * These four have no accessor on Database, so its JSON counters object - * is still the only way to reach them. - * - * @param db NodeStore to read the JSON counters from. - * @param observe Sink for one `metric`-labelled value. - */ - static void - observeReadQueue(node_store::Database& db, ObserveFn const& observe); void registerServerInfoGauge(); // Task 9.7a void From 7aa41e3dfd2519196b1abcc84b72a1e15806bb85 Mon Sep 17 00:00:00 2001 From: Pratik Mankawde <3397372+pratikmankawde@users.noreply.github.com> Date: Tue, 28 Jul 2026 16:24:16 +0100 Subject: [PATCH 3/4] fix(telemetry): show intermediate sync states on Ledger Data & Sync The Sync State panel only ever showed Connected and Full. Two causes: 1. state_tracking{metric="state_value"} is emitted with values 0-6, where 5 is FULL+validating and 6 is FULL+proposing, but the panel declared max: 4 with value mappings for 0-4 only. Values above 4 were pinned to the axis ceiling and rendered unmapped. Most nodes sit at 6, so the majority of series were clipped. 2. The gauge samples the instantaneous mode on a 10s export tick, so states shorter than one tick fall between samples. A real sync showed SYNCING for a single scrape and skipped TRACKING entirely. This is the sampling hazard already noted on StateAccounting in NetworkOPs.h. Extend the panel domain to 0-6 with Validating and Proposing mappings and matching threshold steps, and add a colour-coded state-timeline panel where each band's width is the time spent in that state, so brief states appear as thin slivers rather than disappearing. The timeline reads server_info{metric="server_state"} (raw OperatingMode 0-4) rather than state_value, which folds 5 and 6 onto FULL and would split one Full band into three colours. Panel layout below the insertion point shifts down by 6 rows. Note this makes short states legible, not lossless: exporting StateAccounting's per-state duration accumulators is the sampling-immune fix and is left as follow-up. Co-Authored-By: Claude Opus 5 (1M context) --- .../grafana/dashboards/ledger-data-sync.json | 248 +++++++++++++----- 1 file changed, 189 insertions(+), 59 deletions(-) diff --git a/docker/telemetry/grafana/dashboards/ledger-data-sync.json b/docker/telemetry/grafana/dashboards/ledger-data-sync.json index bfeef82e78..c3bf316903 100644 --- a/docker/telemetry/grafana/dashboards/ledger-data-sync.json +++ b/docker/telemetry/grafana/dashboards/ledger-data-sync.json @@ -800,7 +800,7 @@ }, { "title": "Sync State", - "description": "###### What this is:\n*Current server operating state as a numeric code: 0 disconnected, 1 connected, 2 syncing, 3 tracking, 4 full. A healthy synced node sits at 4.*\n\n###### How it's computed:\n*state_tracking{metric=\"state_value\"} (gauge). Companion time_in_current_state_seconds shows how long it has been stuck there.*\n\n###### Reading it:\n*Flat at 4 = full/healthy. Dropping to 1-2 and staying = the node fell out of sync and is re-acquiring (the primary red flag this row explains).*\n\n###### Healthy range:\n*4 (full), briefly 2-3 right after restart.*\n\n###### Watch for:\n*A node stuck below 4 for more than a few minutes, or oscillating - read the lower panels for the cause.*\n\n###### Source:\n[app/misc/NetworkOPs.cpp](https://github.com/XRPLF/rippled/blob/develop/src/xrpld/app/misc/NetworkOPs.cpp)\n\n###### Function:\n`NetworkOPsImp::setMode`", + "description": "###### What this is:\n*Current server operating state as a numeric code: 0 disconnected, 1 connected, 2 syncing, 3 tracking, 4 full, 5 validating, 6 proposing. A healthy validator sits at 6, a healthy non-validating node at 4.*\n\n###### How it's computed:\n*state_tracking{metric=\"state_value\"} (gauge). Companion time_in_current_state_seconds shows how long it has been stuck there.*\n\n###### Reading it:\n*Flat at 4-6 = full/healthy. Dropping to 1-2 and staying = the node fell out of sync and is re-acquiring (the primary red flag this row explains).*\n\n###### Healthy range:\n*4-6 steady, briefly 2-3 right after restart.*\n\n###### Watch for:\n*A node stuck below 4 for more than a few minutes, or oscillating - read the lower panels for the cause.*\n\n###### Source:\n[app/misc/NetworkOPs.cpp](https://github.com/XRPLF/rippled/blob/develop/src/xrpld/app/misc/NetworkOPs.cpp)\n\n###### Function:\n`NetworkOPsImp::setMode`", "type": "timeseries", "gridPos": { "h": 8, @@ -835,6 +835,185 @@ "showPoints": "auto", "pointSize": 3 }, + "mappings": [ + { + "type": "value", + "options": { + "0": { + "text": "Disconnected", + "color": "red", + "index": 0 + }, + "1": { + "text": "Connected", + "color": "orange", + "index": 1 + }, + "2": { + "text": "Syncing", + "color": "yellow", + "index": 2 + }, + "3": { + "text": "Tracking", + "color": "blue", + "index": 3 + }, + "4": { + "text": "Full", + "color": "green", + "index": 4 + }, + "5": { + "text": "Validating", + "color": "super-light-green", + "index": 5 + }, + "6": { + "text": "Proposing", + "color": "dark-green", + "index": 6 + } + } + } + ], + "thresholds": { + "mode": "absolute", + "steps": [ + { + "color": "red", + "value": null + }, + { + "color": "orange", + "value": 1 + }, + { + "color": "yellow", + "value": 2 + }, + { + "color": "blue", + "value": 3 + }, + { + "color": "green", + "value": 4 + }, + { + "color": "super-light-green", + "value": 5 + }, + { + "color": "dark-green", + "value": 6 + } + ] + }, + "color": { + "mode": "thresholds" + }, + "min": 0, + "max": 6 + }, + "overrides": [] + }, + "id": 17 + }, + { + "title": "Validated Ledger Age", + "description": "###### What this is:\n*Seconds since this node last had a freshly validated ledger. The single clearest 'am I keeping up with the network' signal.*\n\n###### How it's computed:\n*ledgermaster_validated_ledger_age gauge (seconds), per node.*\n\n###### Reading it:\n*Should hover at the network close interval (~3-5s). A rising sawtooth or a high plateau means the node is falling behind or not validating.*\n\n###### Healthy range:\n*<= ~6s on a synced node.*\n\n###### Watch for:\n*Sustained climb above ~15s, or a monotonic ramp = the node is not keeping up; correlate with job-queue wait and NuDB read latency below.*\n\n###### Source:\n[app/ledger/LedgerMaster.cpp](https://github.com/XRPLF/rippled/blob/develop/src/xrpld/app/ledger/detail/LedgerMaster.cpp)\n\n###### Function:\n`LedgerMaster::getValidatedLedgerAge`", + "type": "timeseries", + "gridPos": { + "h": 8, + "w": 12, + "x": 12, + "y": 75 + }, + "options": { + "tooltip": { + "maxHeight": 600, + "mode": "multi", + "sort": "desc" + } + }, + "targets": [ + { + "datasource": { + "type": "prometheus", + "uid": "${DS_PROMETHEUS}" + }, + "expr": "label_replace(label_join(label_replace(ledgermaster_validated_ledger_age{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\"}, \"series\", \"Validated Age\", \"\", \"\"), \"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(ledgermaster_published_ledger_age{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\"}, \"series\", \"Published Age\", \"\", \"\"), \"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": "s", + "custom": { + "axisLabel": "Age (seconds)", + "spanNulls": 1800000, + "insertNulls": false, + "showPoints": "auto", + "pointSize": 3 + } + }, + "overrides": [] + }, + "id": 18 + }, + { + "title": "Time Spent Per State", + "description": "###### What this is:\n*Operating mode as a colour-coded timeline. Each band's width is the time spent in that state, so short-lived states show as thin slivers instead of vanishing.*\n\n###### How it's computed:\n*server_info{metric=\"server_state\"} (gauge), the raw OperatingMode 0-4. Uses server_state rather than state_value because state_value folds 5 and 6 onto FULL, which would split one Full band into three colours.*\n\n###### Reading it:\n*One green band across the window = healthy. Red/orange/yellow bands show when and for how long the node was degraded.*\n\n###### Healthy range:\n*Continuously green (Full), brief orange/yellow/blue only after a restart.*\n\n###### Watch for:\n*Repeated thin bands = the node is oscillating. This is sampled every 10s, so a state shorter than one sample can still be missed.*\n\n###### Source:\n[app/misc/NetworkOPs.cpp](https://github.com/XRPLF/rippled/blob/develop/src/xrpld/app/misc/NetworkOPs.cpp)\n\n###### Function:\n`NetworkOPsImp::setMode`", + "type": "state-timeline", + "gridPos": { + "h": 6, + "w": 24, + "x": 0, + "y": 83 + }, + "options": { + "mergeValues": true, + "showValue": "auto", + "alignValue": "left", + "rowHeight": 0.9, + "tooltip": { + "mode": "single", + "sort": "none" + }, + "legend": { + "displayMode": "list", + "placement": "bottom", + "showLegend": true + } + }, + "targets": [ + { + "datasource": { + "type": "prometheus", + "uid": "${DS_PROMETHEUS}" + }, + "expr": "label_replace(label_join(server_info{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=\"server_state\"}, \"xrpl_ident\", \", \", \"service_instance_id\", \"xrpl_branch\", \"xrpl_work_item\"), \"xrpl_ident\", \"[$1]\", \"xrpl_ident\", \"(?:, )*(.*[^, ])(?:, )*\")", + "refId": "A" + } + ], + "fieldConfig": { + "defaults": { + "displayName": "State ${__field.labels.xrpl_ident}", + "unit": "none", + "custom": { + "fillOpacity": 80, + "lineWidth": 0, + "insertNulls": false, + "spanNulls": false + }, "mappings": [ { "type": "value", @@ -900,56 +1079,7 @@ }, "overrides": [] }, - "id": 17 - }, - { - "title": "Validated Ledger Age", - "description": "###### What this is:\n*Seconds since this node last had a freshly validated ledger. The single clearest 'am I keeping up with the network' signal.*\n\n###### How it's computed:\n*ledgermaster_validated_ledger_age gauge (seconds), per node.*\n\n###### Reading it:\n*Should hover at the network close interval (~3-5s). A rising sawtooth or a high plateau means the node is falling behind or not validating.*\n\n###### Healthy range:\n*<= ~6s on a synced node.*\n\n###### Watch for:\n*Sustained climb above ~15s, or a monotonic ramp = the node is not keeping up; correlate with job-queue wait and NuDB read latency below.*\n\n###### Source:\n[app/ledger/LedgerMaster.cpp](https://github.com/XRPLF/rippled/blob/develop/src/xrpld/app/ledger/detail/LedgerMaster.cpp)\n\n###### Function:\n`LedgerMaster::getValidatedLedgerAge`", - "type": "timeseries", - "gridPos": { - "h": 8, - "w": 12, - "x": 12, - "y": 75 - }, - "options": { - "tooltip": { - "maxHeight": 600, - "mode": "multi", - "sort": "desc" - } - }, - "targets": [ - { - "datasource": { - "type": "prometheus", - "uid": "${DS_PROMETHEUS}" - }, - "expr": "label_replace(label_join(label_replace(ledgermaster_validated_ledger_age{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\"}, \"series\", \"Validated Age\", \"\", \"\"), \"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(ledgermaster_published_ledger_age{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\"}, \"series\", \"Published Age\", \"\", \"\"), \"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": "s", - "custom": { - "axisLabel": "Age (seconds)", - "spanNulls": 1800000, - "insertNulls": false, - "showPoints": "auto", - "pointSize": 3 - } - }, - "overrides": [] - }, - "id": 18 + "id": 27 }, { "title": "Ledger Close Rate", @@ -959,7 +1089,7 @@ "h": 8, "w": 12, "x": 0, - "y": 83 + "y": 89 }, "options": { "tooltip": { @@ -1008,7 +1138,7 @@ "h": 8, "w": 12, "x": 12, - "y": 83 + "y": 89 }, "options": { "tooltip": { @@ -1085,7 +1215,7 @@ "h": 8, "w": 12, "x": 0, - "y": 91 + "y": 97 }, "options": { "tooltip": { @@ -1127,7 +1257,7 @@ "h": 8, "w": 12, "x": 12, - "y": 91 + "y": 97 }, "options": { "tooltip": { @@ -1169,7 +1299,7 @@ "h": 8, "w": 12, "x": 0, - "y": 99 + "y": 105 }, "options": { "tooltip": { @@ -1211,7 +1341,7 @@ "h": 8, "w": 12, "x": 12, - "y": 99 + "y": 105 }, "options": { "tooltip": { @@ -1267,7 +1397,7 @@ "h": 8, "w": 12, "x": 0, - "y": 107 + "y": 113 }, "options": { "tooltip": { @@ -1309,7 +1439,7 @@ "h": 8, "w": 12, "x": 12, - "y": 107 + "y": 113 }, "options": { "tooltip": { From 0a22a512bbc21e31dfe082411764f60aa7116160 Mon Sep 17 00:00:00 2001 From: Pratik Mankawde <3397372+pratikmankawde@users.noreply.github.com> Date: Tue, 28 Jul 2026 16:24:35 +0100 Subject: [PATCH 4/4] Revert the nodestore read-latency histogram Drops nodestore_read_us and everything added to reach it. read_mean_us already carries microsecond precision and separated the two sync failure modes cleanly in live testing -- 8.8 us on a clean store against a 223 us cold-store peak -- so the distribution added no signal that changed a diagnosis. The cost of getting it was disproportionate. NodeStoreScheduler had no path to the metrics registry, so its production constructor grew a ServiceRegistry parameter: a metric addition changing a production signature. That in turn forced an edit to a pre-existing test, src/test/app/SHAMapStore_test.cpp, whose only stake in this is that it constructs a scheduler. Worse, the scheduler is built in Application's member initializer list, long before metricsRegistry_ exists, so the registry could not be captured once and had to be re-resolved on every fetch -- a lookup on a path that runs millions of times per sync. The constructor returns to taking JobQueue& alone and SHAMapStore_test.cpp returns to the single-argument call, leaving that file differing from its pre-change form only by the NodeStore:: to node_store:: rename it picked up from develop. FetchReport::elapsed stays microseconds and onFetch keeps its explicit duration_cast to milliseconds for addLoadEvents, which takes milliseconds. That widening was a separate fix and is what makes read latency measurable at all. kSubMillisecondBoundaries loses its only consumer and regains [[maybe_unused]], which is the state the commit that introduced it left it in; without the attribute an unused constant is an error under wextra with werr. Also removes the ledger-data-sync panel that charted the histogram and the fetch_type and found template variables, which filtered on labels no metric emits any more, plus the runbook and reference-doc sections and the two instrument and view counts that named it. Co-Authored-By: Claude Opus 5 (1M context) --- .../09-data-collection-reference.md | 73 +-- .../grafana/dashboards/ledger-data-sync.json | 124 ---- docs/telemetry-runbook.md | 32 +- include/xrpl/telemetry/NodeStoreMetricNames.h | 199 ------- src/test/app/SHAMapStore_test.cpp | 2 +- src/tests/libxrpl/CMakeLists.txt | 12 - .../telemetry/NodeStoreMetricNames.cpp | 538 ------------------ src/xrpld/app/main/Application.cpp | 6 +- src/xrpld/app/main/NodeStoreScheduler.cpp | 44 +- src/xrpld/app/main/NodeStoreScheduler.h | 61 +- src/xrpld/telemetry/MetricsRegistry.cpp | 32 +- 11 files changed, 30 insertions(+), 1093 deletions(-) delete mode 100644 include/xrpl/telemetry/NodeStoreMetricNames.h delete mode 100644 src/tests/libxrpl/telemetry/NodeStoreMetricNames.cpp diff --git a/OpenTelemetryPlan/09-data-collection-reference.md b/OpenTelemetryPlan/09-data-collection-reference.md index 3a05e4cf35..086a8e21d8 100644 --- a/OpenTelemetryPlan/09-data-collection-reference.md +++ b/OpenTelemetryPlan/09-data-collection-reference.md @@ -1004,12 +1004,9 @@ repeated here: `_running` / `_deferred`). These travel the `beast::insight` pipeline, not the OTel SDK one, so they are documented in [§2.5](#25-per-job-type-queue-gauges). -- The sync-diagnosis signals — 13 further `nodestore_state` label values 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). +- The sync-diagnosis signals — 13 further `nodestore_state` label values — 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) @@ -1044,7 +1041,7 @@ Phase 10 builds a 5-node validator docker-compose harness with RPC load generato | Span attributes | 22 | Per-span attribute assertion | | Legacy `*` families | ~270 (≈224 traffic) | Prometheus `__name__` query | | Native MetricsRegistry | 35 instruments | Prometheus query | -| Call-site `XRPL_METRIC_*` | 8 instruments | Prometheus query | +| Call-site `XRPL_METRIC_*` | 7 instruments | Prometheus query | | Per-job-type gauges | 105 (35 types × 3) | Prometheus `__name__` query | | SpanMetrics RED | 4 per span | Prometheus query | | Grafana dashboards | 10 | Dashboard API "no data" check | @@ -1052,11 +1049,10 @@ Phase 10 builds a 5-node validator docker-compose harness with RPC load generato The two added rows are the families that do not originate as `MetricsRegistry` members. **Call-site** instruments are declared by the `XRPL_METRIC_*` macros -(8 distinct names: `rpc_in_flight_requests`, `ledgers_closed_total`, -`nodestore_read_us`, and the five `getobject_*`). Two of those eight are -workload-gated in a way that makes a zero reading uninformative: -`getobject_rejected_total` needs a non-conforming request, and the `getobject_*` -family as a whole needs an inbound +(7 distinct names: `rpc_in_flight_requests`, `ledgers_closed_total`, and the +five `getobject_*`). Two of those seven are workload-gated in a way that makes a +zero reading uninformative: `getobject_rejected_total` needs a non-conforming +request, and the `getobject_*` family as a whole needs an inbound `TMGetObjectByHash`. **Per-job-type gauges** are the `beast::insight` families from [§2.5](#25-per-job-type-queue-gauges); all 105 should be present on any running node, but `_deferred` reads zero unless a capped type is actually @@ -1218,43 +1214,6 @@ 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`. -#### 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. It is the seventh registered view; the other six are -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 | @@ -1371,9 +1330,9 @@ information the batch totals do not already carry. **All three histograms need an explicit bucket view.** The SDK's default histogram boundaries top out at 10000. Every one of these three exceeds that, so -without a view their top quantiles would all read as a flat 10000. Seven views are -registered in `src/xrpld/telemetry/MetricsRegistry.cpp:293-327`, and three of the -seven are for this family: +without a view their top quantiles would all read as a flat 10000. Six views are +registered in `src/xrpld/telemetry/MetricsRegistry.cpp`, and three of the six are +for this family: | Instrument | View helper | Boundaries | | --------------------------- | ------------------------------- | ------------------------------------------------------ | @@ -1381,10 +1340,9 @@ seven are for this family: | `getobject_request_objects` | `addHistogramView()`, own set | `1, 2, 4, 8, 16, 64, 256, 1024, 4096, 12288` | | `getobject_charge` | `addHistogramView()`, own set | `0, 100, 500, 1000, 5000, 10000, 25000, 50000, 100000` | -The other four views are `addMicrosecondHistogramView()` on `job_queued_us`, -`job_running_us` and `rpc_method_us`, plus `addSubMillisecondHistogramView()` on -`nodestore_read_us` — four µs-ladder views and one sub-millisecond ladder, on top -of these two custom sets. +The other three views are `addMicrosecondHistogramView()` on `job_queued_us`, +`job_running_us`, and `rpc_method_us` — four µs-ladder views plus these two +custom sets. **Why the latter two do not use the µs ladder.** They are not durations. The µs ladder's buckets are chosen for time (sub-millisecond jobs through multi-second @@ -1493,9 +1451,6 @@ increase(nodestore_state{metric="acquire_deferrals", service_instance_id=~"$node # Livelock fingerprint, second half: timeouts staying flat while the above climbs increase(nodestore_state{metric="acquire_timeouts", service_instance_id=~"$node"}[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{service_instance_id=~"$node"}[5m]))) ``` > **Diagnostic procedure.** These signals exist to answer one question — why a diff --git a/docker/telemetry/grafana/dashboards/ledger-data-sync.json b/docker/telemetry/grafana/dashboards/ledger-data-sync.json index 8d27906799..64549b49ee 100644 --- a/docker/telemetry/grafana/dashboards/ledger-data-sync.json +++ b/docker/telemetry/grafana/dashboards/ledger-data-sync.json @@ -1813,90 +1813,6 @@ "overrides": [] }, "id": 36 - }, - { - "title": "NodeStore Read Latency Distribution By Fetch Type & Found", - "description": "###### What this is:\n*Per-fetch nodestore read latency as a distribution rather than a mean, split by whether the fetch was a read-ahead or a blocking one and by whether the object was found. A mean cannot tell \"every read took 9 microseconds\" apart from \"most took 2 and a few took 900\", and the second is the cold-store shape. The split matters because a slow async fetch only delays prefetch while a slow sync fetch blocks a caller outright, and because a miss can cost a read of every backend.*\n\n###### How it's computed:\n*p50, p95 and p99 from histogram_quantile over rate(nodestore_read_us_bucket[$__rate_interval]), grouped by fetch_type and found. The instrument carries explicit sub-millisecond bucket boundaries starting at 1 microsecond, because the default ladder's lowest edge sits above the entire warm-read range and would make every warm read land in bucket zero.*\n\n###### Reading it:\n*Use the Fetch Type and Found template filters at the top of the dashboard to isolate a dimension. sync + found is the series that maps most directly to caller-visible stall time. A p99 that pulls away from p50 while p50 stays low is the cold-read signature the mean-based panels can only hint at: most reads are cached and a minority are paying full disk latency. found=false rising in absolute terms points at working-set misses rather than at cold cache.*\n\n###### Healthy range:\n*p99 within a small multiple of p50, both in the single-digit-to-low-tens of microseconds warm.*\n\n###### Watch for:\n*p99 above roughly 100 microseconds on the sync + found series while the hit ratio stays high -- objects are present but every access reaches disk. Note this instrument is separate from the read_mean_us gauge on the first panel of this row; if the histogram is empty but the gauge is populated, the exporter on that build predates the histogram and only the mean-based panels apply.*\n\n###### Source:\n[app/main/NodeStoreScheduler.cpp](https://github.com/XRPLF/rippled/blob/develop/src/xrpld/app/main/NodeStoreScheduler.cpp)\n\n###### Function:\n`NodeStoreScheduler::onFetch`", - "type": "timeseries", - "gridPos": { - "h": 8, - "w": 24, - "x": 0, - "y": 149 - }, - "options": { - "tooltip": { - "maxHeight": 600, - "mode": "multi", - "sort": "desc" - }, - "legend": { - "displayMode": "table", - "placement": "right", - "calcs": ["mean", "max"] - } - }, - "targets": [ - { - "datasource": { - "type": "prometheus", - "uid": "${DS_PROMETHEUS}" - }, - "expr": "label_replace(label_join(label_replace(label_join(histogram_quantile(0.5, sum by (le, fetch_type, found, service_instance_id, xrpl_branch, xrpl_node_role) (rate(nodestore_read_us_bucket{fetch_type=~\"$fetch_type\", found=~\"$found\", service_instance_id=~\"$node\", deployment_environment=~\"$deployment_environment\", xrpl_network_type=~\"$xrpl_network_type\", service_name=~\"$service_name\", xrpl_work_item=~\"$xrpl_work_item\", xrpl_branch=~\"$xrpl_branch\", xrpl_node_role=~\"$xrpl_node_role\"}[$__rate_interval]))), \"read_dims\", \"-\", \"fetch_type\", \"found\"), \"series\", \"Read p50 [$1]\", \"read_dims\", \"(.*)\"), \"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(label_join(histogram_quantile(0.95, sum by (le, fetch_type, found, service_instance_id, xrpl_branch, xrpl_node_role) (rate(nodestore_read_us_bucket{fetch_type=~\"$fetch_type\", found=~\"$found\", service_instance_id=~\"$node\", deployment_environment=~\"$deployment_environment\", xrpl_network_type=~\"$xrpl_network_type\", service_name=~\"$service_name\", xrpl_work_item=~\"$xrpl_work_item\", xrpl_branch=~\"$xrpl_branch\", xrpl_node_role=~\"$xrpl_node_role\"}[$__rate_interval]))), \"read_dims\", \"-\", \"fetch_type\", \"found\"), \"series\", \"Read p95 [$1]\", \"read_dims\", \"(.*)\"), \"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(label_join(histogram_quantile(0.99, sum by (le, fetch_type, found, service_instance_id, xrpl_branch, xrpl_node_role) (rate(nodestore_read_us_bucket{fetch_type=~\"$fetch_type\", found=~\"$found\", service_instance_id=~\"$node\", deployment_environment=~\"$deployment_environment\", xrpl_network_type=~\"$xrpl_network_type\", service_name=~\"$service_name\", xrpl_work_item=~\"$xrpl_work_item\", xrpl_branch=~\"$xrpl_branch\", xrpl_node_role=~\"$xrpl_node_role\"}[$__rate_interval]))), \"read_dims\", \"-\", \"fetch_type\", \"found\"), \"series\", \"Read p99 [$1]\", \"read_dims\", \"(.*)\"), \"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": "\u00b5s", - "thresholds": { - "steps": [ - { - "color": "green", - "value": null - }, - { - "color": "yellow", - "value": 10 - }, - { - "color": "red", - "value": 100 - } - ] - }, - "custom": { - "axisLabel": "Read Latency (\u00b5s)", - "scaleDistribution": { - "type": "log", - "log": 10 - }, - "thresholdsStyle": { - "mode": "line" - }, - "spanNulls": 1800000, - "insertNulls": false, - "showPoints": "auto", - "pointSize": 3 - } - }, - "overrides": [] - }, - "id": 37 } ], "schemaVersion": 39, @@ -2062,46 +1978,6 @@ "multi": true, "refresh": 2, "sort": 1 - }, - { - "name": "fetch_type", - "label": "Fetch Type", - "description": "Filter nodestore read latency by fetch kind (async read-ahead / sync blocking)", - "type": "query", - "query": "label_values(nodestore_read_us_bucket, fetch_type)", - "datasource": { - "type": "prometheus", - "uid": "prometheus" - }, - "includeAll": true, - "allValue": ".*", - "current": { - "text": "All", - "value": "$__all" - }, - "multi": true, - "refresh": 2, - "sort": 1 - }, - { - "name": "found", - "label": "Found", - "description": "Filter nodestore read latency by whether the fetch found the object", - "type": "query", - "query": "label_values(nodestore_read_us_bucket, found)", - "datasource": { - "type": "prometheus", - "uid": "prometheus" - }, - "includeAll": true, - "allValue": ".*", - "current": { - "text": "All", - "value": "$__all" - }, - "multi": true, - "refresh": 2, - "sort": 1 } ] }, diff --git a/docs/telemetry-runbook.md b/docs/telemetry-runbook.md index a97fda2a68..67d4eaa26a 100644 --- a/docs/telemetry-runbook.md +++ b/docs/telemetry-runbook.md @@ -746,23 +746,6 @@ label values rather than reporting them as zero. 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 | @@ -1612,9 +1595,8 @@ Answer two questions, in this order. Neither one alone is a diagnosis. - Under ~10 µs: reads are **cheap**. Both a clean store and a healthy populated store land here. - Over ~20 µs: reads are **expensive**. -- Between the two: break the tie on the tail. Take either - `max_over_time` of `read_mean_us` across the window, or the `nodestore_read_us` - p99 where that histogram is available. Over ~100 µs counts as expensive; +- Between the two: break the tie on the tail. Take `max_over_time` of + `read_mean_us` across the window. Over ~100 µs counts as expensive; otherwise treat it as cheap. There is no read-max gauge — `nudb_insert_max_us` is a **write** signal and does not answer this. @@ -1680,9 +1662,6 @@ 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]) - -# 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 @@ -1690,10 +1669,9 @@ histogram_quantile(0.99, sum by (le, fetch_type, found) (rate(nodestore_read_us_ **Provenance.** The two columns below are our own measurements: node2 on the AWS dev box, build `e3c2f8279a`, 2026-07-27/28, same host and same binary for both runs, differing only in the state of the store. Use them as the shape to compare -against, not as thresholds. `nodestore_read_us` was not on the measurement binary, -so the read figures below come from the `read_mean_us` gauge; the "highest sample" -row is the largest value that gauge reached over the run, not a read-latency -percentile. The third dataset in this section — the 25-minute devnet stall and its +against, not as thresholds. The read figures below come from the `read_mean_us` +gauge, the only read-latency signal exported; the "highest sample" row is the +largest value that gauge reached over the run, not a read-latency percentile. The third dataset in this section — the 25-minute devnet stall and its healthy peer — is **not** ours; it comes from an incident report supplied to this project and is kept separate for that reason. diff --git a/include/xrpl/telemetry/NodeStoreMetricNames.h b/include/xrpl/telemetry/NodeStoreMetricNames.h deleted file mode 100644 index 6c98f0f47e..0000000000 --- a/include/xrpl/telemetry/NodeStoreMetricNames.h +++ /dev/null @@ -1,199 +0,0 @@ -#pragma once - -// cspell:ignore ISTOGRAM -// The all-caps macro name XRPL_METRIC_HISTOGRAM_RECORD trips cspell's -// compound-word splitter, which emits the subword "ISTOGRAM"; ignore it here. - -/** - * Metric name, description, label key and label values for the per-fetch - * NodeStore read-latency histogram. - * - * The name is referenced from two translation units in two different - * levelization modules, which is why these constants live in a header rather - * than in either unit's unnamed namespace: - * - * NodeStoreMetricNames.h - * | - * +--> NodeStoreScheduler.cpp (xrpld.app -- the record site, via - * | XRPL_METRIC_HISTOGRAM_RECORD_LABELED) - * | - * +--> MetricsRegistry.cpp (xrpld.telemetry -- registers the - * explicit sub-millisecond bucket - * boundaries for the same name) - * - * A copy-pasted literal would let the two drift, and a drifted name silently - * drops the bucket override: the histogram would fall back to the SDK default - * boundaries, whose lowest edge is far above the single-digit-microsecond - * range a warm read occupies, so every warm read would land in bucket 0 and - * the distribution would read as flat. This mirrors the reason - * GetObjectMetricNames.h exists for the `getobject_*` family. - * - * Placed under `include/xrpl/telemetry/` for the same levelization reason as - * GetObjectMetricNames.h: `xrpld.app > xrpl.telemetry` and - * `xrpld.telemetry > xrpl.telemetry` are both existing edges (see - * `.github/scripts/levelization/results/ordering.txt`), so `include/xrpl/` is - * the one level both consumers can already reach. Both sites include this file - * as ``. - * - * Example usage -- registering the bucket view (MetricsRegistry.cpp): - * @code - * addHistogramView( - * *views, - * kNodeStoreReadUs, - * {kSubMillisecondBoundaries.begin(), kSubMillisecondBoundaries.end()}); - * @endcode - * - * Example usage -- edge case: the record site labels one instrument with two - * independent dimensions, which is why the keys and all four values are - * constants rather than literals (a misspelling on either side would create a - * second, silently disjoint series): - * @code - * XRPL_METRIC_HISTOGRAM_RECORD_LABELED( - * app, kNodeStoreReadUs, kNodeStoreReadUsDesc, elapsed.count(), - * {{kFetchTypeLabel, std::string(kFetchTypeAsync)}, - * {kFetchFoundLabel, std::string(kFetchFoundTrue)}}); - * @endcode - * - * @note These are `constexpr char[]`, not `constexpr std::string_view`. The - * OTel C++ API takes `nostd::string_view`, which on this build is OTel's own - * type; it converts from `char const*` and from `std::string` but has no - * converting constructor from `std::string_view`, so a `string_view` constant - * would not compile at the call sites. Same reasoning as - * GetObjectMetricNames.h. - * - * @note Header-only constants with no runtime state, so there is nothing to - * synchronize -- safe to include from any thread context. - */ - -namespace xrpl::telemetry { - -// ===== Metric name and description ========================================== - -/** - * Per-fetch NodeStore backend read latency, in microseconds. - * - * Referenced twice: at the record site in NodeStoreScheduler.cpp, and by the - * sub-millisecond `addHistogramView()` call in MetricsRegistry.cpp. Both must - * use this one constant. - */ -inline constexpr char kNodeStoreReadUs[] = "nodestore_read_us"; - -/** - * Description for kNodeStoreReadUs. - */ -inline constexpr char kNodeStoreReadUsDesc[] = "NodeStore backend fetch latency in microseconds"; - -// ===== Label keys =========================================================== - -/** - * Label key separating an async (read-ahead) fetch from a synchronous one. - * - * The two mean different things: a slow async read delays prefetch, while a - * slow synchronous read blocks a caller outright. Merged into one series they - * cannot be told apart. - */ -inline constexpr char kFetchTypeLabel[] = "fetch_type"; - -/** - * Label key recording whether the fetch found the object. - * - * A miss and a hit have different cost profiles -- a miss can require reading - * every backend -- so mixing them would blur the distribution that matters. - */ -inline constexpr char kFetchFoundLabel[] = "found"; - -// ===== Label values ========================================================= - -/** @{ */ -/** - * kFetchTypeLabel values, one per node_store::FetchType enumerator. - */ -inline constexpr char kFetchTypeAsync[] = "async"; -inline constexpr char kFetchTypeSync[] = "sync"; -/** @} */ - -/** @{ */ -/** - * kFetchFoundLabel values. Spelled out rather than emitted as a bool - * AttributeValue so the exported label text is stable and matches the - * string-valued convention every other label in this codebase follows. - */ -inline constexpr char kFetchFoundTrue[] = "true"; -inline constexpr char kFetchFoundFalse[] = "false"; -/** @} */ - -// ===== Record-site helpers ================================================== - -/** - * Map a fetch's async-ness to its kFetchTypeLabel value. - * - * Takes a bool rather than a node_store::FetchType because this header sits in - * `xrpl.telemetry`, which has no levelization edge to `xrpl.nodestore`. The - * caller does the one-line enum comparison; this function owns the mapping so - * the two label spellings live in exactly one place and are unit-testable. - * - * @param isAsync True for node_store::FetchType::Async. - * @return kFetchTypeAsync when @p isAsync, else kFetchTypeSync. - * - * @note Pure and reentrant: holds no state and performs no I/O. - * - * Example: - * @code - * fetchTypeLabelValue(true); // "async" - * fetchTypeLabelValue(false); // "sync" - * @endcode - */ -[[nodiscard]] constexpr char const* -fetchTypeLabelValue(bool isAsync) noexcept -{ - return isAsync ? kFetchTypeAsync : kFetchTypeSync; -} - -/** - * Map a fetch's hit/miss outcome to its kFetchFoundLabel value. - * - * @param wasFound node_store::FetchReport::wasFound. - * @return kFetchFoundTrue when @p wasFound, else kFetchFoundFalse. - * - * @note Pure and reentrant: holds no state and performs no I/O. - * - * Example: - * @code - * fetchFoundLabelValue(true); // "true" - * fetchFoundLabelValue(false); // "false" - * @endcode - */ -[[nodiscard]] constexpr char const* -fetchFoundLabelValue(bool wasFound) noexcept -{ - return wasFound ? kFetchFoundTrue : kFetchFoundFalse; -} - -/** - * Whether an elapsed microsecond count may be handed to the histogram. - * - * The OTel SDK rejects a negative histogram value and logs a warning on every - * such call, so a clock anomaly on a per-fetch path would turn into a log - * flood. Filtering here drops the bad sample instead. - * - * Zero is recordable: a fetch served from a warm page cache can genuinely - * round to 0 us, and suppressing that would make the fastest reads invisible. - * - * @param elapsedUs Measured fetch duration in microseconds. - * @return True when @p elapsedUs is zero or positive. - * - * @note Pure and reentrant: holds no state and performs no I/O. - * - * Example: - * @code - * shouldRecordFetchLatency(0); // true -- genuinely instant read - * shouldRecordFetchLatency(-1); // false -- clock anomaly, skip - * @endcode - */ -[[nodiscard]] constexpr bool -shouldRecordFetchLatency(long long elapsedUs) noexcept -{ - return elapsedUs >= 0; -} - -} // namespace xrpl::telemetry diff --git a/src/test/app/SHAMapStore_test.cpp b/src/test/app/SHAMapStore_test.cpp index 8c668a51fb..537ee4c177 100644 --- a/src/test/app/SHAMapStore_test.cpp +++ b/src/test/app/SHAMapStore_test.cpp @@ -541,7 +541,7 @@ public: env.app().config().getValueFor(SizedItem::TreeCacheAge, std::nullopt))); } - NodeStoreScheduler scheduler(env.app(), env.app().getJobQueue()); + NodeStoreScheduler scheduler(env.app().getJobQueue()); std::string const writableDb = "write"; std::string const archiveDb = "archive"; diff --git a/src/tests/libxrpl/CMakeLists.txt b/src/tests/libxrpl/CMakeLists.txt index 953bc106dd..3032731a5e 100644 --- a/src/tests/libxrpl/CMakeLists.txt +++ b/src/tests/libxrpl/CMakeLists.txt @@ -98,22 +98,10 @@ if(telemetry) HINTS "${opentelemetry-cpp_PACKAGE_FOLDER_RELEASE}/lib" REQUIRED ) - # The metric side of the in-memory exporter is a SEPARATE archive - # (libopentelemetry_exporter_in_memory_metric.a) with the same - # no-declared-libs problem, so it needs its own find_library. The - # nodestore read-latency histogram tests use it to read exported - # histogram points back and assert per-bucket counts. - find_library( - OTEL_IN_MEMORY_METRIC_EXPORTER_LIB - NAMES opentelemetry_exporter_in_memory_metric - HINTS "${opentelemetry-cpp_PACKAGE_FOLDER_RELEASE}/lib" - REQUIRED - ) target_link_libraries( xrpl_tests PRIVATE "${OTEL_IN_MEMORY_EXPORTER_LIB}" - "${OTEL_IN_MEMORY_METRIC_EXPORTER_LIB}" opentelemetry-cpp::opentelemetry-cpp ) # ValidationTracker lives in src/xrpld/ (not libxrpl), so we compile its diff --git a/src/tests/libxrpl/telemetry/NodeStoreMetricNames.cpp b/src/tests/libxrpl/telemetry/NodeStoreMetricNames.cpp deleted file mode 100644 index 22f1bebeb6..0000000000 --- a/src/tests/libxrpl/telemetry/NodeStoreMetricNames.cpp +++ /dev/null @@ -1,538 +0,0 @@ -/** - * @file NodeStoreMetricNames.cpp - * Unit tests for the nodestore read-latency histogram wiring. - * - * Two independent groups, split by what they can link: - * - * 1. The shared name/label constants and the three record-site helpers from - * ``. Header-only and free of any - * OTel dependency, so these run in **both** builds. That matters: the - * constants are what keeps the bucket-view registration in - * MetricsRegistry.cpp and the record site in NodeStoreScheduler.cpp - * agreeing on one instrument name, and a divergence there silently drops - * the sub-millisecond bucket override. - * - * 2. An end-to-end record-and-read-back over a real SDK MeterProvider fitted - * with the same explicit sub-millisecond boundaries production registers, - * asserting the exact bucket counts a set of known latencies must land in. - * Guarded on XRPL_ENABLE_TELEMETRY because the metrics SDK headers only - * exist in that build. - * - * Why the second group does not drive NodeStoreScheduler directly: that class - * lives in xrpld (`src/xrpld/app/main/`) and its onFetch() needs a live - * JobQueue plus a ServiceRegistry, neither of which the standalone xrpl_tests - * binary can supply -- the same reason MetricsRegistry.cpp is only compiled - * into this binary on the no-op path (see src/tests/libxrpl/CMakeLists.txt). - * What is testable here is everything that decides *what* gets recorded: the - * instrument name, the two label values, the negative-value guard, and the - * bucket ladder the value is filed into. - * - * KNOWN GAP, stated plainly. Two separate steps remain unverified by any test: - * - * - That NodeStoreScheduler::onFetch() calls the histogram macro at all, with - * report.elapsed.count() and those two labels. `NodeStoreScheduler` appears - * in exactly one test file, src/test/app/SHAMapStore_test.cpp, and only as a - * construction site that asserts nothing about onFetch. The nodestore - * suites use DummyScheduler or a test-local CapturingScheduler, neither of - * which is NodeStoreScheduler, so they do NOT cover this call path. - * - That the recorded value has sub-millisecond resolution end to end. That - * half IS covered, in src/tests/libxrpl/nodestore/Database.cpp's - * sub_millisecond_fetch_latency_is_reported, which drives a real store - * through a capturing Scheduler and asserts the reported microsecond total - * equals the nodestore's own accumulator exactly. - * - * Closing the first gap needs an integration test under src/test/ with a live - * jtx::Env and an in-memory metric reader attached to the running - * MetricsRegistry; that is larger than this file's scope and is deliberately - * deferred rather than claimed. - */ - -#include - -#include - -#include - -namespace { - -using namespace xrpl::telemetry; - -// --------------------------------------------------------------------------- -// Group 1: shared constants and record-site helpers. Compile-time first, so a -// regression is a build failure rather than only a test failure; the runtime -// duplicates below name the offending case when one does fail. -// --------------------------------------------------------------------------- - -// The instrument name is the contract between the two call sites. Pinned to -// the exact literal: bare lower snake_case, no `xrpld_` prefix (no metric in -// this codebase carries one), and the `_us` suffix stating the unit. -static_assert(std::string_view{kNodeStoreReadUs} == "nodestore_read_us"); - -// Label keys. `found` rather than `was_found` and `fetch_type` rather than -// `type`, matching what the dashboards query. -static_assert(std::string_view{kFetchTypeLabel} == "fetch_type"); -static_assert(std::string_view{kFetchFoundLabel} == "found"); - -// Label values. -static_assert(std::string_view{kFetchTypeAsync} == "async"); -static_assert(std::string_view{kFetchTypeSync} == "sync"); -static_assert(std::string_view{kFetchFoundTrue} == "true"); -static_assert(std::string_view{kFetchFoundFalse} == "false"); - -// The helpers map each input to exactly one value, and the two arms differ. -static_assert(std::string_view{fetchTypeLabelValue(true)} == "async"); -static_assert(std::string_view{fetchTypeLabelValue(false)} == "sync"); -static_assert(std::string_view{fetchFoundLabelValue(true)} == "true"); -static_assert(std::string_view{fetchFoundLabelValue(false)} == "false"); - -// The negative guard. Zero is admitted on purpose -- a page-cache hit really -// can round to 0 us -- while anything below it is refused. -static_assert(shouldRecordFetchLatency(0)); -static_assert(shouldRecordFetchLatency(1)); -static_assert(shouldRecordFetchLatency(25'000)); -static_assert(!shouldRecordFetchLatency(-1)); - -} // namespace - -TEST(NodeStoreMetricNames, instrument_name_is_the_exact_shared_literal) -{ - // Both the view registration (MetricsRegistry.cpp) and the record site - // (NodeStoreScheduler.cpp) read this one constant. If it changes, the - // dashboard query and the reference doc must change with it, so the exact - // string is asserted rather than merely its shape. - EXPECT_EQ(std::string_view{kNodeStoreReadUs}, "nodestore_read_us"); - - // No `xrpld_` prefix: verified against the live metric surface, where 0 of - // 537 exported names carry one. A prefix here would make this the only - // odd metric out and break every dashboard that globs the family. - EXPECT_FALSE(std::string_view{kNodeStoreReadUs}.starts_with("xrpld_")); - - // The `_us` suffix is load-bearing: FetchReport::elapsed is - // std::chrono::microseconds, and a name implying milliseconds would make - // every reading 1000x wrong to a reader. - EXPECT_TRUE(std::string_view{kNodeStoreReadUs}.ends_with("_us")); - - // The description must name the unit too, since that is all a Prometheus - // consumer sees alongside the metric. - EXPECT_EQ( - std::string_view{kNodeStoreReadUsDesc}, "NodeStore backend fetch latency in microseconds"); -} - -TEST(NodeStoreMetricNames, label_keys_and_values_are_the_exact_literals) -{ - EXPECT_EQ(std::string_view{kFetchTypeLabel}, "fetch_type"); - EXPECT_EQ(std::string_view{kFetchFoundLabel}, "found"); - - EXPECT_EQ(std::string_view{kFetchTypeAsync}, "async"); - EXPECT_EQ(std::string_view{kFetchTypeSync}, "sync"); - EXPECT_EQ(std::string_view{kFetchFoundTrue}, "true"); - EXPECT_EQ(std::string_view{kFetchFoundFalse}, "false"); - - // The two keys must differ, or one label would overwrite the other in the - // attribute map and a whole dimension would vanish. - EXPECT_NE(std::string_view{kFetchTypeLabel}, std::string_view{kFetchFoundLabel}); -} - -TEST(NodeStoreMetricNames, helpers_map_each_input_to_its_own_value) -{ - // Positive path for both arms of both helpers. - EXPECT_EQ(std::string_view{fetchTypeLabelValue(true)}, "async"); - EXPECT_EQ(std::string_view{fetchTypeLabelValue(false)}, "sync"); - EXPECT_EQ(std::string_view{fetchFoundLabelValue(true)}, "true"); - EXPECT_EQ(std::string_view{fetchFoundLabelValue(false)}, "false"); - - // Cause, not just state: the two arms are genuinely distinct, so a - // copy-paste that returned the same value for both would fail here rather - // than quietly collapsing async and sync into one series. - EXPECT_NE( - std::string_view{fetchTypeLabelValue(true)}, std::string_view{fetchTypeLabelValue(false)}); - EXPECT_NE( - std::string_view{fetchFoundLabelValue(true)}, - std::string_view{fetchFoundLabelValue(false)}); - - // Each helper returns one of its own two constants and never the other - // helper's, which is what keeps the two dimensions independent. - EXPECT_EQ(fetchTypeLabelValue(true), kFetchTypeAsync); - EXPECT_EQ(fetchTypeLabelValue(false), kFetchTypeSync); - EXPECT_EQ(fetchFoundLabelValue(true), kFetchFoundTrue); - EXPECT_EQ(fetchFoundLabelValue(false), kFetchFoundFalse); -} - -TEST(NodeStoreMetricNames, latency_guard_admits_zero_and_refuses_negatives) -{ - // Negative path -- the reason the guard exists. The OTel SDK drops a - // negative histogram value AND logs a warning for it; on a per-fetch path - // that is a log flood, so the sample is filtered before it gets there. - EXPECT_FALSE(shouldRecordFetchLatency(-1)); - EXPECT_FALSE(shouldRecordFetchLatency(-1'000)); - - // Zero must NOT be filtered: a read served from the page cache genuinely - // truncates to 0 us, and suppressing it would hide the fastest reads and - // bias the whole distribution upward. - EXPECT_TRUE(shouldRecordFetchLatency(0)); - - // Ordinary and cold-tail values pass. - EXPECT_TRUE(shouldRecordFetchLatency(1)); - EXPECT_TRUE(shouldRecordFetchLatency(9)); - EXPECT_TRUE(shouldRecordFetchLatency(250)); - EXPECT_TRUE(shouldRecordFetchLatency(30'000)); -} - -// --------------------------------------------------------------------------- -// Group 2: record into a real histogram carrying production's explicit -// sub-millisecond boundaries, then read the exported point back and assert the -// exact per-bucket counts. -// -// This is what proves the signal is usable rather than merely emitted. The -// SDK's default boundaries begin at 0/5/10/25... but top out at 10,000, and -// the microsecond ladder used by the other duration histograms begins at 100 -// us -- above the entire range a warm read occupies. Under that ladder every -// warm read files into bucket 0 and the distribution reads flat. The -// assertions below pin warm reads into distinct low buckets, which is exactly -// the property the sub-millisecond ladder exists to provide. -// --------------------------------------------------------------------------- - -#ifdef XRPL_ENABLE_TELEMETRY - -#include -#include -#include -#include -#include -#include -#include -#include -#include -#include -#include -#include -#include -#include -#include -#include -#include - -#include -#include -#include -#include -#include -#include -#include - -namespace { - -namespace metric_sdk = opentelemetry::sdk::metrics; -namespace in_memory = opentelemetry::exporter::memory; - -/** - * The same edges MetricsRegistry.cpp's kSubMillisecondBoundaries holds. - * - * Deliberately a second, independent copy rather than an include of the - * production array: that constant lives in an unnamed namespace inside - * MetricsRegistry.cpp and is unreachable from here, and re-deriving the edges - * from the implementation would make the bucket-index assertions below - * tautological. Written out by hand, they pin the ladder -- so silently - * re-tuning an edge in production without revisiting this file fails here. - */ -constexpr std::array kExpectedBoundaries{ - 1.0, - 2.0, - 5.0, - 10.0, - 25.0, - 50.0, - 100.0, - 250.0, - 500.0, - 1'000.0, - 5'000.0, - 25'000.0}; - -/** - * Meter identity used by the production view selector, so the view this - * fixture registers matches the instrument the fixture creates. - */ -constexpr char kMeterName[] = "xrpld"; -constexpr char kMeterVersion[] = "1.0.0"; - -/** - * A MeterProvider carrying one explicit-bucket view for kNodeStoreReadUs and - * an in-memory exporter, so a test can record values and read the resulting - * histogram point back without any network or OTLP involvement. - * - * Mirrors what MetricsRegistry::initExporterAndProvider() builds for this - * instrument, minus the OTLP exporter. - */ -class HistogramFixture -{ -public: - HistogramFixture() - { - // The view: same instrument type, same name, same meter selector and - // the same boundaries production registers. - auto config = std::make_shared(); - config->boundaries_ = {kExpectedBoundaries.begin(), kExpectedBoundaries.end()}; - - auto views = std::make_unique(); - views->AddView( - metric_sdk::InstrumentSelectorFactory::Create( - metric_sdk::InstrumentType::kHistogram, kNodeStoreReadUs, ""), - metric_sdk::MeterSelectorFactory::Create(kMeterName, kMeterVersion, ""), - metric_sdk::ViewFactory::Create( - kNodeStoreReadUs, "", metric_sdk::AggregationType::kHistogram, config)); - - provider_ = metric_sdk::MeterProviderFactory::Create(std::move(views)); - - // A long export interval keeps the background thread from exporting - // on its own schedule; the test drives collection via ForceFlush(). - metric_sdk::PeriodicExportingMetricReaderOptions readerOpts; - readerOpts.export_interval_millis = std::chrono::milliseconds(600'000); - readerOpts.export_timeout_millis = std::chrono::milliseconds(5'000); - provider_->AddMetricReader( - metric_sdk::PeriodicExportingMetricReaderFactory::Create( - in_memory::InMemoryMetricExporterFactory::Create(data_), readerOpts)); - - histogram_ = provider_->GetMeter(kMeterName, kMeterVersion) - ->CreateDoubleHistogram(kNodeStoreReadUs, kNodeStoreReadUsDesc); - } - - ~HistogramFixture() - { - provider_->Shutdown(); - } - - HistogramFixture(HistogramFixture const&) = delete; - HistogramFixture& - operator=(HistogramFixture const&) = delete; - - /** - * Record one latency with the exact label set the production record site - * attaches, built through the same two helpers. - * - * @param elapsedUs Latency in microseconds. - * @param isAsync True for an async (prefetch) read. - * @param wasFound True when the object was found. - */ - void - record(double elapsedUs, bool isAsync, bool wasFound) - { - histogram_->Record( - elapsedUs, - {{kFetchTypeLabel, std::string(fetchTypeLabelValue(isAsync))}, - {kFetchFoundLabel, std::string(fetchFoundLabelValue(wasFound))}}, - opentelemetry::context::Context{}); - } - - /** - * Flush the reader, then return every exported histogram point for - * kNodeStoreReadUs keyed by its attribute set. - */ - [[nodiscard]] in_memory::SimpleAggregateInMemoryMetricData::AttributeToPoint const& - collect() - { - provider_->ForceFlush(); - return data_->Get(kMeterName, kNodeStoreReadUs); - } - -private: - /** - * Sink the in-memory exporter writes each collection into. - */ - std::shared_ptr data_ = - std::make_shared(); - - /** - * Provider owning the view registry and the in-memory reader. - */ - std::shared_ptr provider_; - - /** - * The instrument under test. - */ - opentelemetry::nostd::unique_ptr> histogram_; -}; - -/** - * Extract the HistogramPointData for the one series matching @p isAsync and - * @p wasFound, or nullptr when no such series was exported. - * - * @param points Exported points keyed by attribute set. - * @param isAsync fetch_type dimension to match. - * @param wasFound found dimension to match. - */ -[[nodiscard]] metric_sdk::HistogramPointData const* -findPoint( - in_memory::SimpleAggregateInMemoryMetricData::AttributeToPoint const& points, - bool isAsync, - bool wasFound) -{ - for (auto const& [attributes, point] : points) - { - auto const type = attributes.find(kFetchTypeLabel); - auto const found = attributes.find(kFetchFoundLabel); - if (type == attributes.end() || found == attributes.end()) - continue; - - if (opentelemetry::nostd::get(type->second) != fetchTypeLabelValue(isAsync) || - opentelemetry::nostd::get(found->second) != fetchFoundLabelValue(wasFound)) - continue; - - return &opentelemetry::nostd::get(point); - } - return nullptr; -} - -} // namespace - -TEST(NodeStoreReadHistogram, view_applies_the_sub_millisecond_boundaries) -{ - HistogramFixture fixture; - fixture.record(9.0, /*isAsync=*/false, /*wasFound=*/true); - - auto const* point = findPoint(fixture.collect(), /*isAsync=*/false, /*wasFound=*/true); - ASSERT_NE(point, nullptr); - - // The exported point must carry OUR boundaries, not the SDK defaults. This - // is the assertion that catches a name mismatch between the view selector - // and the instrument: on a mismatch the view is never applied and the - // default ladder appears here instead. - ASSERT_EQ(point->boundaries_.size(), kExpectedBoundaries.size()); - for (std::size_t i = 0; i < kExpectedBoundaries.size(); ++i) - EXPECT_EQ(point->boundaries_[i], kExpectedBoundaries[i]) << "boundary index " << i; - - // The first edge is 1 us, three orders of magnitude below the microsecond - // ladder's 100 us first edge. That difference is the entire point: without - // it a warm read cannot be distinguished from an instant one. - EXPECT_EQ(point->boundaries_.front(), 1.0); - EXPECT_EQ(point->boundaries_.back(), 25'000.0); -} - -TEST(NodeStoreReadHistogram, warm_reads_land_in_distinct_low_buckets) -{ - HistogramFixture fixture; - - // Four warm latencies, each chosen to fall in a different low bucket. - // Bucket i counts values in (boundaries[i-1], boundaries[i]]. - // 0.5 us -> bucket 0 ( <= 1 ) - // 3 us -> bucket 2 ( 2 < v <= 5 ) - // 9 us -> bucket 3 ( 5 < v <= 10 ) - // 40 us -> bucket 5 ( 25 < v <= 50 ) - fixture.record(0.5, /*isAsync=*/false, /*wasFound=*/true); - fixture.record(3.0, /*isAsync=*/false, /*wasFound=*/true); - fixture.record(9.0, /*isAsync=*/false, /*wasFound=*/true); - fixture.record(40.0, /*isAsync=*/false, /*wasFound=*/true); - - auto const* point = findPoint(fixture.collect(), /*isAsync=*/false, /*wasFound=*/true); - ASSERT_NE(point, nullptr); - - // Exact counts, bucket by bucket -- not merely "the total is 4". Under the - // microsecond ladder all four would sit in bucket 0 and this test would - // fail, which is precisely the regression it guards against. - ASSERT_EQ(point->counts_.size(), kExpectedBoundaries.size() + 1); - EXPECT_EQ(point->counts_[0], 1u); // 0.5 us - EXPECT_EQ(point->counts_[1], 0u); - EXPECT_EQ(point->counts_[2], 1u); // 3 us - EXPECT_EQ(point->counts_[3], 1u); // 9 us - EXPECT_EQ(point->counts_[4], 0u); - EXPECT_EQ(point->counts_[5], 1u); // 40 us - for (std::size_t i = 6; i < point->counts_.size(); ++i) - EXPECT_EQ(point->counts_[i], 0u) << "bucket " << i << " should be empty"; - - // Aggregate state must agree with the per-bucket detail. - EXPECT_EQ(point->count_, 4u); - EXPECT_EQ(opentelemetry::nostd::get(point->sum_), 52.5); - EXPECT_EQ(opentelemetry::nostd::get(point->min_), 0.5); - EXPECT_EQ(opentelemetry::nostd::get(point->max_), 40.0); -} - -TEST(NodeStoreReadHistogram, a_cold_read_lands_in_the_tail_not_the_ceiling) -{ - HistogramFixture fixture; - - // A cold read and an outlier beyond the top edge. 800 us falls in bucket 9 - // ( 500 < v <= 1000 ); 30000 us exceeds the 25000 top edge and so lands in - // the overflow bucket, index 12. - fixture.record(800.0, /*isAsync=*/false, /*wasFound=*/true); - fixture.record(30'000.0, /*isAsync=*/false, /*wasFound=*/true); - - auto const* point = findPoint(fixture.collect(), /*isAsync=*/false, /*wasFound=*/true); - ASSERT_NE(point, nullptr); - - EXPECT_EQ(point->counts_[9], 1u); // 800 us -- resolved, not saturated - EXPECT_EQ(point->counts_[12], 1u); // 30 ms -- overflow bucket - EXPECT_EQ(point->count_, 2u); - EXPECT_EQ(opentelemetry::nostd::get(point->max_), 30'000.0); -} - -TEST(NodeStoreReadHistogram, the_two_labels_split_the_series_four_ways) -{ - HistogramFixture fixture; - - // One record per (fetch_type, found) combination, each with a distinct - // latency so the series cannot be confused with one another. - fixture.record(3.0, /*isAsync=*/true, /*wasFound=*/true); - fixture.record(9.0, /*isAsync=*/true, /*wasFound=*/false); - fixture.record(40.0, /*isAsync=*/false, /*wasFound=*/true); - fixture.record(800.0, /*isAsync=*/false, /*wasFound=*/false); - - auto const& points = fixture.collect(); - - // Four distinct label sets means four distinct time series. If either - // label were dropped or misspelled these would collapse into fewer. - EXPECT_EQ(points.size(), 4u); - - struct Expected - { - bool isAsync; - bool wasFound; - double value; - std::size_t bucket; - }; - - // Each series holds exactly its own one sample, in its own bucket. This is - // the assertion that a label mix-up would break: swapping two values would - // put a sample in the wrong series and fail here. - for (auto const& [isAsync, wasFound, value, bucket] : std::array{ - {{.isAsync = true, .wasFound = true, .value = 3.0, .bucket = 2}, - {.isAsync = true, .wasFound = false, .value = 9.0, .bucket = 3}, - {.isAsync = false, .wasFound = true, .value = 40.0, .bucket = 5}, - {.isAsync = false, .wasFound = false, .value = 800.0, .bucket = 9}}}) - { - auto const* point = findPoint(points, isAsync, wasFound); - ASSERT_NE(point, nullptr) << "missing series for fetch_type=" - << fetchTypeLabelValue(isAsync) - << " found=" << fetchFoundLabelValue(wasFound); - EXPECT_EQ(point->count_, 1u); - EXPECT_EQ(opentelemetry::nostd::get(point->sum_), value); - EXPECT_EQ(point->counts_[bucket], 1u); - } -} - -TEST(NodeStoreReadHistogram, a_guarded_negative_latency_never_reaches_the_instrument) -{ - HistogramFixture fixture; - - // Negative path, end to end: the record site consults - // shouldRecordFetchLatency() before calling Record(), so a clock anomaly - // produces no sample at all. Reproduced here with the same guard. - for (double const elapsedUs : {-1.0, -1'000.0}) - { - if (shouldRecordFetchLatency(static_cast(elapsedUs))) - fixture.record(elapsedUs, /*isAsync=*/false, /*wasFound=*/true); - } - - // No series at all: nothing was recorded, so the instrument exported - // nothing rather than exporting a zero-count point. - EXPECT_TRUE(fixture.collect().empty()); - - // Cause, not just state: the same fixture DOES accept a valid sample, so - // the emptiness above is the guard working and not a broken fixture. - fixture.record(9.0, /*isAsync=*/false, /*wasFound=*/true); - auto const* point = findPoint(fixture.collect(), /*isAsync=*/false, /*wasFound=*/true); - ASSERT_NE(point, nullptr); - EXPECT_EQ(point->count_, 1u); - EXPECT_EQ(point->counts_[3], 1u); -} - -#endif // XRPL_ENABLE_TELEMETRY diff --git a/src/xrpld/app/main/Application.cpp b/src/xrpld/app/main/Application.cpp index c79811f56c..c543e7e628 100644 --- a/src/xrpld/app/main/Application.cpp +++ b/src/xrpld/app/main/Application.cpp @@ -393,11 +393,7 @@ public: logs_->journal("JobQueue"), *logs_, *perfLog_)) - // `*this` is passed as a ServiceRegistry only to reach the - // MetricsRegistry later, from onFetch(). It is not dereferenced here, - // and metricsRegistry_ does not exist yet at this point in the - // initializer list -- the metric macros null-check it per call. - , nodeStoreScheduler_(*this, *jobQueue_) + , nodeStoreScheduler_(*jobQueue_) , shaMapStore_(makeSHAMapStore(*this, nodeStoreScheduler_, logs_->journal("SHAMapStore"))) , tempNodeCache_( "NodeCache", diff --git a/src/xrpld/app/main/NodeStoreScheduler.cpp b/src/xrpld/app/main/NodeStoreScheduler.cpp index ac527707bb..484c6d1ab1 100644 --- a/src/xrpld/app/main/NodeStoreScheduler.cpp +++ b/src/xrpld/app/main/NodeStoreScheduler.cpp @@ -1,29 +1,15 @@ -// cspell:ignore ISTOGRAM -// The all-caps macro name XRPL_METRIC_HISTOGRAM_RECORD_LABELED trips cspell's -// compound-word splitter, which emits the subword "ISTOGRAM"; ignore it here. - #include -#include - #include #include -#include #include #include -#include #include -#include namespace xrpl { -NodeStoreScheduler::NodeStoreScheduler([[maybe_unused]] ServiceRegistry& app, JobQueue& jobQueue) -#ifdef XRPL_ENABLE_TELEMETRY - : app_(app), jobQueue_(jobQueue) -#else - : jobQueue_(jobQueue) -#endif +NodeStoreScheduler::NodeStoreScheduler(JobQueue& jobQueue) : jobQueue_(jobQueue) { } @@ -47,36 +33,14 @@ NodeStoreScheduler::onFetch(node_store::FetchReport const& report) if (jobQueue_.isStopped()) return; - auto const isAsync = report.fetchType == node_store::FetchType::Async; - // The report is in microseconds but addLoadEvents takes milliseconds, so // cast explicitly. The load monitor only tracks whole-millisecond load, - // so the sub-millisecond detail is deliberately dropped here; the - // histogram below keeps it. + // so the sub-millisecond detail is deliberately dropped here; telemetry + // reads the microsecond value from the nodestore instead. jobQueue_.addLoadEvents( - isAsync ? JtNsAsyncRead : JtNsSyncRead, + report.fetchType == node_store::FetchType::Async ? JtNsAsyncRead : JtNsSyncRead, 1, std::chrono::duration_cast(report.elapsed)); - - // Skip a negative elapsed time rather than hand it to the SDK, which - // rejects it and logs a warning on every single call. The clock is - // monotonic, so this needs a clock bug to happen -- but a per-fetch log - // flood would be worse than the missing sample. - if (!telemetry::shouldRecordFetchLatency(report.elapsed.count())) - return; - - // Two labels, both already on the report. fetch_type because a slow async - // read only delays prefetch while a slow sync read blocks a caller; - // found because a miss can cost a read of every backend, so mixing the - // two blurs the distribution. - XRPL_METRIC_HISTOGRAM_RECORD_LABELED( - app_, - telemetry::kNodeStoreReadUs, - telemetry::kNodeStoreReadUsDesc, - report.elapsed.count(), - {{telemetry::kFetchTypeLabel, std::string(telemetry::fetchTypeLabelValue(isAsync))}, - {telemetry::kFetchFoundLabel, - std::string(telemetry::fetchFoundLabelValue(report.wasFound))}}); } void diff --git a/src/xrpld/app/main/NodeStoreScheduler.h b/src/xrpld/app/main/NodeStoreScheduler.h index db05491c65..09a48d5be1 100644 --- a/src/xrpld/app/main/NodeStoreScheduler.h +++ b/src/xrpld/app/main/NodeStoreScheduler.h @@ -6,57 +6,13 @@ namespace xrpl { -// Forward-declared rather than included: only a reference is stored, and -// ServiceRegistry.h pulls in , which every file including this -// header would then pay for. The .cpp includes the full definition. -class ServiceRegistry; - /** * A node_store::Scheduler which uses the JobQueue. - * - * Two responsibilities, both delegating outward: it turns backend write - * requests into JobQueue jobs, and it forwards completion reports to the - * load monitor and to the OTel metrics pipeline. - * - * Collaborator diagram (ASCII): - * - * node_store::Database / Backend - * | - * | scheduleTask / onFetch / onBatchWrite - * v - * +---------------------+ - * | NodeStoreScheduler | - * +---------------------+ - * | | - * v v - * JobQueue ServiceRegistry - * (jobs + (-> MetricsRegistry, - * load events) read-latency histogram) - * - * @note Thread safety: onFetch() and onBatchWrite() are called from backend - * read/write threads, concurrently. Both members are references to - * objects that outlive this one, and every call they make - * (JobQueue::addLoadEvents, OTel Histogram::Record) is itself - * thread-safe, so no locking is needed here. - * @note Lifetime: constructed early, in the Application member initializer - * list, which is BEFORE the MetricsRegistry exists. It therefore stores - * the ServiceRegistry and resolves the registry per call; the metric - * macros null-check it, so fetches completing before the registry is - * created are simply not recorded. */ class NodeStoreScheduler : public node_store::Scheduler { public: - /** - * Construct a scheduler. - * - * @param app Service registry, used only to reach the - * MetricsRegistry when reporting read latency. Must - * outlive this object. - * @param jobQueue Queue that runs scheduled write tasks and receives - * load events. Must outlive this object. - */ - NodeStoreScheduler(ServiceRegistry& app, JobQueue& jobQueue); + explicit NodeStoreScheduler(JobQueue& jobQueue); void scheduleTask(node_store::Task& task) override; @@ -66,21 +22,6 @@ public: onBatchWrite(node_store::BatchWriteReport const& report) override; private: -#ifdef XRPL_ENABLE_TELEMETRY - /** - * Service registry, resolved to a MetricsRegistry on each onFetch(). - * - * Only needed when OTel is compiled in, since the record site is the - * only reader. Held under the guard for the same reason - * MetricsRegistry::app_ is: without OTel it would be an unused private - * field, which -Wall rejects. - */ - ServiceRegistry& app_; -#endif // XRPL_ENABLE_TELEMETRY - - /** - * Queue used for scheduled tasks and load-event reporting. - */ JobQueue& jobQueue_; }; diff --git a/src/xrpld/telemetry/MetricsRegistry.cpp b/src/xrpld/telemetry/MetricsRegistry.cpp index bef7ec8f2d..cb979ff9ef 100644 --- a/src/xrpld/telemetry/MetricsRegistry.cpp +++ b/src/xrpld/telemetry/MetricsRegistry.cpp @@ -46,7 +46,6 @@ #include #include #include -#include #include #include @@ -136,10 +135,11 @@ constexpr std::array kMicrosecondBoundaries{ * range instead, while still reaching far enough to show a cold tail against * it. * - * Used by the kNodeStoreReadUs view registered in - * initExporterAndProvider(). + * Currently unused: no sub-millisecond histogram instrument exists yet. The + * edges live here so the instrument that records nodestore read latency gets + * a ladder that fits it, rather than silently inheriting the wrong one. */ -constexpr std::array kSubMillisecondBoundaries{ +[[maybe_unused]] constexpr std::array kSubMillisecondBoundaries{ 1.0, 2.0, 5.0, @@ -196,23 +196,6 @@ addMicrosecondHistogramView(metric_sdk::ViewRegistry& views, std::string const& addHistogramView(views, name, {kMicrosecondBoundaries.begin(), kMicrosecondBoundaries.end()}); } -/** - * Register the sub-millisecond-ladder view for a duration instrument. - * - * For latencies that normally sit below one millisecond, where the - * microsecond ladder's 100 µs first edge would swallow the whole healthy - * range. See kSubMillisecondBoundaries. - * - * @param views The registry to add the view to. - * @param name Instrument name to match. - */ -void -addSubMillisecondHistogramView(metric_sdk::ViewRegistry& views, std::string const& name) -{ - addHistogramView( - views, name, {kSubMillisecondBoundaries.begin(), kSubMillisecondBoundaries.end()}); -} - } // namespace #endif // XRPL_ENABLE_TELEMETRY @@ -297,13 +280,6 @@ MetricsRegistry::initExporterAndProvider(std::string const& endpoint, std::strin // comes from the shared constant both sites use. addMicrosecondHistogramView(*views, kGetObjectLookupUs); - // Per-fetch nodestore read latency. Recorded at its NodeStoreScheduler.cpp - // call site, so again the name comes from the shared constant. This one - // gets the sub-millisecond ladder, not the microsecond one: a warm read - // answers in single-digit microseconds, which is below the microsecond - // ladder's first edge. - addSubMillisecondHistogramView(*views, kNodeStoreReadUs); - // The remaining two GetObject histograms are not durations, so the // microsecond ladder above does not fit them. Both still need explicit // boundaries: the SDK default stops at 10,000 and both ranges exceed it.