Track rep query response time (#4658)

* Track rep query response time

* Make `stats.sample (...)` signature more ergonomic
This commit is contained in:
Piotr Wójcik 2024-06-26 20:12:41 +02:00 committed by GitHub
commit 15e57ffd70
No known key found for this signature in database
GPG key ID: B5690EEEBB952194
8 changed files with 25 additions and 21 deletions

View file

@ -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 ());

View file

@ -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<sampler_value_t, sampler_value_t> expected_min_max, nano::stats::sampler_value_t value)
void nano::stats::sample (stat::sample sample, nano::stats::sampler_value_t value, std::pair<sampler_value_t, sampler_value_t> expected_min_max)
{
debug_assert (sample != stat::sample::_invalid);

View file

@ -107,7 +107,7 @@ public:
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<sampler_value_t, sampler_value_t> expected_min_max, sampler_value_t value);
void sample (stat::sample sample, sampler_value_t value, std::pair<sampler_value_t, sampler_value_t> 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<sampler_value_t> samples (stat::sample sample);

View file

@ -487,6 +487,7 @@ enum class sample
active_election_duration,
bootstrap_tag_duration,
rep_response_time,
_last // Must be the last enum
};

View file

@ -324,7 +324,8 @@ void nano::active_elections::cleanup_election (nano::unique_lock<nano::mutex> &
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 ();

View file

@ -343,12 +343,14 @@ void nano::bootstrap_ascending::service::process (nano::asc_pull_ack const & mes
auto & tags_by_id = tags.get<tag_id> ();
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);

View file

@ -394,8 +394,7 @@ bool nano::rep_crawler::process (std::shared_ptr<nano::vote> const & vote, std::
{
nano::lock_guard<nano::mutex> lock{ mutex };
auto & index = queries.get<tag_channel> ();
auto [begin, end] = index.equal_range (channel);
auto [begin, end] = queries.get<tag_channel> ().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<nano::vote> 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, nano::log::milliseconds_delta (it->time), { 0, config.query_timeout.count () });
responses.push_back ({ channel, vote });
queries.modify (it, [] (query_entry & e) {

View file

@ -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");