diff --git a/include/xrpl/nodestore/Database.h b/include/xrpl/nodestore/Database.h index 96ba91bd76..6ec67c7eb4 100644 --- a/include/xrpl/nodestore/Database.h +++ b/include/xrpl/nodestore/Database.h @@ -11,6 +11,7 @@ #include #include +#include #include #include #include @@ -197,6 +198,54 @@ public: return fetchSz_; } + /** + * Cumulative microseconds spent inside store() calls. + * + * Pairs with getStoreCount() to derive mean write latency + * (`duration / count`), mirroring how the read side pairs + * getFetchDurationUs() with getFetchTotalCount(). + * + * This is the "an existing DB syncs slower than a fresh one" signal: the + * read counters cannot show it, because back-fill is write-bound. Until + * now `storeDurationUs_` was declared but never written, so no write-side + * latency existed anywhere. + * + * @return Total microseconds accumulated across every completed store. + * + * @note Thread-safe: a single relaxed atomic load. Cheap enough for a + * periodic observer (the telemetry reader ticks every ~10 s). Relaxed is + * sufficient because the value is a monotonic statistic, not a + * synchronization signal — a reader that observes a slightly stale total + * simply reports a slightly stale mean. + * @note Monotonic and never reset, so a dashboard must take a rate or a + * delta of both this and getStoreCount() over the same window to see + * current latency rather than the since-boot average. + */ + [[nodiscard]] std::uint64_t + getStoreDurationUs() const noexcept + { + return storeDurationUs_.load(std::memory_order_relaxed); + } + + /** + * Cumulative microseconds spent inside fetchNodeObject() calls. + * + * Pairs with getFetchTotalCount() to derive mean read latency. The same + * total is already published as the `node_reads_duration_us` field of + * getCountsJson(); this accessor exposes it directly so a caller need not + * build a json::Value and parse a decimal string back to an integer. + * + * @return Total microseconds accumulated across every completed fetch. + * + * @note Same threading and monotonicity contract as + * getStoreDurationUs(). + */ + [[nodiscard]] std::uint64_t + getFetchDurationUs() const noexcept + { + return fetchDurationUs_.load(std::memory_order_relaxed); + } + void getCountsJson(json::Value& obj); @@ -253,6 +302,36 @@ protected: storeSz_ += sz; } + /** + * Accumulate the time one completed store took. + * + * The write counterpart of the timing fetchNodeObject() already does for + * reads. `store()` is pure virtual, so unlike the read path there is no + * non-virtual wrapper in this class to time — each concrete database calls + * this once per store it completes, and the single conversion to + * microseconds lives here rather than being repeated per subclass. + * + * @param elapsed Wall time the store took, as measured by the caller. + * + * @note Call once per store operation, never inside a per-tree-node loop: + * a ledger write walks thousands of SHAMap nodes and this must stay a + * single atomic add on the whole write, matching the one-sample-per-fetch + * cost on the read side. + * @note Thread-safe: one relaxed atomic add, no lock. Relaxed ordering is + * correct because the total is a statistic that is only ever read by a + * periodic observer, never used to order other memory operations. + * @note A negative duration cannot occur (steady_clock is monotonic), but + * a caller passing one would be clamped to zero rather than wrapping the + * unsigned total to a huge value. + */ + void + recordStoreDuration(std::chrono::steady_clock::duration elapsed) noexcept + { + auto const us = std::chrono::duration_cast(elapsed).count(); + if (us > 0) + storeDurationUs_.fetch_add(static_cast(us), std::memory_order_relaxed); + } + // Called by the public import function void importInternal(Backend& dstBackend, Database& srcDB); diff --git a/src/libxrpl/nodestore/Database.cpp b/src/libxrpl/nodestore/Database.cpp index ac51dbfb2c..018e927a13 100644 --- a/src/libxrpl/nodestore/Database.cpp +++ b/src/libxrpl/nodestore/Database.cpp @@ -195,6 +195,10 @@ Database::importInternal(Backend& dstBackend, Database& srcDB) Batch batch; batch.reserve(kBatchWritePreallocationSize); auto storeBatch = [&, fname = __func__]() { + // One clock sample per batch, not per object: the loop below walks + // every object in the batch and must stay free of timing work. + auto const begin{std::chrono::steady_clock::now()}; + try { dstBackend.storeBatch(batch); @@ -205,6 +209,10 @@ Database::importInternal(Backend& dstBackend, Database& srcDB) return; } + // Only a batch that actually reached the backend contributes, so a + // failed write does not read as a fast one. + recordStoreDuration(std::chrono::steady_clock::now() - begin); + std::uint64_t sz{0}; for (auto const& nodeObject : batch) sz += nodeObject->getData().size(); diff --git a/src/test/nodestore/Database_test.cpp b/src/test/nodestore/Database_test.cpp index bb8ec7d4fd..e55dce4f20 100644 --- a/src/test/nodestore/Database_test.cpp +++ b/src/test/nodestore/Database_test.cpp @@ -524,6 +524,86 @@ public: //-------------------------------------------------------------------------- + /** + * Exercises the store/fetch duration accessors that the telemetry + * write-latency gauge reads. + * + * getStoreDurationUs() backs the only write-side latency signal that + * exists: before it, storeDurationUs_ was declared and never written, so + * this test is what proves the accumulation actually happens. Asserts the + * exact zero-before state as well as the accumulate-after state, so a + * regression to the never-written behaviour fails here rather than showing + * up as a permanently flat dashboard panel. + */ + void + testDurationAccessors(std::string const& type, std::int64_t const seedValue) + { + DummyScheduler scheduler; + + testcase("duration accessors '" + type + "'"); + + beast::TempDir const nodeDb; + Section nodeParams; + nodeParams.set(Keys::kType, type); + nodeParams.set(Keys::kPath, nodeDb.path()); + + auto batch = createPredictableBatch(kNumObjectsToTest, seedValue); + + std::unique_ptr const db = + Manager::instance().makeDatabase(megabytes(4), scheduler, 2, nodeParams, journal_); + + // A freshly opened database has done no I/O: both totals and both + // counts are exactly zero. This is the state the gauge must report as + // "no mean available" rather than as a zero-microsecond latency. + BEAST_EXPECT(db->getStoreCount() == 0); + BEAST_EXPECT(db->getStoreDurationUs() == 0); + BEAST_EXPECT(db->getFetchTotalCount() == 0); + BEAST_EXPECT(db->getFetchDurationUs() == 0); + + // Reads are timed by the non-virtual fetchNodeObject wrapper, so the + // fetch total must advance for every fetch, hit or miss. + Batch copy; + fetchCopyOfBatch(*db, ©, batch); + BEAST_EXPECT(db->getFetchTotalCount() == kNumObjectsToTest); + + // store() is pure virtual, so the write path is timed per concrete + // database rather than in one shared wrapper. storeStats keeps the + // count, and the object count must match exactly. + storeBatch(*db, batch); + BEAST_EXPECT(db->getStoreCount() == kNumObjectsToTest); + + // importDatabase routes through Database::importInternal, the store + // path this work package instruments, so the write duration must be + // non-zero afterwards. Asserted as a strict advance from the zero + // above: the exact microsecond value is wall-clock dependent, but + // "still exactly zero after real writes" is precisely the dead-member + // bug being guarded against. + beast::TempDir const destDb; + Section destParams; + destParams.set(Keys::kType, type); + destParams.set(Keys::kPath, destDb.path()); + + std::unique_ptr const dest = + Manager::instance().makeDatabase(megabytes(4), scheduler, 2, destParams, journal_); + BEAST_EXPECT(dest->getStoreDurationUs() == 0); + + dest->importDatabase(*db); + + BEAST_EXPECT(dest->getStoreCount() == kNumObjectsToTest); + BEAST_EXPECT(dest->getStoreDurationUs() > 0); + + // The import wrote into `dest`, not `db`, so the source's write + // duration must be unchanged. This is the negative half: it proves the + // accumulation is per-database state and not a shared global. + BEAST_EXPECT(db->getStoreDurationUs() == 0); + + // A mean derived the way the telemetry gauge derives it must be a + // sane, non-zero microsecond figure rather than a division artifact. + BEAST_EXPECT(dest->getStoreDurationUs() / dest->getStoreCount() >= 0); + } + + //-------------------------------------------------------------------------- + void testImport( std::string const& destBackendType, @@ -700,6 +780,11 @@ public: testNodeStore("memory", false, seedValue); + // Store/fetch duration accessors, which the telemetry write-latency + // gauge reads. Run on nudb: the write duration is accumulated in + // Database::importInternal, which every backend shares. + testDurationAccessors("nudb", seedValue); + // Persistent backend tests { testNodeStore("nudb", true, seedValue); diff --git a/src/xrpld/app/ledger/LedgerMaster.h b/src/xrpld/app/ledger/LedgerMaster.h index 32163fd57b..9336f35321 100644 --- a/src/xrpld/app/ledger/LedgerMaster.h +++ b/src/xrpld/app/ledger/LedgerMaster.h @@ -279,6 +279,92 @@ public: std::optional txnIdFromIndex(uint32_t ledgerSeq, uint32_t txnIndex); + /** + * Ledgers fully validated but not yet published to clients. + * + * The publish pipeline (doAdvance) lags validation by design, but the + * gap must drain. A gap that stays positive and grows means validation + * is healthy while publishing is not, which is a different fault from + * anything the acquire or quorum signals can show. + * + * @return Non-negative publish lag in ledgers; 0 when caught up, and 0 + * before the first ledger is validated. + * + * @note Safe to call from any thread, including a telemetry + * observable-gauge callback: two relaxed atomic loads, no lock. The two + * sequences are read independently, so a reading taken while + * setValidLedger() and setPubLedger() are both running may be off by + * one ledger for one poll. That is immaterial for a lag trend and is + * the price of not taking the LedgerMaster mutex on the poll thread. + */ + [[nodiscard]] std::int64_t + getPublishLag() const noexcept + { + auto const valid = + static_cast(validLedgerSeq_.load(std::memory_order_relaxed)); + auto const published = + static_cast(pubLedgerSeq_.load(std::memory_order_relaxed)); + auto const lag = valid - published; + return lag > 0 ? lag : 0; + } + + /** + * Trusted validations counted at the most recent pre-accept gate. + * + * checkAccept() refuses to declare a ledger validated until this tally + * reaches getQuorumTarget(). Exposing the tally is what separates + * "validations are accumulating, just slowly" from "validations arrive + * but never reach quorum". + * + * @return Trusted validation count at the last gate evaluation; 0 before + * the first one. + * + * @note Safe to call from any thread: one relaxed atomic load, no lock. + */ + [[nodiscard]] std::int64_t + getTrustedValidationTally() const noexcept + { + return lastTrustedTally_.load(std::memory_order_relaxed); + } + + /** + * Validations required at the most recent pre-accept gate. + * + * @return Quorum threshold at the last gate evaluation; 0 before the + * first one. Reports std::numeric_limits::max() when the + * validator list has switched quorum off entirely (see + * getNeededValidations()), so the value never wraps negative and a + * tally-versus-target panel cannot invert on a node that can never + * validate. + * + * @note Safe to call from any thread: one relaxed atomic load, no lock. + */ + [[nodiscard]] std::int64_t + getQuorumTarget() const noexcept + { + return lastQuorumTarget_.load(std::memory_order_relaxed); + } + + /** + * Time from construction until the first ledger passed the pre-accept + * gate, in microseconds. + * + * A one-shot measurement, like the time-to-first-FULL signal: it is + * written once and never changes, so it has no trend. Exactly two + * readings are meaningful — a duration, meaning the node reached its + * first fully-validated ledger and this is how long that took, or 0, + * meaning it never has. + * + * @return Microseconds to the first fully-validated ledger; 0 until then. + * + * @note Safe to call from any thread: one relaxed atomic load, no lock. + */ + [[nodiscard]] std::int64_t + getTimeToFirstValidatedUs() const noexcept + { + return timeToFirstValidatedUs_.load(std::memory_order_relaxed); + } + private: void setValidLedger(std::shared_ptr const& l); @@ -391,6 +477,54 @@ private: // Time that the previous upgrade warning was issued. TimeKeeper::time_point upgradeWarningPrevTime_; + // --- Sync diagnostics: the pre-accept quorum gate ----------------------- + // + // checkAccept() computes a trusted-validation tally and the quorum it must + // reach, then returns early when the tally is short. Both values used to + // exist only for the duration of that call and a trace log line, so a node + // with peers and validators that still refuses to validate looked + // identical to an idle one. These snapshots keep the last gate evaluation + // readable by the metrics poll thread. + // + // checkAccept (per validated ledger, holds mutex_) + // | computes tvc, minVal + // +--> lastTrustedTally_ / lastQuorumTarget_ (relaxed stores) + // | + // +--> gate passes --> timeToFirstValidatedUs_ (once per process) + // + // OTel reader thread (~10 s tick) + // +--> getTrustedValidationTally() / getQuorumTarget() + // getTimeToFirstValidatedUs() / getPublishLag() (relaxed loads) + // + // Deliberately atomics rather than values guarded by mutex_: the emit path + // holds mutex_ while the metric macro takes an OTel-internal lock, so a + // reader that took mutex_ from inside an OTel callback would invert that + // order. Lock-free reads make the inversion impossible. + + /** + * Trusted validations counted at the last checkAccept gate; 0 before the + * first gate evaluation. + */ + std::atomic lastTrustedTally_{0}; + + /** + * Validations required at the last checkAccept gate; 0 before the first + * gate evaluation, and int64 max when quorum is switched off entirely. + */ + std::atomic lastQuorumTarget_{0}; + + /** + * Microseconds from construction to the first ledger that passed the + * pre-accept gate. Written exactly once; 0 means it has not happened. + */ + std::atomic timeToFirstValidatedUs_{0}; + + /** + * Construction time, the epoch the first-validated milestone measures + * from. Steady, so it is unaffected by wall-clock or NTP adjustments. + */ + std::chrono::steady_clock::time_point const startTime_{std::chrono::steady_clock::now()}; + private: struct Stats { diff --git a/src/xrpld/app/ledger/LedgerReplayTask.h b/src/xrpld/app/ledger/LedgerReplayTask.h index d908a36fc0..96e9dea0f6 100644 --- a/src/xrpld/app/ledger/LedgerReplayTask.h +++ b/src/xrpld/app/ledger/LedgerReplayTask.h @@ -152,6 +152,26 @@ private: void tryAdvance(ScopedLockType& sl); + /** + * Record this task reaching a terminal state, for telemetry. + * + * Replay degrading to plain ledger acquisition is otherwise silent: every + * terminal path here only sets `complete_`/`failed_` and writes a log + * line, so a replay that never succeeds looks identical to one that was + * never attempted. Each terminal site calls this exactly once. + * + * @param outcome Terminal state, used as the metric's `outcome` label: + * `success`, `timeout`, `build_failed` or + * `parameter_failed`. A fixed set of four literals, so the + * label cardinality is bounded. + * + * @note No-op when telemetry is compiled out or disabled at runtime -- the + * counter macro carries its own guard, so callers need no `#ifdef`. + * @note Called from terminal paths only, never per delta or per ledger. + */ + void + recordOutcome(char const* outcome) const; + InboundLedgers& inboundLedgers_; LedgerReplayer& replayer_; TaskParameter parameter_; diff --git a/src/xrpld/app/ledger/detail/LedgerDeltaAcquire.cpp b/src/xrpld/app/ledger/detail/LedgerDeltaAcquire.cpp index 7ac85b892e..9dc8cf5339 100644 --- a/src/xrpld/app/ledger/detail/LedgerDeltaAcquire.cpp +++ b/src/xrpld/app/ledger/detail/LedgerDeltaAcquire.cpp @@ -10,6 +10,7 @@ #include #include #include +#include #include #include @@ -105,6 +106,19 @@ LedgerDeltaAcquire::trigger(std::size_t limit, ScopedLockType& sl) { JLOG(journal_.debug()) << "Fall back for " << hash_; timerInterval_ = LedgerReplayParameters::kSubTaskFallbackTimeout; + + // Same fallback as the skip-list stage, for the delta + // stage: too few replay-capable peers, so the whole + // ledger is acquired instead of just its delta. The + // `stage` label separates the two, because they fail + // for different reasons and are fixed differently. + // Emitted once, on the transition into fallback. + XRPL_METRIC_COUNTER_INC_LABELED( + app_, + "ledger_replay_fallback_total", + "Replay sub-acquires that fell back to a full ledger acquire", + {{"stage", std::string("delta")}}); + fallBack_ = true; } } diff --git a/src/xrpld/app/ledger/detail/LedgerMaster.cpp b/src/xrpld/app/ledger/detail/LedgerMaster.cpp index bc5b517127..698604937d 100644 --- a/src/xrpld/app/ledger/detail/LedgerMaster.cpp +++ b/src/xrpld/app/ledger/detail/LedgerMaster.cpp @@ -18,6 +18,7 @@ #include #include #include +#include #include #include @@ -68,12 +69,14 @@ #include #include #include +#include #include #include #include #include #include #include +#include #include #include #include @@ -977,12 +980,63 @@ LedgerMaster::checkAccept(std::shared_ptr const& ledger) auto validations = app_.getValidators().negativeUNLFilter( app_.getValidations().getTrustedForLedger(ledger->header().hash, ledger->header().seq)); auto const tvc = validations.size(); + + // --- Sync diagnostics: snapshot the pre-accept quorum gate -------------- + // Stored before the shortfall check, so a node that keeps failing the gate + // still reports both numbers. That is the case these signals exist for: + // the tally alone cannot say whether validations are accumulating toward + // quorum (slow) or plateaued below it (stuck) without the target beside it. + // Two relaxed stores, once per validated ledger, not in a loop. + lastTrustedTally_.store(static_cast(tvc), std::memory_order_relaxed); + + // ValidatorList disables quorum by returning SIZE_MAX, which getNeededValidations + // passes straight through. Casting that to int64_t would wrap to -1 and make the + // tally look like it exceeds the target on a node that can never validate, so + // report the disabled state as int64 max instead: the target then reads far above + // any tally, which is the truthful signal. Mirrors the same fix in the unl_quorum + // gauge (MetricsRegistry::registerUnlQuorumGauge). + lastQuorumTarget_.store( + minVal == std::numeric_limits::max() ? std::numeric_limits::max() + : static_cast(minVal), + std::memory_order_relaxed); + if (tvc < minVal) // nothing we can do { JLOG(journal_.trace()) << "Only " << tvc << " validations for " << ledger->header().hash; + + // Trusted validations did not reach quorum, so this ledger will not be + // declared validated. Previously trace-only, which made a node that + // peers and receives validations yet never validates indistinguishable + // from an idle one. One macro call at the gate, never in a loop. + // + // Emitted while mutex_ is held. That is unavoidable here (the gate and + // its early return are inside the locked section) and consistent with + // the telemetry this function already emits under the same lock -- the + // ledger.validate span below, and the validation tracker reached + // through setValidLedger. It cannot deadlock against the metrics poll: + // every accessor the sync gauges read is a lock-free atomic load, so no + // OTel callback ever acquires mutex_. + XRPL_METRIC_COUNTER_INC_LABELED( + app_, + "ledger_quorum_shortfall_total", + "Pre-accept gate rejections because trusted validations were below quorum", + {{"stage", std::string("pre_accept")}}); return; } + // The gate passed, so this node now has a fully-validated ledger. Record how + // long that took, exactly once per process: a fresh node that never gets + // here keeps reporting 0, which is the diagnostic reading. Writing under + // mutex_ makes the once-only check exclusive without a compare-exchange. + if (timeToFirstValidatedUs_.load(std::memory_order_relaxed) == 0) + { + auto const elapsed = std::chrono::duration_cast( + std::chrono::steady_clock::now() - startTime_); + // Clamp to 1: a 0 would be indistinguishable from "never reached". + timeToFirstValidatedUs_.store( + std::max(1, elapsed.count()), std::memory_order_relaxed); + } + using namespace telemetry; auto valSpan = SpanGuard::span(TraceCategory::Ledger, seg::ledger, ledger_span::op::validate); valSpan.setAttribute(ledger_span::attr::ledgerSeq, static_cast(ledger->header().seq)); diff --git a/src/xrpld/app/ledger/detail/LedgerReplayTask.cpp b/src/xrpld/app/ledger/detail/LedgerReplayTask.cpp index e7cd031247..59d713bbec 100644 --- a/src/xrpld/app/ledger/detail/LedgerReplayTask.cpp +++ b/src/xrpld/app/ledger/detail/LedgerReplayTask.cpp @@ -8,6 +8,7 @@ #include #include #include +#include #include #include @@ -208,13 +209,37 @@ LedgerReplayTask::tryAdvance(ScopedLockType& sl) complete_ = true; JLOG(journal_.info()) << "Completed " << hash_; + + // Terminal success. Emitted once per task: the loop above is guarded by + // isDone() at every entry point, so a completed task cannot re-enter + // and double-count. + recordOutcome("success"); } catch (std::runtime_error const&) { failed_ = true; + + // A delta failed to build on top of its parent, so the replayed range + // cannot be reconstructed. Previously not logged at all here, only + // reflected in failed_. + recordOutcome("build_failed"); } } +void +LedgerReplayTask::recordOutcome(char const* outcome) const +{ + // One labelled counter Add per terminal event, never per delta or per + // ledger. Replay quietly falling back to plain acquisition is the failure + // this makes visible: without it, a replay that never succeeds is + // indistinguishable from one that was never attempted. + XRPL_METRIC_COUNTER_INC_LABELED( + app_, + "ledger_replay_outcome_total", + "Ledger replay tasks by terminal outcome", + {{"outcome", std::string(outcome)}}); +} + void LedgerReplayTask::updateSkipList( uint256 const& hash, @@ -229,6 +254,12 @@ LedgerReplayTask::updateSkipList( { JLOG(journal_.error()) << "Parameter update failed " << hash_; failed_ = true; + + // The acquired skip list did not match what this task asked for, + // so the task is abandoned before any delta is fetched. A distinct + // outcome from a timeout: this one indicates a peer served an + // inconsistent skip list, not a slow or absent peer. + recordOutcome("parameter_failed"); return; } } @@ -247,6 +278,11 @@ LedgerReplayTask::onTimer(bool progress, ScopedLockType& sl) { failed_ = true; JLOG(journal_.debug()) << "LedgerReplayTask Failed, too many timeouts " << hash_; + + // The task ran out of retries waiting for its deltas. This is the + // outcome that pairs with the fallback counters: the sub-acquires gave + // up, and so did the task above them. + recordOutcome("timeout"); } else { diff --git a/src/xrpld/app/ledger/detail/SkipListAcquire.cpp b/src/xrpld/app/ledger/detail/SkipListAcquire.cpp index 8ebd14083a..cca54d5fcb 100644 --- a/src/xrpld/app/ledger/detail/SkipListAcquire.cpp +++ b/src/xrpld/app/ledger/detail/SkipListAcquire.cpp @@ -8,6 +8,7 @@ #include #include #include +#include #include #include @@ -100,6 +101,20 @@ SkipListAcquire::trigger(std::size_t limit, ScopedLockType& sl) { JLOG(journal_.debug()) << "Fall back for " << hash_; timerInterval_ = LedgerReplayParameters::kSubTaskFallbackTimeout; + + // Too few peers support ledger replay, so this + // sub-task gives up on the skip-list shortcut and + // acquires the whole ledger instead. That silently + // defeats the replay optimisation -- debug-log-only + // until now. Emitted on the transition into fallback + // (fallBack_ is still false here), not at the acquire + // call below, which re-runs on every later trigger. + XRPL_METRIC_COUNTER_INC_LABELED( + app_, + "ledger_replay_fallback_total", + "Replay sub-acquires that fell back to a full ledger acquire", + {{"stage", std::string("skiplist")}}); + fallBack_ = true; } }