diff --git a/include/xrpl/nodestore/Database.h b/include/xrpl/nodestore/Database.h index 47ef8a1aee..85a8ba64fd 100644 --- a/include/xrpl/nodestore/Database.h +++ b/include/xrpl/nodestore/Database.h @@ -242,6 +242,10 @@ public: * * @return Total microseconds accumulated across every completed store. * + * @note Accumulated in nanoseconds and converted here, so the total is + * exact to within one microsecond however fast the stores are. Truncated + * rather than rounded: stores totalling under a microsecond read as 0 until + * they sum past 1000 ns. * @note Thread-safe: a single relaxed atomic load. Cheap enough for a * periodic observer (the telemetry reader ticks every ~10 s). Relaxed is * sufficient because the value is a monotonic statistic, not a @@ -254,7 +258,7 @@ public: [[nodiscard]] std::uint64_t getStoreDurationUs() const noexcept { - return storeDurationUs_.load(std::memory_order_relaxed); + return storeDurationNs_.load(std::memory_order_relaxed) / kNanosecondsPerMicrosecond; } /** @@ -269,13 +273,13 @@ public: * * @return Total microseconds accumulated across every completed fetch. * - * @note Same threading and monotonicity contract as - * getStoreDurationUs(). + * @note Same threading, monotonicity and nanosecond-accumulation contract + * as getStoreDurationUs(). */ [[nodiscard]] std::uint64_t getFetchDurationUs() const noexcept { - return fetchDurationUs_.load(std::memory_order_relaxed); + return fetchDurationNs_.load(std::memory_order_relaxed) / kNanosecondsPerMicrosecond; } void @@ -337,10 +341,14 @@ protected: * The write counterpart of the timing fetchNodeObject() already does for * reads. `store()` is pure virtual, so unlike the read path there is no * non-virtual wrapper in this class to time — each concrete database calls - * this once per store it completes, and the single conversion to - * microseconds lives here rather than being repeated per subclass. Each - * concrete store path times only its backend call, so the total reflects - * disk work and excludes cache bookkeeping. + * this once per store it completes, and the single conversion lives here + * rather than being repeated per subclass. Each concrete store path times + * only its backend call, so the total reflects disk work and excludes cache + * bookkeeping. + * + * 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 the store took, as measured by the caller. * @@ -351,28 +359,37 @@ protected: * @note Thread-safe: one relaxed atomic add, no lock. Relaxed ordering is * correct because the total is a statistic that is only ever read by a * periodic observer, never used to order other memory operations. - * @note A negative duration cannot occur (steady_clock is monotonic), but - * a caller passing one would be clamped to zero rather than wrapping the - * unsigned total to a huge value. + * @note A negative duration cannot occur (steady_clock is monotonic); one + * would convert to a large unsigned value here, so callers must pass an + * end-minus-begin span from a single clock. */ void recordStoreDuration(std::chrono::steady_clock::duration elapsed) noexcept { - auto const us = std::chrono::duration_cast(elapsed).count(); - if (us > 0) - storeDurationUs_.fetch_add(static_cast(us), std::memory_order_relaxed); + storeDurationNs_.fetch_add( + static_cast( + std::chrono::duration_cast(elapsed).count()), + std::memory_order_relaxed); } // 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: @@ -397,20 +414,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 recordStoreDuration(), 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 e264336b35..1dc7669f8a 100644 --- a/src/libxrpl/nodestore/Database.cpp +++ b/src/libxrpl/nodestore/Database.cpp @@ -250,11 +250,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_; @@ -286,8 +289,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/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 6255f1d60a..34c2830ed6 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); diff --git a/src/tests/libxrpl/telemetry/MetricMacros.cpp b/src/tests/libxrpl/telemetry/MetricMacros.cpp index 9d5909a513..d36e7594c6 100644 --- a/src/tests/libxrpl/telemetry/MetricMacros.cpp +++ b/src/tests/libxrpl/telemetry/MetricMacros.cpp @@ -2847,14 +2847,14 @@ TEST(MetricMacros, nodestore_state_gauge_observes_exact_derived_means) EXPECT_EQ(truncating.at("nodestore_state").count(attrs("metric", "read_mean_us")), 0u); EXPECT_EQ(gaugeValue(truncating, "nodestore_state", attrs("metric", "node_reads_total")), 0); - // EDGE CASE: stores counted, but every one measured below a microsecond. - // recordStoreDuration() only adds when the cast to microseconds is > 0, so - // sub-microsecond stores leave the duration total at 0 while the count - // climbs. scaledMean divides on the COUNT alone, so it reports a genuine - // mean of 0 here rather than omitting the series. That is the correct - // reading: the stores really did complete - // in under a microsecond each, and the total beside it proves they - // happened. Absence is reserved for "no samples at all". + // EDGE CASE: stores counted, but the duration total still reads zero. + // The accumulator keeps nanoseconds and getStoreDurationUs() truncates, so + // a total under one microsecond reads as 0 while the count climbs. + // scaledMean divides on the COUNT alone, so it reports a genuine mean of 0 + // here rather than omitting the series. That is the correct reading: the + // stores really did complete in under a microsecond in total, and the count + // beside it proves they happened. Absence is reserved for "no samples at + // all". totals = NodeStoreTotals{ .storeCount = 9000, .storeDurationUs = 0, .fetchCount = 10, .fetchDurationUs = 50}; auto const subMicrosecond = collectWith(totals);