diff --git a/docker/telemetry/grafana/dashboards/ledger-sync-health.json b/docker/telemetry/grafana/dashboards/ledger-sync-health.json index 3a27b65306..443592ad93 100644 --- a/docker/telemetry/grafana/dashboards/ledger-sync-health.json +++ b/docker/telemetry/grafana/dashboards/ledger-sync-health.json @@ -5180,7 +5180,7 @@ "type": "prometheus", "uid": "${DS_PROMETHEUS}" }, - "description": "###### What this is:\n*Median and 95th-percentile consensus round duration, from the same native histogram as the heatmap beside it.*\n\n###### How it's computed:\n*Quantiles over the consensus_round_duration_ms buckets. The heatmap shows the whole shape; these two lines are the trend an alert can be written against.*\n\n###### Reading it:\n*P50 is the typical round and should sit near the network's close interval. The gap between P50 and P95 is the tail: a small gap means rounds are uniform, a wide one means some rounds are much slower than the rest.*\n\n###### Healthy range:\n*P50 around 3-4 s, P95 within a couple of seconds of it.*\n\n###### Watch for:\n*P95 climbing while P50 stays flat \u2014 a minority of rounds are stalling, which is the early form of the problem the heatmap shows later as a second band. Both rising together is the whole network slowing rather than this node.*\n\n###### Keywords:\n- **Consensus round duration** *(per node)* \u2014 wall-clock time from the start of a consensus round to its accepted ledger, as this node measured it.\n\n###### Computation boundary:\n*Result: Per node \u2014 each series is one server's own value.*\n*Computed in xrpld code (call-site metric macro, OpenTelemetry SDK) and exported as a metric; the collector only forwards it; the Grafana query selects and aggregates it.*\n\n###### Source:\n[RCLConsensus.cpp](https://github.com/XRPLF/rippled/blob/develop/src/xrpld/app/consensus/RCLConsensus.cpp)\n\n###### Function:\n`RCLConsensus::Adaptor::makeAcceptSpan`\n\n###### References:\n[Telemetry glossary](https://github.com/XRPLF/rippled/blob/develop/docs/telemetry-glossary.md#consensus-round-duration)", + "description": "###### What this is:\n*p95 wall-clock seconds spent in each online-delete rotation phase, broken down by `stage`. Recorded from `SHAMapStoreImp::RotationPhase`'s destructor at the end of every rotation phase.*\n\n###### What to look for:\n* `freshen.keys` p95 in seconds means the tree-node cache mutex was held across a `getKeys()` copy for that long \u2014 every SHAMap fetch during that window waited.\n* `copy` p95 approaching the rotation cadence means the state-map walk is no longer converging inside its own interval.\n\n###### Source:\n`SHAMapStoreImp.cpp` \u2014 `SHAMapStoreImp::run` and `RotationPhase`\n\n###### Keywords:\nRotation phase duration, online-delete, freshen.keys, rotation stall", "fieldConfig": { "defaults": { "color": { @@ -5190,7 +5190,7 @@ "axisBorderShow": false, "axisCenteredZero": false, "axisColorMode": "text", - "axisLabel": "Round duration", + "axisLabel": "Phase duration (s)", "axisPlacement": "auto", "barAlignment": 0, "barWidthFactor": 0.6, @@ -5280,7 +5280,7 @@ "type": "prometheus", "uid": "${DS_PROMETHEUS}" }, - "description": "###### What this is:\n*Median and 95th-percentile consensus round duration, from the same native histogram as the heatmap beside it.*\n\n###### How it's computed:\n*Quantiles over the consensus_round_duration_ms buckets. The heatmap shows the whole shape; these two lines are the trend an alert can be written against.*\n\n###### Reading it:\n*P50 is the typical round and should sit near the network's close interval. The gap between P50 and P95 is the tail: a small gap means rounds are uniform, a wide one means some rounds are much slower than the rest.*\n\n###### Healthy range:\n*P50 around 3-4 s, P95 within a couple of seconds of it.*\n\n###### Watch for:\n*P95 climbing while P50 stays flat \u2014 a minority of rounds are stalling, which is the early form of the problem the heatmap shows later as a second band. Both rising together is the whole network slowing rather than this node.*\n\n###### Keywords:\n- **Consensus round duration** *(per node)* \u2014 wall-clock time from the start of a consensus round to its accepted ledger, as this node measured it.\n\n###### Computation boundary:\n*Result: Per node \u2014 each series is one server's own value.*\n*Computed in xrpld code (call-site metric macro, OpenTelemetry SDK) and exported as a metric; the collector only forwards it; the Grafana query selects and aggregates it.*\n\n###### Source:\n[RCLConsensus.cpp](https://github.com/XRPLF/rippled/blob/develop/src/xrpld/app/consensus/RCLConsensus.cpp)\n\n###### Function:\n`RCLConsensus::Adaptor::makeAcceptSpan`\n\n###### References:\n[Telemetry glossary](https://github.com/XRPLF/rippled/blob/develop/docs/telemetry-glossary.md#consensus-round-duration)", + "description": "###### What this is:\n*Longest single hold of a `TaggedCache::mutex_` since the previous collection tick, in microseconds. One series each for the tree-node cache and the FullBelow cache, observed on the `cache_metrics` gauge.*\n\n###### What to look for:\n* A multi-second peak in `treenode_lock_hold_peak_us` is the mutex hold that froze every SHAMap fetch job.\n* Correlate with the `nodestore.rotate.freshen.keys` span and the `rotating` log line \u2014 a rotation is the usual cause.\n\n###### Source:\n`TaggedCache.ipp` \u2014 `noteLockHold`, `takeLockHoldPeak`; observed by `MetricsRegistry::observeCacheLockHoldPeaks`\n\n###### Keywords:\nTaggedCache lock hold, TreeNodeCache, FullBelowCache, rotation stall", "fieldConfig": { "defaults": { "color": { @@ -5290,7 +5290,7 @@ "axisBorderShow": false, "axisCenteredZero": false, "axisColorMode": "text", - "axisLabel": "Round duration", + "axisLabel": "Lock hold (us)", "axisPlacement": "auto", "barAlignment": 0, "barWidthFactor": 0.6, diff --git a/docker/telemetry/workload/expected_metrics.json b/docker/telemetry/workload/expected_metrics.json index a12530242c..87311f3cbe 100644 --- a/docker/telemetry/workload/expected_metrics.json +++ b/docker/telemetry/workload/expected_metrics.json @@ -310,7 +310,8 @@ "drop_total": "include/xrpl/resource/detail/Logic.h:42, makeMeter('drop'); same CreateUInt64Counter mapping and same _total suffix as warn_total. Incremented only at Logic.h:505, when a consumer's balance is at or above kDropThreshold and the connection is dropped. Grafana Cloud shows 2 live series, so unlike warn_total this one does fire in the wild \u2014 but only on a genuinely abusive consumer, which the harness deliberately does not create, so it is condition-gated all the same. Its rpc-pathfinding panel is likewise correct rather than phantom.", "jobq_*_milliseconds, jobq_*_q_milliseconds": "This key is a pattern rather than a literal metric name \u2014 unlike every other entry in this map it stands for a whole family, one pair per job type. Created per job type in JobTypeData.h:97-98 from info.name() and info.name() + kSuffixQueued ('_q'), so the exported names are jobq__milliseconds and jobq__q_milliseconds with the job type lowercased by formatName. Which job types appear depends on which jobs a run happens to schedule, so no individual name is guaranteed. They are also rounded up to a whole millisecond at source (Event.h:47-51 applies ceil to a millisecond value type), which is why 6e2b2da772 moved the ledger-data-sync q-wait panels off jobq__q_milliseconds_bucket onto job_queued_us_bucket \u2014 they are poor assertion targets regardless.", "rotation_phase_duration_seconds": "Recorded only at the end of an online-delete rotation phase (SHAMapStoreImp::RotationPhase destructor). The harness never rotates; see the nodestore.rotate note in expected_spans.json.", - "jobq_stall_total": "Incremented in MetricsRegistry::recordJobFinished only when a job ran >= kJobStallThresholdUs (1 s). A healthy 5-node localhost run has no such job, so the series may not exist." + "jobq_stall_total": "Incremented in MetricsRegistry::recordJobFinished only when a job ran >= kJobStallThresholdUs (1 s). A healthy 5-node localhost run has no such job, so the series may not exist.", + "consensus_view_change_total": "Incremented only when RCLConsensus::Adaptor::getPrevLedger sees the network's preferred ledger differ from this node's and mode is not already WrongLedger. A healthy 5-node harness never diverges from the network view, so the series may not exist under run-full-validation.sh." } }, "accounted_patterns": [ diff --git a/docker/telemetry/workload/expected_spans.json b/docker/telemetry/workload/expected_spans.json index b3f06a8677..c4760e221c 100644 --- a/docker/telemetry/workload/expected_spans.json +++ b/docker/telemetry/workload/expected_spans.json @@ -160,7 +160,7 @@ "consensus_phase" ], "config_flag": "trace_consensus", - "note": "Root consensus span created per round. Also carries trace_strategy, previous_ledger_seq, previous_proposers, previous_round_time_ms. Emits seven span EVENTS that this manifest cannot assert: phase.open, phase.recovery, phase.establish, phase.accepted, outcome.yes, outcome.moved_on, outcome.expired (declared ConsensusSpanNames.h:265-277; emitted RCLConsensus.cpp:1344 and via onPhaseEvent/onOutcomeEvent from Consensus.h:764, 793, 1047, 1517-1525, 1530, 1566). validate_telemetry.py reads only span name, attributes and start/end timestamps from the Tempo OTLP payload \u2014 it has no event assertion support \u2014 so adding an \"events\" key here would be silently ignored. Recorded as a note instead; asserting events needs validator support first." + "note": "Root consensus span created per round. Also carries trace_strategy, previous_ledger_seq, previous_proposers, previous_round_time_ms. Emits seven span EVENTS that this manifest cannot assert: phase.open, phase.recovery, phase.establish, phase.accepted, outcome.yes, outcome.moved_on, outcome.expired (declared ConsensusSpanNames.h:265-277; emitted RCLConsensus.cpp:1344 and via onPhaseEvent/onOutcomeEvent from Consensus.h:764, 793, 1047, 1517-1525, 1530, 1566), plus a `view.change` event emitted from RCLConsensus::Adaptor::getPrevLedger when the network's preferred ledger differs from this node's (carries prev_ledger_prefix and net_ledger_prefix). validate_telemetry.py reads only span name, attributes and start/end timestamps from the Tempo OTLP payload \u2014 it has no event assertion support \u2014 so adding an \"events\" key here would be silently ignored. Recorded as a note instead; asserting events needs validator support first." }, { "name": "consensus.phase.open", diff --git a/src/xrpld/app/misc/SHAMapStoreImp.cpp b/src/xrpld/app/misc/SHAMapStoreImp.cpp index e4d39a42c9..3dc1ef6383 100644 --- a/src/xrpld/app/misc/SHAMapStoreImp.cpp +++ b/src/xrpld/app/misc/SHAMapStoreImp.cpp @@ -3,6 +3,7 @@ #include #include +#include #include #include #include @@ -34,6 +35,8 @@ #include #include #include +#include +#include #include @@ -440,7 +443,8 @@ SHAMapStoreImp::run() rotating = false; } }; - RotationOutcome outcome{rotateSpan, rotating_, std::nullopt}; + RotationOutcome outcome{ + .span = rotateSpan, .rotating = rotating_, .exit = std::nullopt}; rotating_ = true; auto const exitFor = [](HealthResult r) { @@ -456,7 +460,7 @@ SHAMapStoreImp::run() << "s. Complete ledgers: " << ledgerMaster_->getCompleteLedgers(); { - RotationPhase phase(*this, ns::phase::clearPrior, lv::clearPrior); + RotationPhase const phase(*this, ns::phase::clearPrior, lv::clearPrior); clearPrior(lastRotated); } if (auto const r = healthWait(); r != HealthResult::KeepGoing) @@ -529,13 +533,13 @@ SHAMapStoreImp::run() JLOG(journal_.trace()) << "Making a new backend"; auto newBackend = [&] { - RotationPhase phase(*this, ns::phase::newBackend, lv::newBackend); + RotationPhase const phase(*this, ns::phase::newBackend, lv::newBackend); return makeBackendRotating(); }(); JLOG(journal_.debug()) << validatedSeq << " new backend " << newBackend->getName(); { - RotationPhase phase(*this, ns::phase::clearCaches, lv::clearCaches); + RotationPhase const phase(*this, ns::phase::clearCaches, lv::clearCaches); clearCaches(validatedSeq); } if (auto const r = healthWait(); r != HealthResult::KeepGoing) diff --git a/src/xrpld/app/misc/SHAMapStoreImp.h b/src/xrpld/app/misc/SHAMapStoreImp.h index 554abc8c2e..726425147a 100644 --- a/src/xrpld/app/misc/SHAMapStoreImp.h +++ b/src/xrpld/app/misc/SHAMapStoreImp.h @@ -22,17 +22,20 @@ #include #include #include +#include #include #include #include #include +#include #include #include #include #include #include #include +#include #include namespace xrpl { @@ -223,7 +226,9 @@ private: ~RotationPhase() { - auto const seconds = + // [[maybe_unused]] so a -DXRPL_ENABLE_TELEMETRY=0 build (macro + // expands to `do {} while (false)`) keeps compiling under -Werror. + [[maybe_unused]] auto const seconds = std::chrono::duration(std::chrono::steady_clock::now() - start_).count(); XRPL_METRIC_HISTOGRAM_RECORD_LABELED( owner_.app_, diff --git a/src/xrpld/telemetry/MetricsRegistry.cpp b/src/xrpld/telemetry/MetricsRegistry.cpp index dc27239ab8..f785b6094c 100644 --- a/src/xrpld/telemetry/MetricsRegistry.cpp +++ b/src/xrpld/telemetry/MetricsRegistry.cpp @@ -838,7 +838,7 @@ MetricsRegistry::registerCacheHitRateGauge() // Longest TaggedCache mutex hold since the last tick. // Split out to keep this callback under the 80-line limit. - self->observeCacheLockHoldPeaks(result, app); + MetricsRegistry::observeCacheLockHoldPeaks(result, app); } catch (...) // NOLINT(bugprone-empty-catch) { @@ -851,7 +851,7 @@ MetricsRegistry::registerCacheHitRateGauge() void MetricsRegistry::observeCacheLockHoldPeaks( opentelemetry::metrics::ObserverResult& result, - ServiceRegistry& app) const + ServiceRegistry& app) { auto const tnPeak = app.getNodeFamily().getTreeNodeCache()->takeLockHoldPeak(); opentelemetry::nostd::get< diff --git a/src/xrpld/telemetry/MetricsRegistry.h b/src/xrpld/telemetry/MetricsRegistry.h index f36f9aea5e..4189576e8c 100644 --- a/src/xrpld/telemetry/MetricsRegistry.h +++ b/src/xrpld/telemetry/MetricsRegistry.h @@ -172,6 +172,7 @@ #ifdef XRPL_ENABLE_TELEMETRY #include #include +#include #include #include #include @@ -1295,11 +1296,11 @@ private: /** * Observe the two TaggedCache lock-hold peaks onto the cache_metrics * gauge. Split out to keep registerCacheHitRateGauge's callback under - * the 80-line limit. + * the 80-line limit. Static because it touches neither instance state + * nor telemetry members — it reads through the passed app reference. */ - void - observeCacheLockHoldPeaks(opentelemetry::metrics::ObserverResult& result, ServiceRegistry& app) - const; + static void + observeCacheLockHoldPeaks(opentelemetry::metrics::ObserverResult& result, ServiceRegistry& app); void registerTxqGauge(); void