fix(nodestore): accumulate read and write latency in nanoseconds

The fetch and store duration counters converted each sample to
microseconds before adding it, so any backend call finishing in under a
microsecond contributed zero. A warm nudb read answers in a few hundred
nanoseconds, so on fast hardware every read floored and the totals stayed
at zero no matter how many reads happened -- the same loss of resolution
the microsecond report was introduced to avoid, one decade lower.

Both accumulators now hold nanoseconds, the clock's own resolution, and
convert once in getFetchDurationUs() and getStoreDurationUs(). The public
accessors, the node_reads_duration_us and node_writes_duration_us JSON
fields, and the metrics that read them all keep microseconds, so nothing
downstream changes unit. storeDurationStats() takes the raw duration
instead of a pre-converted integer so no caller can round early, and
updateFetchMetrics() scales its microsecond input to match.

FetchReport::elapsed stays microseconds: it carries one fetch, not a
total, and that is the unit it declares. The reported sum is therefore the
accumulated total minus a sub-microsecond remainder per fetch, so the two
tests that asserted exact equality between them now assert that bound.
Both had assertions that depended on how fast the host reads; the bound
holds on any hardware.

include/xrpl/nodestore/Database.h

@@ -12,6 +12,7 @@
 #include <xrpl/nodestore/WriteStats.h>
 
 #include <atomic>
+#include <chrono>
 #include <condition_variable>
 #include <cstdint>
 #include <functional>
@@ -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::uint64_t>(
+            std::chrono::duration_cast<std::chrono::nanoseconds>(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<std::uint64_t> 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<std::uint64_t> fetchDurationUs_{0};
+    std::atomic<std::uint64_t> 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<std::uint64_t> storeDurationUs_{0};
+    std::atomic<std::uint64_t> storeDurationNs_{0};
 
     mutable std::mutex readLock_;
     std::condition_variable readCondVar_;

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<std::uint64_t>(duration_cast<nanoseconds>(dur).count());
     auto const elapsedUs = duration_cast<microseconds>(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

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::uint64_t>(std::chrono::duration_cast<std::chrono::microseconds>(
-                                       std::chrono::steady_clock::now() - begin)
-                                       .count()));
+    storeDurationStats(std::chrono::steady_clock::now() - begin);
 
     if (cache_)
     {

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::uint64_t>(std::chrono::duration_cast<std::chrono::microseconds>(
-                                       std::chrono::steady_clock::now() - begin)
-                                       .count()));
+    storeDurationStats(std::chrono::steady_clock::now() - begin);
 
     storeStats(1, nObj->getData().size());
 }

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:

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);