diff --git a/include/xrpl/nodestore/Database.h b/include/xrpl/nodestore/Database.h index d88296e6b2..eaca10a059 100644 --- a/include/xrpl/nodestore/Database.h +++ b/include/xrpl/nodestore/Database.h @@ -12,6 +12,7 @@ #include #include +#include #include #include #include @@ -221,12 +222,17 @@ public: * is what separates a cold store from a warm one: a warm store reads in * single-digit microseconds, a cold one in low hundreds. * + * Accumulated in nanoseconds and converted here, so the total is exact to + * within one microsecond however fast the reads are. Truncated rather than + * rounded: reads totalling under a microsecond read as 0 until they sum + * past 1000 ns. + * * @return The running microsecond total for the lifetime of this process. */ std::uint64_t getFetchDurationUs() const { - return fetchDurationUs_; + return fetchDurationNs_ / kNanosecondsPerMicrosecond; } /** @@ -236,12 +242,15 @@ public: * any time the backend spent waiting for its own internal locks, so it is * wall time per store, not service time. * + * Same accumulate-in-nanoseconds, convert-on-read contract as + * getFetchDurationUs(). + * * @return The running microsecond total for the lifetime of this process. */ std::uint64_t getStoreDurationUs() const { - return storeDurationUs_; + return storeDurationNs_ / kNanosecondsPerMicrosecond; } /** @@ -312,27 +321,39 @@ protected: * Add the wall time of one backend store to the cumulative total. * * Each concrete store path times only its backend call, so the total - * reflects disk work and excludes cache bookkeeping. Callers must pass - * microseconds. + * reflects disk work and excludes cache bookkeeping. * - * @param us Wall time of the completed backend store, in microseconds. + * Takes the raw duration rather than a converted integer, so every caller + * accumulates at the same resolution. See storeDurationNs_ for the + * accumulate-then-convert contract. + * + * @param elapsed Wall time of the completed backend store. */ void - storeDurationStats(std::uint64_t us) + storeDurationStats(std::chrono::steady_clock::duration elapsed) { - storeDurationUs_ += us; + storeDurationNs_ += static_cast( + std::chrono::duration_cast(elapsed).count()); } // Called by the public import function void importInternal(Backend& dstBackend, Database& srcDB); + /** + * Fold an imported database's read counters into this one's. + * + * @param fetches Number of completed fetches to add. + * @param hits Number of those fetches that found their object. + * @param durationUs Wall time of those fetches, in microseconds. Scaled up + * to nanoseconds internally to match the accumulator's unit. + */ void - updateFetchMetrics(uint64_t fetches, uint64_t hits, uint64_t duration) + updateFetchMetrics(uint64_t fetches, uint64_t hits, uint64_t durationUs) { fetchTotalCount_ += fetches; fetchHitCount_ += hits; - fetchDurationUs_ += duration; + fetchDurationNs_ += durationUs * kNanosecondsPerMicrosecond; } private: @@ -357,20 +378,35 @@ private: std::atomic fetchSz_{0}; /** - * Wall time spent in backend fetches, in microseconds. + * Divisor converting the nanosecond accumulators to microseconds. + * + * Named rather than inline so the two accessors and updateFetchMetrics() + * cannot drift onto different scale factors. + */ + static constexpr std::uint64_t kNanosecondsPerMicrosecond = 1000; + + /** + * Wall time spent in backend fetches, in nanoseconds. * * Written by fetchNodeObject(), which times the whole fetch including a * cache lookup that misses. + * + * Nanoseconds, the clock's own resolution, because a warm store answers a + * read in a few hundred of them. Accumulating here and converting once, in + * getFetchDurationUs(), keeps the total exact to within one microsecond + * regardless of how fast the reads are. A 64-bit nanosecond counter spans + * roughly 584 years, so it cannot wrap on any real node. */ - std::atomic fetchDurationUs_{0}; + std::atomic fetchDurationNs_{0}; /** - * Wall time spent in backend stores, in microseconds. + * Wall time spent in backend stores, in nanoseconds. * * Written by each concrete store path via storeDurationStats(), which - * times only the backend call. + * times only the backend call. Nanoseconds for the same + * accumulate-then-convert reason as fetchDurationNs_. */ - std::atomic storeDurationUs_{0}; + std::atomic storeDurationNs_{0}; mutable std::mutex readLock_; std::condition_variable readCondVar_; diff --git a/src/libxrpl/nodestore/Database.cpp b/src/libxrpl/nodestore/Database.cpp index e2aef00d67..cfc52977cc 100644 --- a/src/libxrpl/nodestore/Database.cpp +++ b/src/libxrpl/nodestore/Database.cpp @@ -242,11 +242,14 @@ Database::fetchNodeObject( auto nodeObject{fetchNodeObject(hash, ledgerSeq, fetchReport, duplicate)}; auto dur = steady_clock::now() - begin; - // 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. + // One measurement, dur, feeds both the cumulative counter and the scheduler + // report, so the two can never disagree about how long this fetch took. + // They express it in different units: the counter accumulates nanoseconds, + // the clock's own resolution, so a run of reads each faster than a + // microsecond still sums to the right total; the report carries + // microseconds, the unit FetchReport::elapsed declares. + fetchDurationNs_ += static_cast(duration_cast(dur).count()); auto const elapsedUs = duration_cast(dur); - fetchDurationUs_ += elapsedUs.count(); if (nodeObject) { ++fetchHitCount_; @@ -278,8 +281,10 @@ Database::getCountsJson(json::Value& obj) obj[jss::node_reads_hit] = std::to_string(fetchHitCount_); obj[jss::node_written_bytes] = std::to_string(storeSz_); obj[jss::node_read_bytes] = std::to_string(fetchSz_); - obj[jss::node_reads_duration_us] = std::to_string(fetchDurationUs_); - obj[jss::node_writes_duration_us] = std::to_string(storeDurationUs_); + // Through the accessors: the accumulators hold nanoseconds and these two + // fields are declared in microseconds. + obj[jss::node_reads_duration_us] = std::to_string(getFetchDurationUs()); + obj[jss::node_writes_duration_us] = std::to_string(getStoreDurationUs()); } } // namespace xrpl::node_store diff --git a/src/libxrpl/nodestore/DatabaseNodeImp.cpp b/src/libxrpl/nodestore/DatabaseNodeImp.cpp index 16a3249c27..5491f2311c 100644 --- a/src/libxrpl/nodestore/DatabaseNodeImp.cpp +++ b/src/libxrpl/nodestore/DatabaseNodeImp.cpp @@ -29,10 +29,7 @@ DatabaseNodeImp::store(NodeObjectType type, Blob&& data, uint256 const& hash, st // would blur the write latency signal. auto const begin = std::chrono::steady_clock::now(); backend_->store(obj); - storeDurationStats( - static_cast(std::chrono::duration_cast( - std::chrono::steady_clock::now() - begin) - .count())); + storeDurationStats(std::chrono::steady_clock::now() - begin); if (cache_) { diff --git a/src/libxrpl/nodestore/DatabaseRotatingImp.cpp b/src/libxrpl/nodestore/DatabaseRotatingImp.cpp index 3c1554faac..a9298317a3 100644 --- a/src/libxrpl/nodestore/DatabaseRotatingImp.cpp +++ b/src/libxrpl/nodestore/DatabaseRotatingImp.cpp @@ -142,10 +142,7 @@ DatabaseRotatingImp::store(NodeObjectType type, Blob&& data, uint256 const& hash // paths feed the same accumulator with comparable numbers. auto const begin = std::chrono::steady_clock::now(); backend->store(nObj); - storeDurationStats( - static_cast(std::chrono::duration_cast( - std::chrono::steady_clock::now() - begin) - .count())); + storeDurationStats(std::chrono::steady_clock::now() - begin); storeStats(1, nObj->getData().size()); } diff --git a/src/test/nodestore/DatabaseConfig_test.cpp b/src/test/nodestore/DatabaseConfig_test.cpp index 9929c6f8cc..8021351b0d 100644 --- a/src/test/nodestore/DatabaseConfig_test.cpp +++ b/src/test/nodestore/DatabaseConfig_test.cpp @@ -161,20 +161,17 @@ private: }; /** - * Assert the read accumulator holds exactly what the fetch reports carried. + * Assert the read accumulator agrees with what the fetch reports carried. * - * Deliberately not `getFetchDurationUs() > 0`: an individual read served - * from NuDB's in-memory buckets can genuinely measure under one - * microsecond and truncate to zero, so on a fast enough host every read - * truncates and the total stays at zero with nothing wrong. That makes - * `> 0` an assertion about the machine rather than about the code, and it - * is what failed on the macOS runner. + * The accumulator keeps nanoseconds and each report carries its own fetch + * truncated to whole microseconds, so the reported sum is the accumulated + * total minus one sub-microsecond remainder per fetch. That gives a bound + * rather than an equality, and the bound is machine-independent: an + * accumulator that dropped a fetch, double-counted one, or reported the + * write member instead would break it however fast the host is. * - * The equality below is machine-independent and strictly stronger: each - * fetch is measured once and that one value feeds both the accumulator - * and the report, so an accumulator that dropped a fetch, double-counted - * one, or reported the write member instead would break the equality - * however fast the host is. + * Deliberately not `getFetchDurationUs() > 0` on its own: that is an + * assertion about how fast the host reads, not about the code. * * @param db Database whose read accumulator is checked. * @param scheduler Scheduler that received the reports for @p db. @@ -187,7 +184,10 @@ private: std::uint64_t expectedReports) { BEAST_EXPECT(scheduler.fetchReports.load() == expectedReports); - BEAST_EXPECT(db.getFetchDurationUs() == scheduler.reportedFetchUs.load()); + auto const accumulatedUs = db.getFetchDurationUs(); + auto const reportedUs = scheduler.reportedFetchUs.load(); + BEAST_EXPECT(reportedUs <= accumulatedUs); + BEAST_EXPECT(accumulatedUs - reportedUs <= expectedReports); } public: diff --git a/src/tests/libxrpl/nodestore/Database.cpp b/src/tests/libxrpl/nodestore/Database.cpp index 6f01bfc788..9ee57bda69 100644 --- a/src/tests/libxrpl/nodestore/Database.cpp +++ b/src/tests/libxrpl/nodestore/Database.cpp @@ -321,22 +321,21 @@ TEST(NodeStoreDatabase, sub_millisecond_fetch_latency_is_reported) 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. + // The accumulator keeps nanoseconds internally, so 256 reads sum past a + // microsecond and register here even when each individual read finishes in + // well under one. This is a statement about the accumulator's resolution, + // not about this machine's speed: to still read zero, all 256 reads would + // have to complete inside a single microsecond in total. 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); + // Each report truncates its own fetch to whole microseconds, while the + // accumulator keeps the remainder. The reported total can therefore only be + // smaller than the accumulated one, and only by the discarded remainder of + // each fetch, which is strictly under 1 us per fetch. + auto const reportedUs = scheduler.totalReportedUs.load(); + EXPECT_LE(reportedUs, internalUs); + EXPECT_LE(internalUs - reportedUs, kNumStored); // 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 @@ -350,16 +349,18 @@ TEST(NodeStoreDatabase, sub_millisecond_fetch_latency_is_reported) 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. + // The same bound still holds once misses are included, so the miss path + // reports 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. + // GE and not GT: a cumulative total cannot shrink, but the microsecond view + // of it only advances once the accumulated nanoseconds cross the next + // thousand, so requiring growth from 32 more reads 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); + auto const reportedUsWithMisses = scheduler.totalReportedUs.load(); + EXPECT_LE(reportedUsWithMisses, internalUsWithMisses); + EXPECT_LE(internalUsWithMisses - reportedUsWithMisses, kNumStored + kNumMissing); // Reads perform no writes, so the write-report count cannot have moved. EXPECT_EQ(scheduler.batchWriteCount.load(), kNumStored);