diff --git a/include/xrpl/nodestore/WriteStats.h b/include/xrpl/nodestore/WriteStats.h index 08d4529960..11aafff0c9 100644 --- a/include/xrpl/nodestore/WriteStats.h +++ b/include/xrpl/nodestore/WriteStats.h @@ -25,7 +25,7 @@ namespace xrpl::node_store { * | * concurrentWriters = queue length here * insertTotalUs / insertCount = time in the whole system (W) - * depthSum / insertCount = mean depth (L) + * depthSum / depthSamples = mean depth (L) * * @note All fields except @ref concurrentWriters are cumulative for the * life of the backend, so a reader must difference successive @@ -38,7 +38,7 @@ namespace xrpl::node_store { * if (auto const s = backend->getWriteStats(); s && s->insertCount) * { * double const meanUs = double(s->insertTotalUs) / s->insertCount; - * double const meanDepth = double(s->depthSum) / s->insertCount; + * double const meanDepth = double(s->depthSum) / s->depthSamples; * double const serviceUs = meanUs / meanDepth; // Little's Law * } * @endcode @@ -76,6 +76,15 @@ struct WriteStats * @ref insertCount this gives mean depth. */ std::uint64_t depthSum = 0; + + /** + * Number of depth samples summed into @ref depthSum. + * + * Divide @ref depthSum by this, not by @ref insertCount: a sample is + * taken when an insert starts, while insertCount only rises when one + * finishes, so the two populations differ while inserts are in flight. + */ + std::uint64_t depthSamples = 0; }; } // namespace xrpl::node_store diff --git a/src/libxrpl/nodestore/backend/NuDBFactory.cpp b/src/libxrpl/nodestore/backend/NuDBFactory.cpp index 4f19283c8e..26b1af1037 100644 --- a/src/libxrpl/nodestore/backend/NuDBFactory.cpp +++ b/src/libxrpl/nodestore/backend/NuDBFactory.cpp @@ -87,10 +87,21 @@ public: std::atomic insertMaxUs{0}; /** - * Summed depth observed at each insert. + * Summed depth observed at each insert, accumulated at insert entry. */ std::atomic depthSum{0}; + /** + * How many depth samples make up @ref depthSum. + * + * Its own counter rather than reusing the completed-insert count, because + * the two are taken at different moments: a depth sample exists as soon + * as an insert starts, while the insert count only rises when one + * finishes. Dividing by the wrong one biases the mean downward under + * load, which is when the mean matters. + */ + std::atomic depthSamples{0}; + NuDBBackend( size_t keyBytes, Section const& keyValues, @@ -270,7 +281,16 @@ public: // NuDB takes one global mutex for the whole insert, so the wait is // invisible from here. Record the depth we joined at and the wall // time we spent; the split follows from Little's Law. + // + // Depth and its sample count are both folded in HERE, at entry, so + // the mean is over the same population. Counting the sample at exit + // instead would drop every insert still in flight, and those are the + // slow, deep ones -- biasing the mean down exactly when queueing is + // worst. With all writers inside their first insert the exit-counted + // version reports no depth at all. auto const depth = concurrentWriters.fetch_add(1, std::memory_order_relaxed) + 1; + depthSum.fetch_add(depth, std::memory_order_relaxed); + depthSamples.fetch_add(1, std::memory_order_relaxed); auto const begin = std::chrono::steady_clock::now(); // A scope guard rather than straight-line code, because the insert @@ -369,6 +389,7 @@ public: stats.insertTotalUs = insertTotalUs.load(std::memory_order_relaxed); stats.insertMaxUs = insertMaxUs.load(std::memory_order_relaxed); stats.depthSum = depthSum.load(std::memory_order_relaxed); + stats.depthSamples = depthSamples.load(std::memory_order_relaxed); return stats; } @@ -424,7 +445,6 @@ private: concurrentWriters.fetch_sub(1, std::memory_order_relaxed); insertCount.fetch_add(1, std::memory_order_relaxed); insertTotalUs.fetch_add(elapsedUs, std::memory_order_relaxed); - depthSum.fetch_add(depth, std::memory_order_relaxed); // std::atomic has no fetch_max, so raise the maximum with a CAS // loop. Mirrors the clamp loop in OTelCollector.cpp. diff --git a/src/xrpld/app/ledger/AcquireStats.h b/src/xrpld/app/ledger/AcquireStats.h index 027a6b346b..7ed93e85c7 100644 --- a/src/xrpld/app/ledger/AcquireStats.h +++ b/src/xrpld/app/ledger/AcquireStats.h @@ -93,9 +93,11 @@ public: * advance the retry count toward give-up. */ void - recordDeferral() + recordDeferral(bool ledgerAcquisition = false) { deferrals_.fetch_add(1, std::memory_order_relaxed); + if (ledgerAcquisition) + ledgerDeferrals_.fetch_add(1, std::memory_order_relaxed); } /** @@ -105,9 +107,11 @@ public: * separate from deferrals. */ void - recordTimeout() + recordTimeout(bool ledgerAcquisition = false) { timeouts_.fetch_add(1, std::memory_order_relaxed); + if (ledgerAcquisition) + ledgerTimeouts_.fetch_add(1, std::memory_order_relaxed); } /** @@ -171,6 +175,32 @@ public: return timeouts_.load(std::memory_order_relaxed); } + /** + * Deferrals that belong to ledger acquisition only. + * + * @ref getDeferrals covers every TimeoutCounter subclass, so a busy + * replay or transaction-set lane inflates it. Compare this against + * @ref getLedgerTimeouts to judge ledger acquisition on its own. + */ + [[nodiscard]] std::uint64_t + getLedgerDeferrals() const + { + return ledgerDeferrals_.load(std::memory_order_relaxed); + } + + /** + * Timeouts that belong to ledger acquisition only. + * + * The partner of @ref getLedgerDeferrals: rising deferrals with flat + * timeouts here means ledger acquisition's give-up path is disarmed, + * which the all-lane counters cannot show. + */ + [[nodiscard]] std::uint64_t + getLedgerTimeouts() const + { + return ledgerTimeouts_.load(std::memory_order_relaxed); + } + /** * Return the number of acquisitions that exhausted their retry budget. */ @@ -224,6 +254,16 @@ private: */ std::atomic deferrals_{0}; + /** + * Deferrals attributable to ledger acquisition alone. + */ + std::atomic ledgerDeferrals_{0}; + + /** + * Timeouts attributable to ledger acquisition alone. + */ + std::atomic ledgerTimeouts_{0}; + /** * Timer bodies that ran and advanced the retry count. */ diff --git a/src/xrpld/app/ledger/detail/TimeoutCounter.cpp b/src/xrpld/app/ledger/detail/TimeoutCounter.cpp index c5a54b8cc9..3e9961bfb1 100644 --- a/src/xrpld/app/ledger/detail/TimeoutCounter.cpp +++ b/src/xrpld/app/ledger/detail/TimeoutCounter.cpp @@ -67,7 +67,7 @@ TimeoutCounter::queueJob(ScopedLockType& sl) // Counted separately from timeouts: this path re-arms the timer // without running invokeOnTimer, so timeouts_ does not advance and the // give-up test that reads it cannot fire while the lane stays full. - app_.getAcquireStats().recordDeferral(); + app_.getAcquireStats().recordDeferral(isLedgerAcquisition()); JLOG(journal_.debug()) << "Deferring " << queueJobParameter_.jobName << " timer due to load"; setTimer(sl); @@ -92,7 +92,7 @@ TimeoutCounter::invokeOnTimer() if (!progress_) { ++timeouts_; - app_.getAcquireStats().recordTimeout(); + app_.getAcquireStats().recordTimeout(isLedgerAcquisition()); JLOG(journal_.debug()) << "Timeout(" << timeouts_ << ") " << " acquiring " << hash_; onTimer(false, sl); diff --git a/src/xrpld/app/ledger/detail/TimeoutCounter.h b/src/xrpld/app/ledger/detail/TimeoutCounter.h index 682abf1537..bba22139be 100644 --- a/src/xrpld/app/ledger/detail/TimeoutCounter.h +++ b/src/xrpld/app/ledger/detail/TimeoutCounter.h @@ -139,6 +139,23 @@ protected: QueueJobParameter queueJobParameter_; + /** + * Whether this counter belongs to ledger acquisition. + * + * Deferrals and timeouts are recorded in this base class, so they would + * otherwise pool every subclass together: a saturated replay lane would + * look exactly like a stalled ledger acquisition. The job name already + * identifies the subclass, so it is the cheapest discriminator available + * and needs no extra state. + * + * @return True for the InboundLedger lane, false for every other. + */ + [[nodiscard]] bool + isLedgerAcquisition() const + { + return queueJobParameter_.jobName == "InboundLedger"; + } + private: /** * Calls onTimer() if in the right state. diff --git a/src/xrpld/telemetry/MetricsRegistry.cpp b/src/xrpld/telemetry/MetricsRegistry.cpp index e9114daa1a..7a9ff556b4 100644 --- a/src/xrpld/telemetry/MetricsRegistry.cpp +++ b/src/xrpld/telemetry/MetricsRegistry.cpp @@ -852,7 +852,7 @@ MetricsRegistry::observeWritePathDetail(node_store::Database const& db, ObserveF // above 1.0 even under load. An integral gauge would truncate that to 1 // and lose the whole signal, hence the fixed-point scale -- which the // name states, so nobody reads 140 as 140 writers. - if (auto const mean = scaledMean(ws->depthSum, ws->insertCount, 100)) + if (auto const mean = scaledMean(ws->depthSum, ws->depthSamples, 100)) observe("nudb_writer_depth_x100", *mean); } @@ -865,6 +865,13 @@ MetricsRegistry::observeAcquireStats(AcquireStats const& stats, ObserveFn const& // give-up path cannot fire, so an acquisition never ends. observe("acquire_deferrals", static_cast(stats.getDeferrals())); observe("acquire_timeouts", static_cast(stats.getTimeouts())); + + // The same two events, narrowed to ledger acquisition. The pair above + // sums every TimeoutCounter subclass, so a busy replay lane can imitate + // a stalled ledger acquisition; compare these two instead when asking + // whether ledger acquisition's give-up path is advancing. + observe("acquire_ledger_deferrals", static_cast(stats.getLedgerDeferrals())); + observe("acquire_ledger_timeouts", static_cast(stats.getLedgerTimeouts())); observe("acquire_give_ups", static_cast(stats.getGiveUps())); observe("acquire_aborts", static_cast(stats.getAborts())); observe("acquire_aborts_partial", static_cast(stats.getAbortsWithPartialWork()));