From 2d6f82c27fc0c39c60c2e4ece36988d03f56b979 Mon Sep 17 00:00:00 2001 From: Sergey Kuznetsov Date: Fri, 20 Feb 2026 18:01:15 +0000 Subject: [PATCH] feat: Metrics for requested ledger age (#2947) Adding metrics to be able to analyse requested ledger age distribution. --------- Co-authored-by: Claude Sonnet 4.5 --- .gitignore | 2 + src/rpc/Counters.cpp | 50 +++++++++++ src/rpc/Counters.hpp | 14 ++++ src/rpc/RPCEngine.hpp | 33 ++++++-- src/web/RPCServerHandler.hpp | 8 +- src/web/ng/RPCServerHandler.hpp | 8 +- tests/common/util/MockRPCEngine.hpp | 26 ++++++ tests/unit/rpc/CountersTests.cpp | 92 +++++++++++++++++++++ tests/unit/web/ng/RPCServerHandlerTests.cpp | 5 ++ 9 files changed, 224 insertions(+), 14 deletions(-) diff --git a/.gitignore b/.gitignore index 65c4dab24..3de8bc74e 100644 --- a/.gitignore +++ b/.gitignore @@ -10,3 +10,5 @@ .sanitizer-report CMakeUserPresets.json config.json +CLAUDE.md +.claude/** diff --git a/src/rpc/Counters.cpp b/src/rpc/Counters.cpp index b850a8333..abc97a6db 100644 --- a/src/rpc/Counters.cpp +++ b/src/rpc/Counters.cpp @@ -21,18 +21,24 @@ #include "rpc/JS.hpp" #include "rpc/WorkQueue.hpp" +#include "util/JsonUtils.hpp" #include "util/prometheus/Label.hpp" #include "util/prometheus/Prometheus.hpp" #include +#include +#include #include #include #include +#include #include #include +#include #include #include +#include namespace rpc { @@ -138,6 +144,21 @@ Counters::Counters(Reportable const& wq) "Total number of internal errors" ) ) + , ledgerAgeLedgersHistogram_( + PrometheusService::histogramInt( + "rpc_requested_ledger_age_histogram", + Labels{}, + {0, 10, 100, 1'000, 10'000, 100'000, 1'000'000, 10'000'000, 100'000'000}, + "Age of requested ledgers in ledger count" + ) + ) + , ledgerHashRequestsCounter_( + PrometheusService::counterInt( + "rpc_ledger_hash_requests_total_number", + Labels{}, + "Total number of successful requests containing ledger_hash field" + ) + ) , workQueue_(std::cref(wq)) , startupTime_{std::chrono::system_clock::now()} { @@ -217,6 +238,35 @@ Counters::onInternalError() ++internalErrorCounter_.get(); } +void +Counters::recordLedgerRequest( + boost::json::object const& params, + std::uint32_t currentLedgerSequence +) +{ + if (params.contains(JS(ledger_hash))) { + ++ledgerHashRequestsCounter_.get(); + return; + } + + if (not params.contains(JS(ledger_index))) { + ledgerAgeLedgersHistogram_.get().observe(0); + return; + } + auto const& indexValue = params.at("ledger_index"); + if (auto const parsed = util::getLedgerIndex(indexValue); parsed.has_value()) { + if (*parsed <= currentLedgerSequence) { + auto const ageLedgers = static_cast(currentLedgerSequence - *parsed); + ledgerAgeLedgersHistogram_.get().observe(ageLedgers); + } + } else if (indexValue.is_string()) { + auto const indexStr = boost::json::value_to(indexValue); + if (indexStr == "validated") { + ledgerAgeLedgersHistogram_.get().observe(0); + } + } +} + std::chrono::seconds Counters::uptime() const { diff --git a/src/rpc/Counters.hpp b/src/rpc/Counters.hpp index 772373330..0fda7642f 100644 --- a/src/rpc/Counters.hpp +++ b/src/rpc/Counters.hpp @@ -21,11 +21,13 @@ #include "rpc/WorkQueue.hpp" #include "util/prometheus/Counter.hpp" +#include "util/prometheus/Histogram.hpp" #include #include #include +#include #include #include #include @@ -66,6 +68,9 @@ class Counters { CounterType unknownCommandCounter_; CounterType internalErrorCounter_; + std::reference_wrapper ledgerAgeLedgersHistogram_; + CounterType ledgerHashRequestsCounter_; + std::reference_wrapper workQueue_; std::chrono::time_point startupTime_; @@ -150,6 +155,15 @@ public: void onInternalError(); + /** + * @brief Records ledger request metrics based on the ledger parameter in the request. + * + * @param params The request parameters containing ledger information + * @param currentLedgerSequence The current ledger sequence number + */ + void + recordLedgerRequest(boost::json::object const& params, std::uint32_t currentLedgerSequence); + /** @return Uptime of this instance in seconds. */ std::chrono::seconds uptime() const; diff --git a/src/rpc/RPCEngine.hpp b/src/rpc/RPCEngine.hpp index 162b69485..95240326a 100644 --- a/src/rpc/RPCEngine.hpp +++ b/src/rpc/RPCEngine.hpp @@ -27,7 +27,6 @@ #include "rpc/common/HandlerProvider.hpp" #include "rpc/common/Types.hpp" #include "rpc/common/impl/ForwardingProxy.hpp" -#include "util/OverloadSet.hpp" #include "util/ResponseExpirationCache.hpp" #include "util/log/Logger.hpp" #include "web/Context.hpp" @@ -41,6 +40,7 @@ #include #include +#include #include #include #include @@ -228,16 +228,37 @@ public: } /** - * @brief Notify the system that specified method was executed. + * @brief Notify the system that specified method was executed and record ledger metrics. * - * @param method + * @param context The web context containing method, params, and ledger information * @param duration The time it took to execute the method specified in microseconds + * @param isForwarded Whether the request was forwarded to rippled or not */ void - notifyComplete(std::string const& method, std::chrono::microseconds const& duration) + notifyComplete( + web::Context const& context, + std::chrono::microseconds const& duration, + bool isForwarded + ) { - if (validHandler(method)) - counters_.get().rpcComplete(method, duration); + if (validHandler(context.method)) { + counters_.get().rpcComplete(context.method, duration); + if (not isForwarded) { + counters_.get().recordLedgerRequest(context.params, context.range.maxSequence); + } + } + } + + /** + * @brief Record ledger request metrics. + * + * @param params The request parameters containing ledger information + * @param currentLedgerSequence The current ledger sequence + */ + void + recordLedgerMetrics(boost::json::object const& params, std::uint32_t currentLedgerSequence) + { + counters_.get().recordLedgerRequest(params, currentLedgerSequence); } /** diff --git a/src/web/RPCServerHandler.hpp b/src/web/RPCServerHandler.hpp index 1cda53154..5630cd33b 100644 --- a/src/web/RPCServerHandler.hpp +++ b/src/web/RPCServerHandler.hpp @@ -229,14 +229,14 @@ private: LOG(perfLog_.debug()) << context->tag() << "Encountered error: " << responseStr; LOG(log_.debug()) << context->tag() << "Encountered error: " << responseStr; } else { - // This can still technically be an error. Clio counts forwarded requests as - // successful. - rpcEngine_->notifyComplete(context->method, us); - auto& json = result.response.value(); auto const isForwarded = json.contains("forwarded") && json.at("forwarded").is_bool() && json.at("forwarded").as_bool(); + // This can still technically be an error. Clio counts forwarded requests + // as successful. + rpcEngine_->notifyComplete(*context, us, isForwarded); + if (isForwarded) json.erase("forwarded"); diff --git a/src/web/ng/RPCServerHandler.hpp b/src/web/ng/RPCServerHandler.hpp index 6c765b1cb..f83d3ff55 100644 --- a/src/web/ng/RPCServerHandler.hpp +++ b/src/web/ng/RPCServerHandler.hpp @@ -287,14 +287,14 @@ private: LOG(perfLog_.debug()) << context->tag() << "Encountered error: " << responseStr; LOG(log_.debug()) << context->tag() << "Encountered error: " << responseStr; } else { - // This can still technically be an error. Clio counts forwarded requests as - // successful. - rpcEngine_->notifyComplete(context->method, us); - auto& json = result.response.value(); auto const isForwarded = json.contains("forwarded") && json.at("forwarded").is_bool() && json.at("forwarded").as_bool(); + // This can still technically be an error. Clio counts forwarded requests + // as successful. + rpcEngine_->notifyComplete(*context, us, isForwarded); + if (isForwarded) json.erase("forwarded"); diff --git a/tests/common/util/MockRPCEngine.hpp b/tests/common/util/MockRPCEngine.hpp index 5acb12d94..88d6ecddd 100644 --- a/tests/common/util/MockRPCEngine.hpp +++ b/tests/common/util/MockRPCEngine.hpp @@ -25,9 +25,11 @@ #include #include #include +#include #include #include +#include #include #include @@ -49,6 +51,17 @@ struct MockAsyncRPCEngine { } MOCK_METHOD(void, notifyComplete, (std::string const&, std::chrono::microseconds const&), ()); + void + notifyComplete( + web::Context const& ctx, + std::chrono::microseconds const& duration, + bool isForwarded + ) + { + notifyComplete(ctx.method, duration); + if (not isForwarded) + recordLedgerMetrics(ctx.params, ctx.range.maxSequence); + } MOCK_METHOD(void, notifyFailed, (std::string const&), ()); MOCK_METHOD(void, notifyErrored, (std::string const&), ()); MOCK_METHOD(void, notifyForwarded, (std::string const&), ()); @@ -58,6 +71,7 @@ struct MockAsyncRPCEngine { MOCK_METHOD(void, notifyTooBusy, (), ()); MOCK_METHOD(void, notifyUnknownCommand, (), ()); MOCK_METHOD(void, notifyInternalError, (), ()); + MOCK_METHOD(void, recordLedgerMetrics, (boost::json::object const&, std::uint32_t), ()); MOCK_METHOD(rpc::Result, buildResponse, (web::Context const&), ()); }; @@ -69,6 +83,17 @@ struct MockRPCEngine { () ); MOCK_METHOD(void, notifyComplete, (std::string const&, std::chrono::microseconds const&), ()); + void + notifyComplete( + web::Context const& ctx, + std::chrono::microseconds const& duration, + bool isForwarded + ) + { + notifyComplete(ctx.method, duration); + if (not isForwarded) + recordLedgerMetrics(ctx.params, ctx.range.maxSequence); + } MOCK_METHOD(void, notifyErrored, (std::string const&), ()); MOCK_METHOD(void, notifyForwarded, (std::string const&), ()); MOCK_METHOD(void, notifyFailedToForward, (std::string const&), ()); @@ -77,5 +102,6 @@ struct MockRPCEngine { MOCK_METHOD(void, notifyTooBusy, (), ()); MOCK_METHOD(void, notifyUnknownCommand, (), ()); MOCK_METHOD(void, notifyInternalError, (), ()); + MOCK_METHOD(void, recordLedgerMetrics, (boost::json::object const&, std::uint32_t), ()); MOCK_METHOD(rpc::Result, buildResponse, (web::Context const&), ()); }; diff --git a/tests/unit/rpc/CountersTests.cpp b/tests/unit/rpc/CountersTests.cpp index 818de938a..b0c6aeaff 100644 --- a/tests/unit/rpc/CountersTests.cpp +++ b/tests/unit/rpc/CountersTests.cpp @@ -22,6 +22,7 @@ #include "rpc/WorkQueue.hpp" #include "util/MockPrometheus.hpp" #include "util/prometheus/Counter.hpp" +#include "util/prometheus/Histogram.hpp" #include #include @@ -30,6 +31,7 @@ #include #include +#include #include using namespace rpc; @@ -272,3 +274,93 @@ TEST_F(RPCCountersMockPrometheusTests, onInternalError) EXPECT_CALL(internalErrorMock, add(1)); counters.onInternalError(); } + +struct RPCCountersMockPrometheusRecotdLedgerRequestTest : RPCCountersMockPrometheusTests { + testing::StrictMock>& ageLedgersHistogramMock = + makeMock("rpc_requested_ledger_age_histogram", ""); +}; + +TEST_F(RPCCountersMockPrometheusRecotdLedgerRequestTest, currentLedger) +{ + // "current" is not tracked in the histogram (it's not a historical ledger lookup) + // No mock expectations needed + boost::json::object params; + params["ledger_index"] = "current"; + counters.recordLedgerRequest(params, 1000); +} + +TEST_F(RPCCountersMockPrometheusRecotdLedgerRequestTest, validateLedger) +{ + EXPECT_CALL(ageLedgersHistogramMock, observe(0)); + + boost::json::object params; + params["ledger_index"] = "validated"; + counters.recordLedgerRequest(params, 1000); +} + +TEST_F(RPCCountersMockPrometheusRecotdLedgerRequestTest, validatedDefaultLedger) +{ + EXPECT_CALL(ageLedgersHistogramMock, observe(0)); + + boost::json::object params; + counters.recordLedgerRequest(params, 1000); +} + +TEST_F(RPCCountersMockPrometheusRecotdLedgerRequestTest, specificLedger) +{ + auto& ageLedgersHistogramMock = + makeMock("rpc_requested_ledger_age_histogram", ""); + + EXPECT_CALL(ageLedgersHistogramMock, observe(100)); // age is 1000 - 900 = 100 + + boost::json::object params; + params["ledger_index"] = 900; + counters.recordLedgerRequest(params, 1000); +} + +TEST_F(RPCCountersMockPrometheusRecotdLedgerRequestTest, stringNumberLedger) +{ + EXPECT_CALL(ageLedgersHistogramMock, observe(50)); // 1000 - 950 = 50 ledgers + + boost::json::object params; + params["ledger_index"] = "950"; + counters.recordLedgerRequest(params, 1000); +} + +TEST_F(RPCCountersMockPrometheusRecotdLedgerRequestTest, zeroAgeLedger) +{ + auto& ageLedgersHistogramMock = + makeMock("rpc_requested_ledger_age_histogram", ""); + + EXPECT_CALL(ageLedgersHistogramMock, observe(0)); // 1000 - 1000 = 0 ledgers + + boost::json::object params; + params["ledger_index"] = 1000; // Same as current + counters.recordLedgerRequest(params, 1000); +} + +TEST_F(RPCCountersMockPrometheusRecotdLedgerRequestTest, ledgerHashRequest) +{ + auto& ledgerHashCounterMock = makeMock("rpc_ledger_hash_requests_total_number", ""); + + EXPECT_CALL(ledgerHashCounterMock, add(1)); + + boost::json::object params; + params["ledger_hash"] = "ABCDEF0123456789ABCDEF0123456789ABCDEF0123456789ABCDEF0123456789"; + counters.recordLedgerRequest(params, 1000); +} + +TEST_F(RPCCountersMockPrometheusRecotdLedgerRequestTest, ledgerHashWithIndexIgnoresIndex) +{ + auto& ledgerHashCounterMock = makeMock("rpc_ledger_hash_requests_total_number", ""); + + // When both ledger_hash and ledger_index are present, only ledger_hash counter should be + // incremented + EXPECT_CALL(ledgerHashCounterMock, add(1)); + // No histogram call should be made + + boost::json::object params; + params["ledger_hash"] = "ABCDEF0123456789ABCDEF0123456789ABCDEF0123456789ABCDEF0123456789"; + params["ledger_index"] = 900; // This should be ignored + counters.recordLedgerRequest(params, 1000); +} diff --git a/tests/unit/web/ng/RPCServerHandlerTests.cpp b/tests/unit/web/ng/RPCServerHandlerTests.cpp index 432360d23..54ff9e1f0 100644 --- a/tests/unit/web/ng/RPCServerHandlerTests.cpp +++ b/tests/unit/web/ng/RPCServerHandlerTests.cpp @@ -414,6 +414,7 @@ TEST_F(NgRpcServerHandlerTest, HandleRequest_Successful_HttpRequest) EXPECT_CALL(dosguard_, request(ip_, boost::json::parse(requestStr).as_object())) .WillOnce(Return(true)); EXPECT_CALL(dosguard_, add(ip_, testing::_)).WillOnce(Return(true)); + EXPECT_CALL(*rpcEngine_, recordLedgerMetrics); EXPECT_CALL(*rpcEngine_, post).WillOnce([&](auto&& fn, auto&&) { EXPECT_CALL(connectionMetadata_, wasUpgraded) .WillRepeatedly(Return(not request.isHttp())); @@ -454,6 +455,7 @@ TEST_F(NgRpcServerHandlerTest, HandleRequest_OutdatedWarning) EXPECT_CALL(dosguard_, request(ip_, boost::json::parse(requestStr).as_object())) .WillOnce(Return(true)); EXPECT_CALL(dosguard_, add(ip_, testing::_)).WillOnce(Return(true)); + EXPECT_CALL(*rpcEngine_, recordLedgerMetrics); EXPECT_CALL(*rpcEngine_, post).WillOnce([&](auto&& fn, auto&&) { EXPECT_CALL(connectionMetadata_, wasUpgraded) .WillRepeatedly(Return(not request.isHttp())); @@ -541,6 +543,7 @@ TEST_F(NgRpcServerHandlerTest, HandleRequest_Successful_HttpRequest_HasError) EXPECT_CALL(dosguard_, request(ip_, boost::json::parse(requestStr).as_object())) .WillOnce(Return(true)); EXPECT_CALL(dosguard_, add(ip_, testing::_)).WillOnce(Return(true)); + EXPECT_CALL(*rpcEngine_, recordLedgerMetrics); EXPECT_CALL(*rpcEngine_, post).WillOnce([&](auto&& fn, auto&&) { EXPECT_CALL(connectionMetadata_, wasUpgraded) .WillRepeatedly(Return(not request.isHttp())); @@ -606,6 +609,7 @@ TEST_F(NgRpcServerHandlerWsTest, HandleRequest_Successful_WsRequest) EXPECT_CALL(dosguard_, request(ip_, boost::json::parse(requestStr).as_object())) .WillOnce(Return(true)); EXPECT_CALL(dosguard_, add(ip_, testing::_)).WillOnce(Return(true)); + EXPECT_CALL(*rpcEngine_, recordLedgerMetrics); EXPECT_CALL(*rpcEngine_, post).WillOnce([&](auto&& fn, auto&&) { EXPECT_CALL(connectionMetadata_, wasUpgraded) .WillRepeatedly(Return(not request.isHttp())); @@ -650,6 +654,7 @@ TEST_F(NgRpcServerHandlerWsTest, HandleRequest_Successful_WsRequest_HasError) EXPECT_CALL(dosguard_, request(ip_, boost::json::parse(requestStr).as_object())) .WillOnce(Return(true)); EXPECT_CALL(dosguard_, add(ip_, testing::_)).WillOnce(Return(true)); + EXPECT_CALL(*rpcEngine_, recordLedgerMetrics); EXPECT_CALL(*rpcEngine_, post).WillOnce([&](auto&& fn, auto&&) { EXPECT_CALL(connectionMetadata_, wasUpgraded) .WillRepeatedly(Return(not request.isHttp()));