mirror of
https://github.com/XRPLF/rippled.git
synced 2026-08-21 22:30:57 +00:00
feat(telemetry): add quorum, publish and back-fill diagnostics (WP-A5, WP-A6)
Quorum and publish (A5): - ledger_quorum_publish gauge: the trusted-validation tally against the quorum the candidate ledger must reach, plus the gap between the validated and published sequences. The published sequence was never exported, so a publish pipeline falling behind healthy validation was invisible. - ledger_quorum_shortfall_total: counts the pre-accept early return where a node has peers and validators yet still declines to declare a ledger validated. That path was log-only, and it is the difference between accumulating toward quorum and never reaching it. Back-fill and persistence (A6): - nodestore_latency: read and write service time. storeDurationUs_ was declared but never written and had no accessor, so there was no write latency signal at all. This is the direct fingerprint of a node with an existing database syncing slower than a fresh one, where the node cache is cold and every tree step reaches disk. Distinct from the existing NuDB read panels, which show volume and hit ratio rather than service time. - ledger_replay_fallback_total and ledger_replay_outcome_total: the replay path silently falls back to plain acquisition on timeout or failure, so a defeated optimisation looked like ordinary slow back-fill. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
This commit is contained in:
@@ -11,6 +11,7 @@
|
||||
#include <xrpl/nodestore/Scheduler.h>
|
||||
|
||||
#include <atomic>
|
||||
#include <chrono>
|
||||
#include <condition_variable>
|
||||
#include <cstdint>
|
||||
#include <functional>
|
||||
@@ -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<std::chrono::microseconds>(elapsed).count();
|
||||
if (us > 0)
|
||||
storeDurationUs_.fetch_add(static_cast<std::uint64_t>(us), std::memory_order_relaxed);
|
||||
}
|
||||
|
||||
// Called by the public import function
|
||||
void
|
||||
importInternal(Backend& dstBackend, Database& srcDB);
|
||||
|
||||
@@ -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();
|
||||
|
||||
@@ -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<Database> 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<Database> 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);
|
||||
|
||||
@@ -279,6 +279,92 @@ public:
|
||||
std::optional<uint256>
|
||||
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<std::int64_t>(validLedgerSeq_.load(std::memory_order_relaxed));
|
||||
auto const published =
|
||||
static_cast<std::int64_t>(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<std::int64_t>::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<Ledger const> 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<std::int64_t> 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<std::int64_t> 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<std::int64_t> 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
|
||||
{
|
||||
|
||||
@@ -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_;
|
||||
|
||||
@@ -10,6 +10,7 @@
|
||||
#include <xrpld/app/main/Application.h>
|
||||
#include <xrpld/overlay/Peer.h>
|
||||
#include <xrpld/overlay/PeerSet.h>
|
||||
#include <xrpld/telemetry/MetricMacros.h>
|
||||
|
||||
#include <xrpl/basics/Log.h>
|
||||
#include <xrpl/basics/base_uint.h>
|
||||
@@ -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;
|
||||
}
|
||||
}
|
||||
|
||||
@@ -18,6 +18,7 @@
|
||||
#include <xrpld/overlay/Overlay.h>
|
||||
#include <xrpld/overlay/Peer.h>
|
||||
#include <xrpld/rpc/detail/PathRequestManager.h>
|
||||
#include <xrpld/telemetry/MetricMacros.h>
|
||||
#include <xrpld/telemetry/MetricsRegistry.h>
|
||||
|
||||
#include <xrpl/basics/Log.h>
|
||||
@@ -68,12 +69,14 @@
|
||||
#include <algorithm>
|
||||
#include <atomic>
|
||||
#include <chrono>
|
||||
#include <cstddef>
|
||||
#include <cstdint>
|
||||
#include <cstdlib>
|
||||
#include <exception>
|
||||
#include <functional>
|
||||
#include <iostream>
|
||||
#include <iterator>
|
||||
#include <limits>
|
||||
#include <map>
|
||||
#include <memory>
|
||||
#include <mutex>
|
||||
@@ -977,12 +980,63 @@ LedgerMaster::checkAccept(std::shared_ptr<Ledger const> 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<std::int64_t>(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<std::size_t>::max() ? std::numeric_limits<std::int64_t>::max()
|
||||
: static_cast<std::int64_t>(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::microseconds>(
|
||||
std::chrono::steady_clock::now() - startTime_);
|
||||
// Clamp to 1: a 0 would be indistinguishable from "never reached".
|
||||
timeToFirstValidatedUs_.store(
|
||||
std::max<std::int64_t>(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<int64_t>(ledger->header().seq));
|
||||
|
||||
@@ -8,6 +8,7 @@
|
||||
#include <xrpld/app/ledger/detail/SkipListAcquire.h>
|
||||
#include <xrpld/app/ledger/detail/TimeoutCounter.h>
|
||||
#include <xrpld/app/main/Application.h>
|
||||
#include <xrpld/telemetry/MetricMacros.h>
|
||||
|
||||
#include <xrpl/basics/Log.h>
|
||||
#include <xrpl/basics/base_uint.h>
|
||||
@@ -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
|
||||
{
|
||||
|
||||
@@ -8,6 +8,7 @@
|
||||
#include <xrpld/app/main/Application.h>
|
||||
#include <xrpld/overlay/Peer.h>
|
||||
#include <xrpld/overlay/PeerSet.h>
|
||||
#include <xrpld/telemetry/MetricMacros.h>
|
||||
|
||||
#include <xrpl/basics/Log.h>
|
||||
#include <xrpl/basics/base_uint.h>
|
||||
@@ -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;
|
||||
}
|
||||
}
|
||||
|
||||
Reference in New Issue
Block a user