feat(telemetry): add ledger-acquire and SHAMap fetch diagnostics (WP-A3)

Signals that separate a sync that is merely slow from one that will never
finish:

- sync_acquire{missing_state_nodes_max, missing_tx_nodes_max, in_flight,
  received_data_depth}: how many SHAMap nodes each in-flight acquire is
  still waiting for. getMissingNodes already computed this and the callers
  discarded it after a trace log. A count that stays flat means the
  acquire is wedged; a shrinking count means it is progressing. Recorded
  once per sweep, never inside the per-node walk, and reset when a tree
  completes so a finished acquire does not read as stuck forever.
- shamap_cache_hit_rate{treenode}: hit rate of the in-memory tree-node
  cache, which sits above the node store, so it is distinct from the
  existing NuDB ratio. A cold cache on a fresh node sends every traversal
  step to disk.
- sync_acquire_no_progress_total: timer ticks where an acquire made no
  progress, previously only logged.
- sync_addnode_total{good,duplicate,invalid}: whether arriving nodes are
  useful, duplicated or rejected, so wasted fetch work is visible.
- sync_acquire_source_total{local,network}: whether a ledger was served
  from the local store or had to be fetched.

Adds getBad()/getDuplicate() to SHAMapAddNode and an acquireProgress()
accessor on InboundLedgers so the xrpld gauge can read these without
libxrpl depending on telemetry.

ledger_seq is deliberately not a metric label: it is unbounded. Per-ledger
identity stays on the ledger.acquire span; the metrics expose bounded
aggregates instead.

The full-below cache hit rate is not exported: KeyCache updates different
counters than getHitRate() reads, so it would always report zero. That
libxrpl bug is documented rather than papered over.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
This commit is contained in:
Pratik Mankawde
2026-07-25 10:18:08 +01:00
parent 7c7509d01f
commit 3e2a1ea958
16 changed files with 1676 additions and 38 deletions

View File

@@ -252,6 +252,14 @@ public:
return 0;
}
// This mock holds no InboundLedger objects, so there is no acquire progress
// to report; the all-zero snapshot is the honest answer.
AcquireProgress
acquireProgress() override
{
return {};
}
LedgerMaster& ledgerSource;
LedgerMaster& ledgerSink;
InboundLedgersBehavior bhvr;

View File

@@ -1246,4 +1246,342 @@ TEST(MetricMacros, state_changes_total_emits_nothing_when_registry_disabled)
EXPECT_EQ(app.registry().meterCalls(), 0);
}
// -----------------------------------------------------------------
// Acquire + SHAMap sync diagnostics (WP-A3).
//
// Asserts the EXACT values and label shapes of the five acquire signals:
// sync_acquire_source_total{source} InboundLedger::init
// sync_acquire_no_progress_total InboundLedger::onTimer
// sync_addnode_total{outcome} InboundLedger::recordBatchOutcome
// sync_acquire{metric} MetricsRegistry::registerSyncAcquireGauge
// missing_state_nodes_max
// missing_tx_nodes_max
// received_data_depth
// in_flight
// shamap_cache_hit_rate{metric} MetricsRegistry::registerCacheHitRateDetailGauge
//
// The counters go through the same macros production uses. The two observable
// instruments are registered directly on the SDK meter, mirroring the production
// callback shape, because the real MetricsRegistry's enabled path cannot be
// linked into this standalone binary (see the file header).
// -----------------------------------------------------------------
// sync_acquire_source_total splits acquires by whether the local node store
// already held the ledger. This is the disk-bound vs peer-bound distinction, so
// the two sources must never collapse into one series.
TEST(MetricMacros, acquire_source_splits_local_and_network)
{
CollectingProvider const provider;
FakeApp app;
wire(app, /*enabled=*/true, provider.meter());
// Mirrors the production call site in InboundLedger::init(): one macro
// invocation whose label is derived from complete_ after the first tryDB().
auto const acquire = [&app](bool localComplete) {
XRPL_METRIC_COUNTER_INC_LABELED(
app,
"sync_acquire_source_total",
"Ledger acquires by where the data came from",
{{"source", std::string(localComplete ? "local" : "network")}});
};
// One satisfied locally, two needing the network.
acquire(true);
acquire(false);
acquire(false);
auto const data = provider.collect();
ASSERT_EQ(data.at("sync_acquire_source_total").size(), 2u);
EXPECT_EQ(counterValue(data, "sync_acquire_source_total", attrs("source", "local")), 1);
EXPECT_EQ(counterValue(data, "sync_acquire_source_total", attrs("source", "network")), 2);
// The label key is exactly "source" and nothing rides along with it.
auto const& firstKey = data.at("sync_acquire_source_total").begin()->first;
ASSERT_EQ(firstKey.size(), 1u);
EXPECT_EQ(firstKey.begin()->first, "source");
// NEGATIVE: a source value that was never emitted has no series, so the
// counts above are not an artifact of a catch-all series.
EXPECT_EQ(data.at("sync_acquire_source_total").count(attrs("source", "fetch_pack")), 0u);
}
// sync_acquire_no_progress_total counts ONLY timeouts where no node arrived.
// InboundLedger::onTimer reaches the macro exclusively on its !wasProgress
// branch, so a tick that made progress must leave the total unchanged -- that
// is the whole difference between "slow" and "stuck".
TEST(MetricMacros, acquire_no_progress_counts_only_stalled_timeouts)
{
CollectingProvider const provider;
FakeApp app;
wire(app, /*enabled=*/true, provider.meter());
// Stands in for onTimer(): the guard lives at the call site in production,
// so the harness reproduces the guard rather than the macro alone.
auto const onTimer = [&app](bool wasProgress) {
if (!wasProgress)
{
XRPL_METRIC_COUNTER_INC(
app,
"sync_acquire_no_progress_total",
"Ledger-acquire timeouts where no new node arrived");
}
};
onTimer(/*wasProgress=*/false);
onTimer(/*wasProgress=*/false);
// Exactly two stalled timeouts so far, on one unlabelled series.
auto const stalled = provider.collect();
ASSERT_EQ(stalled.at("sync_acquire_no_progress_total").size(), 1u);
EXPECT_TRUE(stalled.at("sync_acquire_no_progress_total").begin()->first.empty());
EXPECT_EQ(
counterValue(stalled, "sync_acquire_no_progress_total", otel_sdk::PointAttributes{}), 2);
// A tick that DID make progress must not advance the counter: still 2.
onTimer(/*wasProgress=*/true);
EXPECT_EQ(
counterValue(
provider.collect(), "sync_acquire_no_progress_total", otel_sdk::PointAttributes{}),
2);
// A further stalled tick does advance it, proving the counter is live and
// the unchanged reading above was the guard working, not a dead instrument.
onTimer(/*wasProgress=*/false);
EXPECT_EQ(
counterValue(
provider.collect(), "sync_acquire_no_progress_total", otel_sdk::PointAttributes{}),
3);
}
// sync_addnode_total separates useful progress from wasted work. All three
// outcomes come from ONE aggregated batch tally, added after the per-node loop
// has finished, so each outcome must land on its own series with its exact count.
TEST(MetricMacros, addnode_outcomes_record_exact_batch_tallies)
{
CollectingProvider const provider;
FakeApp app;
wire(app, /*enabled=*/true, provider.meter());
// Mirrors InboundLedger::recordBatchOutcome(): three _ADD calls per batch,
// each skipped when its tally is zero (a zero Add would create a series that
// says "we saw invalid nodes", which would be false).
auto const emitBatch = [&app](int good, int duplicate, int invalid) {
auto const emit = [&app](char const* outcome, int count) {
if (count <= 0)
return;
XRPL_METRIC_COUNTER_ADD_LABELED(
app,
"sync_addnode_total",
"SHAMap nodes received during ledger acquire, by outcome",
static_cast<std::uint64_t>(count),
{{"outcome", std::string(outcome)}});
};
emit("good", good);
emit("duplicate", duplicate);
emit("invalid", invalid);
};
// One batch: 5 good, 2 duplicate, 1 invalid.
emitBatch(5, 2, 1);
auto const oneBatch = provider.collect();
ASSERT_EQ(oneBatch.at("sync_addnode_total").size(), 3u);
EXPECT_EQ(counterValue(oneBatch, "sync_addnode_total", attrs("outcome", "good")), 5);
EXPECT_EQ(counterValue(oneBatch, "sync_addnode_total", attrs("outcome", "duplicate")), 2);
EXPECT_EQ(counterValue(oneBatch, "sync_addnode_total", attrs("outcome", "invalid")), 1);
// Every series key carries exactly the one expected label name.
for (auto const& [labels, point] : oneBatch.at("sync_addnode_total"))
{
ASSERT_EQ(labels.size(), 1u);
EXPECT_EQ(labels.count("outcome"), 1u);
}
// A second batch accumulates per outcome rather than replacing: 3 more good
// and 4 more duplicates, no invalid this time.
emitBatch(3, 4, 0);
auto const twoBatches = provider.collect();
EXPECT_EQ(counterValue(twoBatches, "sync_addnode_total", attrs("outcome", "good")), 8);
EXPECT_EQ(counterValue(twoBatches, "sync_addnode_total", attrs("outcome", "duplicate")), 6);
// The zero-tally outcome did NOT advance: still exactly 1 from the first
// batch, so an all-good batch cannot inflate the invalid series.
EXPECT_EQ(counterValue(twoBatches, "sync_addnode_total", attrs("outcome", "invalid")), 1);
// Still exactly three series after two batches: the zero-tally guard means a
// batch never invents a series for an outcome it did not observe.
EXPECT_EQ(twoBatches.at("sync_addnode_total").size(), 3u);
// NEGATIVE: an outcome value outside the production set has no series, so
// the three counts above are not an artifact of a catch-all series.
EXPECT_EQ(twoBatches.at("sync_addnode_total").count(attrs("outcome", "stale")), 0u);
}
// sync_acquire fans four values out of ONE aggregated snapshot, mirroring
// MetricsRegistry::registerSyncAcquireGauge(). The values chosen are the
// headline stuck-sync reading: two acquires in flight, the state tree still
// missing nodes, a backed-up stash.
TEST(MetricMacros, sync_acquire_gauge_observes_exact_stuck_acquire_values)
{
CollectingProvider const provider;
// The snapshot the callback reports, owned by the test exactly as the real
// registry reads it from InboundLedgers on each collection tick.
struct Observed
{
std::int64_t maxMissingStateNodes;
std::int64_t maxMissingTxNodes;
std::int64_t receivedDataDepth;
std::int64_t inFlight;
};
// A stuck acquire: 256 state nodes still outstanding (the sweep cap), the tx
// tree already done, 4 packets stashed, 2 acquires running.
Observed observed{256, 0, 4, 2};
// Keep the instrument alive for the whole test: destroying the handle
// deregisters the callback, which is why the real registry holds a member.
auto gauge = provider.meter()->CreateInt64ObservableGauge(
"sync_acquire", "Aggregate ledger-acquire progress across in-flight acquires");
gauge->AddCallback(
[](opentelemetry::metrics::ObserverResult result, void* state) {
auto const* self = static_cast<Observed const*>(state);
// Same Observe() form the production callback uses.
auto observe = [&](char const* name, std::int64_t value) {
opentelemetry::nostd::get<opentelemetry::nostd::shared_ptr<
opentelemetry::metrics::ObserverResultT<std::int64_t>>>(result)
->Observe(value, {{"metric", name}});
};
observe("missing_state_nodes_max", self->maxMissingStateNodes);
observe("missing_tx_nodes_max", self->maxMissingTxNodes);
observe("received_data_depth", self->receivedDataDepth);
observe("in_flight", self->inFlight);
},
&observed);
auto const stuck = provider.collect();
// Exactly four series, one per `metric` value.
ASSERT_EQ(stuck.at("sync_acquire").size(), 4u);
EXPECT_EQ(gaugeValue(stuck, "sync_acquire", attrs("metric", "missing_state_nodes_max")), 256);
EXPECT_EQ(gaugeValue(stuck, "sync_acquire", attrs("metric", "received_data_depth")), 4);
EXPECT_EQ(gaugeValue(stuck, "sync_acquire", attrs("metric", "in_flight")), 2);
// Zero is a REAL reading here, not a missing series: it says the tx tree
// needs nothing while the state tree is still stuck, which is exactly the
// per-map split this signal exists to provide.
ASSERT_EQ(stuck.at("sync_acquire").count(attrs("metric", "missing_tx_nodes_max")), 1u);
EXPECT_EQ(gaugeValue(stuck, "sync_acquire", attrs("metric", "missing_tx_nodes_max")), 0);
// The label key is exactly "metric" and it is the only label present. This
// is the cardinality guard: a ledger_seq label here would mint a new series
// per ledger acquired.
auto const& firstKey = stuck.at("sync_acquire").begin()->first;
ASSERT_EQ(firstKey.size(), 1u);
EXPECT_EQ(firstKey.begin()->first, "metric");
EXPECT_EQ(stuck.at("sync_acquire").count(attrs("metric", "ledger_seq")), 0u);
// A shrinking count is the "slow but alive" reading, and an idle node
// reports all zeros with in_flight=0 -- distinguishable from a stuck node
// only because in_flight is exported alongside.
observed = Observed{128, 0, 1, 2};
EXPECT_EQ(
gaugeValue(provider.collect(), "sync_acquire", attrs("metric", "missing_state_nodes_max")),
128);
observed = Observed{0, 0, 0, 0};
auto const idle = provider.collect();
EXPECT_EQ(gaugeValue(idle, "sync_acquire", attrs("metric", "missing_state_nodes_max")), 0);
EXPECT_EQ(gaugeValue(idle, "sync_acquire", attrs("metric", "in_flight")), 0);
}
// shamap_cache_hit_rate reports the tree-node cache rate normalized to 0.0-1.0,
// mirroring MetricsRegistry::registerCacheHitRateDetailGauge(). The scaling is
// the part worth pinning: TaggedCache::getHitRate() returns 0-100, and the
// dashboard panel uses percentunit, so an unnormalized value would render as
// 9000% instead of 90%.
TEST(MetricMacros, shamap_cache_hit_rate_gauge_normalizes_to_unit_fraction)
{
CollectingProvider const provider;
// What TaggedCache::getHitRate() would return: 90 means 90%.
float rawHitRatePercent = 90.0F;
auto gauge = provider.meter()->CreateDoubleObservableGauge(
"shamap_cache_hit_rate", "SHAMap tree-node cache hit rate (0.0-1.0), by cache");
gauge->AddCallback(
[](opentelemetry::metrics::ObserverResult result, void* state) {
auto const* raw = static_cast<float const*>(state);
// Same normalization the production callback performs.
opentelemetry::nostd::get<
opentelemetry::nostd::shared_ptr<opentelemetry::metrics::ObserverResultT<double>>>(
result)
->Observe(static_cast<double>(*raw / 100.0F), {{"metric", "treenode"}});
},
&rawHitRatePercent);
auto const warm = provider.collect();
// Exactly one series: the full-below cache is deliberately not reported
// (its TaggedCache hit accounting writes members getHitRate() never reads,
// so it would be a hard-wired zero).
ASSERT_EQ(warm.at("shamap_cache_hit_rate").size(), 1u);
EXPECT_EQ(warm.at("shamap_cache_hit_rate").count(attrs("metric", "full_below")), 0u);
// 90 percent arrives as exactly 0.9, not 90 and not 9000.
auto const& warmPoint = warm.at("shamap_cache_hit_rate").at(attrs("metric", "treenode"));
auto const& warmLast = opentelemetry::nostd::get<otel_sdk::LastValuePointData>(warmPoint);
EXPECT_DOUBLE_EQ(opentelemetry::nostd::get<double>(warmLast.value_), 0.9);
// A cold cache reads exactly 0.0 -- the fresh-sync case, where every lookup
// goes to the node store.
rawHitRatePercent = 0.0F;
auto const cold = provider.collect();
auto const& coldPoint = cold.at("shamap_cache_hit_rate").at(attrs("metric", "treenode"));
auto const& coldLast = opentelemetry::nostd::get<otel_sdk::LastValuePointData>(coldPoint);
EXPECT_DOUBLE_EQ(opentelemetry::nostd::get<double>(coldLast.value_), 0.0);
// A fully warm cache reads exactly 1.0, pinning the upper bound of the
// normalized range.
rawHitRatePercent = 100.0F;
auto const full = provider.collect();
auto const& fullPoint = full.at("shamap_cache_hit_rate").at(attrs("metric", "treenode"));
auto const& fullLast = opentelemetry::nostd::get<otel_sdk::LastValuePointData>(fullPoint);
EXPECT_DOUBLE_EQ(opentelemetry::nostd::get<double>(fullLast.value_), 1.0);
}
// RUNTIME-DISABLED no-op proof for the counter half of WP-A3: with the registry
// disabled, all three acquire counters emit NOTHING -- no series at all, and
// meter() is never consulted, so not even an instrument was created.
TEST(MetricMacros, acquire_counters_emit_nothing_when_registry_disabled)
{
CollectingProvider const provider;
FakeApp app;
wire(app, /*enabled=*/false, provider.meter());
XRPL_METRIC_COUNTER_INC_LABELED(
app,
"sync_acquire_source_total",
"Ledger acquires by where the data came from",
{{"source", std::string("network")}});
XRPL_METRIC_COUNTER_INC(
app, "sync_acquire_no_progress_total", "Ledger-acquire timeouts where no new node arrived");
XRPL_METRIC_COUNTER_ADD_LABELED(
app,
"sync_addnode_total",
"SHAMap nodes received during ledger acquire, by outcome",
static_cast<std::uint64_t>(5),
{{"outcome", std::string("good")}});
auto const data = provider.collect();
// Total absence, not zero-valued series: the instruments never existed.
EXPECT_EQ(data.count("sync_acquire_source_total"), 0u);
EXPECT_EQ(data.count("sync_acquire_no_progress_total"), 0u);
EXPECT_EQ(data.count("sync_addnode_total"), 0u);
EXPECT_EQ(data.size(), 0u);
// Cause, not just state: the isEnabled() gate short-circuited before the
// macros asked for a meter.
EXPECT_EQ(app.registry().meterCalls(), 0);
}
#endif // XRPL_ENABLE_TELEMETRY

View File

@@ -18,15 +18,17 @@
*
* CONSEQUENCE for the sync-diagnostics gauges (`unl_quorum`,
* `clock_close_offset_seconds`, `sync_state`,
* `server_stall_events_total`): this file CANNOT assert an observed gauge
* `server_stall_events_total`, `sync_acquire`, `shamap_cache_hit_rate`):
* this file CANNOT assert an observed gauge
* value, because on this build the gauges do not exist -- their registration
* methods and the OTel instrument members are inside
* `#ifdef XRPL_ENABLE_TELEMETRY`, and there is no MeterProvider at all. What
* is provable here, and what the tests below assert, is the complementary
* half: that nothing is registered and no service is consulted. The exact
* observed values (trusted_keys=5, quorum=4, offset=-3, and the sync_state /
* stall-episode values) are asserted in MetricMacros.cpp, which is the file
* compiled when telemetry IS enabled.
* observed values (trusted_keys=5, quorum=4, offset=-3, the sync_state /
* stall-episode values, and the acquire-progress / cache-hit-rate values) are
* asserted in MetricMacros.cpp, which is the file compiled when telemetry IS
* enabled.
*/
// When telemetry is globally enabled, MetricsRegistry.cpp requires xrpld
@@ -378,9 +380,12 @@ TEST_F(MetricsRegistryTest, destructor_calls_stop)
//
// `unl_quorum` reads ValidatorList::trustedKeyCount() and quorum();
// `clock_close_offset_seconds` reads TimeKeeper::closeOffset(); `sync_state` and
// `server_stall_events_total` read NetworkOPs and LoadManager. All are
// `server_stall_events_total` read NetworkOPs and LoadManager; `sync_acquire`
// reads InboundLedgers::acquireProgress() and `shamap_cache_hit_rate` reads the
// node Family's tree-node cache. All are
// reached through the ServiceRegistry, and MockServiceRegistry::getValidators()
// / getTimeKeeper() / getOPs() / getLoadManager() THROW std::logic_error. So "no
// / getTimeKeeper() / getOPs() / getLoadManager() / getInboundLedgers() /
// getNodeFamily() THROW std::logic_error. So "no
// gauge callback ran" is directly observable here: had registerAsyncGauges() run
// and had a callback fired, one of those accessors would have thrown.
//
@@ -419,7 +424,8 @@ TEST_F(MetricsRegistryTest, disabled_lifecycle_never_consults_gauge_services)
// start() is where registerAsyncGauges() -- and with it
// registerUnlQuorumGauge() / registerClockSkewGauge() /
// registerSyncStateGauge() / registerStallEventsCounter() -- would run.
// registerSyncStateGauge() / registerStallEventsCounter() /
// registerSyncAcquireGauge() / registerCacheHitRateDetailGauge() -- would run.
EXPECT_NO_THROW(registry.start("http://localhost:4318/v1/metrics"));
// detachCallbacks() is the shutdown hook the real gauges honour. It must be
@@ -443,6 +449,11 @@ TEST_F(MetricsRegistryTest, disabled_lifecycle_never_consults_gauge_services)
// firing would have thrown above.
EXPECT_THROW(mockApp_.getOPs(), std::logic_error);
EXPECT_THROW(mockApp_.getLoadManager(), std::logic_error);
// The two services the WP-A3 acquire signals read: sync_acquire polls the
// in-flight acquire collection, shamap_cache_hit_rate polls the node
// Family's tree-node cache. Neither was consulted above.
EXPECT_THROW(mockApp_.getInboundLedgers(), std::logic_error);
EXPECT_THROW(mockApp_.getNodeFamily(), std::logic_error);
}
// Even asking for enabled=true registers no sync-diagnostics gauge on a
@@ -461,9 +472,10 @@ TEST_F(MetricsRegistryTest, enabled_flag_alone_registers_no_gauges_when_compiled
// Yet the whole lifecycle stays inert. If registerAsyncGauges() had run and
// registered registerUnlQuorumGauge()/registerClockSkewGauge()/
// registerSyncStateGauge()/registerStallEventsCounter(), a callback would
// reach getValidators()/getTimeKeeper()/getOPs()/getLoadManager() and throw
// std::logic_error.
// registerSyncStateGauge()/registerStallEventsCounter()/
// registerSyncAcquireGauge()/registerCacheHitRateDetailGauge(), a callback
// would reach getValidators()/getTimeKeeper()/getOPs()/getLoadManager()/
// getInboundLedgers()/getNodeFamily() and throw std::logic_error.
EXPECT_NO_THROW(enabledRequest.start("http://localhost:4318/v1/metrics"));
EXPECT_NO_THROW(enabledRequest.detachCallbacks());
EXPECT_NO_THROW(enabledRequest.stop());

View File

@@ -14,11 +14,13 @@
#include <xrpl/nodestore/Database.h>
#include <xrpl/shamap/SHAMap.h>
#include <xrpl/shamap/SHAMapAddNode.h>
#include <xrpl/shamap/SHAMapMissingNode.h>
#include <xrpl/shamap/SHAMapNodeID.h>
#include <xrpl/telemetry/SpanGuard.h>
#include <xrpl.pb.h>
#include <atomic>
#include <chrono>
#include <cstddef>
#include <cstdint>
@@ -122,6 +124,43 @@ public:
return lastAction_;
}
/**
* Outstanding missing SHAMap nodes in one of this acquire's two trees.
*
* Refreshed by trigger() after each getMissingNodes() sweep, which already
* computes the count as a byproduct of its walk — this accessor adds no
* traversal of its own and does not take the acquire lock.
*
* Read by the telemetry observable-gauge callback (~10 s cadence). A count
* that stays flat and non-zero across ticks means the acquire will never
* finish; a shrinking count means it is slow but alive.
*
* @param type Which tree to report: SHAMapType::TRANSACTION selects the
* transaction tree, every other value selects the account-state tree.
* @return Node count from the most recent sweep of that tree; 0 before the
* first sweep and after the tree completes.
*
* @note Thread-safe and lock-free: a relaxed atomic load. The reader
* tolerates a value one sweep out of date.
*/
[[nodiscard]] int
getMissingNodeCount(SHAMapType type) const noexcept;
/**
* Number of peer packets stashed in receivedData_ awaiting processing.
*
* A deep stash means node data is arriving faster than runData() can apply
* it, which is a processing bottleneck rather than a peer-supply one.
*
* @return Current stash depth; 0 when nothing is pending.
*
* @note Thread-safe and lock-free: a relaxed atomic load of a counter
* mirrored on every push/drain, so it never blocks the receive path
* nor waits on receivedDataLock_.
*/
[[nodiscard]] std::size_t
getReceivedDataDepth() const noexcept;
private:
enum class TriggerReason { Added, Reply, Timeout };
@@ -173,6 +212,37 @@ private:
std::vector<uint256>
neededStateHashes(int max, SHAMapSyncFilter const* filter) const;
/**
* Re-publish the missing-node counts from the completion flags.
*
* Called under mtx_ wherever a tree flips to complete. A tree that needs no
* more nodes must publish 0: otherwise the last sweep's count lingers and a
* finished acquire keeps reporting a flat non-zero, which is exactly the
* "permanently stuck" reading the gauge exists to detect. Idempotent, so it
* is safe to call from every flip site.
*/
void
refreshMissingNodeCounts() noexcept;
/**
* Fold one processed batch into the acquire totals and emit its telemetry.
*
* Both processData() branches (header batch and node batch) finished with
* the same three steps, so they share this one helper: mark progress, add to
* stats_, and emit the per-outcome add-node counters.
*
* @param san Outcome tally for the batch just processed.
* @return Number of good nodes in the batch, which is processData()'s
* "useful data from this peer" return value.
*
* @note Called once per received packet, after the per-node loop inside
* receiveNode() has completed. The tallies are already aggregated, so
* the counters are emitted once per batch and never per node.
* @note Call with mtx_ held, as both call sites already do.
*/
int
recordBatchOutcome(SHAMapAddNode const& san);
clock_type& clock_;
clock_type::time_point lastAction_;
@@ -196,6 +266,27 @@ private:
bool receiveDispatched_{false};
std::unique_ptr<PeerSet> peerSet_;
/**
* Outstanding missing nodes in the account-state tree, as counted by the
* last getMissingNodes() sweep in trigger(). Relaxed atomic: written by the
* acquiring thread, read by the telemetry gauge callback, and a value one
* sweep stale is acceptable for a ~10 s gauge.
*/
std::atomic<int> missingStateNodes_{0};
/**
* Outstanding missing nodes in the transaction tree. Same ownership and
* staleness contract as missingStateNodes_.
*/
std::atomic<int> missingTxNodes_{0};
/**
* Mirror of receivedData_.size(), maintained under receivedDataLock_ on
* every push and drain. Exists so the telemetry gauge callback can read the
* depth without contending for that lock on the node-receive path.
*/
std::atomic<std::size_t> receivedDataDepth_{0};
/**
* Spans the acquire lifecycle: started in init(), finalized in done()
* with the outcome (complete/failed), timeout count, and peer count.

View File

@@ -91,6 +91,56 @@ public:
virtual std::size_t
cacheSize() = 0;
/**
* Aggregate acquire-progress snapshot across every in-flight acquire.
*
* Bounded, pre-aggregated telemetry: one value per field regardless of how
* many acquires are in flight, so the derived metric cannot grow a series
* per ledger. Per-ledger detail stays available on the `ledger.acquire`
* span, which is where unbounded identity belongs.
*/
struct AcquireProgress
{
/**
* Largest outstanding account-state node count of any in-flight
* acquire. The max, not the sum, so one stuck acquire stays visible
* instead of being averaged away by healthy ones.
*/
int maxMissingStateNodes{0};
/**
* Largest outstanding transaction-tree node count of any in-flight
* acquire.
*/
int maxMissingTxNodes{0};
/**
* Total unprocessed peer packets stashed across all in-flight acquires.
* Summed because it measures one shared processing backlog.
*/
std::size_t receivedDataDepth{0};
/**
* Number of acquires currently in flight, so the three values above can
* be read in context (all zero with zero acquires is idle, not healthy).
*/
std::size_t inFlight{0};
};
/**
* Collect the aggregate acquire-progress snapshot.
*
* Intended for the telemetry observable gauge, polled about every 10 s.
* Takes the collection lock only long enough to copy the handles, then reads
* each acquire's relaxed atomics without holding it, so it never blocks the
* node-receive path.
*
* @return Aggregated progress; an all-zero value with `inFlight == 0` when
* nothing is being acquired.
*/
[[nodiscard]] virtual AcquireProgress
acquireProgress() = 0;
};
std::unique_ptr<InboundLedgers>

View File

@@ -10,6 +10,7 @@
#include <xrpld/overlay/Message.h>
#include <xrpld/overlay/Overlay.h>
#include <xrpld/overlay/PeerSet.h>
#include <xrpld/telemetry/MetricMacros.h>
#include <xrpl/basics/Blob.h>
#include <xrpl/basics/Log.h>
@@ -29,6 +30,7 @@
#include <xrpl/protocol/SystemParameters.h> // IWYU pragma: keep
#include <xrpl/protocol/jss.h>
#include <xrpl/resource/Fees.h>
#include <xrpl/shamap/SHAMapMissingNode.h>
#include <xrpl/shamap/SHAMapNodeID.h>
#include <xrpl/shamap/SHAMapSyncFilter.h>
#include <xrpl/telemetry/SpanGuard.h>
@@ -39,6 +41,7 @@
#include <xrpl.pb.h>
#include <algorithm>
#include <atomic>
#include <chrono>
#include <cstddef>
#include <cstdint>
@@ -133,6 +136,17 @@ InboundLedger::init(ScopedLockType& collectionLock)
if (failed_)
return;
// Whether the local node store already held the whole ledger. Emitted once
// per new acquire (init() runs exactly once), never per node, so the cost is
// a single labelled counter Add. This is what separates disk-bound sync
// ("everything was local, we are just slow to read it") from peer-bound sync
// ("nothing was local, every node must come over the wire").
XRPL_METRIC_COUNTER_INC_LABELED(
app_,
"sync_acquire_source_total",
"Ledger acquires by where the data came from",
{{"source", std::string(complete_ ? "local" : "network")}});
if (!complete_)
{
addPeers();
@@ -157,6 +171,28 @@ InboundLedger::init(ScopedLockType& collectionLock)
app_.getLedgerMaster().checkAccept(ledger_);
}
int
InboundLedger::getMissingNodeCount(SHAMapType type) const noexcept
{
return (type == SHAMapType::TRANSACTION ? missingTxNodes_ : missingStateNodes_)
.load(std::memory_order_relaxed);
}
std::size_t
InboundLedger::getReceivedDataDepth() const noexcept
{
return receivedDataDepth_.load(std::memory_order_relaxed);
}
void
InboundLedger::refreshMissingNodeCounts() noexcept
{
if (haveState_)
missingStateNodes_.store(0, std::memory_order_relaxed);
if (haveTransactions_)
missingTxNodes_.store(0, std::memory_order_relaxed);
}
std::size_t
InboundLedger::getPeerCount() const
{
@@ -359,6 +395,10 @@ InboundLedger::tryDB(NodeStore::Database& srcDB)
}
}
// A tree satisfied from the local store never ran a sweep, so publish its
// zero here rather than leaving the gauge on a stale count.
refreshMissingNodeCounts();
if (haveTransactions_ && haveState_)
{
JLOG(journal_.debug()) << "Had everything locally";
@@ -408,6 +448,16 @@ InboundLedger::onTimer(bool wasProgress, ScopedLockType&)
std::size_t const pc = getPeerCount();
JLOG(journal_.debug()) << "No progress(" << pc << ") for ledger " << hash_;
// A timeout with no node received since the previous one means this
// acquire is stalled. Fires on the acquire timer (once every 3 s at
// most), not on any per-node path, so one counter Add here is free.
// A climbing rate here alongside a flat missing-node count is the
// signature of a sync that will never complete.
XRPL_METRIC_COUNTER_INC(
app_,
"sync_acquire_no_progress_total",
"Ledger-acquire timeouts where no new node arrived");
// addPeers triggers if the reason is not HISTORY
// So if the reason IS HISTORY, need to trigger after we add
// otherwise, we need to trigger before we add
@@ -681,6 +731,12 @@ InboundLedger::trigger(std::shared_ptr<Peer> const& peer, TriggerReason reason)
auto nodes = ledger_->stateMap().getMissingNodes(kMissingNodesFind, &filter);
sl.lock();
// Publish the outstanding count for the telemetry gauge. The sweep
// above already produced it, so this is one relaxed atomic store per
// sweep and never per tree node -- getMissingNodes() walks thousands
// of nodes internally and must stay free of metric work.
missingStateNodes_.store(static_cast<int>(nodes.size()), std::memory_order_relaxed);
// Make sure nothing happened while we released the lock
if (!failed_ && !complete_ && !haveState_)
{
@@ -749,6 +805,10 @@ InboundLedger::trigger(std::shared_ptr<Peer> const& peer, TriggerReason reason)
auto nodes = ledger_->txMap().getMissingNodes(kMissingNodesFind, &filter);
// Same contract as the state-tree store above: one atomic store per
// sweep, outside the per-node walk.
missingTxNodes_.store(static_cast<int>(nodes.size()), std::memory_order_relaxed);
if (nodes.empty())
{
if (!ledger_->txMap().isValid())
@@ -874,6 +934,10 @@ InboundLedger::takeHeader(std::string const& data)
if (ledger_->header().accountHash.isZero())
haveState_ = true;
// An empty tree is complete on arrival of the header, with no sweep to
// publish its count.
refreshMissingNodeCounts();
ledger_->txMap().setSynching();
ledger_->stateMap().setSynching();
@@ -969,6 +1033,11 @@ InboundLedger::receiveNode(protocol::TMLedgerData const& packet, SHAMapAddNode&
haveState_ = true;
}
// The tree finished on this batch, so the last sweep's count is now
// stale. Publishing 0 here is what stops a completed acquire from
// reading as a permanently stuck one. Outside the per-node loop above.
refreshMissingNodeCounts();
if (haveTransactions_ && haveState_)
{
complete_ = true;
@@ -1077,6 +1146,8 @@ InboundLedger::gotData(
return false;
receivedData_.emplace_back(peer, data);
// Mirror the depth for the telemetry gauge, which must not take this lock.
receivedDataDepth_.store(receivedData_.size(), std::memory_order_relaxed);
if (receiveDispatched_)
return false;
@@ -1144,11 +1215,7 @@ InboundLedger::processData(std::shared_ptr<Peer> peer, protocol::TMLedgerData co
return -1;
}
if (san.isUseful())
progress_ = true;
stats_ += san;
return san.getGood();
return recordBatchOutcome(san);
}
if ((packet.type() == protocol::liTX_NODE) || (packet.type() == protocol::liAS_NODE))
@@ -1180,16 +1247,43 @@ InboundLedger::processData(std::shared_ptr<Peer> peer, protocol::TMLedgerData co
<< ((packet.type() == protocol::liTX_NODE) ? "TX" : "AS")
<< " node stats: " << san.get();
if (san.isUseful())
progress_ = true;
stats_ += san;
return san.getGood();
return recordBatchOutcome(san);
}
return -1;
}
int
InboundLedger::recordBatchOutcome(SHAMapAddNode const& san)
{
if (san.isUseful())
progress_ = true;
stats_ += san;
// Emit the tallies the trace log above already printed. receiveNode() walks
// every node in the packet, so these MUST stay out here: the loop has
// finished and the tallies are aggregated, giving at most three counter Adds
// per received packet rather than per node. The split is what separates real
// progress (good) from wasted bandwidth (duplicate) and a misbehaving peer
// (invalid) -- traffic-level metrics show all three as healthy throughput.
auto const emit = [this](char const* outcome, int count) {
if (count <= 0)
return;
XRPL_METRIC_COUNTER_ADD_LABELED(
app_,
"sync_addnode_total",
"SHAMap nodes received during ledger acquire, by outcome",
static_cast<std::uint64_t>(count),
{{"outcome", std::string(outcome)}});
};
emit("good", san.getGood());
emit("duplicate", san.getDuplicate());
emit("invalid", san.getBad());
return san.getGood();
}
namespace detail {
// Track the amount of useful data that each peer returns
struct PeerDataCounts
@@ -1290,10 +1384,13 @@ InboundLedger::runData()
if (receivedData_.empty())
{
receiveDispatched_ = false;
receivedDataDepth_.store(0, std::memory_order_relaxed);
break;
}
data.swap(receivedData_);
// The stash was just drained into `data`; keep the mirror in step.
receivedDataDepth_.store(receivedData_.size(), std::memory_order_relaxed);
}
for (auto& entry : data)

View File

@@ -24,10 +24,12 @@
#include <xrpl/protocol/Serializer.h>
#include <xrpl/protocol/jss.h>
#include <xrpl/server/NetworkOPs.h>
#include <xrpl/shamap/SHAMapMissingNode.h>
#include <xrpl/shamap/SHAMapTreeNode.h>
#include <xrpl.pb.h>
#include <algorithm>
#include <chrono>
#include <cstddef>
#include <cstdint>
@@ -435,6 +437,37 @@ public:
return ledgers_.size();
}
AcquireProgress
acquireProgress() override
{
// Copy the handles under the lock, then read each acquire's atomics
// without it -- same pattern gotFetchPack() uses, so the ~10 s telemetry
// poll never contends with the node-receive path.
std::vector<std::shared_ptr<InboundLedger>> acquires;
{
ScopedLockType const sl(lock_);
acquires.reserve(ledgers_.size());
for (auto const& it : ledgers_)
{
XRPL_ASSERT(
it.second, "xrpl::InboundLedgersImp::acquireProgress : non-null ledger");
acquires.push_back(it.second);
}
}
AcquireProgress out;
out.inFlight = acquires.size();
for (auto const& acquire : acquires)
{
out.maxMissingStateNodes =
std::max(out.maxMissingStateNodes, acquire->getMissingNodeCount(SHAMapType::STATE));
out.maxMissingTxNodes = std::max(
out.maxMissingTxNodes, acquire->getMissingNodeCount(SHAMapType::TRANSACTION));
out.receivedDataDepth += acquire->getReceivedDataDepth();
}
return out;
}
private:
clock_type& clock_;

View File

@@ -488,6 +488,8 @@ MetricsRegistry::registerAsyncGauges()
registerClockSkewGauge();
registerSyncStateGauge();
registerStallEventsCounter();
registerSyncAcquireGauge();
registerCacheHitRateDetailGauge();
}
void
@@ -1637,6 +1639,88 @@ MetricsRegistry::registerStallEventsCounter()
this);
}
void
MetricsRegistry::registerSyncAcquireGauge()
{
// --- Sync diagnostics: is ledger acquisition actually progressing? ---
// Aggregated on purpose: a per-ledger label would add one series per ledger
// acquired, which is unbounded. The per-ledger view lives on the
// ledger.acquire span instead.
syncAcquireGauge_ = meter_->CreateInt64ObservableGauge(
"sync_acquire", "Aggregate ledger-acquire progress across in-flight acquires");
syncAcquireGauge_->AddCallback(
[](opentelemetry::metrics::ObserverResult result, void* state) {
auto* self = static_cast<MetricsRegistry*>(state);
if (self->callbacksDetached_.load(std::memory_order_acquire))
return;
auto& app = self->app_;
try
{
auto observe = [&](char const* name, int64_t value) {
opentelemetry::nostd::get<opentelemetry::nostd::shared_ptr<
opentelemetry::metrics::ObserverResultT<int64_t>>>(result)
->Observe(value, {{"metric", name}});
};
// One snapshot feeds all four series, so they are mutually
// consistent rather than read at four different instants.
auto const progress = app.getInboundLedgers().acquireProgress();
// Flat and non-zero across ticks = this acquire will never
// finish. Shrinking = slow but alive.
observe(
"missing_state_nodes_max", static_cast<int64_t>(progress.maxMissingStateNodes));
observe("missing_tx_nodes_max", static_cast<int64_t>(progress.maxMissingTxNodes));
// Deep stash = arriving data outpaces processing.
observe("received_data_depth", static_cast<int64_t>(progress.receivedDataDepth));
// Context for the three above: zero everywhere with zero
// in-flight acquires is idle, not healthy.
observe("in_flight", static_cast<int64_t>(progress.inFlight));
}
catch (...) // NOLINT(bugprone-empty-catch)
{
// Silently skip if services are not yet ready.
}
},
this);
}
void
MetricsRegistry::registerCacheHitRateDetailGauge()
{
// --- Sync diagnostics: SHAMap tree-node cache hit rate ---
// The memory layer above the node store: a miss here is what causes a
// node-store read, which the NuDB hit-ratio panel then measures.
shamapCacheHitRateGauge_ = meter_->CreateDoubleObservableGauge(
"shamap_cache_hit_rate", "SHAMap tree-node cache hit rate (0.0-1.0), by cache");
shamapCacheHitRateGauge_->AddCallback(
[](opentelemetry::metrics::ObserverResult result, void* state) {
auto* self = static_cast<MetricsRegistry*>(state);
if (self->callbacksDetached_.load(std::memory_order_acquire))
return;
auto& app = self->app_;
try
{
// TaggedCache::getHitRate() returns 0-100; normalize to 0.0-1.0
// so the panel can use Grafana's "percentunit" unit, matching
// how cache_metrics already reports its rates.
auto const rate = app.getNodeFamily().getTreeNodeCache()->getHitRate() / 100.0F;
opentelemetry::nostd::get<opentelemetry::nostd::shared_ptr<
opentelemetry::metrics::ObserverResultT<double>>>(result)
->Observe(static_cast<double>(rate), {{"metric", "treenode"}});
}
catch (...) // NOLINT(bugprone-empty-catch)
{
// Silently skip if services are not yet ready.
}
},
this);
}
#endif // XRPL_ENABLE_TELEMETRY
// -----------------------------------------------------------------

View File

@@ -570,6 +570,18 @@ private:
*/
opentelemetry::nostd::shared_ptr<opentelemetry::metrics::ObservableInstrument>
stallEventsObservable_;
/**
* Observable gauge for aggregate ledger-acquire progress (max missing state
* and tx nodes, received-data stash depth, in-flight acquire count).
*/
opentelemetry::nostd::shared_ptr<opentelemetry::metrics::ObservableInstrument>
syncAcquireGauge_;
/**
* Observable gauge for the SHAMap tree-node cache hit rate, which is the
* memory layer above the node store's own hit ratio.
*/
opentelemetry::nostd::shared_ptr<opentelemetry::metrics::ObservableInstrument>
shamapCacheHitRateGauge_;
/**
* Observable gauge for build version info (label-based, value=1).
*/
@@ -832,7 +844,65 @@ private:
*/
void
registerStallEventsCounter(); // sync diagnostics: stall episode count
#endif // XRPL_ENABLE_TELEMETRY
/**
* Register the `sync_acquire` gauge.
*
* One instrument fanning out four series under the `metric` attribute, all
* from a single InboundLedgers::acquireProgress() snapshot:
*
* `missing_state_nodes_max` — largest outstanding account-state node count
* of any in-flight acquire. THE headline stuck-sync signal: flat and
* non-zero across ticks means the acquire will never finish, shrinking
* means it is slow but alive.
* `missing_tx_nodes_max` — the same for the transaction tree.
* `received_data_depth` — peer packets stashed across all acquires waiting
* to be applied. Deep means processing, not peer supply, is the limit.
* `in_flight` — how many acquires are running, so the three values above
* can be read in context: all zero with `in_flight` zero is idle, not
* healthy.
*
* Deliberately aggregated rather than per-ledger. A `ledger_seq` label would
* mint a new time series for every ledger the node ever acquires, which is
* unbounded cardinality; the max/sum keeps the "is it stuck?" answer while
* the per-ledger identity stays on the `ledger.acquire` span, where
* high-cardinality identity belongs.
*
* @note Pulled on the OTel reader thread (~10 s tick), never on a hot path.
* The snapshot takes the acquire-collection lock only to copy shared_ptrs,
* then reads relaxed atomics; the emit sites that feed those atomics all sit
* outside the per-tree-node loops.
*/
void
registerSyncAcquireGauge(); // sync diagnostics: acquire progress
/**
* Register the `shamap_cache_hit_rate` gauge.
*
* Observes one series, `treenode`, from TreeNodeCache::getHitRate(): the
* percentage of SHAMap tree-node lookups served from memory instead of the
* node store. During a fresh sync a low rate means the node re-reads the
* same subtrees from disk, so sync is disk-bound rather than peer-bound.
*
* Distinct from the `NuDB Cache Hit Ratio` panel on the ledger-data-sync
* dashboard: that one is derived from `nodestore_state` and measures the
* node-store layer (`node_reads_hit / node_reads_total`). This gauge
* measures the in-memory tree-node cache that sits ABOVE it, so a request
* missing here is what produces a node-store read there.
*
* The full-below cache is deliberately NOT reported. It is a KeyCache, whose
* only lookup path is TaggedCache::touchIfExists(), and that method
* increments `stats_.hits`/`stats_.misses` while `getHitRate()` reads the
* separate `hits_`/`misses_` members. Its hit rate is therefore hard-wired
* to 0 regardless of behaviour, so exporting it would ship a permanently
* empty panel; fixing that accounting belongs in a libxrpl change of its own.
*
* @note Pulled on the OTel reader thread (~10 s tick). Takes the cache's
* mutex for two integer reads and a divide; no hot-path cost.
*/
void
registerCacheHitRateDetailGauge(); // sync diagnostics: treenode cache
#endif // XRPL_ENABLE_TELEMETRY
};
} // namespace telemetry