feat(nodestore): expose fetch and store durations directly

fetchDurationUs_ had no getter, so telemetry reached it by building a JSON
object, stringifying a uint64 and parsing it back with stoll on every
collect tick. storeDurationUs_ was declared and never written or read at
all, along with the jss::node_writes_duration_us key.

Both now have accessors, both production store paths time their backend
call, and the registry reads them without the round trip. get_counts also
reports the write duration, so the RPC and the metric agree. Mean read
latency is the signal that separates a cold store from a warm one: warm
reads are single-digit microseconds, cold ones low hundreds.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>

include/xrpl/nodestore/Database.h

@@ -203,6 +203,36 @@ public:
         return storeSz_;
     }
 
+    /**
+     * Cumulative time spent in backend fetches, in microseconds.
+     *
+     * Divide by getFetchTotalCount() to get the mean read latency. That mean
+     * is what separates a cold store from a warm one: a warm store reads in
+     * single-digit microseconds, a cold one in low hundreds.
+     *
+     * @return The running microsecond total for the lifetime of this process.
+     */
+    std::uint64_t
+    getFetchDurationUs() const
+    {
+        return fetchDurationUs_;
+    }
+
+    /**
+     * Cumulative time spent in backend stores, in microseconds.
+     *
+     * Divide by getStoreCount() to get the mean write latency. This includes
+     * any time the backend spent waiting for its own internal locks, so it is
+     * wall time per store, not service time.
+     *
+     * @return The running microsecond total for the lifetime of this process.
+     */
+    std::uint64_t
+    getStoreDurationUs() const
+    {
+        return storeDurationUs_;
+    }
+
     /**
      * Total payload bytes returned by successful fetches.
      *
@@ -267,6 +297,21 @@ protected:
         storeSz_ += sz;
     }
 
+    /**
+     * 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.
+     *
+     * @param us Wall time of the completed backend store, in microseconds.
+     */
+    void
+    storeDurationStats(std::uint64_t us)
+    {
+        storeDurationUs_ += us;
+    }
+
     // Called by the public import function
     void
     importInternal(Backend& dstBackend, Database& srcDB);
@@ -300,7 +345,20 @@ private:
      */
     std::atomic<std::uint64_t> fetchSz_{0};
 
+    /**
+     * Wall time spent in backend fetches, in microseconds.
+     *
+     * Written by fetchNodeObject(), which times the whole fetch including a
+     * cache lookup that misses.
+     */
     std::atomic<std::uint64_t> fetchDurationUs_{0};
+
+    /**
+     * Wall time spent in backend stores, in microseconds.
+     *
+     * Written by each concrete store path via storeDurationStats(), which
+     * times only the backend call.
+     */
     std::atomic<std::uint64_t> storeDurationUs_{0};
 
     mutable std::mutex readLock_;

src/libxrpl/nodestore/Database.cpp

@@ -274,6 +274,7 @@ Database::getCountsJson(json::Value& obj)
     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_);
 }
 
 }  // namespace xrpl::NodeStore

src/libxrpl/nodestore/DatabaseNodeImp.cpp

@@ -9,6 +9,7 @@
 #include <xrpl/nodestore/Scheduler.h>
 #include <xrpl/nodestore/Types.h>
 
+#include <chrono>
 #include <cstdint>
 #include <exception>
 #include <functional>
@@ -23,7 +24,16 @@ DatabaseNodeImp::store(NodeObjectType type, Blob&& data, uint256 const& hash, st
     storeStats(1, data.size());
 
     auto obj = NodeObject::createObject(type, std::move(data), hash);
+
+    // Time only the backend call. The cache work below is not disk work and
+    // 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()));
+
     if (cache_)
     {
         // After the store, replace a negative cache entry if there is one

src/libxrpl/nodestore/DatabaseRotatingImp.cpp

@@ -14,6 +14,7 @@
 #include <xrpl/nodestore/Types.h>
 
 #include <atomic>
+#include <chrono>
 #include <cstdint>
 #include <exception>
 #include <functional>
@@ -128,7 +129,15 @@ DatabaseRotatingImp::store(NodeObjectType type, Blob&& data, uint256 const& hash
         return writableBackend_;
     }();
 
+    // Time only the backend call, matching DatabaseNodeImp, so the two store
+    // 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()));
+
     storeStats(1, nObj->getData().size());
 }
 

src/test/nodestore/Database_test.cpp

@@ -13,10 +13,12 @@
 #include <xrpl/beast/xor_shift_engine.h>
 #include <xrpl/config/BasicConfig.h>
 #include <xrpl/config/Constants.h>
+#include <xrpl/nodestore/Backend.h>
 #include <xrpl/nodestore/Database.h>
 #include <xrpl/nodestore/DummyScheduler.h>
 #include <xrpl/nodestore/Manager.h>
 #include <xrpl/nodestore/Types.h>
+#include <xrpl/nodestore/detail/DatabaseRotatingImp.h>
 #include <xrpl/protocol/SystemParameters.h>
 #include <xrpl/rdb/DatabaseCon.h>
 
@@ -614,6 +616,178 @@ public:
 
     //--------------------------------------------------------------------------
 
+    /**
+     * Verify the fetch and store duration accumulators are readable directly.
+     *
+     * Telemetry needs the mean backend latency, which is the cumulative
+     * duration divided by the matching operation count. Both accumulators
+     * must therefore be readable without a JSON round trip, must be zero on
+     * a fresh database, and must be independent of each other: writes may
+     * not move the read total and reads may not move the write total.
+     */
+    void
+    testDurationAccessors()
+    {
+        testcase("Fetch and store duration accessors");
+
+        DummyScheduler scheduler;
+
+        beast::TempDir const nodeDb;
+        Section nodeParams;
+        nodeParams.set(Keys::kType, "nudb");
+        nodeParams.set(Keys::kPath, nodeDb.path());
+
+        // No cache_size/cache_age is set, so DatabaseNodeImp builds no cache
+        // and every fetch reaches the backend. That makes the counts exact.
+        std::unique_ptr<Database> db =
+            Manager::instance().makeDatabase(megabytes(4), scheduler, 2, nodeParams, journal_);
+        if (!BEAST_EXPECT(db))
+            return;
+
+        // A fresh database has done no work, so every accumulator reads zero.
+        BEAST_EXPECT(db->getStoreCount() == 0);
+        BEAST_EXPECT(db->getStoreDurationUs() == 0);
+        BEAST_EXPECT(db->getFetchTotalCount() == 0);
+        BEAST_EXPECT(db->getFetchHitCount() == 0);
+        BEAST_EXPECT(db->getFetchDurationUs() == 0);
+
+        // Writes must advance the write count exactly and the write duration
+        // past zero: the backend inserts take microseconds of real work.
+        constexpr std::uint64_t kNumStored = 32;
+        auto const stored = createPredictableBatch(static_cast<int>(kNumStored), 4321);
+        BEAST_EXPECT(stored.size() == kNumStored);
+        storeBatch(*db, stored);
+
+        BEAST_EXPECT(db->getStoreCount() == kNumStored);
+        BEAST_EXPECT(db->getStoreDurationUs() > 0);
+
+        // Writes must leave the read accumulator alone. This also proves the
+        // read accessor does not report the write member.
+        BEAST_EXPECT(db->getFetchDurationUs() == 0);
+
+        auto const storeDurationAfterWrites = db->getStoreDurationUs();
+
+        // Positive path: every fetch finds its object, so the read counters
+        // and the read duration all advance.
+        for (auto const& object : stored)
+            BEAST_EXPECT(db->fetchNodeObject(object->getHash(), 0) != nullptr);
+
+        BEAST_EXPECT(db->getFetchTotalCount() == kNumStored);
+        BEAST_EXPECT(db->getFetchHitCount() == kNumStored);
+        BEAST_EXPECT(db->getFetchDurationUs() > 0);
+
+        // Reads must leave the write accumulator alone. This also proves the
+        // write accessor does not report the read member.
+        BEAST_EXPECT(db->getStoreDurationUs() == storeDurationAfterWrites);
+
+        // Negative path: a miss counts as a fetch but not as a hit, and it
+        // performs no write, so the write accumulator still cannot move.
+        constexpr std::uint64_t kNumMissing = 8;
+        auto const missing = createPredictableBatch(static_cast<int>(kNumMissing), 999);
+        BEAST_EXPECT(missing.size() == kNumMissing);
+        for (auto const& object : missing)
+            BEAST_EXPECT(db->fetchNodeObject(object->getHash(), 0) == nullptr);
+
+        BEAST_EXPECT(db->getFetchTotalCount() == kNumStored + kNumMissing);
+        BEAST_EXPECT(db->getFetchHitCount() == kNumStored);
+        BEAST_EXPECT(db->getStoreCount() == kNumStored);
+        BEAST_EXPECT(db->getStoreDurationUs() == storeDurationAfterWrites);
+    }
+
+    //--------------------------------------------------------------------------
+
+    /**
+     * Verify the rotating database records its write duration too.
+     *
+     * DatabaseRotatingImp has its own store path, separate from
+     * DatabaseNodeImp, and it is the path a node with online delete runs.
+     * A getter that only the non-rotating path feeds would read zero for
+     * the whole lifetime of such a node.
+     */
+    void
+    testRotatingDurationAccessors()
+    {
+        testcase("Rotating store duration accessors");
+
+        DummyScheduler scheduler;
+
+        beast::TempDir const writableDir;
+        beast::TempDir const archiveDir;
+
+        Section writableParams;
+        writableParams.set(Keys::kType, "nudb");
+        writableParams.set(Keys::kPath, writableDir.path());
+
+        Section archiveParams;
+        archiveParams.set(Keys::kType, "nudb");
+        archiveParams.set(Keys::kPath, archiveDir.path());
+
+        std::shared_ptr<Backend> writableBackend =
+            Manager::instance().makeBackend(writableParams, megabytes(4), scheduler, journal_);
+        std::shared_ptr<Backend> archiveBackend =
+            Manager::instance().makeBackend(archiveParams, megabytes(4), scheduler, journal_);
+        if (!BEAST_EXPECT(writableBackend) || !BEAST_EXPECT(archiveBackend))
+            return;
+        writableBackend->open();
+        archiveBackend->open();
+
+        DatabaseRotatingImp rotating(
+            scheduler,
+            2,
+            std::move(writableBackend),
+            std::move(archiveBackend),
+            writableParams,
+            journal_);
+
+        // The private fetchNodeObject override hides the public base overload,
+        // so exercise the rotating store through the Database interface, which
+        // is also how production callers reach it.
+        Database& db = rotating;
+
+        // A fresh rotating database has done no work either.
+        BEAST_EXPECT(db.getStoreCount() == 0);
+        BEAST_EXPECT(db.getStoreDurationUs() == 0);
+        BEAST_EXPECT(db.getFetchTotalCount() == 0);
+        BEAST_EXPECT(db.getFetchDurationUs() == 0);
+
+        constexpr std::uint64_t kNumStored = 32;
+        auto const stored = createPredictableBatch(static_cast<int>(kNumStored), 8642);
+        BEAST_EXPECT(stored.size() == kNumStored);
+        storeBatch(db, stored);
+
+        BEAST_EXPECT(db.getStoreCount() == kNumStored);
+        BEAST_EXPECT(db.getStoreDurationUs() > 0);
+        BEAST_EXPECT(db.getFetchDurationUs() == 0);
+
+        auto const storeDurationAfterWrites = db.getStoreDurationUs();
+
+        // Every object is in the writable backend, so the archive is never
+        // consulted and no copy-forward write happens on these reads.
+        for (auto const& object : stored)
+            BEAST_EXPECT(db.fetchNodeObject(object->getHash(), 0) != nullptr);
+
+        BEAST_EXPECT(db.getFetchTotalCount() == kNumStored);
+        BEAST_EXPECT(db.getFetchHitCount() == kNumStored);
+        BEAST_EXPECT(db.getFetchDurationUs() > 0);
+        BEAST_EXPECT(db.getStoreCount() == kNumStored);
+        BEAST_EXPECT(db.getStoreDurationUs() == storeDurationAfterWrites);
+
+        // Negative path: a hash in neither backend misses both, so it counts
+        // as a fetch, not as a hit, and triggers no copy-forward write.
+        constexpr std::uint64_t kNumMissing = 8;
+        auto const missing = createPredictableBatch(static_cast<int>(kNumMissing), 1357);
+        BEAST_EXPECT(missing.size() == kNumMissing);
+        for (auto const& object : missing)
+            BEAST_EXPECT(db.fetchNodeObject(object->getHash(), 0) == nullptr);
+
+        BEAST_EXPECT(db.getFetchTotalCount() == kNumStored + kNumMissing);
+        BEAST_EXPECT(db.getFetchHitCount() == kNumStored);
+        BEAST_EXPECT(db.getStoreCount() == kNumStored);
+        BEAST_EXPECT(db.getStoreDurationUs() == storeDurationAfterWrites);
+    }
+
+    //--------------------------------------------------------------------------
+
     void
     testImport(
         std::string const& destBackendType,
@@ -788,6 +962,10 @@ public:
 
         testCounterWidths();
 
+        testDurationAccessors();
+
+        testRotatingDurationAccessors();
+
         testConfig();
 
         testNodeStore("memory", false, seedValue);

src/xrpld/telemetry/MetricsRegistry.cpp

@@ -805,10 +805,16 @@ MetricsRegistry::registerNodeStoreGauge()
                 observe("node_written_bytes", static_cast<int64_t>(db.getStoreSize()));
                 observe("node_read_bytes", static_cast<int64_t>(db.getFetchSize()));
 
+                // Cumulative I/O durations, read straight off the atomics.
+                observe("node_reads_duration_us", static_cast<int64_t>(db.getFetchDurationUs()));
+                observe("node_writes_duration_us", static_cast<int64_t>(db.getStoreDurationUs()));
+
                 // Write load score (instantaneous).
                 observe("write_load", static_cast<int64_t>(db.getWriteLoad()));
 
-                // Read queue depth (instantaneous).
+                // Read queue depth (instantaneous). The JSON object is still
+                // needed for the queue and thread-pool values, which have no
+                // accessors.
                 json::Value obj(json::ValueType::Object);
                 db.getCountsJson(obj);
                 if (obj.isMember("read_queue"))
@@ -816,16 +822,6 @@ MetricsRegistry::registerNodeStoreGauge()
                     observe("read_queue", static_cast<int64_t>(obj["read_queue"].asUInt()));
                 }
 
-                // Cumulative read duration (stored as JSON string, not int).
-                if (obj.isMember(jss::node_reads_duration_us))
-                {
-                    auto durStr = obj[jss::node_reads_duration_us].asString();
-                    if (!durStr.empty())
-                    {
-                        observe("node_reads_duration_us", static_cast<int64_t>(std::stoll(durStr)));
-                    }
-                }
-
                 // Read thread pool stats (native JSON ints, no jss:: constants).
                 if (obj.isMember("read_request_bundle"))
                 {