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

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

src/libxrpl/nodestore/backend/NuDBFactory.cpp

@@ -87,10 +87,21 @@ public:
     std::atomic<std::uint64_t> insertMaxUs{0};
 
     /**
-     * Summed depth observed at each insert.
+     * Summed depth observed at each insert, accumulated at insert entry.
      */
     std::atomic<std::uint64_t> 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<std::uint64_t> 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.

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<std::uint64_t> deferrals_{0};
 
+    /**
+     * Deferrals attributable to ledger acquisition alone.
+     */
+    std::atomic<std::uint64_t> ledgerDeferrals_{0};
+
+    /**
+     * Timeouts attributable to ledger acquisition alone.
+     */
+    std::atomic<std::uint64_t> ledgerTimeouts_{0};
+
     /**
      * Timer bodies that ran and advanced the retry count.
      */

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

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.

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<std::int64_t>(stats.getDeferrals()));
     observe("acquire_timeouts", static_cast<std::int64_t>(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<std::int64_t>(stats.getLedgerDeferrals()));
+    observe("acquire_ledger_timeouts", static_cast<std::int64_t>(stats.getLedgerTimeouts()));
     observe("acquire_give_ups", static_cast<std::int64_t>(stats.getGiveUps()));
     observe("acquire_aborts", static_cast<std::int64_t>(stats.getAborts()));
     observe("acquire_aborts_partial", static_cast<std::int64_t>(stats.getAbortsWithPartialWork()));