Phase-10 brought in the upstream nodestore/peerfinder/consensus reorganisation
along with its own write-path telemetry, which collided with the sync-diagnostic
signals on this branch. Twelve files conflicted; every resolution keeps both
intents rather than picking a side.
The nodestore write timing was implemented twice, independently. Both sides
added getStoreDurationUs()/getFetchDurationUs() to Database and both timed the
backend call in each concrete store(). Keeping both would have added twice to
storeDurationUs_ per store while storeStats() still counted one, so the mean
write latency would have read double on every dashboard -- silently, since no
test on either side asserts an exact microsecond figure. Resolved to one
accumulator API: recordStoreDuration(), which takes a duration, clamps a
sub-microsecond sample to zero and uses a relaxed atomic add. Phase-10's
storeDurationStats() is gone and its two call sites now use the survivor, so
all three store paths -- both store() overrides and importInternal() -- add
exactly once.
SlotCensus and its pure virtual moved from src/xrpld/peerfinder/ to
include/xrpl/peerfinder/PeerfinderManager.h, following the Manager interface
upstream relocated. The xrpld header is now phase-10's makeConfig shim, and
Overlay.h, MetricMacros.cpp and the getSlotCensus() override chain point at the
new location. ConsensusSpanNames.h and peerfinder Slot.h/Config.h include paths
followed their headers into libxrpl the same way.
InboundLedger gained phase-10's AcquireStats counters next to this branch's
span activations in both the destructor abort path and done(); neither
displaces the other. nodestore_state keeps the constant-based name this branch
requires of it and phase-10's fuller description.
Upstream #7292 deleted src/test/nodestore/Database_test.cpp, which held this
branch's testDurationAccessors. Phase-10 restored the per-store half of that
coverage in DatabaseConfig_test, but nothing covered importInternal -- it writes
through storeBatch() and never through store(), so it is a third store path that
has to time itself. That half is ported to a GTest in
src/tests/libxrpl/nodestore/Database.cpp, keeping the exact zero-before and
accumulate-after assertions and the per-instance negative check.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
FetchReport::elapsed was milliseconds, so every nodestore read rounded to
zero: a warm store answers in single-digit microseconds and a cold one in
low hundreds, and both became 0 ms. That difference is the whole signal
separating a cold-read stall from a healthy node, and it was being
discarded at the type. Database::fetchNodeObject now measures once and
uses that one value for both the cumulative counter and the report, so
the two can never disagree. The job-queue call still takes milliseconds
and now casts explicitly.
BatchWriteReport::elapsed stays milliseconds and is documented as such:
a batch write covers many objects and reaches the disk, so it belongs in
that range.
Also adds a sub-millisecond histogram ladder, because the existing bucket
edges start at 100 microseconds and put the entire warm range in bucket
0. It is not wired to a view yet: no sub-millisecond instrument exists to
name, so the edges wait for the instrument that records read latency.
The new test captures what the nodestore reports and asserts the reported
total equals the internal microsecond accumulator exactly, plus that at
least one report is not a whole number of milliseconds -- which a
millisecond-typed field can never satisfy on any hardware.
A saturated ledgerData lane makes TimeoutCounter re-arm its timer
without running the timer body, so timeouts_ never advances and the
six-timeout give-up can never fire. Acquisitions then neither finish
nor fail until the one-minute sweep destroys their partial maps, and
the work restarts. Every step of that chain was debug-log-only, so a
node at warning level could not be diagnosed after the fact.
The counters are separate on purpose: deferrals rising while timeouts
stay flat is the signature, and no single counter shows it.
Completions are recorded in done() rather than at the "Done: complete"
log line, because that line also fires for failures and misses the
checkLocal and receiveNode paths; done() is the one funnel every
outcome passes through and its signaled_ guard makes it idempotent.
AcquireStats is only forward-declared in ServiceRegistry so libxrpl
still includes nothing from xrpld. The src/ include path for the test
binary moves out of the telemetry guard, since a header-only type
under src/xrpld/ is testable in every build.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
The consensus headers moved into the isolated xrpl/consensus module and
took a dependency on xrpl/telemetry for the tracing span constants, but
two things were left behind:
- Four includes still pointed at the old src/xrpld/consensus/ location,
which no longer exists, so the build failed with
"fatal error: 'xrpld/consensus/ConsensusParms.h' file not found".
- xrpl.libxrpl.consensus never linked xrpl.libxrpl.telemetry. add_module
isolates each module's headers, so xrpl/telemetry/SpanNames.h was not
on the include path even once the include was repointed.
Repoint the stale includes at xrpl/consensus/, and declare the telemetry
module before consensus so consensus can link it. Regenerate ordering.txt
for the resulting edge.
NuDB serializes every insert behind one global mutex held for the whole
call, so a caller cannot see how long it waited. Record instead the
writer depth joined at and the wall time spent; with mean depth L and
mean insert time W, Little's Law gives service time W/L and queueing
W - W/L. That distinguishes a serialized write path from a saturated
disk: measured on a dev box the device sat 89 percent idle while
throughput stayed flat at 42k inserts per second.
The accounting runs from a ScopeExit guard because the insert can
allocate and therefore throw; leaking the depth would strand the gauge
above zero for the life of the process.
getWriteLoad also stops returning a hardcoded zero. It now reports
writer depth, which is bounded by the writing-thread count and so stays
far below the kMaxWriteLoadAcquire cutoff that gates history
acquisition, where returning bytes or microseconds would have silently
suppressed it.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
json::ValueConstIterator and ValueIterator declared difference_type,
reference and pointer but not value_type or iterator_category. Under
C++23, std::iterator_traits then classifies them as output iterators,
so std::all_of over a Value's members (isValidJson2 in RPCCall.cpp)
fails to instantiate on GCC 13/14 with:
cannot convert 'output_iterator_tag' to 'std::input_iterator_tag'
GCC 15 masks this via LWG-3798/P2609, but the perf CI image ships
GCC 13, so the source needs the traits regardless. The iterators wrap
a std::map iterator (++/-- only), so the category is bidirectional.
Add value_type + iterator_category to both iterators, include <iterator>,
and add a regression test asserting the traits and that std::all_of /
std::count_if compile and run over Value members.
Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
Two suspects from the 3.3.0 slowdown investigation had no signal. Both were
already computing the numbers and throwing them away, so this exposes them
rather than adding measurement.
Per-sweep heap trim. The trim runs after every cache sweep, and its cost
scales with resident heap, so it is the leading explanation for a node with
a populated database syncing slower than a fresh one. The report already
carried duration, fault deltas and reclaimed pages, but the whole
measurement sat behind a debug-journal check, so an ordinary node measured
nothing, and the call site discarded the result. The measurement now always
runs and only the log line stays gated. Records trim duration, minor faults
and reclaimed kilobytes. Measured cost of the always-on path is about six
microseconds per sweep against a trim costing milliseconds, at a cadence of
ten to a hundred and twenty seconds.
Honest limit, stated in the runbook: the fault delta spans only the trim
call, so it shows the trim itself faulting but not the faults that follow as
caches refill. The duration is the signal to correlate against sweep-job
queueing.
Rotation writes. Rotation copies archive-served reads forward and re-stores
nodes missing from both backends, both of which compete with sync I/O and
only happen on a populated online_delete database. The copy-forward count
existed but was reset by the rotation's own log line, so a metric reading it
would drop to zero on every swap; a never-reset total sits beside it now.
The re-store count was not measured at all. Rotation duration is
deliberately not recorded: the health throttle sleeps at eight points inside
the sequence and dominates exactly when the node is unhealthy, so the number
would conflate work with waiting.
Nothing added for the other two suspects. Get-object serving is already
covered by the handler label, the lookup histogram and the deferred and
saturation gauges; peer churn by the disconnect-reason counter.
Also replaces nine per-file cspell ignores with one ignoreRegExpList entry
for the telemetry macro names, and picks up the levelization baseline for the
consensus span-name test.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
fetchDurationUs_ had no getter, so telemetry reached it by building a JSON
object, stringifying a uint64 and parsing it back with stoll on every
collect tick. storeDurationUs_ was declared and never written or read at
all, along with the jss::node_writes_duration_us key.
Both now have accessors, both production store paths time their backend
call, and the registry reads them without the round trip. get_counts also
reports the write duration, so the RPC and the metric agree. Mean read
latency is the signal that separates a cold store from a warm one: warm
reads are single-digit microseconds, cold ones low hundreds.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Both were uint32_t while every sibling counter was uint64_t. On a
multi-day node node_read_bytes read 1,481,244,491 for 1,894,924,394
reads, i.e. 0.8 bytes per read, which is impossible: the counter had
wrapped about 350 times. Read hit rate is used to tell a cold-read
stall from a write-lock ceiling, so a wrapping numerator makes that
diagnosis wrong rather than merely imprecise.
getFetchTotalCount() was already backed by a uint64_t member, so its
32-bit return type truncated a correct value at the accessor. All
three getters now return uint64_t.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Phase-10 independently instrumented the peer object-fetch path while this
branch instrumented fresh-node sync, so the two overlapped in three places.
Resolved by keeping each side's stronger implementation rather than shipping
both.
Per-job-type waiting/running/deferred existed twice. Phase-10's version
survives: it publishes per-type gauges from JobQueue::collect(), which
snapshots under the queue lock and publishes after releasing it, a
deliberate lock-order fix against the collector's own lock. This branch's
jobq_backlog gauge and the JobQueue::getJobTypeCounts() accessor that fed it
are removed, along with their panels, assertions and reference rows.
jobq_saturation stays: it reports the whole worker pool, which phase-10 has
no equivalent for.
The histogram view helper also existed twice with identical bodies under two
names; one survives, and the microsecond ladder is now the named array
rather than boundaries repeated inline. The job_type label was declared
twice, once as a file-local constant invisible to the naming check; both it
and handler now come from the constants header.
Two things phase-10 adds are complementary, not duplicates, and are kept as
they are: the handler label, which separates the two request kinds that both
report as the same job type, and getobject_rejected_total, which counts
malformed requests where this branch's serve_refused_total counts requests
this node declined to serve.
Also fixes two naming-check failures that pre-date this merge on phase-10.
The check derived label keys only from namespaced constants, so it could not
see the per-subsystem headers' flat k-prefixed style and rejected dashboards
querying labels the code really emits. It now reads both styles, with the
enforcement rules unchanged.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
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>
Sync-critical job types run at very low concurrency limits (ledgerRequest
and ledgerData allow 3 each), so a node can stall simply because those
jobs are held back behind other work. Nothing exposed that until now:
the existing job metrics are rates and quantiles of jobs that already
moved, or a single queue-wide depth.
- jobq_backlog{metric,job_type}: instantaneous waiting, running and
deferred counts per job type. Deferred is the starvation signal and had
no exposure anywhere; it is set when a type is at its concurrency limit.
- jobq_saturation{metric}: running tasks, worker-thread count and total
waiting, so a slowdown spanning several subsystems can be attributed to
worker-pool exhaustion instead of being diagnosed once per victim.
Both read through two new const accessors on JobQueue that take the
existing mutex once and copy integers, so a single reading is internally
consistent and no per-job cost is added. The job_type label reuses the
same JobTypes name helper the existing job counters use, so the two label
sets join.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Slowness on the peer object-fetch path could be observed but not
attributed. Job duration metrics carry only `job_type`, and both
`RcvGetLedger` and `RcvGetObjByHash` report as `ledgerRequest`, so a
queue-wait spike could not be traced to a handler. Nothing measured
NodeStore cost, request size, or the differential charge.
Latency now decomposes into three additive parts, each separately
measurable:
end-to-end = queue wait + NodeStore lookup + everything else
- `handler` label on job_queued_total/_started_total/_finished_total and
job_queued_us/job_running_us. The value is sanitised: a name passes
through only if non-empty and all ASCII letters, else "other". Two job
names embed a ledger sequence, so a raw label would mint one series
per ledger; the rule bounds the domain at 43 names plus "other".
- getobject_lookup_us, _request_objects, _lookups_total{result},
_rejected_total{reason} and _charge, recorded at their call sites.
All three histograms get explicit bucket views: the SDK default stops
at 10,000, which every one of them exceeds.
- Per-job-type waiting/running/deferred gauges for the 35 non-special
job types. `deferred` is the leading indicator, since addJob never
rejects -- it defers, so backpressure otherwise shows up only as
latency after the fact.
`JobQueue::collect()` snapshots the counters under the queue lock and
publishes gauges after releasing it. Writing them while holding the lock
would invert a lock order against the collector's own lock, which the
collector's flush thread already holds when it calls this hook.
Tests assert exact values, including that the charge is priced on the
requested count rather than the capped iteration count.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
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>
Five signals that explain why a node is not advancing toward full, none of
which were observable before:
- state_changes_total now carries {from,to} mode labels, emitted at
setMode using the existing strOperatingMode helper. A bare count could
not distinguish a healthy climb from a node flapping between tracking
and connected. Removes the now-unused incrementStateChanges wrapper.
- sync_state{initial_full_duration_us}: time to first reach full, which
StateAccounting already computed but exposed only in server_info.
- sync_state{network_ledger_gate}: whether the node is still refusing to
build ledgers because it has no network ledger.
- sync_state{server_stall_seconds} and server_stall_events_total: how
long the main thread has been unresponsive. LoadManager computed this
and only logged it, so a stall was invisible until the fatal threshold.
The episode rule is a pure function so it can be tested without adding
a test-only mutator to LoadManager.
- sync_state{ledgers_behind}: how far our validated sequence trails the
best sequence any peer advertises, read from already-cached peer ranges
so no extra network traffic is added.
Also fixes the naming checker: it derived only the first label of a
multi-label instrument, so a dashboard querying the second label was
wrongly rejected.
Note: the clang-tidy hook cannot run in this worktree (no build
directory); the remaining pre-commit hooks, the naming check, dashboard
schema and harness syntax all pass.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Add shared current_ledger_seq / current_ledger_hash span attributes so a
transaction's work can be joined to the ledger trace that produced it, and
fix discrepancy D1 (txq.enqueue was a detached trace root).
- Define current_ledger_seq / current_ledger_hash once in SpanNames.h and
re-export via `using` from TxQ/TxApply/Tx span-name headers. These name the
ledger being worked on (open/tentative apply or in-flight consensus build),
distinct from ledger_seq (the built/validated ledger on ledger.build /
consensus.round). Named after the RPC field ledger_current_index.
- txq.enqueue: set current_ledger_seq/hash from the view, and parent the span
to the caller's tx.process span via an explicit captured SpanContext (new
trailing TxQ::apply param) instead of a detached root. The parent is
explicit, not ambient-inherited, and the ScopedSpanGuard scope is RAII-bound
to the synchronous apply, so it cannot leak onto a reused worker (D1 fix).
On the open-ledger rebuild path no tx.process context exists, so it stays a
root and the attribute provides the correlation.
- tx.preclaim / tx.transactor: set both attributes from their ledger view.
tx.preflight is stateless (no view) and is the documented exception.
- tx.process / tx.receive: set current_ledger_seq from the current open ledger
index at submit/receive time (no hash: not yet applied to a ledger).
- Contract test pins the two new attribute key strings.
Neither key is a spanmetrics dimension, so there is no metric-cardinality
impact. Dashboards/collector/docs land on the later phases per the chain split.
Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
