diff --git a/include/xrpl/nodestore/Scheduler.h b/include/xrpl/nodestore/Scheduler.h index 40c36ce8ab..a7ab26852b 100644 --- a/include/xrpl/nodestore/Scheduler.h +++ b/include/xrpl/nodestore/Scheduler.h @@ -17,7 +17,17 @@ struct FetchReport { } - std::chrono::milliseconds elapsed{}; + /** + * Wall time the fetch took, in microseconds. + * + * Microseconds and not milliseconds: a warm nodestore answers a read in + * single-digit microseconds and a cold one in low hundreds. A + * millisecond field rounds both to zero, so it discards the only + * quantity that separates a healthy read path from a stalled one. + * + * A consumer that needs milliseconds casts explicitly. + */ + std::chrono::microseconds elapsed{}; FetchType const fetchType; bool wasFound = false; }; @@ -29,7 +39,18 @@ struct BatchWriteReport { explicit BatchWriteReport() = default; + /** + * Wall time the batch write took, in milliseconds. + * + * Milliseconds is the right unit here, unlike on FetchReport: a batch + * write covers many objects and reaches the disk, so it lands in the + * millisecond range rather than below it. + */ std::chrono::milliseconds elapsed; + + /** + * Number of objects written in the batch. + */ int writeCount; }; diff --git a/src/libxrpl/nodestore/Database.cpp b/src/libxrpl/nodestore/Database.cpp index 1279cfd4f0..e2aef00d67 100644 --- a/src/libxrpl/nodestore/Database.cpp +++ b/src/libxrpl/nodestore/Database.cpp @@ -241,7 +241,12 @@ Database::fetchNodeObject( auto nodeObject{fetchNodeObject(hash, ledgerSeq, fetchReport, duplicate)}; auto dur = steady_clock::now() - begin; - fetchDurationUs_ += duration_cast(dur).count(); + + // Measured once and used for both the cumulative counter and the + // scheduler report, so the two can never disagree about how long this + // fetch took. + auto const elapsedUs = duration_cast(dur); + fetchDurationUs_ += elapsedUs.count(); if (nodeObject) { ++fetchHitCount_; @@ -249,7 +254,7 @@ Database::fetchNodeObject( } ++fetchTotalCount_; - fetchReport.elapsed = duration_cast(dur); + fetchReport.elapsed = elapsedUs; scheduler_.onFetch(fetchReport); return nodeObject; } diff --git a/src/tests/libxrpl/nodestore/Database.cpp b/src/tests/libxrpl/nodestore/Database.cpp index 6921384d88..70f06b42bc 100644 --- a/src/tests/libxrpl/nodestore/Database.cpp +++ b/src/tests/libxrpl/nodestore/Database.cpp @@ -7,6 +7,8 @@ #include #include #include +#include +#include #include #include #include @@ -16,6 +18,9 @@ #include #include +#include +#include +#include #include #include #include @@ -58,6 +63,72 @@ importBackends() return types; } +/** + * A scheduler that records what the nodestore reports about each operation. + * + * The production scheduler forwards these reports to the job queue and to + * telemetry, so capturing them here lets a test observe exactly the values a + * dashboard would receive. + * + * Database::fetchNodeObject() + * | + * +-- FetchReport{elapsed, wasFound} --> onFetch() + * + * Database::store() -> backend + * | + * +-- BatchWriteReport{elapsed, writeCount} --> onBatchWrite() + * + * @note Counters are atomic because Scheduler is called from the nodestore's + * read threads in production. The tests below fetch synchronously on + * one thread, so the totals are still exact. + */ +struct CapturingScheduler : Scheduler +{ + std::atomic totalReportedUs{0}; ///< Sum of reported fetch durations. + std::atomic fetchCount{0}; ///< Fetch reports received. + std::atomic foundCount{0}; ///< Fetch reports with wasFound set. + std::atomic batchWriteCount{0}; ///< Batch-write reports received. + + /** + * Fetch reports whose duration is not a whole number of milliseconds. + * + * A millisecond-typed duration converts to a whole multiple of 1000 + * microseconds, so it can never be counted here however fast or slow the + * machine is. A non-zero count therefore proves the report carried + * sub-millisecond resolution, and it proves it without assuming anything + * about how long a read takes. + */ + std::atomic subMillisecondCount{0}; + + void + scheduleTask(Task& task) override + { + task.performScheduledTask(); + } + + void + onFetch(FetchReport const& report) override + { + // duration_cast, not .count(), so this compiles against either unit + // and the test can be run before and after the fix. + auto const us = static_cast( + std::chrono::duration_cast(report.elapsed).count()); + + totalReportedUs += us; + ++fetchCount; + if (report.wasFound) + ++foundCount; + if (us % 1000 != 0) + ++subMillisecondCount; + } + + void + onBatchWrite(BatchWriteReport const&) override + { + ++batchWriteCount; + } +}; + } // namespace // Shared setup for the parameterized Database tests: builds the node params, @@ -190,6 +261,98 @@ TEST_P(NodeStoreDatabaseTest, write_stats_forwarded_from_backend) EXPECT_GE(after->insertMaxUs * after->insertCount, after->insertTotalUs); } +// Read latency is the discriminator between a warm nodestore and a cold one: +// a warm store answers in single-digit microseconds and a cold one in low +// hundreds, while the hit rate reads the same for both. FetchReport::elapsed +// is what the production scheduler forwards, so if that field cannot hold a +// sub-millisecond value the difference is gone before anything can record it. +// +// nudb rather than memory: a real store's reads take microseconds of +// measurable work, whereas an in-memory map lookup can finish inside a single +// microsecond tick and report a legitimate zero. +TEST(NodeStoreDatabase, sub_millisecond_fetch_latency_is_reported) +{ + CapturingScheduler scheduler; + beast::TempDir const nodeDb; + Section nodeParams; + nodeParams.set("type", "nudb"); + nodeParams.set("path", nodeDb.path()); + + beast::Journal const journal(TestSink::instance()); + + // No cache_size/cache_age, so DatabaseNodeImp builds no cache and every + // fetch reaches the backend. That keeps the counts exact. + auto db = Manager::instance().makeDatabase(megabytes(4), scheduler, 2, nodeParams, journal); + ASSERT_NE(db, nullptr); + + // Nothing has been fetched, so nothing has been reported. This also + // proves the counters below are moved by this test and not by setup. + ASSERT_EQ(scheduler.fetchCount.load(), 0u); + ASSERT_EQ(scheduler.totalReportedUs.load(), 0u); + ASSERT_EQ(db->getFetchDurationUs(), 0u); + + constexpr std::size_t kNumStored = 256; + auto const stored = createPredictableBatch(kNumStored, kSeedValue); + ASSERT_EQ(stored.size(), kNumStored); + storeBatch(*db, stored); + + // Each store reaches the backend once, and nudb reports every insert as a + // one-object batch write. A change to BatchWriteReport that broke its + // millisecond contract would show up here rather than silently. + EXPECT_EQ(scheduler.batchWriteCount.load(), kNumStored); + + // Positive path: every object is present, so every fetch is a hit. + for (auto const& object : stored) + EXPECT_NE(db->fetchNodeObject(object->getHash(), 0), nullptr); + + // Every fetch produced exactly one report, and each one saw its object. + ASSERT_EQ(scheduler.fetchCount.load(), kNumStored); + EXPECT_EQ(scheduler.foundCount.load(), kNumStored); + + // The nodestore's own microsecond accumulator moved, so there is real + // measured time for the reports to carry. + auto const internalUs = db->getFetchDurationUs(); + ASSERT_GT(internalUs, 0u); + + // The core assertion. Database::fetchNodeObject() measures each fetch once + // and uses that one value for both the internal accumulator and the + // report, so the two totals must agree exactly. A millisecond-typed report + // truncates every sub-millisecond fetch to zero and this fails. + EXPECT_EQ(scheduler.totalReportedUs.load(), internalUs); + + // Independent of the equality above, and independent of how fast this + // machine is: a millisecond-typed duration always converts to a whole + // multiple of 1000 microseconds, so at least one report carrying a + // non-multiple proves the field itself holds sub-millisecond resolution. + EXPECT_GT(scheduler.subMillisecondCount.load(), 0u); + + // Negative path: a miss is still a fetch, so it is still reported and + // still timed, but it is not a hit. A report that only fired on hits + // would hide exactly the cold-read case this measures. + constexpr std::size_t kNumMissing = 32; + auto const missing = createPredictableBatch(kNumMissing, kSeedValue + 1); + ASSERT_EQ(missing.size(), kNumMissing); + for (auto const& object : missing) + EXPECT_EQ(db->fetchNodeObject(object->getHash(), 0), nullptr); + + EXPECT_EQ(scheduler.fetchCount.load(), kNumStored + kNumMissing); + EXPECT_EQ(scheduler.foundCount.load(), kNumStored); + + // The totals still agree once misses are included, so the miss path + // reports exactly what it measured rather than substituting a zero. + // + // GE and not GT: a cumulative total cannot shrink, but an individual miss + // served from NuDB's in-memory buckets can genuinely measure under one + // microsecond and truncate to zero, so requiring growth here would be a + // statement about this machine's speed rather than about the code. + auto const internalUsWithMisses = db->getFetchDurationUs(); + EXPECT_GE(internalUsWithMisses, internalUs); + EXPECT_EQ(scheduler.totalReportedUs.load(), internalUsWithMisses); + + // Reads perform no writes, so the write-report count cannot have moved. + EXPECT_EQ(scheduler.batchWriteCount.load(), kNumStored); +} + INSTANTIATE_TEST_SUITE_P( NodeStoreBackends, NodeStoreDatabaseTest, diff --git a/src/xrpld/app/main/NodeStoreScheduler.cpp b/src/xrpld/app/main/NodeStoreScheduler.cpp index c3ac5d78cf..484c6d1ab1 100644 --- a/src/xrpld/app/main/NodeStoreScheduler.cpp +++ b/src/xrpld/app/main/NodeStoreScheduler.cpp @@ -5,6 +5,8 @@ #include #include +#include + namespace xrpl { NodeStoreScheduler::NodeStoreScheduler(JobQueue& jobQueue) : jobQueue_(jobQueue) @@ -31,10 +33,14 @@ NodeStoreScheduler::onFetch(node_store::FetchReport const& report) if (jobQueue_.isStopped()) return; + // 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; telemetry + // reads the microsecond value from the nodestore instead. jobQueue_.addLoadEvents( report.fetchType == node_store::FetchType::Async ? JtNsAsyncRead : JtNsSyncRead, 1, - report.elapsed); + std::chrono::duration_cast(report.elapsed)); } void diff --git a/src/xrpld/telemetry/MetricsRegistry.cpp b/src/xrpld/telemetry/MetricsRegistry.cpp index fe8ebc47b5..b0ef79beb4 100644 --- a/src/xrpld/telemetry/MetricsRegistry.cpp +++ b/src/xrpld/telemetry/MetricsRegistry.cpp @@ -123,6 +123,36 @@ constexpr std::array kMicrosecondBoundaries{ 30'000'000.0, 60'000'000.0}; +/** + * Bucket boundaries for latencies that are normally sub-millisecond. + * + * 1 µs, 2 µs, 5 µs, 10 µs, 25 µs, 50 µs, 100 µs, 250 µs, 500 µs, 1 ms, 5 ms, + * 25 ms. + * + * kMicrosecondBoundaries starts at 100 µs, which is above the entire range a + * healthy nodestore read occupies, so every warm read falls in its first + * bucket and the distribution reads as flat. These edges resolve the warm + * range instead, while still reaching far enough to show a cold tail against + * it. + * + * 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. + */ +[[maybe_unused]] constexpr std::array kSubMillisecondBoundaries{ + 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}; + /** * Register an explicit-bucket histogram view. *