Increase active elections capacity with periodic full checks (#2641)

* Confirmed to expiry fixed at 5 seconds

* Only increase the election counter for unconfirmed elections

* Increase default active elections size to 50k but only perform a full check periodically

* Add timing logging for large number of elections (every 5 seconds max)

* Adjust timing logging for block processor

* Tune search_frontiers such that therre are no delays in aggressive mode but also not too many added

* Add erroneously removed mutex lock in https://github.com/nanocurrency/nano-node/pull/2619

* Feedback on variable name

* Empty commit to fix actions

* Tweak blockprocessor logging to resemble previous behavior with disabled timing logging

nano/node/active_transactions.cpp

@@ -19,6 +19,7 @@ confirmation_height_processor (confirmation_height_processor_a),
 node (node_a),
 multipliers_cb (20, 1.),
 trended_active_difficulty (node_a.network_params.network.publish_threshold),
+check_all_elections_period (node_a.network_params.network.is_test_network () ? 10ms : 5s),
 election_time_to_live (node_a.network_params.network.is_test_network () ? 0s : 2s),
 thread ([this]() {
 	nano::thread_role::set (nano::thread_role::name::request_loop);
@@ -61,11 +62,11 @@ void nano::active_transactions::search_frontiers (nano::transaction const & tran
 	nano::unique_lock<std::mutex> lk (mutex);
 	auto check_time_exceeded = std::chrono::steady_clock::now () >= next_frontier_check;
 	lk.unlock ();
-	auto max_elections = (node.config.active_elections_size / 20);
+	auto max_elections = 1000;
 	auto low_active_elections = roots_size < max_elections;
 	bool wallets_check_required = (!skip_wallets || !priority_wallet_cementable_frontiers.empty ()) && !agressive_mode;
 	// Minimise dropping real-time transactions, set the number of frontiers added to a factor of the total number of active elections
-	auto max_active = node.config.active_elections_size / 5;
+	auto max_active = node.config.active_elections_size / 20;
 	if (roots_size <= max_active && (check_time_exceeded || wallets_check_required || (!is_test_network && low_active_elections && agressive_mode)))
 	{
 		// When the number of active elections is low increase max number of elections for setting confirmation height.
@@ -229,11 +230,12 @@ void nano::active_transactions::request_confirm (nano::unique_lock<std::mutex> &
 	nano::confirmation_solicitor solicitor (node.network, node.network_params.network);
 	solicitor.prepare (node.rep_crawler.principal_representatives (std::numeric_limits<size_t>::max (), node.network_params.protocol.tcp_realtime_protocol_version_min));
 
-	auto election_ttl_cutoff_l (std::chrono::steady_clock::now () - election_time_to_live);
-	auto roots_size_l (roots.size ());
-	bool saturated_l (roots_size_l > node.config.active_elections_size / 2);
-	auto & sorted_roots_l = roots.get<tag_difficulty> ();
-	size_t count_l{ 0 };
+	auto & sorted_roots_l (roots.get<tag_difficulty> ());
+	auto const election_ttl_cutoff_l (std::chrono::steady_clock::now () - election_time_to_live);
+	bool const check_all_elections_l (std::chrono::steady_clock::now () - last_check_all_elections > check_all_elections_period);
+	size_t const this_loop_target_l (check_all_elections_l ? sorted_roots_l.size () : node.config.active_elections_size / 10);
+	size_t unconfirmed_count_l (0);
+	nano::timer<std::chrono::milliseconds> elapsed (nano::timer_state::started);
 
 	/*
 	 * Loop through active elections in descending order of proof-of-work difficulty, requesting confirmation
@@ -242,11 +244,12 @@ void nano::active_transactions::request_confirm (nano::unique_lock<std::mutex> &
 	 * Elections extending the soft config.active_elections_size limit are flushed after a certain time-to-live cutoff
 	 * Flushed elections are later re-activated via frontier confirmation
 	 */
-	for (auto i = sorted_roots_l.begin (), n = sorted_roots_l.end (); i != n; ++count_l)
+	for (auto i = sorted_roots_l.begin (), n = sorted_roots_l.end (); i != n && unconfirmed_count_l < this_loop_target_l;)
 	{
 		auto & election_l (i->election);
-		bool const overflow_l (count_l >= node.config.active_elections_size && election_l->election_start < election_ttl_cutoff_l && !node.wallets.watcher->is_watched (i->root));
-		if (overflow_l || election_l->transition_time (solicitor, saturated_l))
+		unconfirmed_count_l += !election_l->confirmed ();
+		bool const overflow_l (unconfirmed_count_l > node.config.active_elections_size && election_l->election_start < election_ttl_cutoff_l && !node.wallets.watcher->is_watched (i->root));
+		if (overflow_l || election_l->transition_time (solicitor))
 		{
 			election_l->clear_blocks ();
 			i = sorted_roots_l.erase (i);
@@ -259,6 +262,16 @@ void nano::active_transactions::request_confirm (nano::unique_lock<std::mutex> &
 	lock_a.unlock ();
 	solicitor.flush ();
 	lock_a.lock ();
+
+	// This is updated after the loop to ensure slow machines don't do the full check often
+	if (check_all_elections_l)
+	{
+		last_check_all_elections = std::chrono::steady_clock::now ();
+		if (node.config.logging.timing_logging () && this_loop_target_l > node.config.active_elections_size / 10)
+		{
+			node.logger.try_log (boost::str (boost::format ("Processed %1% elections (%2% were already confirmed) in %3% %4%") % this_loop_target_l % (this_loop_target_l - unconfirmed_count_l) % elapsed.value ().count () % elapsed.unit ()));
+		}
+	}
 }
 
 void nano::active_transactions::request_loop ()

nano/node/active_transactions.hpp

@@ -155,6 +155,10 @@ private:
 	bool started{ false };
 	std::atomic<bool> stopped{ false };
 
+	// Periodically check all elections
+	std::chrono::milliseconds const check_all_elections_period;
+	std::chrono::steady_clock::time_point last_check_all_elections{};
+
 	// Maximum time an election can be kept active if it is extending the container
 	std::chrono::seconds const election_time_to_live;
 

nano/node/blockprocessor.cpp

@@ -127,13 +127,13 @@ void nano::block_processor::process_blocks ()
 	}
 }
 
-bool nano::block_processor::should_log (bool first_time)
+bool nano::block_processor::should_log ()
 {
 	auto result (false);
 	auto now (std::chrono::steady_clock::now ());
-	if (first_time || next_log < now)
+	if (next_log < now)
 	{
-		next_log = now + std::chrono::seconds (15);
+		next_log = now + (node.config.logging.timing_logging () ? std::chrono::seconds (2) : std::chrono::seconds (15));
 		result = true;
 	}
 	return result;
@@ -238,9 +238,9 @@ void nano::block_processor::verify_state_blocks (nano::unique_lock<std::mutex> &
 			}
 			items.pop_front ();
 		}
-		if (node.config.logging.timing_logging ())
+		if (node.config.logging.timing_logging () && timer_l.stop () > std::chrono::milliseconds (10))
 		{
-			node.logger.try_log (boost::str (boost::format ("Batch verified %1% state blocks in %2% %3%") % size % timer_l.stop ().count () % timer_l.unit ()));
+			node.logger.try_log (boost::str (boost::format ("Batch verified %1% state blocks in %2% %3%") % size % timer_l.value ().count () % timer_l.unit ()));
 		}
 	}
 	else
@@ -272,29 +272,12 @@ void nano::block_processor::process_batch (nano::unique_lock<std::mutex> & lock_
 	timer_l.restart ();
 	lock_a.lock ();
 	// Processing blocks
-	auto first_time (true);
 	unsigned number_of_blocks_processed (0), number_of_forced_processed (0);
 	while ((!blocks.empty () || !forced.empty ()) && (timer_l.before_deadline (node.config.block_processor_batch_max_time) || (number_of_blocks_processed < node.flags.block_processor_batch_size)) && !awaiting_write)
 	{
-		auto log_this_record (false);
-		if (node.config.logging.timing_logging ())
-		{
-			if (should_log (first_time))
-			{
-				log_this_record = true;
-			}
-		}
-		else
-		{
-			if (((blocks.size () + state_blocks.size () + forced.size ()) > 64 && should_log (false)))
-			{
-				log_this_record = true;
-			}
-		}
-
+		bool log_this_record = (blocks.size () + state_blocks.size () + forced.size () > 64) && should_log ();
 		if (log_this_record)
 		{
-			first_time = false;
 			node.logger.always_log (boost::str (boost::format ("%1% blocks (+ %2% state blocks) (+ %3% forced) in processing queue") % blocks.size () % state_blocks.size () % forced.size ()));
 		}
 		nano::unchecked_info info;
@@ -358,9 +341,9 @@ void nano::block_processor::process_batch (nano::unique_lock<std::mutex> & lock_
 	awaiting_write = false;
 	lock_a.unlock ();
 
-	if (node.config.logging.timing_logging () && number_of_blocks_processed != 0)
+	if (node.config.logging.timing_logging () && number_of_blocks_processed != 0 && timer_l.stop () > std::chrono::milliseconds (10))
 	{
-		node.logger.always_log (boost::str (boost::format ("Processed %1% blocks (%2% blocks were forced) in %3% %4%") % number_of_blocks_processed % number_of_forced_processed % timer_l.stop ().count () % timer_l.unit ()));
+		node.logger.always_log (boost::str (boost::format ("Processed %1% blocks (%2% blocks were forced) in %3% %4%") % number_of_blocks_processed % number_of_forced_processed % timer_l.value ().count () % timer_l.unit ()));
 	}
 }
 

nano/node/blockprocessor.hpp

@@ -39,7 +39,7 @@ public:
 	void add (std::shared_ptr<nano::block>, uint64_t = 0);
 	void force (std::shared_ptr<nano::block>);
 	void wait_write ();
-	bool should_log (bool);
+	bool should_log ();
 	bool have_blocks ();
 	void process_blocks ();
 	nano::process_return process_one (nano::write_transaction const &, nano::unchecked_info, const bool = false, const bool = false);

nano/node/election.cpp

@@ -9,7 +9,6 @@ using namespace std::chrono;
 int constexpr nano::election::passive_duration_factor;
 int constexpr nano::election::active_duration_factor;
 int constexpr nano::election::confirmed_duration_factor;
-int constexpr nano::election::confirmed_duration_factor_saturated;
 
 std::chrono::milliseconds nano::election::base_latency () const
 {
@@ -249,7 +248,7 @@ void nano::election::broadcast_block (nano::confirmation_solicitor & solicitor_a
 	}
 }
 
-bool nano::election::transition_time (nano::confirmation_solicitor & solicitor_a, bool const saturated_a)
+bool nano::election::transition_time (nano::confirmation_solicitor & solicitor_a)
 {
 	debug_assert (!node.active.mutex.try_lock ());
 	nano::unique_lock<std::mutex> lock (timepoints_mutex);
@@ -282,7 +281,7 @@ bool nano::election::transition_time (nano::confirmation_solicitor & solicitor_a
 			send_confirm_req (solicitor_a);
 			break;
 		case nano::election::state_t::confirmed:
-			if (base_latency () * (saturated_a ? confirmed_duration_factor_saturated : confirmed_duration_factor) < std::chrono::steady_clock::now () - state_start)
+			if (base_latency () * confirmed_duration_factor < std::chrono::steady_clock::now () - state_start)
 			{
 				result = true;
 				state_change (nano::election::state_t::confirmed, nano::election::state_t::expired_confirmed);

nano/node/election.hpp

@@ -48,8 +48,7 @@ private: // State management
 	};
 	static int constexpr passive_duration_factor = 5;
 	static int constexpr active_duration_factor = 30;
-	static int constexpr confirmed_duration_factor = 10;
-	static int constexpr confirmed_duration_factor_saturated = 1;
+	static int constexpr confirmed_duration_factor = 5;
 	std::atomic<nano::election::state_t> state_m = { state_t::idle };
 
 	// Protects state_start, last_vote and last_block
@@ -82,7 +81,7 @@ public:
 	void insert_inactive_votes_cache (nano::block_hash const &);
 
 public: // State transitions
-	bool transition_time (nano::confirmation_solicitor &, bool const saturated);
+	bool transition_time (nano::confirmation_solicitor &);
 	void transition_passive ();
 	void transition_active ();
 

nano/node/json_handler.cpp

@@ -1851,6 +1851,7 @@ void nano::json_handler::confirmation_info ()
 	if (!root.decode_hex (root_text))
 	{
 		auto election (node.active.election (root));
+		nano::lock_guard<std::mutex> guard (node.active.mutex);
 		if (election != nullptr && !election->confirmed ())
 		{
 			response_l.put ("announcements", std::to_string (election->confirmation_request_count));

nano/node/nodeconfig.hpp

@@ -82,7 +82,7 @@ public:
 	/** Timeout for initiated async operations */
 	std::chrono::seconds tcp_io_timeout{ (network_params.network.is_test_network () && !is_sanitizer_build) ? std::chrono::seconds (5) : std::chrono::seconds (15) };
 	std::chrono::nanoseconds pow_sleep_interval{ 0 };
-	size_t active_elections_size{ 10000 };
+	size_t active_elections_size{ 50000 };
 	/** Default maximum incoming TCP connections, including realtime network & bootstrap */
 	unsigned tcp_incoming_connections_max{ 1024 };
 	bool use_memory_pools{ true };