From 0a9c195880075c6066d9abde06777730bc2ae4ff Mon Sep 17 00:00:00 2001 From: Pratik Mankawde <3397372+pratikmankawde@users.noreply.github.com> Date: Thu, 1 Oct 2026 09:09:36 +0100 Subject: [PATCH] fix(telemetry): Drop the getobject one-call-site refactor 7934506ca1 sent getobject_rejected_total through a helper and getobject_lookups_total through a loop, so each had one call site. Both name the getobject constants outside the XRPL_METRIC_* macros, but PeerImp.cpp includes GetObjectMetricNames.h only when telemetry is compiled in, so a telemetry-off build fails. Two macro calls with the same name, kind and description already export one stream. So the call sites go back to plain macro calls on the shared constants, and the include stays guarded. GetObjectCounts gains hits() and misses(), which the code and its tests share, and the docs state the rule as one kind and one description per metric name. The GetObject Lookups panel description is rewritten to match, as are the comments on the counts and on the two counter calls. --- .../dashboards/overlay-traffic-detail.json | 2 +- include/xrpl/telemetry/GetObjectMetricNames.h | 21 +++--- include/xrpl/telemetry/MetricMacros.h | 20 +++-- src/test/overlay/TMGetObjectByHash_test.cpp | 28 +++---- src/xrpld/overlay/detail/PeerImp.cpp | 71 ++++++++---------- src/xrpld/overlay/detail/PeerImp.h | 73 ++++++++++++------- src/xrpld/perflog/detail/PerfLogImp.cpp | 6 +- 7 files changed, 117 insertions(+), 104 deletions(-) diff --git a/docker/telemetry/grafana/dashboards/overlay-traffic-detail.json b/docker/telemetry/grafana/dashboards/overlay-traffic-detail.json index e57e5905c4..f1820589b7 100644 --- a/docker/telemetry/grafana/dashboards/overlay-traffic-detail.json +++ b/docker/telemetry/grafana/dashboards/overlay-traffic-detail.json @@ -809,7 +809,7 @@ }, { "title": "GetObject Lookups by Result", - "description": "###### What this is:\n*NodeStore lookups performed by the handler, split into hits and misses. A miss does a node-store seek while a hit is usually served from cache, so the hit/miss mix is the reason NodeStore Lookup time moves.*\n\n###### How it's computed:\n*Per-second rate of getobject_lookups_total, grouped by the result label. The counter is advanced once per request with the batch totals -- hits are the objects returned, misses are the lookups that found nothing, and an entry skipped as malformed counts as neither -- not once per object, so the rate is objects per second rather than requests per second.*\n\n###### Reading it:\n*Use this to explain the NodeStore Lookup line on the breakdown panel. A miss-heavy mix makes that line rise for a real reason: seeks, not a regression. A hit-heavy mix with rising lookup time points at the storage layer instead.*\n\n###### Healthy range:\n*Hits dominating on a warm synced node; misses low and driven by genuine catch-up requests.*\n\n###### Watch for:\n*A sustained miss rate far above the hit rate: a peer is asking for hashes this node does not hold, which is either a peer far out of sync or a client requesting objects this node never stored. Cross-check GetObject Charge Distribution, since misses are billed first and at eight times the hit cost.*\n\n###### Keywords:\n- **NodeStore lookup (hit / miss)** *(per node)* \u2014 one object-store fetch by hash; a hit is usually served from cache, a miss does a disk seek.\n- **NodeStore** *(per node)* \u2014 the key-value object store holding ledger data (tree nodes), backed by NuDB.\n- **Resource charge** *(per node)* \u2014 the load cost the resource manager bills a peer per request; crossing the warning then drop threshold sheds the peer.\n\n###### Computation boundary:\n*Result: Per node \u2014 each series is one server's own value.*\n*Computed in xrpld code (MetricsRegistry, OpenTelemetry SDK) and exported as a metric; the collector only forwards it; the Grafana query selects and aggregates it.*\n\n###### Source:\n[PeerImp.cpp](https://github.com/XRPLF/rippled/blob/develop/src/xrpld/overlay/detail/PeerImp.cpp)\n\n###### Function:\n`PeerImp::recordGetObjectMetrics`\n\n###### References:\n[Telemetry glossary](https://github.com/XRPLF/rippled/blob/develop/docs/telemetry-glossary.md#nodestore-lookup-hit-miss)", + "description": "###### What this is:\n*NodeStore lookups performed by the handler, split into hits and misses. A miss does a node-store seek while a hit is usually served from cache, so the hit/miss mix is the main reason NodeStore Lookup time moves.*\n\n###### How it's computed:\n*Per-second rate of getobject_lookups_total, grouped by the result label. The handler adds each request's totals once, not once per object, so the rate counts objects per second, not requests. Hits are the objects returned. Misses are lookups that found nothing. An entry skipped as malformed counts as neither.*\n\n###### Reading it:\n*Use this to explain the NodeStore Lookup line on the breakdown panel. A miss-heavy mix makes that line rise for a real reason: seeks, not a regression. A hit-heavy mix with rising lookup time points at the storage layer instead.*\n\n###### Healthy range:\n*Hits dominating on a warm synced node; misses low and driven by genuine catch-up requests.*\n\n###### Watch for:\n*A sustained miss rate far above the hit rate: a peer is asking for hashes this node does not hold, either because it is far out of sync or because it asks for history this node never stored or has deleted. Cross-check GetObject Charge Distribution. The charge treats every requested entry that returned nothing as a miss, malformed ones included. After the first 16 free entries, it bills misses before hits, at eight times a hit's cost.*\n\n###### Keywords:\n- **NodeStore lookup (hit / miss)** *(per node)* \u2014 one object-store fetch by hash; a hit is usually served from cache, a miss does a disk seek.\n- **NodeStore** *(per node)* \u2014 the key-value object store holding ledger data (tree nodes), backed by NuDB.\n- **Resource charge** *(per node)* \u2014 the load cost the resource manager bills a peer per request; crossing the warning then drop threshold sheds the peer.\n\n###### Computation boundary:\n*Result: Per node \u2014 each series is one server's own value.*\n*Computed in xrpld code (MetricsRegistry, OpenTelemetry SDK) and exported as a metric; the collector only forwards it; the Grafana query selects and aggregates it.*\n\n###### Source:\n[PeerImp.cpp](https://github.com/XRPLF/rippled/blob/develop/src/xrpld/overlay/detail/PeerImp.cpp)\n\n###### Function:\n`PeerImp::recordGetObjectMetrics`\n\n###### References:\n[Telemetry glossary](https://github.com/XRPLF/rippled/blob/develop/docs/telemetry-glossary.md#nodestore-lookup-hit-miss)", "type": "timeseries", "gridPos": { "h": 10, diff --git a/include/xrpl/telemetry/GetObjectMetricNames.h b/include/xrpl/telemetry/GetObjectMetricNames.h index a486487ba5..02cfa9772d 100644 --- a/include/xrpl/telemetry/GetObjectMetricNames.h +++ b/include/xrpl/telemetry/GetObjectMetricNames.h @@ -45,18 +45,17 @@ * app_, kGetObjectRequestObjects, kGetObjectRequestObjectsDesc, requested); * @endcode * - * Example usage -- edge case: the same instrument recorded under two - * different label values from one call site, so it is created once. The - * label key and both values are constants rather than literals: + * Example usage -- edge case: two calls record one metric under two label + * values. Each call creates its own instrument, but both pass the same name + * and description constants, so the SDK exports one stream. The label key and + * values are constants too, so the two calls cannot drift apart: * @code - * std::array, 2> const split{ - * {{kResultHit, hits}, {kResultMiss, misses}}}; - * for (auto const& [result, amount] : split) - * { - * XRPL_METRIC_COUNTER_ADD_LABELED( - * app_, kGetObjectLookupsTotal, kGetObjectLookupsTotalDesc, amount, - * {{kLabelResult, std::string(result)}}); - * } + * XRPL_METRIC_COUNTER_ADD_LABELED( + * app_, kGetObjectLookupsTotal, kGetObjectLookupsTotalDesc, hits, + * {{kLabelResult, std::string(kResultHit)}}); + * XRPL_METRIC_COUNTER_ADD_LABELED( + * app_, kGetObjectLookupsTotal, kGetObjectLookupsTotalDesc, misses, + * {{kLabelResult, std::string(kResultMiss)}}); * @endcode * * @note These are `constexpr char[]`, not `constexpr std::string_view`. The diff --git a/include/xrpl/telemetry/MetricMacros.h b/include/xrpl/telemetry/MetricMacros.h index 970e68cc59..509ffed972 100644 --- a/include/xrpl/telemetry/MetricMacros.h +++ b/include/xrpl/telemetry/MetricMacros.h @@ -60,7 +60,8 @@ * unwrapped literal is recorded as `true`. * * Example usage -- UpDownCounter (edge case: value that can decrease). The - * +1 and the -1 go through one helper, so the name has one call site: + * +1 and the -1 go through one helper, so the name and description are + * written once and cannot drift apart: * @code * void addRpcInFlight(ServiceRegistry& app, std::int64_t const delta) * { @@ -102,13 +103,15 @@ * empty while the registry is enabled (a no-op meter stands in if the * pipeline failed to build, and again after stop()). So a call site holds * a valid instrument from its first call and needs no check of its own. - * The only branch on the hot path is the recording() gate, which is false - * once stop() has torn the pipeline down; without that gate a Record on a - * stale SDK instrument would deref a dangling AggregationConfig. + * On the hot path a call checks the registry pointer, its recording() + * gate and the init guard of the instrument's static. The gate is false + * once stop() has torn the pipeline down; without it a Record on a stale + * SDK instrument would deref a dangling AggregationConfig. * - * @note Give each metric name one call site. Every expansion creates its own - * instrument, and two whose descriptions differ become two streams under one - * name. Route every value through one helper or loop. + * @note Give each metric name one kind and one description. Every expansion + * creates its own instrument. The SDK exports instruments with the same name, + * kind, unit and description as one stream. Any difference starts a second + * stream under that name. * * @note Static-init safety: Meter::CreateXxx is declared noexcept in the * OTel API (opentelemetry/metrics/meter.h), so the function-local static @@ -201,7 +204,8 @@ // UpDownCounter: like COUNTER_ADD, but the underlying instrument permits a // negative amount (e.g. in-flight request count: +1 on start and -1 on -// finish, both through one helper so the name has one call site). +// finish, both through one helper, so the name and description are written +// once). // A plain Counter's Add() must never see a negative value per the OTel // API contract; use this macro, not COUNTER_ADD, whenever the value can // decrease. diff --git a/src/test/overlay/TMGetObjectByHash_test.cpp b/src/test/overlay/TMGetObjectByHash_test.cpp index 40e28f2dd6..88fe07a41e 100644 --- a/src/test/overlay/TMGetObjectByHash_test.cpp +++ b/src/test/overlay/TMGetObjectByHash_test.cpp @@ -153,7 +153,7 @@ class TMGetObjectByHash_test : public beast::unit_test::Suite /** * Capture the counts the handler hands to the metric record, then * record for real. Same seam as charge(): the override sees the exact - * struct the handler built, so the split it chose is observable. + * struct the handler built. */ void recordGetObjectMetrics( @@ -822,8 +822,10 @@ class TMGetObjectByHash_test : public beast::unit_test::Suite BEAST_EXPECT(counts->attempted == numStored + numUnstored); BEAST_EXPECT(counts->found == numStored); - // The miss count the metric records: only the unstored hashes. - BEAST_EXPECT(counts->attempted - counts->found == numUnstored); + // The split the metric records: the stored hashes are hits, and only + // the unstored ones are misses. + BEAST_EXPECT(counts->hits() == numStored); + BEAST_EXPECT(counts->misses() == numUnstored); } /** @@ -854,6 +856,7 @@ class TMGetObjectByHash_test : public beast::unit_test::Suite BEAST_EXPECT(counts->requested == requested); BEAST_EXPECT(counts->attempted == static_cast(tuning::kHardMaxReplyNodes)); BEAST_EXPECT(counts->found == 0); + BEAST_EXPECT(counts->misses() == static_cast(tuning::kHardMaxReplyNodes)); } /** @@ -1134,14 +1137,12 @@ class TMGetObjectByHash_test : public beast::unit_test::Suite void run() override { - // NOTE ON METRIC COVERAGE. The five getobject_* instruments are - // recorded through the XRPL_METRIC_* macros, which push into the - // OpenTelemetry SDK. That API is write-only by design -- there is no - // read-back accessor and no in-memory metric reader in this build -- - // and a default jtx::Env leaves telemetry disabled, so the macros do - // not execute at all here. These tests therefore assert the - // observable behaviour of each instrumented code path, which pins - // the values the instruments are fed: + // NOTE ON METRIC COVERAGE. The five getobject_* metrics are + // recorded through the XRPL_METRIC_* macros, and a default jtx::Env + // leaves telemetry disabled, so the macros record nothing here. + // These tests therefore assert the observable behaviour of each + // instrumented code path, which pins the counts the record step + // receives: // getobject_request_objects <- the request's objects_size() // getobject_lookups_total <- the counts captured by // PeerTest::recordGetObjectMetrics() @@ -1150,9 +1151,8 @@ class TMGetObjectByHash_test : public beast::unit_test::Suite // getobject_rejected_total <- the two gates' exact fee_ values // plus "no charge was applied" // Only getobject_lookup_us has no in-process witness, being a wall - // clock reading. The counter and histogram values themselves remain - // unverified by unit test and are checked live against Prometheus - // per the design's live-validation step. + // clock reading. This suite does not read back the values PeerImp + // records. int const limit = static_cast(tuning::kHardMaxReplyNodes); testReplyLimit(limit + 1, limit); testReplyLimit(limit, limit); diff --git a/src/xrpld/overlay/detail/PeerImp.cpp b/src/xrpld/overlay/detail/PeerImp.cpp index cf3347c77a..040ae6371f 100644 --- a/src/xrpld/overlay/detail/PeerImp.cpp +++ b/src/xrpld/overlay/detail/PeerImp.cpp @@ -97,7 +97,6 @@ #include #include -#include #include #include #include @@ -2823,7 +2822,12 @@ PeerImp::onMessage(std::shared_ptr const& m) { JLOG(pJournal_.debug()) << "GetObj: malformed ledgerhash from peer " << id_; fee_.update(resource::kFeeMalformedRequest, "get object ledger hash"); - recordGetObjectRejected(telemetry::kReasonMalformedLedgerHash); + XRPL_METRIC_COUNTER_INC_LABELED( + app_, + telemetry::kGetObjectRejectedTotal, + telemetry::kGetObjectRejectedTotalDesc, + {{telemetry::kLabelReason, + std::string(telemetry::kReasonMalformedLedgerHash)}}); return; } } @@ -2836,7 +2840,11 @@ PeerImp::onMessage(std::shared_ptr const& m) << "GetObj: oversized request from peer " << id_ << " (" << packet.objects_size() << " > " << tuning::kHardMaxReplyNodes << ")"; fee_.update(resource::kFeeInvalidData, "oversized get object request"); - recordGetObjectRejected(telemetry::kReasonOversize); + XRPL_METRIC_COUNTER_INC_LABELED( + app_, + telemetry::kGetObjectRejectedTotal, + telemetry::kGetObjectRejectedTotalDesc, + {{telemetry::kLabelReason, std::string(telemetry::kReasonOversize)}}); return; } @@ -3009,8 +3017,7 @@ PeerImp::processGetObjectByHash(std::shared_ptr con charge(fee, "processed get object by hash request"); // Called unconditionally: the body only feeds XRPL_METRIC_* macros, which - // discard their arguments when telemetry is compiled out, and every value - // here is already computed for the request itself. + // drop their arguments when telemetry is compiled out. recordGetObjectMetrics( GetObjectCounts{ .requested = requested, .attempted = attempted, .found = reply.objects_size()}, @@ -3021,20 +3028,6 @@ PeerImp::processGetObjectByHash(std::shared_ptr con send(std::make_shared(reply, protocol::mtGET_OBJECTS)); } -// These read app_ through the metric macros when telemetry is compiled in and -// touch no member when it is not, so clang-tidy asks for them to be static. -// Making them static would give the two builds different signatures. -// NOLINTBEGIN(readability-convert-member-functions-to-static) -void -PeerImp::recordGetObjectRejected(std::string_view reason) -{ - XRPL_METRIC_COUNTER_INC_LABELED( - app_, - telemetry::kGetObjectRejectedTotal, - telemetry::kGetObjectRejectedTotalDesc, - {{telemetry::kLabelReason, std::string(reason)}}); -} - void PeerImp::recordGetObjectMetrics( GetObjectCounts const& counts, @@ -3053,28 +3046,28 @@ PeerImp::recordGetObjectMetrics( // Batch totals, added once per request rather than once per object: // per-object increments on a loop bounded by kHardMaxReplyNodes would be - // a measurable cost for no extra information. + // a measurable cost for no extra information. Only entries that reached + // the NodeStore count; see GetObjectCounts::hits() and misses(). // - // Only entries that reached the NodeStore are lookups: misses are the - // attempts that found nothing, so a malformed entry the loop skipped counts - // as neither. std::max keeps a caller that breaks `found <= attempted` from - // wrapping the unsigned amount to ~1.8e19. - // - // One call site for both label values, so the counter is created once. - std::array, 2> const split{ - {{kResultHit, counts.found}, {kResultMiss, counts.attempted - counts.found}}}; - for (auto const& [result, amount] : split) - { - XRPL_METRIC_COUNTER_ADD_LABELED( - app_, - kGetObjectLookupsTotal, - kGetObjectLookupsTotalDesc, - static_cast(std::max(0, amount)), - {{kLabelResult, std::string(result)}}); - } -} + // Two calls, one per label value. Both pass the same name and + // description, so the SDK exports one stream. Keep them as plain calls: a + // loop would name kResultHit and kResultMiss outside the XRPL_METRIC_* + // arguments, and their header is included only when telemetry is + // compiled in. + XRPL_METRIC_COUNTER_ADD_LABELED( + app_, + kGetObjectLookupsTotal, + kGetObjectLookupsTotalDesc, + static_cast(counts.hits()), + {{kLabelResult, std::string(kResultHit)}}); -// NOLINTEND(readability-convert-member-functions-to-static) + XRPL_METRIC_COUNTER_ADD_LABELED( + app_, + kGetObjectLookupsTotal, + kGetObjectLookupsTotalDesc, + static_cast(counts.misses()), + {{kLabelResult, std::string(kResultMiss)}}); +} void PeerImp::onMessage(std::shared_ptr const& m) diff --git a/src/xrpld/overlay/detail/PeerImp.h b/src/xrpld/overlay/detail/PeerImp.h index f73a161e16..1aa20ca703 100644 --- a/src/xrpld/overlay/detail/PeerImp.h +++ b/src/xrpld/overlay/detail/PeerImp.h @@ -43,6 +43,7 @@ #include +#include #include #include #include @@ -54,7 +55,6 @@ #include #include #include -#include #include #include #include @@ -697,20 +697,6 @@ private: std::shared_ptr getTxSet(std::shared_ptr const& m) const; - /** - * Counts one TMGetObjectByHash request refused before any NodeStore - * access. The only call site of getobject_rejected_total, so both gates - * share one instrument. - * - * @param reason Which gate refused it: kReasonMalformedLedgerHash or - * kReasonOversize. - * - * @note No-op when telemetry is compiled out or disabled; the macro - * carries that guard. - */ - void - recordGetObjectRejected(std::string_view reason); - protected: void processLedgerRequest( @@ -720,16 +706,24 @@ protected: /** * The three object counts of one `TMGetObjectByHash` request. * + * @code * processGetObjectByHash() --> GetObjectCounts --> recordGetObjectMetrics() + * @endcode * - * `found <= attempted <= requested` always holds. An entry with no hash or - * a wrong-size hash is skipped before the lookup, nothing past - * `kHardMaxReplyNodes` is looked at, and the reply grows only on a hit. + * processGetObjectByHash() fills it so that `found <= attempted <= + * requested`. It skips an entry with no hash or a wrong-size hash before + * the lookup, looks at nothing past `kHardMaxReplyNodes`, and grows the + * reply only on a hit. * * @code * // 5 entries: 1 malformed, 3 of the other 4 stored. * GetObjectCounts const counts{.requested = 5, .attempted = 4, .found = 3}; - * // Hits 3, misses 1. The malformed entry is neither. + * // counts.hits() is 3 and counts.misses() is 1; the malformed entry is + * // neither. + * + * // Edge case: every entry malformed, so nothing is looked up. + * GetObjectCounts const none{.requested = 2, .attempted = 0, .found = 0}; + * // none.hits() and none.misses() are both 0. * @endcode * * @note A plain value built per request, so there is nothing to lock. @@ -748,25 +742,48 @@ protected: * Objects returned in the reply. */ int found = 0; + + /** + * Lookups that found their object. + * + * @return `found`, or 0 if it is negative. + */ + [[nodiscard]] int + hits() const + { + return std::max(0, found); + } + + /** + * Lookups that found nothing. A skipped malformed entry is not one. + * Clamped at zero: a caller that breaks `found <= attempted` gets 0 + * rather than a negative value, which the unsigned counter would read + * as about 1.8e19. + * + * @return `attempted - found`, or 0 if that is negative. + */ + [[nodiscard]] int + misses() const + { + return std::max(0, attempted - found); + } }; /** * Record the OTel metrics for one completed `TMGetObjectByHash` request. * * Called once per request from `processGetObjectByHash()`, after the fetch - * loop and the `charge()` call. A separate method so that one stays within - * the 80-line limit; it holds no logic of its own beyond deriving the - * hit/miss split from the counts. Virtual so a test subclass can capture - * the counts, as it does with `charge()`. + * loop and the `charge()` call. A separate method keeps that function + * shorter. Virtual so a test subclass can capture the counts, as it does + * with `charge()`. * * Records `getobject_request_objects`, `getobject_lookup_us`, * `getobject_charge`, and both label values of - * `getobject_lookups_total`, the last from one call site in a loop. The - * macros discard their arguments when telemetry is disabled, so the body - * costs nothing in that build and the call site needs no guard. + * `getobject_lookups_total`. The body only feeds `XRPL_METRIC_*` macros, + * which drop their arguments when telemetry is compiled out, so the call + * site needs no guard. * - * @param counts The request's counts. Hits are `found`; misses are - * `attempted - found`. + * @param counts The request's counts; see GetObjectCounts. * @param lookupElapsed Wall time of the whole fetch loop. * @param fee The dynamic charge that was applied, so the * recorded value is exactly the one charged. diff --git a/src/xrpld/perflog/detail/PerfLogImp.cpp b/src/xrpld/perflog/detail/PerfLogImp.cpp index 3f45d4307e..897fc39785 100644 --- a/src/xrpld/perflog/detail/PerfLogImp.cpp +++ b/src/xrpld/perflog/detail/PerfLogImp.cpp @@ -345,9 +345,9 @@ PerfLogImp::~PerfLogImp() namespace { /** - * Adds delta to the count of RPC requests currently executing. The only call - * site of rpc_in_flight_requests, so rpcStart() and rpcEnd() share one - * instrument. + * Adds delta to the count of RPC requests currently executing. rpcStart() + * and rpcEnd() both call it, so they use one name and description and + * share one instrument. * * @param app The application, which holds the metrics registry. * @param delta +1 when a request starts, -1 when it ends.