diff --git a/include/xrpl/nodestore/Database.h b/include/xrpl/nodestore/Database.h index 45b81ce094..957402a35f 100644 --- a/include/xrpl/nodestore/Database.h +++ b/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 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 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 storeDurationUs_{0}; mutable std::mutex readLock_; diff --git a/src/libxrpl/nodestore/Database.cpp b/src/libxrpl/nodestore/Database.cpp index ac51dbfb2c..cd3f4063d6 100644 --- a/src/libxrpl/nodestore/Database.cpp +++ b/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 diff --git a/src/libxrpl/nodestore/DatabaseNodeImp.cpp b/src/libxrpl/nodestore/DatabaseNodeImp.cpp index 9323d69131..8d7eb28443 100644 --- a/src/libxrpl/nodestore/DatabaseNodeImp.cpp +++ b/src/libxrpl/nodestore/DatabaseNodeImp.cpp @@ -9,6 +9,7 @@ #include #include +#include #include #include #include @@ -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::chrono::duration_cast( + std::chrono::steady_clock::now() - begin) + .count())); + if (cache_) { // After the store, replace a negative cache entry if there is one diff --git a/src/libxrpl/nodestore/DatabaseRotatingImp.cpp b/src/libxrpl/nodestore/DatabaseRotatingImp.cpp index 23a48a3bf3..23ea3c5ac4 100644 --- a/src/libxrpl/nodestore/DatabaseRotatingImp.cpp +++ b/src/libxrpl/nodestore/DatabaseRotatingImp.cpp @@ -14,6 +14,7 @@ #include #include +#include #include #include #include @@ -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::chrono::duration_cast( + std::chrono::steady_clock::now() - begin) + .count())); + storeStats(1, nObj->getData().size()); } diff --git a/src/test/nodestore/Database_test.cpp b/src/test/nodestore/Database_test.cpp index 69b7dabe16..3791dd3d67 100644 --- a/src/test/nodestore/Database_test.cpp +++ b/src/test/nodestore/Database_test.cpp @@ -13,10 +13,12 @@ #include #include #include +#include #include #include #include #include +#include #include #include @@ -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 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(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(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 writableBackend = + Manager::instance().makeBackend(writableParams, megabytes(4), scheduler, journal_); + std::shared_ptr 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(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(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); diff --git a/src/xrpld/telemetry/MetricsRegistry.cpp b/src/xrpld/telemetry/MetricsRegistry.cpp index 1c0c83221e..833c7f35d4 100644 --- a/src/xrpld/telemetry/MetricsRegistry.cpp +++ b/src/xrpld/telemetry/MetricsRegistry.cpp @@ -805,10 +805,16 @@ MetricsRegistry::registerNodeStoreGauge() observe("node_written_bytes", static_cast(db.getStoreSize())); observe("node_read_bytes", static_cast(db.getFetchSize())); + // Cumulative I/O durations, read straight off the atomics. + observe("node_reads_duration_us", static_cast(db.getFetchDurationUs())); + observe("node_writes_duration_us", static_cast(db.getStoreDurationUs())); + // Write load score (instantaneous). observe("write_load", static_cast(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(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(std::stoll(durStr))); - } - } - // Read thread pool stats (native JSON ints, no jss:: constants). if (obj.isMember("read_request_bundle")) {