Merge branch 'pratik/otel-phase9-metric-gap-fill' into pratik/otel-phase10-workload-validation

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