From 8c7cb21b9102107b2a4f79d108950cded40129dd Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Piotr=20W=C3=B3jcik?= <3044353+pwojcikdev@users.noreply.github.com> Date: Sun, 20 Apr 2025 22:49:51 +0200 Subject: [PATCH] Periodically log queue sizes for node components (#4890) --- nano/lib/logging_enums.hpp | 3 +++ nano/nano_node/daemon.cpp | 2 +- nano/nano_rpc/entry.cpp | 2 +- nano/node/block_processor.cpp | 2 +- nano/node/cementing_set.cpp | 7 ++++++ nano/node/cementing_set.hpp | 3 +++ nano/node/local_block_broadcaster.cpp | 5 ++++ nano/node/local_block_broadcaster.hpp | 2 ++ nano/node/message_processor.cpp | 5 ++++ nano/node/message_processor.hpp | 3 +++ nano/node/node.cpp | 2 +- nano/node/request_aggregator.cpp | 5 ++++ nano/node/request_aggregator.hpp | 3 +++ nano/node/vote_generator.cpp | 36 +++++++++++++++++++-------- nano/node/vote_generator.hpp | 4 +++ nano/node/vote_processor.cpp | 14 +++++++++++ nano/node/vote_processor.hpp | 5 ++++ nano/node/vote_rebroadcaster.cpp | 9 +++++++ nano/node/vote_rebroadcaster.hpp | 3 +++ nano/secure/ledger.cpp | 10 ++++---- 20 files changed, 106 insertions(+), 19 deletions(-) diff --git a/nano/lib/logging_enums.hpp b/nano/lib/logging_enums.hpp index 8ad6f9040..a00c594e6 100644 --- a/nano/lib/logging_enums.hpp +++ b/nano/lib/logging_enums.hpp @@ -74,8 +74,10 @@ enum class type txn_tracker, gap_cache, vote_processor, + vote_cache_processor, election_scheduler, vote_generator, + vote_generator_final, rep_tiers, syn_cookies, thread_runner, @@ -88,6 +90,7 @@ enum class type cementing_set, bounded_backlog, request_aggregator, + vote_rebroadcaster, // bootstrap bulk_pull_client, diff --git a/nano/nano_node/daemon.cpp b/nano/nano_node/daemon.cpp index 3e08aabe8..7801281a0 100644 --- a/nano/nano_node/daemon.cpp +++ b/nano/nano_node/daemon.cpp @@ -219,5 +219,5 @@ void nano::daemon::run (std::filesystem::path const & data_path, nano::node_flag logger.critical (nano::log::type::daemon, "Error while running node: {}", e.what ()); } - logger.info (nano::log::type::daemon, "Daemon stopped"); + logger.info (nano::log::type::daemon, "Stopped"); } diff --git a/nano/nano_rpc/entry.cpp b/nano/nano_rpc/entry.cpp index f576dee8c..2bd612266 100644 --- a/nano/nano_rpc/entry.cpp +++ b/nano/nano_rpc/entry.cpp @@ -78,7 +78,7 @@ void run (std::filesystem::path const & data_path, std::vector cons logger.critical (nano::log::type::daemon_rpc, "Error deserializing config: {}", error.get_message ()); } - logger.info (nano::log::type::daemon_rpc, "Daemon stopped (RPC)"); + logger.info (nano::log::type::daemon_rpc, "Stopped"); } } diff --git a/nano/node/block_processor.cpp b/nano/node/block_processor.cpp index 67da0d1ec..b20f13477 100644 --- a/nano/node/block_processor.cpp +++ b/nano/node/block_processor.cpp @@ -232,7 +232,7 @@ void nano::block_processor::run () { if (log_interval.elapse (15s)) { - logger.info (nano::log::type::block_processor, "{} blocks (+ {} forced) in processing queue", + logger.info (nano::log::type::block_processor, "{} blocks ({} forced) in processing queue", queue.size (), queue.size ({ nano::block_source::forced })); } diff --git a/nano/node/cementing_set.cpp b/nano/node/cementing_set.cpp index 931aecf9f..8851e77d2 100644 --- a/nano/node/cementing_set.cpp +++ b/nano/node/cementing_set.cpp @@ -129,6 +129,13 @@ void nano::cementing_set::run () if (!set.empty ()) { + if (log_interval.elapse (15s)) + { + logger.info (nano::log::type::cementing_set, "{} blocks in cementing set, {} deferred", + set.size (), + deferred.size ()); + } + run_batch (lock); debug_assert (!lock.owns_lock ()); lock.lock (); diff --git a/nano/node/cementing_set.hpp b/nano/node/cementing_set.hpp index 1a65a1887..98a869dcf 100644 --- a/nano/node/cementing_set.hpp +++ b/nano/node/cementing_set.hpp @@ -1,5 +1,6 @@ #pragma once +#include #include #include #include @@ -127,5 +128,7 @@ private: std::thread thread; nano::thread_pool workers; + + nano::interval log_interval; }; } diff --git a/nano/node/local_block_broadcaster.cpp b/nano/node/local_block_broadcaster.cpp index 2eff68c25..b7021fd4f 100644 --- a/nano/node/local_block_broadcaster.cpp +++ b/nano/node/local_block_broadcaster.cpp @@ -134,6 +134,11 @@ void nano::local_block_broadcaster::run () debug_assert (lock.owns_lock ()); } + if (log_interval.elapse (15s)) + { + logger.info (nano::log::type::local_block_broadcaster, "{} blocks in broadcasting set", local_blocks.size ()); + } + run_broadcasts (lock); debug_assert (!lock.owns_lock ()); lock.lock (); diff --git a/nano/node/local_block_broadcaster.hpp b/nano/node/local_block_broadcaster.hpp index 57afe8fb4..26f24f20e 100644 --- a/nano/node/local_block_broadcaster.hpp +++ b/nano/node/local_block_broadcaster.hpp @@ -122,5 +122,7 @@ private: nano::condition_variable condition; mutable nano::mutex mutex; std::thread thread; + + nano::interval log_interval; }; } diff --git a/nano/node/message_processor.cpp b/nano/node/message_processor.cpp index b6828f812..ef138085d 100644 --- a/nano/node/message_processor.cpp +++ b/nano/node/message_processor.cpp @@ -115,6 +115,11 @@ void nano::message_processor::run () if (!queue.empty ()) { + if (log_interval.elapse (15s)) + { + logger.info (nano::log::type::message_processor, "{} messages in processing queue", queue.size ()); + } + run_batch (lock); debug_assert (!lock.owns_lock ()); lock.lock (); diff --git a/nano/node/message_processor.hpp b/nano/node/message_processor.hpp index f0bfa8d8c..a48a80b4c 100644 --- a/nano/node/message_processor.hpp +++ b/nano/node/message_processor.hpp @@ -1,5 +1,6 @@ #pragma once +#include #include #include #include @@ -56,5 +57,7 @@ private: mutable nano::mutex mutex; nano::condition_variable condition; std::vector threads; + + nano::interval log_interval; }; } \ No newline at end of file diff --git a/nano/node/node.cpp b/nano/node/node.cpp index fd7b72edf..8d6ab6969 100644 --- a/nano/node/node.cpp +++ b/nano/node/node.cpp @@ -609,7 +609,7 @@ void nano::node::stop () return; } - logger.info (nano::log::type::node, "Node stopping..."); + logger.info (nano::log::type::node, "Stopping..."); tcp_listener.stop (); online_reps.stop (); diff --git a/nano/node/request_aggregator.cpp b/nano/node/request_aggregator.cpp index c59894bc5..2f80e0909 100644 --- a/nano/node/request_aggregator.cpp +++ b/nano/node/request_aggregator.cpp @@ -123,6 +123,11 @@ void nano::request_aggregator::run () if (!queue.empty ()) { + if (log_interval.elapse (15s)) + { + logger.info (nano::log::type::request_aggregator, "{} requests in processing queue", queue.size ()); + } + run_batch (lock); debug_assert (!lock.owns_lock ()); lock.lock (); diff --git a/nano/node/request_aggregator.hpp b/nano/node/request_aggregator.hpp index 1332875c2..2a6432479 100644 --- a/nano/node/request_aggregator.hpp +++ b/nano/node/request_aggregator.hpp @@ -1,5 +1,6 @@ #pragma once +#include #include #include #include @@ -101,5 +102,7 @@ private: nano::condition_variable condition; mutable nano::mutex mutex{ mutex_identifier (mutexes::request_aggregator) }; std::vector threads; + + nano::interval log_interval; }; } diff --git a/nano/node/vote_generator.cpp b/nano/node/vote_generator.cpp index c36460871..593d92754 100644 --- a/nano/node/vote_generator.cpp +++ b/nano/node/vote_generator.cpp @@ -65,7 +65,7 @@ bool nano::vote_generator::should_vote (transaction_variant_t const & transactio should_vote = block != nullptr && ledger.dependents_confirmed (transaction, *block); } - logger.trace (nano::log::type::vote_generator, nano::log::detail::should_vote, + logger.trace (log_type (), nano::log::detail::should_vote, nano::log::arg{ "should_vote", should_vote }, nano::log::arg{ "block", block }, nano::log::arg{ "is_final", is_final }); @@ -292,6 +292,7 @@ void nano::vote_generator::run () nano::unique_lock lock{ mutex }; while (!stopped) { + // Wait for at most vote_generator_delay in case no further notification is received condition.wait_for (lock, config.vote_generator_delay, [this] () { return stopped || broadcast_predicate () || !requests.empty (); }); @@ -301,17 +302,27 @@ void nano::vote_generator::run () return; } - if (broadcast_predicate ()) + if (broadcast_predicate () || !requests.empty ()) { - broadcast (lock); - next_broadcast = std::chrono::steady_clock::now () + config.vote_generator_delay; - } + stats.inc (stat_type (), nano::stat::detail::loop); - if (!requests.empty ()) - { - auto request (requests.front ()); - requests.pop_front (); - reply (lock, std::move (request)); + if (log_interval.elapse (15s)) + { + logger.info (log_type (), "{} candidates, {} requests in processing queue", candidates.size (), requests.size ()); + } + + if (broadcast_predicate ()) + { + broadcast (lock); + next_broadcast = std::chrono::steady_clock::now () + config.vote_generator_delay; + } + + if (!requests.empty ()) + { + auto request (requests.front ()); + requests.pop_front (); + reply (lock, std::move (request)); + } } } } @@ -345,4 +356,9 @@ nano::container_info nano::vote_generator::container_info () const nano::stat::type nano::vote_generator::stat_type () const { return is_final ? nano::stat::type::vote_generator_final : nano::stat::type::vote_generator; +} + +nano::log::type nano::vote_generator::log_type () const +{ + return is_final ? nano::log::type::vote_generator_final : nano::log::type::vote_generator; } \ No newline at end of file diff --git a/nano/node/vote_generator.hpp b/nano/node/vote_generator.hpp index 97c08e47f..0233bf907 100644 --- a/nano/node/vote_generator.hpp +++ b/nano/node/vote_generator.hpp @@ -1,5 +1,6 @@ #pragma once +#include #include #include #include @@ -59,6 +60,7 @@ private: bool broadcast_predicate () const; nano::stat::type stat_type () const; + nano::log::type log_type () const; private: // Dependencies nano::node_config const & config; @@ -84,5 +86,7 @@ private: std::thread thread; std::shared_ptr inproc_channel; nano::processing_queue vote_generation_queue; + + nano::interval log_interval; }; } diff --git a/nano/node/vote_processor.cpp b/nano/node/vote_processor.cpp index eee880e11..8c75407ae 100644 --- a/nano/node/vote_processor.cpp +++ b/nano/node/vote_processor.cpp @@ -136,6 +136,15 @@ void nano::vote_processor::run () if (!queue.empty ()) { + if (log_interval.elapse (15s)) + { + logger.info (nano::log::type::vote_processor, "{} votes (tier 3: {}, tier 2: {}, tier 1: {}) in processing queue", + queue.size (), + queue.size ({ nano::rep_tier::tier_3 }), + queue.size ({ nano::rep_tier::tier_2 }), + queue.size ({ nano::rep_tier::tier_1 })); + } + run_batch (lock); debug_assert (!lock.owns_lock ()); lock.lock (); @@ -314,6 +323,11 @@ void nano::vote_cache_processor::run () if (!triggered.empty ()) { + if (log_interval.elapse (15s)) + { + logger.info (nano::log::type::vote_cache_processor, "{} hashes in processing queue", triggered.size ()); + } + run_batch (lock); debug_assert (!lock.owns_lock ()); lock.lock (); diff --git a/nano/node/vote_processor.hpp b/nano/node/vote_processor.hpp index c50d43a9a..230b2e93b 100644 --- a/nano/node/vote_processor.hpp +++ b/nano/node/vote_processor.hpp @@ -1,5 +1,6 @@ #pragma once +#include #include #include #include @@ -81,6 +82,8 @@ private: nano::condition_variable condition; mutable nano::mutex mutex{ mutex_identifier (mutexes::vote_processor) }; std::vector threads; + + nano::interval log_interval; }; class vote_cache_processor final @@ -118,5 +121,7 @@ private: nano::condition_variable condition; mutable nano::mutex mutex; std::thread thread; + + nano::interval log_interval; }; } diff --git a/nano/node/vote_rebroadcaster.cpp b/nano/node/vote_rebroadcaster.cpp index 79f103368..819c0e11e 100644 --- a/nano/node/vote_rebroadcaster.cpp +++ b/nano/node/vote_rebroadcaster.cpp @@ -206,6 +206,15 @@ void nano::vote_rebroadcaster::run () if (!queue.empty ()) { + if (log_interval.elapse (15s)) + { + logger.info (nano::log::type::vote_rebroadcaster, "{} votes (tier 3: {}, tier 2: {}, tier 1: {}) in rebroadcast queue", + queue.size (), + queue.size ({ nano::rep_tier::tier_3 }), + queue.size ({ nano::rep_tier::tier_2 }), + queue.size ({ nano::rep_tier::tier_1 })); + } + auto [vote, tier] = next (); lock.unlock (); diff --git a/nano/node/vote_rebroadcaster.hpp b/nano/node/vote_rebroadcaster.hpp index 61b512eef..44c5b9fec 100644 --- a/nano/node/vote_rebroadcaster.hpp +++ b/nano/node/vote_rebroadcaster.hpp @@ -1,5 +1,6 @@ #pragma once +#include #include #include #include @@ -170,5 +171,7 @@ private: std::condition_variable condition; mutable std::mutex mutex; std::thread thread; + + nano::interval log_interval; }; } \ No newline at end of file diff --git a/nano/secure/ledger.cpp b/nano/secure/ledger.cpp index db6a4274a..0a8fc854b 100644 --- a/nano/secure/ledger.cpp +++ b/nano/secure/ledger.cpp @@ -799,11 +799,11 @@ void nano::ledger::initialize (nano::generate_cache_flags const & generate_cache cache.pruned_count = store.pruned.count (transaction); } - logger.info (nano::log::type::ledger, "Block count: {:>10}", cache.block_count.load ()); - logger.info (nano::log::type::ledger, "Cemented count: {:>10}", cache.cemented_count.load ()); - logger.info (nano::log::type::ledger, "Account count: {:>10}", cache.account_count.load ()); - logger.info (nano::log::type::ledger, "Pruned count: {:>10}", cache.pruned_count.load ()); - logger.info (nano::log::type::ledger, "Representative count: {}", cache.rep_weights.size ()); + logger.info (nano::log::type::ledger, "Block count: {:>11}", cache.block_count.load ()); + logger.info (nano::log::type::ledger, "Cemented count: {:>11}", cache.cemented_count.load ()); + logger.info (nano::log::type::ledger, "Account count: {:>11}", cache.account_count.load ()); + logger.info (nano::log::type::ledger, "Pruned count: {:>11}", cache.pruned_count.load ()); + logger.info (nano::log::type::ledger, "Representative count: {:>5}", cache.rep_weights.size ()); } bool nano::ledger::unconfirmed_exists (secure::transaction const & transaction, nano::block_hash const & hash)