mirror of
https://github.com/XRPLF/rippled.git
synced 2026-10-22 11:37:07 +00:00
fix(telemetry): Count getobject lookups that reach the NodeStore
Misses were counted as requested - found, so entries the fetch loop skips as malformed, and anything past the cap, counted as misses. Count the entries that reach the NodeStore and record misses as attempted - found. The charge still uses the requested count. Each metric that was declared at several call sites is now declared once: getobject_lookups_total in one loop over hit and miss, and getobject_rejected_total and rpc_in_flight_requests through a small helper. Two Beast tests pin the counts.
This commit is contained in:
7 files changed
+303
-84
No files matched your search
@@ -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,
|
||||
|
||||
@@ -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<std::pair<std::string_view, int>, 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";
|
||||
|
||||
|
||||
@@ -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.
|
||||
|
||||
@@ -33,6 +33,7 @@
|
||||
|
||||
#include <xrpl.pb.h>
|
||||
|
||||
#include <chrono>
|
||||
#include <cstddef>
|
||||
#include <memory>
|
||||
#include <optional>
|
||||
@@ -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<GetObjectCounts> 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<GetObjectCounts> 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<protocol::TMGetObjectByHash>
|
||||
buildMixedRequest(Env& env, int const numStored, int const numUnstored, int const numMalformed)
|
||||
{
|
||||
std::set<uint256> 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<int>(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<int>(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();
|
||||
}
|
||||
|
||||
@@ -97,6 +97,7 @@
|
||||
#include <xrpl.pb.h>
|
||||
|
||||
#include <algorithm>
|
||||
#include <array>
|
||||
#include <atomic>
|
||||
#include <chrono>
|
||||
#include <cstddef>
|
||||
@@ -2822,12 +2823,7 @@ PeerImp::onMessage(std::shared_ptr<protocol::TMGetObjectByHash> 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<protocol::TMGetObjectByHash> 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<protocol::TMGetObjectByHash> 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<protocol::TMGetObjectByHash> 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<Message>(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::uint64_t>(std::max(0, found)),
|
||||
{{kLabelResult, std::string(kResultHit)}});
|
||||
|
||||
XRPL_METRIC_COUNTER_ADD_LABELED(
|
||||
app_,
|
||||
kGetObjectLookupsTotal,
|
||||
kGetObjectLookupsTotalDesc,
|
||||
static_cast<std::uint64_t>(std::max(0, requested - found)),
|
||||
{{kLabelResult, std::string(kResultMiss)}});
|
||||
// One call site for both label values, so the counter is created once.
|
||||
std::array<std::pair<std::string_view, int>, 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::uint64_t>(std::max(0, amount)),
|
||||
{{kLabelResult, std::string(result)}});
|
||||
}
|
||||
}
|
||||
|
||||
// NOLINTEND(readability-convert-member-functions-to-static)
|
||||
|
||||
@@ -54,6 +54,7 @@
|
||||
#include <queue>
|
||||
#include <shared_mutex>
|
||||
#include <string>
|
||||
#include <string_view>
|
||||
#include <type_traits>
|
||||
#include <utility>
|
||||
#include <vector>
|
||||
@@ -696,38 +697,83 @@ private:
|
||||
std::shared_ptr<SHAMap const>
|
||||
getTxSet(std::shared_ptr<protocol::TMGetLedger> 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<protocol::TMGetLedger> const& m,
|
||||
std::vector<SHAMapNodeID> 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);
|
||||
|
||||
|
||||
@@ -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
|
||||
|
||||
Reference in new issue
Block a user