Reduce logging of component queues (#4897)

nano/lib/config.cpp

@@ -170,6 +170,19 @@ std::array<uint8_t, 2> nano::test_magic_number ()
 	return ret;
 }
 
+size_t nano::queue_warning_threshold ()
+{
+	static auto const env_override = [] () -> std::optional<size_t> {
+		if (auto value = nano::env::get<size_t> ("NANO_QUEUE_WARNING_THRESHOLD"))
+		{
+			std::cerr << "Queue warning threshold overridden by NANO_QUEUE_WARNING_THRESHOLD environment variable: " << *value << std::endl;
+			return *value;
+		}
+		return std::nullopt;
+	}();
+	return env_override.value_or (100);
+}
+
 std::string_view nano::to_string (nano::networks network)
 {
 	switch (network)

nano/lib/config.hpp

@@ -108,6 +108,8 @@ void force_nano_dev_network ();
 
 /** Checks that we are running in test mode */
 bool is_dev_run ();
+
+size_t queue_warning_threshold ();
 }
 
 namespace nano

nano/node/block_processor.cpp

@@ -235,9 +235,9 @@ void nano::block_processor::wait_backlog (nano::unique_lock<nano::mutex> & lock)
 
 	if (log_backlog_interval.elapse (15s))
 	{
-		logger.warn (nano::log::type::block_processor, "Backlog exceeded, throttling for {}ms (backlog size: {})",
+		logger.warn (nano::log::type::block_processor, "Backlog exceeded, throttling for {}ms (backlog factor: {})",
 		throttle_wait.count (),
-		ledger.backlog_count ());
+		factor);
 	}
 
 	stats.inc (nano::stat::type::block_processor, nano::stat::detail::cooldown_backlog);
@@ -274,7 +274,8 @@ void nano::block_processor::run ()
 
 		if (!queue.empty ())
 		{
-			if (log_processing_interval.elapse (15s))
+			// Only log if component is under pressure
+			if (queue.size () > nano::queue_warning_threshold () && log_processing_interval.elapse (15s))
 			{
 				logger.info (nano::log::type::block_processor, "{} blocks ({} forced) in processing queue",
 				queue.size (),

nano/node/cementing_set.cpp

@@ -129,7 +129,8 @@ void nano::cementing_set::run ()
 
 		if (!set.empty ())
 		{
-			if (log_interval.elapse (15s))
+			// Only log if component is under pressure
+			if ((set.size () + deferred.size ()) > nano::queue_warning_threshold () && log_interval.elapse (15s))
 			{
 				logger.info (nano::log::type::cementing_set, "{} blocks in cementing set, {} deferred",
 				set.size (),

nano/node/local_block_broadcaster.cpp

@@ -136,7 +136,7 @@ void nano::local_block_broadcaster::run ()
 
 			if (log_interval.elapse (15s))
 			{
-				logger.info (nano::log::type::local_block_broadcaster, "{} blocks in broadcasting set", local_blocks.size ());
+				logger.info (nano::log::type::local_block_broadcaster, "{} blocks in local broadcasting set", local_blocks.size ());
 			}
 
 			run_broadcasts (lock);

nano/node/message_processor.cpp

@@ -115,7 +115,8 @@ void nano::message_processor::run ()
 
 		if (!queue.empty ())
 		{
-			if (log_interval.elapse (15s))
+			// Only log if component is under pressure
+			if (queue.size () > nano::queue_warning_threshold () && log_interval.elapse (15s))
 			{
 				logger.info (nano::log::type::message_processor, "{} messages in processing queue", queue.size ());
 			}

nano/node/request_aggregator.cpp

@@ -123,7 +123,8 @@ void nano::request_aggregator::run ()
 
 		if (!queue.empty ())
 		{
-			if (log_interval.elapse (15s))
+			// Only log if component is under pressure
+			if (queue.size () > nano::queue_warning_threshold () && log_interval.elapse (15s))
 			{
 				logger.info (nano::log::type::request_aggregator, "{} requests in processing queue", queue.size ());
 			}

nano/node/rpc_callbacks.cpp

@@ -52,9 +52,7 @@ void nano::http_callbacks::setup_callbacks ()
 		{
 			stats.inc (nano::stat::type::http_callbacks_notified, nano::stat::detail::block_confirmed);
 
-			constexpr size_t warning_threshold = 10000;
+			if (workers.queued_tasks () > nano::queue_warning_threshold () && warning_interval.elapse (15s))
-
-			if (workers.queued_tasks () > warning_threshold && warning_interval.elapse (15s))
 			{
 				stats.inc (nano::stat::type::http_callbacks, nano::stat::detail::large_backlog);
 				logger.warn (nano::log::type::http_callbacks, "Backlog of {} http callback notifications to process", workers.queued_tasks ());

nano/node/vote_generator.cpp

@@ -306,7 +306,8 @@ void nano::vote_generator::run ()
 		{
 			stats.inc (stat_type (), nano::stat::detail::loop);
 
-			if (log_interval.elapse (15s))
+			// Only log if component is under pressure
+			if ((candidates.size () + requests.size ()) > nano::queue_warning_threshold () && log_interval.elapse (15s))
 			{
 				logger.info (log_type (), "{} candidates, {} requests in processing queue", candidates.size (), requests.size ());
 			}

nano/node/vote_processor.cpp

@@ -136,7 +136,8 @@ void nano::vote_processor::run ()
 
 		if (!queue.empty ())
 		{
-			if (log_interval.elapse (15s))
+			// Only log if component is under pressure
+			if (queue.size () > nano::queue_warning_threshold () && log_interval.elapse (15s))
 			{
 				logger.info (nano::log::type::vote_processor, "{} votes (tier 3: {}, tier 2: {}, tier 1: {}) in processing queue",
 				queue.size (),
@@ -323,7 +324,8 @@ void nano::vote_cache_processor::run ()
 
 		if (!triggered.empty ())
 		{
-			if (log_interval.elapse (15s))
+			// Only log if component is under pressure
+			if (triggered.size () > nano::queue_warning_threshold () && log_interval.elapse (15s))
 			{
 				logger.info (nano::log::type::vote_cache_processor, "{} hashes in processing queue", triggered.size ());
 			}

nano/node/vote_rebroadcaster.cpp

@@ -206,7 +206,8 @@ void nano::vote_rebroadcaster::run ()
 
 		if (!queue.empty ())
 		{
-			if (log_interval.elapse (15s))
+			// Only log if component is under pressure
+			if (queue.size () > nano::queue_warning_threshold () && log_interval.elapse (15s))
 			{
 				logger.info (nano::log::type::vote_rebroadcaster, "{} votes (tier 3: {}, tier 2: {}, tier 1: {}) in rebroadcast queue",
 				queue.size (),