mirror of
https://github.com/XRPLF/rippled.git
synced 2026-09-27 07:26:51 +00:00
Merge branch 'pratik/otel-sync-diagnostics' into pratik/otel-sync-diagnostics-freshen-fix
# Conflicts: # OpenTelemetryPlan/09-data-collection-reference.md # docker/telemetry/workload/expected_spans.json # include/xrpl/telemetry/HistogramBuckets.h # src/tests/libxrpl/telemetry/HistogramBuckets.cpp
This commit is contained in:
Pratik Mankawde
@@ -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 + 7 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 seven children — `clear_prior`, `copy`, `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. A `freshen.keys` child once covered the single `cache.getKeys()` call whose multi-second mutex hold froze every job and flapped the node; the freshen now copies keys one partition at a time (`TaggedCache::forEachKeyPartition`), so that child is gone and the per-partition hold is read from `cache_metrics{metric="treenode_lock_hold_peak_us"}` instead. |
|
||||
| `nodestore.rotate` span + 7 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 seven children — `clear_prior`, `copy`, `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. A `freshen.keys` child once covered the single `cache.getKeys()` call whose multi-second mutex hold froze every job and flapped the node; the freshen now copies keys one partition at a time (`TaggedCache::forEachKeyPartition`), so that child is gone and the per-partition hold is read from `cache_metrics{metric="treenode_lock_hold_peak_us"}` instead. |
|
||||
| `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. |
|
||||
| `rotation_freshen_keys_total` (`cache` = `treenode` \| `master_tx`, `outcome` = `fetched` \| `copied`) | counter | `SHAMapStoreImp.cpp` — `SHAMapStoreImp::recordFreshen` | Rotation Freshen Yield (keys per rotation) | The freshen's yield. `fetched` is every cached key the rotation re-read from the node store; `copied` is the subset that was only in the archive and was written to the writable backend (`DatabaseRotating::duplicateCopyForwardTotal` before/after the loop). Two Adds per cache per rotation, none per key. Exists because `copy_forward` and `node_writes` both miss these writes: the rotating store counts copy-forwards only on `duplicate == false` reads and stores them straight to the backend, so until this counter the freshen's usefulness was unmeasured. The same delta is stamped on the `freshen.fetch` span as `keys_copied` and on the `copy` span as `nodes_copied`. |
|
||||
| `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. |
|
||||
@@ -2424,8 +2424,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 seven
|
||||
|
||||
@@ -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
|
||||
|
||||
@@ -3390,9 +3390,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
|
||||
|
||||
@@ -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});
|
||||
|
||||
Reference in New Issue
Block a user