From f6758eaf2ee55b0d03011a10184893a221491eb1 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Piotr=20Wo=CC=81jcik?= <3044353+pwojcikdev@users.noreply.github.com> Date: Wed, 26 Jun 2024 12:53:27 +0200 Subject: [PATCH 1/2] Track rep query response time --- nano/lib/stats_enums.hpp | 1 + nano/node/repcrawler.cpp | 8 ++++---- 2 files changed, 5 insertions(+), 4 deletions(-) diff --git a/nano/lib/stats_enums.hpp b/nano/lib/stats_enums.hpp index 6bec768d2e..803c15e86c 100644 --- a/nano/lib/stats_enums.hpp +++ b/nano/lib/stats_enums.hpp @@ -487,6 +487,7 @@ enum class sample active_election_duration, bootstrap_tag_duration, + rep_response_time, _last // Must be the last enum }; diff --git a/nano/node/repcrawler.cpp b/nano/node/repcrawler.cpp index f8f04a4ce3..8990eda35f 100644 --- a/nano/node/repcrawler.cpp +++ b/nano/node/repcrawler.cpp @@ -394,8 +394,7 @@ bool nano::rep_crawler::process (std::shared_ptr const & vote, std:: { nano::lock_guard lock{ mutex }; - auto & index = queries.get (); - auto [begin, end] = index.equal_range (channel); + auto [begin, end] = queries.get ().equal_range (channel); for (auto it = begin; it != end; ++it) { // TODO: This linear search could be slow, especially with large votes. @@ -403,12 +402,13 @@ bool nano::rep_crawler::process (std::shared_ptr const & vote, std:: bool found = std::any_of (vote->hashes.begin (), vote->hashes.end (), [&target_hash] (nano::block_hash const & hash) { return hash == target_hash; }); - if (found) { logger.debug (nano::log::type::rep_crawler, "Processing response for block {} from {}", target_hash.to_string (), channel->to_string ()); stats.inc (nano::stat::type::rep_crawler, nano::stat::detail::response); - // TODO: Track query response time + + // Track response time + stats.sample (nano::stat::sample::rep_response_time, { 0, config.query_timeout.count () }, nano::log::milliseconds_delta (it->time)); responses.push_back ({ channel, vote }); queries.modify (it, [] (query_entry & e) { From 55018eade5345d52b3f108a9075bea39c7bf1eb2 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Piotr=20Wo=CC=81jcik?= <3044353+pwojcikdev@users.noreply.github.com> Date: Wed, 26 Jun 2024 12:56:47 +0200 Subject: [PATCH 2/2] Make `stats.sample (...)` signature more ergonomic --- nano/core_test/stats.cpp | 12 ++++++------ nano/lib/stats.cpp | 2 +- nano/lib/stats.hpp | 2 +- nano/node/active_elections.cpp | 3 ++- nano/node/bootstrap_ascending/service.cpp | 6 ++++-- nano/node/repcrawler.cpp | 2 +- nano/rpc_test/rpc.cpp | 12 ++++++------ 7 files changed, 21 insertions(+), 18 deletions(-) diff --git a/nano/core_test/stats.cpp b/nano/core_test/stats.cpp index b1af34390f..6ee083d274 100644 --- a/nano/core_test/stats.cpp +++ b/nano/core_test/stats.cpp @@ -50,12 +50,12 @@ TEST (stats, samples) nano::test::system system; auto & node = *system.add_node (); - node.stats.sample (nano::stat::sample::active_election_duration, { 1, 10 }, 5); - node.stats.sample (nano::stat::sample::active_election_duration, { 1, 10 }, 5); - node.stats.sample (nano::stat::sample::active_election_duration, { 1, 10 }, 11); - node.stats.sample (nano::stat::sample::active_election_duration, { 1, 10 }, 37); + node.stats.sample (nano::stat::sample::active_election_duration, 5, { 1, 10 }); + node.stats.sample (nano::stat::sample::active_election_duration, 5, { 1, 10 }); + node.stats.sample (nano::stat::sample::active_election_duration, 11, { 1, 10 }); + node.stats.sample (nano::stat::sample::active_election_duration, 37, { 1, 10 }); - node.stats.sample (nano::stat::sample::bootstrap_tag_duration, { 1, 10 }, 2137); + node.stats.sample (nano::stat::sample::bootstrap_tag_duration, 2137, { 1, 10 }); auto samples1 = node.stats.samples (nano::stat::sample::active_election_duration); ASSERT_EQ (4, samples1.size ()); @@ -67,7 +67,7 @@ TEST (stats, samples) auto samples2 = node.stats.samples (nano::stat::sample::active_election_duration); ASSERT_EQ (0, samples2.size ()); - node.stats.sample (nano::stat::sample::active_election_duration, { 1, 10 }, 3); + node.stats.sample (nano::stat::sample::active_election_duration, 3, { 1, 10 }); auto samples3 = node.stats.samples (nano::stat::sample::active_election_duration); ASSERT_EQ (1, samples3.size ()); diff --git a/nano/lib/stats.cpp b/nano/lib/stats.cpp index 55511e9d92..fa3bd13146 100644 --- a/nano/lib/stats.cpp +++ b/nano/lib/stats.cpp @@ -165,7 +165,7 @@ nano::stats::counter_value_t nano::stats::count (stat::type type, stat::dir dir) return result; } -void nano::stats::sample (stat::sample sample, std::pair expected_min_max, nano::stats::sampler_value_t value) +void nano::stats::sample (stat::sample sample, nano::stats::sampler_value_t value, std::pair expected_min_max) { debug_assert (sample != stat::sample::_invalid); diff --git a/nano/lib/stats.hpp b/nano/lib/stats.hpp index 905153f957..8f20ada726 100644 --- a/nano/lib/stats.hpp +++ b/nano/lib/stats.hpp @@ -107,7 +107,7 @@ class stats final counter_value_t count (stat::type type, stat::dir dir = stat::dir::in) const; /** Adds a sample to the given sampler */ - void sample (stat::sample sample, std::pair expected_min_max, sampler_value_t value); + void sample (stat::sample sample, sampler_value_t value, std::pair expected_min_max = {}); /** Returns a potentially empty list of the last N samples, where N is determined by the 'max_samples' configuration. Samples are reset after each lookup. */ std::vector samples (stat::sample sample); diff --git a/nano/node/active_elections.cpp b/nano/node/active_elections.cpp index 92bfde942f..aa183428e8 100644 --- a/nano/node/active_elections.cpp +++ b/nano/node/active_elections.cpp @@ -324,7 +324,8 @@ void nano::active_elections::cleanup_election (nano::unique_lock & lock_a.unlock (); - node.stats.sample (nano::stat::sample::active_election_duration, { 0, 1000 * 60 * 10 /* 0-10 minutes range */ }, election->duration ().count ()); + // Track election duration + node.stats.sample (nano::stat::sample::active_election_duration, election->duration ().count (), { 0, 1000 * 60 * 10 /* 0-10 minutes range */ }); vacancy_update (); diff --git a/nano/node/bootstrap_ascending/service.cpp b/nano/node/bootstrap_ascending/service.cpp index b0ee33dccf..8bceda97d3 100644 --- a/nano/node/bootstrap_ascending/service.cpp +++ b/nano/node/bootstrap_ascending/service.cpp @@ -343,12 +343,14 @@ void nano::bootstrap_ascending::service::process (nano::asc_pull_ack const & mes auto & tags_by_id = tags.get (); if (tags_by_id.count (message.id) > 0) { + stats.inc (nano::stat::type::bootstrap_ascending, nano::stat::detail::reply); + auto iterator = tags_by_id.find (message.id); auto tag = *iterator; tags_by_id.erase (iterator); - stats.inc (nano::stat::type::bootstrap_ascending, nano::stat::detail::reply); - stats.sample (nano::stat::sample::bootstrap_tag_duration, { 0, config.bootstrap_ascending.timeout }, nano::milliseconds_since_epoch () - tag.time); + // Track bootstrap request response time + stats.sample (nano::stat::sample::bootstrap_tag_duration, nano::milliseconds_since_epoch () - tag.time, { 0, config.bootstrap_ascending.timeout }); scoring.received_message (channel); diff --git a/nano/node/repcrawler.cpp b/nano/node/repcrawler.cpp index 8990eda35f..f2e22f3575 100644 --- a/nano/node/repcrawler.cpp +++ b/nano/node/repcrawler.cpp @@ -408,7 +408,7 @@ bool nano::rep_crawler::process (std::shared_ptr const & vote, std:: stats.inc (nano::stat::type::rep_crawler, nano::stat::detail::response); // Track response time - stats.sample (nano::stat::sample::rep_response_time, { 0, config.query_timeout.count () }, nano::log::milliseconds_delta (it->time)); + stats.sample (nano::stat::sample::rep_response_time, nano::log::milliseconds_delta (it->time), { 0, config.query_timeout.count () }); responses.push_back ({ channel, vote }); queries.modify (it, [] (query_entry & e) { diff --git a/nano/rpc_test/rpc.cpp b/nano/rpc_test/rpc.cpp index b2ff31eb49..4365ac1d24 100644 --- a/nano/rpc_test/rpc.cpp +++ b/nano/rpc_test/rpc.cpp @@ -5779,13 +5779,13 @@ TEST (rpc, stats_samples) auto node = add_ipc_enabled_node (system); auto const rpc_ctx = add_rpc (system, node); - node->stats.sample (nano::stat::sample::active_election_duration, { 0, 10 }, 1); - node->stats.sample (nano::stat::sample::active_election_duration, { 0, 10 }, 2); - node->stats.sample (nano::stat::sample::active_election_duration, { 0, 10 }, 3); - node->stats.sample (nano::stat::sample::active_election_duration, { 0, 10 }, 4); + node->stats.sample (nano::stat::sample::active_election_duration, 1, { 0, 10 }); + node->stats.sample (nano::stat::sample::active_election_duration, 2, { 0, 10 }); + node->stats.sample (nano::stat::sample::active_election_duration, 3, { 0, 10 }); + node->stats.sample (nano::stat::sample::active_election_duration, 4, { 0, 10 }); - node->stats.sample (nano::stat::sample::bootstrap_tag_duration, { 0, 999 }, 5); - node->stats.sample (nano::stat::sample::bootstrap_tag_duration, { 0, 999 }, 5); + node->stats.sample (nano::stat::sample::bootstrap_tag_duration, 5, { 0, 999 }); + node->stats.sample (nano::stat::sample::bootstrap_tag_duration, 5, { 0, 999 }); boost::property_tree::ptree request; request.put ("action", "stats");