Track rep query response time (#4658)

* Track rep query response time

* Make `stats.sample (...)` signature more ergonomic

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

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

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

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
 };

nano/node/active_elections.cpp

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

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

nano/node/repcrawler.cpp

@@ -394,21 +394,21 @@ 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.
 		auto const target_hash = it->hash;
 		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) {

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