From 0a198cf12da108a1cafd3e3c1b93040332f0e122 Mon Sep 17 00:00:00 2001 From: Guilherme Lawless Date: Fri, 6 Mar 2020 10:22:40 +0000 Subject: [PATCH 01/10] Confirmed to expiry fixed at 5 seconds --- nano/node/active_transactions.cpp | 2 +- nano/node/election.cpp | 5 ++--- nano/node/election.hpp | 5 ++--- 3 files changed, 5 insertions(+), 7 deletions(-) diff --git a/nano/node/active_transactions.cpp b/nano/node/active_transactions.cpp index 6161501d49..f419adfcd5 100644 --- a/nano/node/active_transactions.cpp +++ b/nano/node/active_transactions.cpp @@ -247,7 +247,7 @@ void nano::active_transactions::request_confirm (nano::unique_lock & { 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)) + if (overflow_l || election_l->transition_time (solicitor)) { election_l->clear_blocks (); i = sorted_roots_l.erase (i); diff --git a/nano/node/election.cpp b/nano/node/election.cpp index 8481bb0456..ca13d1e9bc 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 { @@ -256,7 +255,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); @@ -289,7 +288,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 6ea73c11ce..b20b82a121 100644 --- a/nano/node/election.hpp +++ b/nano/node/election.hpp @@ -48,8 +48,7 @@ class election final : public std::enable_shared_from_this }; static int constexpr passive_duration_factor = 5; static int constexpr active_duration_factor = 20; - 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 @@ -83,7 +82,7 @@ class election final : public std::enable_shared_from_this 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 (); From 46bc1dfe8abf4b4660a98d0694f758c317840b73 Mon Sep 17 00:00:00 2001 From: Guilherme Lawless Date: Fri, 6 Mar 2020 10:30:04 +0000 Subject: [PATCH 02/10] Only increase the election counter for unconfirmed elections --- nano/node/active_transactions.cpp | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/nano/node/active_transactions.cpp b/nano/node/active_transactions.cpp index f419adfcd5..d8f1d0f70f 100644 --- a/nano/node/active_transactions.cpp +++ b/nano/node/active_transactions.cpp @@ -243,10 +243,11 @@ 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;) { 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)); + count_l += !election_l->confirmed (); + 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)) { election_l->clear_blocks (); From c8754a0d1a18ef0c235e72fcef6cccff153edd93 Mon Sep 17 00:00:00 2001 From: Guilherme Lawless Date: Fri, 6 Mar 2020 11:28:08 +0000 Subject: [PATCH 03/10] Increase default active elections size to 50k but only perform a full check periodically --- nano/node/active_transactions.cpp | 19 +++++++++++++------ nano/node/active_transactions.hpp | 4 ++++ nano/node/nodeconfig.hpp | 2 +- 3 files changed, 18 insertions(+), 7 deletions(-) diff --git a/nano/node/active_transactions.cpp b/nano/node/active_transactions.cpp index d8f1d0f70f..7d11bd24c0 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); @@ -230,11 +231,11 @@ void nano::active_transactions::request_confirm (nano::unique_lock & nano::confirmation_solicitor solicitor (node.network, node.network_params.network); solicitor.prepare (node.rep_crawler.representatives (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 count_l (0); /* * Loop through active elections in descending order of proof-of-work difficulty, requesting confirmation @@ -243,7 +244,7 @@ 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;) + for (auto i = sorted_roots_l.begin (), n = sorted_roots_l.end (); i != n && count_l < this_loop_target_l;) { auto & election_l (i->election); count_l += !election_l->confirmed (); @@ -261,6 +262,12 @@ 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 (); + } } void nano::active_transactions::request_loop () diff --git a/nano/node/active_transactions.hpp b/nano/node/active_transactions.hpp index d1ffcb3d09..fee740091a 100644 --- a/nano/node/active_transactions.hpp +++ b/nano/node/active_transactions.hpp @@ -155,6 +155,10 @@ class active_transactions final 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/nodeconfig.hpp b/nano/node/nodeconfig.hpp index dab89a6c38..77e1e909a9 100644 --- a/nano/node/nodeconfig.hpp +++ b/nano/node/nodeconfig.hpp @@ -82,7 +82,7 @@ class node_config /** 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 }; From c93d2a26b0abd5e1dda905cb57505ea9be79666b Mon Sep 17 00:00:00 2001 From: Guilherme Lawless Date: Fri, 6 Mar 2020 12:54:21 +0000 Subject: [PATCH 04/10] Add timing logging for large number of elections (every 5 seconds max) --- nano/node/active_transactions.cpp | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/nano/node/active_transactions.cpp b/nano/node/active_transactions.cpp index 7d11bd24c0..712c7718b3 100644 --- a/nano/node/active_transactions.cpp +++ b/nano/node/active_transactions.cpp @@ -236,6 +236,7 @@ void nano::active_transactions::request_confirm (nano::unique_lock & 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 count_l (0); + nano::timer elapsed (nano::timer_state::started); /* * Loop through active elections in descending order of proof-of-work difficulty, requesting confirmation @@ -267,6 +268,10 @@ void nano::active_transactions::request_confirm (nano::unique_lock & 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 - count_l) % elapsed.value ().count () % elapsed.unit ())); + } } } From 380255a9adbfac9502ef3b90822d948b245c87fd Mon Sep 17 00:00:00 2001 From: Guilherme Lawless Date: Fri, 6 Mar 2020 12:55:02 +0000 Subject: [PATCH 05/10] Adjust timing logging for block processor --- nano/node/blockprocessor.cpp | 33 ++++++++------------------------- nano/node/blockprocessor.hpp | 2 +- 2 files changed, 9 insertions(+), 26 deletions(-) diff --git a/nano/node/blockprocessor.cpp b/nano/node/blockprocessor.cpp index 5447645f39..59a22c0306 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 + std::chrono::seconds (2); 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 1395400d00..eb4416e8f9 100644 --- a/nano/node/blockprocessor.hpp +++ b/nano/node/blockprocessor.hpp @@ -39,7 +39,7 @@ class block_processor final 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); From ac242efe89a962d4a6725256bce59c056749d94a Mon Sep 17 00:00:00 2001 From: Guilherme Lawless Date: Mon, 9 Mar 2020 10:08:18 +0000 Subject: [PATCH 06/10] Tune search_frontiers such that therre are no delays in aggressive mode but also not too many added --- nano/node/active_transactions.cpp | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/nano/node/active_transactions.cpp b/nano/node/active_transactions.cpp index 712c7718b3..a465594e7b 100644 --- a/nano/node/active_transactions.cpp +++ b/nano/node/active_transactions.cpp @@ -62,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. From 32092f282ec3bc73eb80fa93e151cc34186ec30e Mon Sep 17 00:00:00 2001 From: Guilherme Lawless Date: Mon, 9 Mar 2020 18:27:14 +0000 Subject: [PATCH 07/10] Add erroneously removed mutex lock in https://github.com/nanocurrency/nano-node/pull/2619 --- nano/node/json_handler.cpp | 1 + 1 file changed, 1 insertion(+) diff --git a/nano/node/json_handler.cpp b/nano/node/json_handler.cpp index e05e32df21..0a34ee2578 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)); From 1c8df9a595f0fe0515a55b86a0b2dae464724ab5 Mon Sep 17 00:00:00 2001 From: Guilherme Lawless Date: Mon, 9 Mar 2020 18:41:02 +0000 Subject: [PATCH 08/10] Feedback on variable name --- nano/node/active_transactions.cpp | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/nano/node/active_transactions.cpp b/nano/node/active_transactions.cpp index a465594e7b..515d1ce09a 100644 --- a/nano/node/active_transactions.cpp +++ b/nano/node/active_transactions.cpp @@ -235,7 +235,7 @@ void nano::active_transactions::request_confirm (nano::unique_lock & 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 count_l (0); + size_t unconfirmed_count_l (0); nano::timer elapsed (nano::timer_state::started); /* @@ -245,11 +245,11 @@ 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 < this_loop_target_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); - count_l += !election_l->confirmed (); - 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)); + 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 (); @@ -270,7 +270,7 @@ void nano::active_transactions::request_confirm (nano::unique_lock & 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 - count_l) % elapsed.value ().count () % elapsed.unit ())); + 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 ())); } } } From 97e8c3df9749fc61fa552d575744613e292a322e Mon Sep 17 00:00:00 2001 From: Guilherme Lawless Date: Mon, 9 Mar 2020 19:42:24 +0000 Subject: [PATCH 09/10] Empty commit to fix actions From 8aa98b9e5401078d3ad3a6e124f170a974b995d8 Mon Sep 17 00:00:00 2001 From: Guilherme Lawless Date: Tue, 10 Mar 2020 19:20:43 +0000 Subject: [PATCH 10/10] Tweak blockprocessor logging to resemble previous behavior with disabled timing logging --- nano/node/blockprocessor.cpp | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/nano/node/blockprocessor.cpp b/nano/node/blockprocessor.cpp index 59a22c0306..583a446624 100644 --- a/nano/node/blockprocessor.cpp +++ b/nano/node/blockprocessor.cpp @@ -133,7 +133,7 @@ bool nano::block_processor::should_log () auto now (std::chrono::steady_clock::now ()); if (next_log < now) { - next_log = now + std::chrono::seconds (2); + next_log = now + (node.config.logging.timing_logging () ? std::chrono::seconds (2) : std::chrono::seconds (15)); result = true; } return result;