From 42181b8ed28b641992236df07227174541db038b Mon Sep 17 00:00:00 2001 From: Pratik Mankawde <3397372+pratikmankawde@users.noreply.github.com> Date: Tue, 15 Sep 2026 14:22:40 +0100 Subject: [PATCH 1/4] test(server): silence false-positive optional-access on asserted reads clang-tidy's bugprone-unchecked-optional-access does not model GTest's ASSERT_TRUE(x.has_value()), so it flags every deref that follows one. The reads are guarded; mark them NOLINT, matching the same suppression in src/tests/libxrpl/consensus/LedgerTrie.cpp. .value() does not help -- the checker treats it as an unchecked access too. Co-Authored-By: Claude Opus 4.8 (1M context) --- src/tests/libxrpl/server/NodeIdentity.cpp | 9 +++++++++ 1 file changed, 9 insertions(+) diff --git a/src/tests/libxrpl/server/NodeIdentity.cpp b/src/tests/libxrpl/server/NodeIdentity.cpp index 6c5d1341f3..a6a1b6500b 100644 --- a/src/tests/libxrpl/server/NodeIdentity.cpp +++ b/src/tests/libxrpl/server/NodeIdentity.cpp @@ -109,8 +109,10 @@ TEST(WalletNodeIdentity, store_then_read_returns_the_same_pair) auto db = (*wallet).checkoutDb(); auto const stored = readNodeIdentity(*db); ASSERT_TRUE(stored.has_value()); + // NOLINTBEGIN(bugprone-unchecked-optional-access): presence asserted above. EXPECT_EQ(stored->first, minted.first); EXPECT_TRUE(std::ranges::equal(stored->second, minted.second)); + // NOLINTEND(bugprone-unchecked-optional-access) } TEST(WalletNodeIdentity, store_appends_rather_than_replacing) @@ -137,6 +139,7 @@ TEST(WalletNodeIdentity, store_appends_rather_than_replacing) // comes back -- not which one. auto const stored = readNodeIdentity(*db); ASSERT_TRUE(stored.has_value()); + // NOLINTNEXTLINE(bugprone-unchecked-optional-access): presence asserted above. EXPECT_TRUE(stored->first == first.first || stored->first == second.first) << "readNodeIdentity must return one of the two stored pairs"; } @@ -159,8 +162,10 @@ TEST(WalletNodeIdentity, clear_then_store_installs_the_new_pair) storeNodeIdentity(*db, replacement); auto const stored = readNodeIdentity(*db); ASSERT_TRUE(stored.has_value()); + // NOLINTBEGIN(bugprone-unchecked-optional-access): presence asserted above. EXPECT_EQ(stored->first, replacement.first); EXPECT_TRUE(std::ranges::equal(stored->second, replacement.second)); + // NOLINTEND(bugprone-unchecked-optional-access) } TEST(WalletNodeIdentity, get_mints_and_persists_when_the_table_is_empty) @@ -175,6 +180,7 @@ TEST(WalletNodeIdentity, get_mints_and_persists_when_the_table_is_empty) auto const stored = readNodeIdentity(*db); ASSERT_TRUE(stored.has_value()) << "getNodeIdentity() must persist what it mints"; + // NOLINTNEXTLINE(bugprone-unchecked-optional-access): presence asserted above. EXPECT_EQ(stored->first, minted.first); EXPECT_EQ(getNodeIdentity(*db).first, minted.first); } @@ -217,6 +223,7 @@ TEST(ParseNodeIdentitySeed, valid_cmdline_returns_that_seed) auto const seed = parseNodeIdentitySeed(std::string{kValidSeed}, std::nullopt); ASSERT_TRUE(seed.has_value()); + // NOLINTNEXTLINE(bugprone-unchecked-optional-access): presence asserted above. auto const sk = generateSecretKey(KeyType::Secp256k1, *seed); auto const pk = derivePublicKey(KeyType::Secp256k1, sk); EXPECT_EQ(toBase58(TokenType::NodePublic, pk), std::string{kValidSeedPublic}); @@ -229,6 +236,7 @@ TEST(ParseNodeIdentitySeed, valid_config_returns_that_seed) auto const seed = parseNodeIdentitySeed(std::nullopt, std::string{kValidSeed}); ASSERT_TRUE(seed.has_value()); + // NOLINTNEXTLINE(bugprone-unchecked-optional-access): presence asserted above. auto const sk = generateSecretKey(KeyType::Secp256k1, *seed); auto const pk = derivePublicKey(KeyType::Secp256k1, sk); EXPECT_EQ(toBase58(TokenType::NodePublic, pk), std::string{kValidSeedPublic}); @@ -261,6 +269,7 @@ TEST(ParseNodeIdentitySeed, cmdline_wins_over_config) auto const seed = parseNodeIdentitySeed(std::string{kValidSeed}, std::string{kOtherSeed}); ASSERT_TRUE(seed.has_value()); + // NOLINTNEXTLINE(bugprone-unchecked-optional-access): presence asserted above. auto const sk = generateSecretKey(KeyType::Secp256k1, *seed); auto const pk = derivePublicKey(KeyType::Secp256k1, sk); EXPECT_EQ(toBase58(TokenType::NodePublic, pk), std::string{kValidSeedPublic}); From 866ab77ececf6dfd4f6b17f4e111c525e1edba77 Mon Sep 17 00:00:00 2001 From: Pratik Mankawde <3397372+pratikmankawde@users.noreply.github.com> Date: Tue, 15 Sep 2026 14:26:17 +0100 Subject: [PATCH 2/4] docs(telemetry): describe rotation measurements without naming the host The runbook provenance paragraph named the internal AWS dev box and a build hash and dates. State what was measured (one mainnet node, same host and binary, differing only in store state) without the deployment detail, which belongs in an internal runbook, not the public repo. --- docs/telemetry-runbook.md | 5 ++--- 1 file changed, 2 insertions(+), 3 deletions(-) diff --git a/docs/telemetry-runbook.md b/docs/telemetry-runbook.md index e1098a30b4..1274ee51df 100644 --- a/docs/telemetry-runbook.md +++ b/docs/telemetry-runbook.md @@ -3308,9 +3308,8 @@ increase(nodestore_state{metric="acquire_ledger_timeouts", service_instance_id=~ #### Measured reference points -**Provenance.** The two columns below are our own measurements: node2 on the AWS -dev box, build `e3c2f8279a`, 2026-07-27/28, same host and same binary for both -runs, differing only in the state of the store. Use them as the shape to compare +**Provenance.** The two columns below are our own measurements: one mainnet node, +same host and same binary for both runs, differing only in the state of the store. Use them as the shape to compare against, not as thresholds. The read figures below come from the `read_mean_us` gauge, the only read-latency signal exported; the "highest sample" row is the largest value that gauge reached over the run, not a read-latency percentile. The third dataset in this section — the 25-minute devnet stall and its From 50eff17dd458030f7b0c98215c688551f5a6cf10 Mon Sep 17 00:00:00 2001 From: Pratik Mankawde <3397372+pratikmankawde@users.noreply.github.com> Date: Tue, 15 Sep 2026 14:26:23 +0100 Subject: [PATCH 3/4] docs(telemetry): drop the host name from the sampling-clock comment The comment measured date +%s%N cost 'on a dev box'; say 'on one Linux host' instead. The number is the point, not where it was taken. --- docker/telemetry/workload/collect_system_metrics.sh | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/docker/telemetry/workload/collect_system_metrics.sh b/docker/telemetry/workload/collect_system_metrics.sh index 931b0ef6ed..87cc707bab 100755 --- a/docker/telemetry/workload/collect_system_metrics.sh +++ b/docker/telemetry/workload/collect_system_metrics.sh @@ -133,8 +133,8 @@ log "Collecting metrics for ${DURATION}s (${SAMPLES} samples, ${#RPC_PORTS[@]} n # exit 0 with an all-zero JSON — a silent false pass. # # The clock has to be cheap as well as precise, because the latency it -# measures is compared against a 2 ms threshold. Measured on a dev box: `date -# +%s%N` costs ~1.2 ms per call, forking python3 for the same value ~13 ms. +# measures is compared against a 2 ms threshold. Measured on one Linux host: +# `date +%s%N` costs ~1.2 ms per call, forking python3 for the same value ~13 ms. # Two calls bracket every request, so a python3 fallback would add ~26 ms of # its own overhead to a 2 ms budget and make the number meaningless. There is # no cheap alternative worth having, so probe once and refuse to run without From b1345fff8de04c86dd81ccb793055f797b6e72f1 Mon Sep 17 00:00:00 2001 From: Pratik Mankawde <3397372+pratikmankawde@users.noreply.github.com> Date: Tue, 15 Sep 2026 14:26:25 +0100 Subject: [PATCH 4/4] docs(telemetry): describe the rotation stall without internal host names The reference doc, span-harness notes and histogram-bucket comments named the internal AWS dev box and dates while explaining why the rotation phases are timed. Reword to the general mechanism (a multi-second freeze at the copy-walk to freshen boundary on a populated node); the specific hosts, dates and trace ids stay in the task notes. --- OpenTelemetryPlan/09-data-collection-reference.md | 6 +++--- docker/telemetry/workload/expected_spans.json | 4 ++-- include/xrpl/telemetry/HistogramBuckets.h | 7 ++++--- src/tests/libxrpl/telemetry/HistogramBuckets.cpp | 6 +++--- 4 files changed, 12 insertions(+), 11 deletions(-) diff --git a/OpenTelemetryPlan/09-data-collection-reference.md b/OpenTelemetryPlan/09-data-collection-reference.md index 2c50b8e6a3..5c96c6234b 100644 --- a/OpenTelemetryPlan/09-data-collection-reference.md +++ b/OpenTelemetryPlan/09-data-collection-reference.md @@ -2409,7 +2409,7 @@ no panel (it is read in Tempo instead). | `txset.acquire` span (`outcome`, `txset_hash`, `duration_ms`, `timeouts`, `peer_count`) | span | `TransactionAcquire.cpp` — `TransactionAcquire::finalizeAcquireSpan` | Tx-Set Acquire Outcomes; Tx-Set Acquire Duration (p95) | One attempt to fetch the transaction set a consensus proposal referenced but this node did not hold. `TransactionAcquire` had **zero** telemetry of any kind before this, so a consensus round stalled waiting on a set was indistinguishable from an idle one. The sibling of `ledger.acquire`: same `TimeoutCounter` base, same trigger/onTimer/takeNodes shape, and the same `trace_ledger` flag so the two halves of a stuck sync cannot be enabled apart. `outcome` is `complete` \| `failed` \| `timeout` \| `abandoned`, stamped by one idempotent finalizer on every exit: `done()`; `abandonAcquireSpan()` when `InboundTransactions` stops pursuing the fetch (`giveSet`, the `newRound` sweep, `stop`, or the container being destroyed); and `cancel()`, a `TimeoutCounter` exit that fails the task without reaching `done()`. Each closes the span where the fetch really stops, so `duration_ms` never includes the time a stray reference lived; the destructor only asserts one of them ran. A fetch dropped before `init()` emits no span at all, so these outcomes cover the spans that exist, not every fetch constructed. `timeout` is distinct from `failed` because the exhausted-budget path sets the terminal `failed_` flag too — that flag is how the timer loop stops — so the outcome rule checks the timeout first or every timeout would read as a data fault. `txset_hash` identifies WHICH set stalled and stays span-only: one metric series per consensus round would be unbounded. **Which round(s) asked** is a repeated `round.request` **event** (`current_ledger_hash` + `current_ledger_seq`, re-exported keys), one per requesting round rather than a parent, a link or one attribute — each of those flattens a many-to-many relation to 1:1. Fired once per ROUND, not per peer proposal, keyed on the round's parent-ledger hash: that separates rounds STARTED on different forks at the same height, but NOT a mid-round wrong-ledger recovery, which never re-reaches `preStartRound`. The count is a LOWER BOUND valid only while the span is open — after it closes, later requests add nothing, so a fetch that kept three rounds waiting can show one event. Requester, never consumer. | | `ledger.serve` span (`object_type`, `outcome`, `served_nodes`, `peer_id`, `ledger_seq`) | span | `PeerImp.cpp` — `PeerImp::processLedgerRequest` (the `JtLedgerReq` worker) | Ledger Serve Rate by Object Type | This node answering a peer's `TMGetLedger` request — the **supply side** of the sync exchange, and the trace-level companion to the existing `serve_refused_total` counter. The whole serve path had no span, so how long this node takes to answer, and whether it answered at all, was unobservable. A fresh trace root, because the request arrives from the wire on a shared worker whose ambient span is unrelated. `object_type` (`header` \| `tx` \| `as` \| `txset`) and `outcome` (`complete` \| `partial` \| `refused`) are both derived by shared rules in `LedgerSpanNames.h` rather than named per branch, which is what stops the eight exits of `processLedgerRequest` disagreeing about one request. `outcome` is derived from the reply itself — `served_nodes` is the reply's own node count and is 0 on all seven refusal paths — so nothing is accumulated and no work is added to the per-node assembly loop. `partial` means the reply hit `Tuning::kSoftMaxReplyNodes`, so the peer must make another round trip. | | `peer.dial` span (`outcome`, `remote_endpoint`, `duration_ms`) | span | `ConnectAttempt.cpp` — `ConnectAttempt::reportOutcome` | Outbound Dial Outcomes (span-derived, per attempt) | One outbound connect attempt, as a per-attempt timeline rather than a rate. The trace-level companion to `overlay_connect_total` / `overlay_dial_latency_ms`: it carries the same six `outcome` values, set from the same `reportOutcome` funnel, so span and counter cannot disagree, and the funnel's existing first-call-wins guard makes the span exactly-once for free. What it adds is `remote_endpoint` — WHICH peer — which the counter deliberately cannot carry, because one series per peer address would be unbounded cardinality; it is a dedicated Tempo span column instead. A fresh trace root: a dial is the first thing a starting node does, so there is nothing to parent it to. An attempt torn down mid-dial by shutdown ends its span in the destructor with no `outcome`, which is the honest record of "never concluded" rather than a dropped span. | -| `nodestore.rotate` span + 8 children (`ledger_seq`, `last_rotated`, `outcome`; children carry a phase-specific attribute) | span | `SHAMapStoreImp.cpp` — `SHAMapStoreImp::run` rotation block; `RotationPhase` helper | Rotation Phase Duration (p95 by stage) | One trace per online-delete rotation. Fresh root: the SHAMapStore thread has no ambient span. The eight children — `clear_prior`, `copy`, `freshen.keys`, `freshen.fetch`, `new_backend`, `clear_caches`, `swap`, `health_wait` — are child spans through the thread's ambient scope, so each one covers exactly its own step. `outcome` is `complete`\|`expired`\|`stopping`\|`missing_node`, stamped by the `RotationOutcome` finalizer on whichever exit runs first; its destructor asserts one exit was named, catching a new return path that forgot to. Exists to make the 2026-09-13 dev-box discovery reproducible from telemetry alone: the `freshen.keys` child sits inside `SHAMapStoreImp::freshenCache` around `cache.getKeys()` on the tree-node cache, so a Tempo view of one rotation shows that child overlapping the frozen `consensus.*.receive` spans instead of leaving the lock hold un-attributable. | +| `nodestore.rotate` span + 8 children (`ledger_seq`, `last_rotated`, `outcome`; children carry a phase-specific attribute) | span | `SHAMapStoreImp.cpp` — `SHAMapStoreImp::run` rotation block; `RotationPhase` helper | Rotation Phase Duration (p95 by stage) | One trace per online-delete rotation. Fresh root: the SHAMapStore thread has no ambient span. The eight children — `clear_prior`, `copy`, `freshen.keys`, `freshen.fetch`, `new_backend`, `clear_caches`, `swap`, `health_wait` — are child spans through the thread's ambient scope, so each one covers exactly its own step. `outcome` is `complete`\|`expired`\|`stopping`\|`missing_node`, stamped by the `RotationOutcome` finalizer on whichever exit runs first; its destructor asserts one exit was named, catching a new return path that forgot to. Exists to make a rotation-driven stall reproducible from telemetry alone: the `freshen.keys` child sits inside `SHAMapStoreImp::freshenCache` around `cache.getKeys()` on the tree-node cache, so a Tempo view of one rotation shows that child overlapping the frozen `consensus.*.receive` spans instead of leaving the lock hold un-attributable. | | `rotation_phase_duration_seconds` (`stage`) | histogram | `SHAMapStoreImp.cpp` — `RotationPhase::~RotationPhase` | Rotation Phase Duration (p95 by stage) | Wall-clock seconds spent in one rotation phase, recorded once per phase end. Exists beside the spans because the Grafana Cloud collector applies 0.5% probabilistic tail sampling, so any single trace is likely dropped; the histogram is unsampled and exact. `stage` is the child span's suffix (see `lval::rotation_phase`), so a p95 panel breaks down by phase. Bucket ladder covers 1 s to 3600 s (see `HistogramBuckets.h`'s `kRotationPhaseSecondsBuckets`), because a `copy` phase runs ~10 min on mainnet and the spanmetrics 120 s ceiling would pin every quantile. | | `jobq_stall_total` (`job_type`) | counter | `MetricsRegistry.cpp` — `recordJobFinished` (compares against `kJobStallThresholdUs`) | Job Stalls >=1 s (Count By Job Type) | Every job whose run time reached `LoadMonitor`'s 1 s warn bar (the same "Job: … run:" log line). A process-wide freeze shows up here as several job types crossing the bar in the same second — the exact detector for a rotation-driven stall, since sampling cannot drop a counter. `job_type` comes from `JobTypes::name()`; no per-handler dimension, because the rotation stall pathology is not per-handler. | | `cache_metrics{metric="treenode_lock_hold_peak_us"\|"fullbelow_lock_hold_peak_us"}` | observable gauge | `MetricsRegistry.cpp` — `observeCacheLockHoldPeaks` reads `TaggedCache::takeLockHoldPeak()` | Cache Lock Hold Peak (us) | Longest single hold of the `TaggedCache::mutex_` since the previous collection tick, in microseconds, observed on the existing `cache_metrics` gauge. `take*()` is destructive: the tick reads the peak and resets. Emitted at 0 on an idle node, so absence of the series is a wiring bug rather than a healthy state. A multi-second value is the lock that froze every SHAMap-node fetch during a rotation, which is exactly the signal WP-B6 exists to expose. `TaggedCache` lives in `xrpl/basics` and cannot include telemetry headers, so the cache exposes a value and `MetricsRegistry` reads it — the same pattern `registerNodeStoreGauge` already uses. | @@ -2423,8 +2423,8 @@ threshold. A single wall-clock duration spanning the whole rotation would fold work-time and throttle-time into one number, and the throttle dominates precisely when the node is unhealthy — which is when the number would be read. -The trigger for splitting is the measurement of 2026-09-13/14: on `aws-dev-xrpl-1/2` -every rotation freezes the process 5–6 s at the copy-walk → freshen boundary, and no +The trigger for splitting was a measurement on two mainnet nodes with populated stores: +every rotation froze the process for seconds at the copy-walk → freshen boundary, and no existing signal could place that freeze in time (the `rotation_state{in_flight}` gauge is 60 s-resolution and only brackets the freshen/swap window, not the whole rotation). The fix, WP-B6, is per-phase timing: `rotation_phase_duration_seconds{stage}` and eight diff --git a/docker/telemetry/workload/expected_spans.json b/docker/telemetry/workload/expected_spans.json index c4760e221c..9d9b6b5e5c 100644 --- a/docker/telemetry/workload/expected_spans.json +++ b/docker/telemetry/workload/expected_spans.json @@ -503,7 +503,7 @@ "required_attributes": ["node_count"], "config_flag": "trace_ledger", "optional": true, - "note": "The whole-state-map walk. Measured 2026-09-13 on aws-dev-xrpl-1: ~10 min." + "note": "The whole-state-map walk; ten minutes or more on a populated node." }, { "name": "nodestore.rotate.freshen.keys", @@ -512,7 +512,7 @@ "required_attributes": ["key_count"], "config_flag": "trace_ledger", "optional": true, - "note": "TaggedCache::getKeys() under the tree-node cache mutex -- the 5-6 s hold that froze every job on aws-dev-xrpl-1/2 (2026-09-13). This is the child that must overlap the stalled receive spans in a Tempo view for the proof to close." + "note": "TaggedCache::getKeys() under the tree-node cache mutex -- a hold of seconds on a large cache that freezes every job. This is the child that must overlap the stalled receive spans in a Tempo view for the proof to close." }, { "name": "nodestore.rotate.freshen.fetch", diff --git a/include/xrpl/telemetry/HistogramBuckets.h b/include/xrpl/telemetry/HistogramBuckets.h index c0ed2540a2..599d92508d 100644 --- a/include/xrpl/telemetry/HistogramBuckets.h +++ b/include/xrpl/telemetry/HistogramBuckets.h @@ -108,9 +108,10 @@ inline constexpr std::array kMillisecondBuckets{ /** * Bucket edges, in seconds, for `rotation_phase_duration_seconds`. * - * Measured 2026-09-13 on aws-dev-xrpl-1: freshen.keys 5-6 s, freshen.fetch - * ~3 min, copy ~10 min, whole rotation 13-17 min. The 1 s floor sits under - * the lock hold; 3600 s leaves headroom above a slow rotation. + * On a populated online_delete node the phases run from seconds (freshen.keys) + * through minutes (freshen.fetch) to ten minutes or more (copy), and a whole + * rotation about a quarter of an hour. The 1 s floor sits under the shortest + * phase; 3600 s leaves headroom above a slow rotation. */ inline constexpr std::array kRotationPhaseSecondsBuckets{ 1.0, diff --git a/src/tests/libxrpl/telemetry/HistogramBuckets.cpp b/src/tests/libxrpl/telemetry/HistogramBuckets.cpp index 4ec1fcc9c8..87e8f06afa 100644 --- a/src/tests/libxrpl/telemetry/HistogramBuckets.cpp +++ b/src/tests/libxrpl/telemetry/HistogramBuckets.cpp @@ -68,9 +68,9 @@ INSTANTIATE_TEST_SUITE_P( TEST(HistogramBucketsRange, rotationPhaseLadderSpansSecondsToAnHour) { - // Measured 2026-09-13 on aws-dev-xrpl-1: freshen.keys 5-6 s, freshen.fetch - // ~3 min, copy ~10 min, whole rotation 13-17 min. The floor must sit under - // the lock hold; the ceiling above a whole rotation with headroom. + // Phases run from seconds (freshen.keys) to ten minutes or more (copy), and + // a whole rotation about a quarter of an hour. The floor must sit under the + // shortest phase; the ceiling above a whole rotation with headroom. EXPECT_EQ(kRotationPhaseSecondsBuckets.front(), 1.0); EXPECT_LE(kRotationPhaseSecondsBuckets.front(), 5.0); EXPECT_EQ(kRotationPhaseSecondsBuckets.back(), 3600.0);