diff --git a/docker/telemetry/grafana/dashboards/overlay-traffic-detail.json b/docker/telemetry/grafana/dashboards/overlay-traffic-detail.json index 2d23930642..e57e5905c4 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 rest of the request -- 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 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)", "type": "timeseries", "gridPos": { "h": 10, diff --git a/include/xrpl/telemetry/GetObjectMetricNames.h b/include/xrpl/telemetry/GetObjectMetricNames.h index e2951a43d0..a486487ba5 100644 --- a/include/xrpl/telemetry/GetObjectMetricNames.h +++ b/include/xrpl/telemetry/GetObjectMetricNames.h @@ -46,15 +46,17 @@ * @endcode * * Example usage -- edge case: the same instrument recorded under two - * different label values, which is why the label key and both values are - * constants rather than literals: + * different label values from one call site, so it is created once. The + * label key and both values are constants rather than literals: * @code - * 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)}}); + * 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)}}); + * } * @endcode * * @note These are `constexpr char[]`, not `constexpr std::string_view`. The @@ -95,7 +97,8 @@ inline constexpr char kGetObjectRequestObjects[] = "getobject_request_objects"; inline constexpr char kGetObjectLookupUs[] = "getobject_lookup_us"; /** - * NodeStore lookups performed, split by the `result` label. + * NodeStore lookups attempted, split by the `result` label. An entry skipped + * before the lookup is not counted. */ inline constexpr char kGetObjectLookupsTotal[] = "getobject_lookups_total"; diff --git a/include/xrpl/telemetry/MetricMacros.h b/include/xrpl/telemetry/MetricMacros.h index 31ef5db4c6..970e68cc59 100644 --- a/include/xrpl/telemetry/MetricMacros.h +++ b/include/xrpl/telemetry/MetricMacros.h @@ -59,17 +59,21 @@ * in which a bare `const char*` selects the boolean alternative, so an * unwrapped literal is recorded as `true`. * - * Example usage -- UpDownCounter (edge case: value that can decrease): + * 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: * @code - * void ServerHandler::onRpcStart() + * void addRpcInFlight(ServiceRegistry& app, std::int64_t const delta) * { - * XRPL_METRIC_UPDOWN_ADD(app_, "rpc_in_flight_requests", - * "RPC requests currently executing", 1); + * XRPL_METRIC_UPDOWN_ADD(app, "rpc_in_flight_requests", + * "RPC requests currently executing", delta); * } - * void ServerHandler::onRpcFinish() + * void PerfLogImp::rpcStart(std::string_view method, std::uint64_t requestId) * { - * XRPL_METRIC_UPDOWN_ADD(app_, "rpc_in_flight_requests", - * "RPC requests currently executing", -1); + * addRpcInFlight(app_, 1); + * } + * void PerfLogImp::rpcEnd(std::string_view method, std::uint64_t requestId, bool finish) + * { + * addRpcInFlight(app_, -1); * } * @endcode * @@ -102,6 +106,10 @@ * once stop() has torn the pipeline down; without that gate 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 Static-init safety: Meter::CreateXxx is declared noexcept in the * OTel API (opentelemetry/metrics/meter.h), so the function-local static * that caches the instrument cannot throw during first-call construction. @@ -192,8 +200,8 @@ } while (false) // UpDownCounter: like COUNTER_ADD, but the underlying instrument permits a -// negative amount (e.g. in-flight request count, +1 on start / -1 on -// finish from two different points in the same or different call sites). +// 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). // 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 759c78fefc..40e28f2dd6 100644 --- a/src/test/overlay/TMGetObjectByHash_test.cpp +++ b/src/test/overlay/TMGetObjectByHash_test.cpp @@ -33,6 +33,7 @@ #include +#include #include #include #include @@ -149,6 +150,31 @@ class TMGetObjectByHash_test : public beast::unit_test::Suite return lastChargeContext_; } + /** + * 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. + */ + void + recordGetObjectMetrics( + GetObjectCounts const& counts, + std::chrono::microseconds const lookupElapsed, + resource::Charge const& fee) override + { + lastCounts_ = counts; + PeerImp::recordGetObjectMetrics(counts, lookupElapsed, fee); + } + + /** + * The counts captured by the override above, or nullopt if the + * handler never reached the metric record. + */ + [[nodiscard]] std::optional const& + getLastCounts() const + { + return lastCounts_; + } + // Synchronous test access to the JobQueue-dispatched processor. // The production path runs this on JtLedgerReq; tests need a // synchronous entry point to inspect the reply via send(). @@ -212,6 +238,11 @@ class TMGetObjectByHash_test : public beast::unit_test::Suite * @see getLastChargeContext(). Same threading rules as above. */ std::string lastChargeContext_; + + /** + * @see getLastCounts(). Same threading rules as above. + */ + std::optional lastCounts_; }; shared_context context_{makeSslContext("")}; @@ -631,6 +662,36 @@ class TMGetObjectByHash_test : public beast::unit_test::Suite return request; } + /** + * Build a request of numStored stored hashes and numUnstored unstored + * hashes, then numMalformed entries the fetch loop must skip: every even + * one has no hash field, every odd one a hash one byte short. + * + * @param env Environment whose NodeStore receives the writes. + * @param numStored Hashes written to the NodeStore, i.e. hits. + * @param numUnstored Hashes left absent, i.e. misses. + * @param numMalformed Entries skipped before any NodeStore access. + * @return The assembled request. + */ + std::shared_ptr + buildMixedRequest(Env& env, int const numStored, int const numUnstored, int const numMalformed) + { + std::set storedHashes; + auto request = buildInterleavedRequest(env, numStored, numUnstored, storedHashes); + for (int i = 0; i < numMalformed; ++i) + { + auto* object = request->add_objects(); + if (i % 2 == 1) + { + object->set_hash(std::string(uint256::size() - 1, 'x')); + } + } + + // Setup assertion: the malformed entries were appended. + BEAST_EXPECT(request->objects_size() == numStored + numUnstored + numMalformed); + return request; + } + /** * Every replied object is a distinct hash drawn from @p storedHashes. * @@ -662,8 +723,9 @@ class TMGetObjectByHash_test : public beast::unit_test::Suite * A mixed request returns exactly the stored objects and nothing else. * * This is the split `getobject_lookups_total{result=hit|miss}` records: - * the handler derives the miss count as `requested - found`, so an - * exact reply size is exactly the hit count the metric would report. + * the handler derives the miss count as `attempted - found`, and with no + * malformed entries `attempted == requested`, so an exact reply size is + * exactly the hit count the metric would report. * * @param numStored Hashes written to the NodeStore before the call. * @param numUnstored Hashes that will miss. @@ -719,6 +781,81 @@ class TMGetObjectByHash_test : public beast::unit_test::Suite BEAST_EXPECT(peer->peekFeeCharge().cost() == resource::kFeeTrivialPeer.cost()); } + /** + * Malformed entries are skipped before any NodeStore access, so they are + * neither hits nor misses. attempted counts only the entries that reached + * fetchNodeObject(); requested still counts the whole message. + * + * @param numStored Hashes written to the NodeStore before the call. + * @param numUnstored Hashes that will miss. + * @param numMalformed Entries with no hash or a short hash. + */ + void + testMalformedEntriesAreNotLookups( + int const numStored, + int const numUnstored, + int const numMalformed) + { + testcase( + "Malformed Entries Are Not Lookups: " + std::to_string(numStored) + "/" + + std::to_string(numUnstored) + "/" + std::to_string(numMalformed)); + + Env env(*this); + PeerTest::resetId(); + auto peer = createPeer(env); + + auto request = buildMixedRequest(env, numStored, numUnstored, numMalformed); + + // Setup assertion: nothing has been recorded yet, so the counts below + // can only come from this call. + BEAST_EXPECT(!peer->getLastCounts().has_value()); + + peer->runProcessGetObjectByHash(request); + + auto const& counts = peer->getLastCounts(); + BEAST_EXPECT(counts.has_value()); + if (!counts) + { + return; + } + BEAST_EXPECT(counts->requested == numStored + numUnstored + numMalformed); + 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); + } + + /** + * Past the iteration cap nothing is looked up, so attempted is the cap, + * not the request size. Reachable only by direct call: onMessage() + * rejects an oversized request before dispatch. + */ + void + testAttemptedIsCappedAtHardMax() + { + testcase("Attempted Is Capped At Hard Max"); + + Env env(*this); + PeerTest::resetId(); + auto peer = createPeer(env); + + BEAST_EXPECT(!peer->getLastCounts().has_value()); + + int const requested = static_cast(tuning::kHardMaxReplyNodes) + 3; + peer->runProcessGetObjectByHash(createUnstoredRequest(requested)); + + auto const& counts = peer->getLastCounts(); + BEAST_EXPECT(counts.has_value()); + if (!counts) + { + return; + } + BEAST_EXPECT(counts->requested == requested); + BEAST_EXPECT(counts->attempted == static_cast(tuning::kHardMaxReplyNodes)); + BEAST_EXPECT(counts->found == 0); + } + /** * One pricing case: inputs, the derived expectation, and the literal. * @@ -1006,8 +1143,8 @@ class TMGetObjectByHash_test : public beast::unit_test::Suite // observable behaviour of each instrumented code path, which pins // the values the instruments are fed: // getobject_request_objects <- the request's objects_size() - // getobject_lookups_total <- reply size (hits) and the derived - // miss count, per testHitMissSplit + // getobject_lookups_total <- the counts captured by + // PeerTest::recordGetObjectMetrics() // getobject_charge <- the applied resource::Charge, // captured by PeerTest::charge() // getobject_rejected_total <- the two gates' exact fee_ values @@ -1032,6 +1169,11 @@ class TMGetObjectByHash_test : public beast::unit_test::Suite testHitMissSplit(0, 4); testHitMissSplit(4, 0); + testMalformedEntriesAreNotLookups(3, 2, 4); + testMalformedEntriesAreNotLookups(0, 0, 6); + testMalformedEntriesAreNotLookups(5, 0, 0); + testAttemptedIsCappedAtHardMax(); + testComputeFeeExactValues(); testChargeUsesRequestedCount(); } diff --git a/src/xrpld/overlay/detail/PeerImp.cpp b/src/xrpld/overlay/detail/PeerImp.cpp index a2a8532bae..cf3347c77a 100644 --- a/src/xrpld/overlay/detail/PeerImp.cpp +++ b/src/xrpld/overlay/detail/PeerImp.cpp @@ -97,6 +97,7 @@ #include #include +#include #include #include #include @@ -2822,12 +2823,7 @@ PeerImp::onMessage(std::shared_ptr const& m) { JLOG(pJournal_.debug()) << "GetObj: malformed ledgerhash from peer " << id_; fee_.update(resource::kFeeMalformedRequest, "get object ledger hash"); - XRPL_METRIC_COUNTER_INC_LABELED( - app_, - telemetry::kGetObjectRejectedTotal, - telemetry::kGetObjectRejectedTotalDesc, - {{telemetry::kLabelReason, - std::string(telemetry::kReasonMalformedLedgerHash)}}); + recordGetObjectRejected(telemetry::kReasonMalformedLedgerHash); return; } } @@ -2840,11 +2836,7 @@ 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"); - XRPL_METRIC_COUNTER_INC_LABELED( - app_, - telemetry::kGetObjectRejectedTotal, - telemetry::kGetObjectRejectedTotalDesc, - {{telemetry::kLabelReason, std::string(telemetry::kReasonOversize)}}); + recordGetObjectRejected(telemetry::kReasonOversize); return; } @@ -2971,12 +2963,16 @@ PeerImp::processGetObjectByHash(std::shared_ptr con // Stopwatch holds no state in that build. telemetry::Stopwatch const lookupTimer; + // Entries that reach the NodeStore. A malformed entry is skipped first, + // so it is not a lookup. + int attempted = 0; for (int i = 0; i < iterLimit; ++i) { auto const& obj = packet.objects(i); if (!obj.has_hash() || !stringIsUInt256Sized(obj.hash())) continue; + ++attempted; uint256 const hash = uint256::fromRaw(obj.hash()); // VFALCO TODO Move this someplace more sensible so we don't // need to inject the NodeStore interfaces. @@ -3012,31 +3008,43 @@ PeerImp::processGetObjectByHash(std::shared_ptr con resource::Charge const fee = computeGetObjectByHashFee(requested, reply.objects_size()); charge(fee, "processed get object by hash request"); - // Called unconditionally: every statement in the body is an XRPL_METRIC_* - // argument, and those macros discard their arguments when telemetry is - // compiled out. All four values here are already computed for the request - // itself, so passing them costs nothing. - recordGetObjectMetrics(requested, reply.objects_size(), lookupElapsed, fee); + // 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. + recordGetObjectMetrics( + GetObjectCounts{ + .requested = requested, .attempted = attempted, .found = reply.objects_size()}, + lookupElapsed, + fee); JLOG(pJournal_.trace()) << "GetObj: " << reply.objects_size() << " of " << requested; send(std::make_shared(reply, protocol::mtGET_OBJECTS)); } -// Reads app_ through the metric macros when telemetry is compiled in and -// touches no member when it is not, so clang-tidy asks for it to be static. -// Making it static would give the two builds different signatures. +// 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( - int const requested, - int const found, + GetObjectCounts const& counts, std::chrono::microseconds const lookupElapsed, resource::Charge const& fee) { using namespace telemetry; XRPL_METRIC_HISTOGRAM_RECORD( - app_, kGetObjectRequestObjects, kGetObjectRequestObjectsDesc, requested); + app_, kGetObjectRequestObjects, kGetObjectRequestObjectsDesc, counts.requested); XRPL_METRIC_HISTOGRAM_RECORD( app_, kGetObjectLookupUs, kGetObjectLookupUsDesc, lookupElapsed.count()); @@ -3047,29 +3055,23 @@ PeerImp::recordGetObjectMetrics( // per-object increments on a loop bounded by kHardMaxReplyNodes would be // a measurable cost for no extra information. // - // `found` is the reply size, which the fetch loop only grows on a - // successful lookup within `iterLimit <= requested`, so `found <= - // requested` always holds. std::max still clamps both values, so a future - // caller passing found > requested cannot make the miss count wrap - // negative -- the counter takes an unsigned amount, where a wrap would - // read as ~1.8e19 rather than as an error. + // 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. // - // Written as two calls rather than a loop over a {hit, miss} pair: the two - // amounts come from different expressions, so there is no single value to - // iterate over. - XRPL_METRIC_COUNTER_ADD_LABELED( - app_, - kGetObjectLookupsTotal, - kGetObjectLookupsTotalDesc, - static_cast(std::max(0, found)), - {{kLabelResult, std::string(kResultHit)}}); - - XRPL_METRIC_COUNTER_ADD_LABELED( - app_, - kGetObjectLookupsTotal, - kGetObjectLookupsTotalDesc, - static_cast(std::max(0, requested - found)), - {{kLabelResult, std::string(kResultMiss)}}); + // 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)}}); + } } // NOLINTEND(readability-convert-member-functions-to-static) diff --git a/src/xrpld/overlay/detail/PeerImp.h b/src/xrpld/overlay/detail/PeerImp.h index faa9e7d544..f73a161e16 100644 --- a/src/xrpld/overlay/detail/PeerImp.h +++ b/src/xrpld/overlay/detail/PeerImp.h @@ -54,6 +54,7 @@ #include #include #include +#include #include #include #include @@ -696,38 +697,83 @@ 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( std::shared_ptr const& m, std::vector nodeIDs); + /** + * The three object counts of one `TMGetObjectByHash` request. + * + * processGetObjectByHash() --> GetObjectCounts --> recordGetObjectMetrics() + * + * `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. + * + * @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. + * @endcode + * + * @note A plain value built per request, so there is nothing to lock. + */ + struct GetObjectCounts + { + /** + * Entries in the request, `objects_size()`. + */ + int requested = 0; + /** + * Entries that reached the NodeStore lookup. + */ + int attempted = 0; + /** + * Objects returned in the reply. + */ + int found = 0; + }; + /** * 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 `requested` and `found`. + * hit/miss split from the counts. 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`. Every statement is an `XRPL_METRIC_*` record, - * and those 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 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. * - * @param requested Objects the peer asked for (`objects_size()`). - * @param found Objects returned, i.e. the reply's object count. - * Expected to be `<= requested`; clamped either way - * so the derived miss count cannot go negative. + * @param counts The request's counts. Hits are `found`; misses are + * `attempted - found`. * @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. */ - void + virtual void recordGetObjectMetrics( - int const requested, - int const found, + GetObjectCounts const& counts, std::chrono::microseconds const lookupElapsed, resource::Charge const& fee); diff --git a/src/xrpld/perflog/detail/PerfLogImp.cpp b/src/xrpld/perflog/detail/PerfLogImp.cpp index 189fbdac79..3f45d4307e 100644 --- a/src/xrpld/perflog/detail/PerfLogImp.cpp +++ b/src/xrpld/perflog/detail/PerfLogImp.cpp @@ -342,6 +342,25 @@ PerfLogImp::~PerfLogImp() stop(); } +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. + * + * @param app The application, which holds the metrics registry. + * @param delta +1 when a request starts, -1 when it ends. + */ +void +addRpcInFlight(Application& app, std::int64_t const delta) +{ + XRPL_METRIC_UPDOWN_ADD( + app, "rpc_in_flight_requests", "RPC requests currently executing", delta); +} + +} // namespace + void PerfLogImp::rpcStart(std::string_view method, std::uint64_t const requestId) { @@ -373,11 +392,10 @@ PerfLogImp::rpcStart(std::string_view method, std::uint64_t const requestId) mr->recordRpcStarted(method); #endif - // A value that must be able to decrease (UpDownCounter), added at its - // call site with no MetricsRegistry member/init-line/method. Paired with - // the matching -1 in rpcEnd(). Runs on the same path as recordRpcStarted - // above, i.e. only after a methods-map entry exists for this request. - XRPL_METRIC_UPDOWN_ADD(app_, "rpc_in_flight_requests", "RPC requests currently executing", 1); + // Paired with the matching -1 in rpcEnd(). Runs on the same path as + // recordRpcStarted above, i.e. only after a methods-map entry exists for + // this request. + addRpcInFlight(app_, 1); } void @@ -446,7 +464,7 @@ PerfLogImp::rpcEnd(std::string_view method, std::uint64_t const requestId, bool // Matching -1 for the +1 recorded in rpcStart(). Placed after the early // returns above so it runs only when this request's methods-map entry was // found (i.e. a +1 was recorded for it), keeping the in-flight count balanced. - XRPL_METRIC_UPDOWN_ADD(app_, "rpc_in_flight_requests", "RPC requests currently executing", -1); + addRpcInFlight(app_, -1); } void