From 2ca651f54b4c11a93482117ad1cf1f6e7c426708 Mon Sep 17 00:00:00 2001 From: Guilherme Lawless Date: Tue, 10 Mar 2020 19:56:54 +0000 Subject: [PATCH] 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 | 33 +++++++++++++++++++++---------- nano/node/active_transactions.hpp | 4 ++++ nano/node/blockprocessor.cpp | 33 ++++++++----------------------- nano/node/blockprocessor.hpp | 2 +- nano/node/election.cpp | 5 ++--- nano/node/election.hpp | 5 ++--- nano/node/json_handler.cpp | 1 + nano/node/nodeconfig.hpp | 2 +- 8 files changed, 42 insertions(+), 43 deletions(-) diff --git a/nano/node/active_transactions.cpp b/nano/node/active_transactions.cpp index ce3fb047b..35f5a76d4 100644 --- a/nano/node/active_transactions.cpp +++ b/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 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 & nano::confirmation_solicitor solicitor (node.network, node.network_params.network); solicitor.prepare (node.rep_crawler.principal_representatives (std::numeric_limits::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 (); - size_t count_l{ 0 }; + auto & sorted_roots_l (roots.get ()); + 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 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 & * 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 & 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 () diff --git a/nano/node/active_transactions.hpp b/nano/node/active_transactions.hpp index d1ffcb3d0..fee740091 100644 --- a/nano/node/active_transactions.hpp +++ b/nano/node/active_transactions.hpp @@ -155,6 +155,10 @@ private: bool started{ false }; std::atomic 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; diff --git a/nano/node/blockprocessor.cpp b/nano/node/blockprocessor.cpp index 5447645f3..583a44662 100644 --- a/nano/node/blockprocessor.cpp +++ b/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 & } 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 & 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 & 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 ())); } } diff --git a/nano/node/blockprocessor.hpp b/nano/node/blockprocessor.hpp index 1395400d0..eb4416e8f 100644 --- a/nano/node/blockprocessor.hpp +++ b/nano/node/blockprocessor.hpp @@ -39,7 +39,7 @@ public: void add (std::shared_ptr, uint64_t = 0); void force (std::shared_ptr); 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); diff --git a/nano/node/election.cpp b/nano/node/election.cpp index 09ae2f2b2..e85892340 100644 --- a/nano/node/election.cpp +++ b/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 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); diff --git a/nano/node/election.hpp b/nano/node/election.hpp index 16b500b98..117d70ddf 100644 --- a/nano/node/election.hpp +++ b/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 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 (); diff --git a/nano/node/json_handler.cpp b/nano/node/json_handler.cpp index e05e32df2..0a34ee257 100644 --- a/nano/node/json_handler.cpp +++ b/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 guard (node.active.mutex); if (election != nullptr && !election->confirmed ()) { response_l.put ("announcements", std::to_string (election->confirmation_request_count)); diff --git a/nano/node/nodeconfig.hpp b/nano/node/nodeconfig.hpp index 2baee4d86..b61179055 100644 --- a/nano/node/nodeconfig.hpp +++ b/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 };