Stats & logs

nano/core_test/node.cpp

@@ -2911,7 +2911,7 @@ TEST (node, block_processor_reject_state)
 	send1->signature.bytes[0] ^= 1;
 	ASSERT_FALSE (node.ledger.block_or_pruned_exists (send1->hash ()));
 	node.process_active (send1);
-	ASSERT_TIMELY_EQ (5s, 1, node.stats.count (nano::stat::type::blockprocessor, nano::stat::detail::bad_signature));
+	ASSERT_TIMELY_EQ (5s, 1, node.stats.count (nano::stat::type::blockprocessor_result, nano::stat::detail::bad_signature));
 	ASSERT_FALSE (node.ledger.block_or_pruned_exists (send1->hash ()));
 	auto send2 = builder.make_block ()
 				 .account (nano::dev::genesis_key.pub)

nano/lib/stats_enums.hpp

@@ -36,7 +36,8 @@ enum class type : uint8_t
 	vote_cache,
 	hinting,
 	blockprocessor,
-	blockprocessor_sources,
+	blockprocessor_source,
+	blockprocessor_result,
 	bootstrap_server,
 	active,
 	active_started,
@@ -112,7 +113,12 @@ enum class detail : uint8_t
 	representative_mismatch,
 	block_position,
 
-	// blockprocessor result
+	// blockprocessor
+	process_blocking,
+	process_blocking_timeout,
+	force,
+
+	// block source
 	live,
 	bootstrap,
 	bootstrap_legacy,

nano/node/blockprocessor.cpp

@@ -88,14 +88,22 @@ void nano::block_processor::add (std::shared_ptr<nano::block> const & block, blo
 		node.stats.inc (nano::stat::type::blockprocessor, nano::stat::detail::insufficient_work);
 		return;
 	}
+
+	node.stats.inc (nano::stat::type::blockprocessor, nano::stat::detail::process);
+	node.logger.debug (nano::log::type::blockprocessor, "Processing block (async): {} (source: {})", block->hash ().to_string (), to_string (source));
+
 	add_impl (block, context{ source });
 }
 
 std::optional<nano::process_return> nano::block_processor::add_blocking (std::shared_ptr<nano::block> const & block, block_source const source)
 {
+	node.stats.inc (nano::stat::type::blockprocessor, nano::stat::detail::process_blocking);
+	node.logger.debug (nano::log::type::blockprocessor, "Processing block (blocking): {} (source: {})", block->hash ().to_string (), to_string (source));
+
 	context ctx{ source };
 	auto future = ctx.get_future ();
 	add_impl (block, std::move (ctx));
+
 	try
 	{
 		auto status = future.wait_for (node.config.block_process_timeout);
@@ -107,10 +115,25 @@ std::optional<nano::process_return> nano::block_processor::add_blocking (std::sh
 	}
 	catch (std::future_error const &)
 	{
+		node.stats.inc (nano::stat::type::blockprocessor, nano::stat::detail::process_blocking_timeout);
+		node.logger.error (nano::log::type::blockprocessor, "Timeout processing block: {}", block->hash ().to_string ());
 	}
+
 	return std::nullopt;
 }
 
+void nano::block_processor::force (std::shared_ptr<nano::block> const & block_a)
+{
+	node.stats.inc (nano::stat::type::blockprocessor, nano::stat::detail::force);
+	node.logger.debug (nano::log::type::blockprocessor, "Forcing block: {}", block_a->hash ().to_string ());
+
+	{
+		nano::lock_guard<nano::mutex> lock{ mutex };
+		forced.emplace_back (entry{ block_a, context{ block_source::forced } });
+	}
+	condition.notify_all ();
+}
+
 void nano::block_processor::rollback_competitor (store::write_transaction const & transaction, nano::block const & block)
 {
 	auto hash = block.hash ();
@@ -143,15 +166,6 @@ void nano::block_processor::rollback_competitor (store::write_transaction const
 	}
 }
 
-void nano::block_processor::force (std::shared_ptr<nano::block> const & block_a)
-{
-	{
-		nano::lock_guard<nano::mutex> lock{ mutex };
-		forced.emplace_back (entry{ block_a, context{ block_source::forced } });
-	}
-	condition.notify_all ();
-}
-
 void nano::block_processor::process_blocks ()
 {
 	nano::unique_lock<nano::mutex> lock{ mutex };
@@ -304,8 +318,8 @@ nano::process_return nano::block_processor::process_one (store::write_transactio
 	auto const hash = block->hash ();
 	nano::process_return result = node.ledger.process (transaction_a, *block);
 
-	node.stats.inc (nano::stat::type::blockprocessor, to_stat_detail (result.code));
-	node.stats.inc (nano::stat::type::blockprocessor_sources, to_stat_detail (context.source));
+	node.stats.inc (nano::stat::type::blockprocessor_result, to_stat_detail (result.code));
+	node.stats.inc (nano::stat::type::blockprocessor_source, to_stat_detail (context.source));
 	node.logger.trace (nano::log::type::blockprocessor, nano::log::detail::block_processed,
 	nano::log::arg{ "result", result.code },
 	nano::log::arg{ "source", context.source },
@@ -415,6 +429,11 @@ std::unique_ptr<nano::container_info_component> nano::collect_container_info (bl
 	return composite;
 }
 
+std::string_view nano::to_string (nano::block_source source)
+{
+	return magic_enum::enum_name (source);
+}
+
 nano::stat::detail nano::to_stat_detail (nano::block_source type)
 {
 	auto value = magic_enum::enum_cast<nano::stat::detail> (magic_enum::enum_name (type));

nano/node/blockprocessor.hpp

@@ -31,6 +31,7 @@ enum class block_source
 	forced,
 };
 
+std::string_view to_string (nano::block_source);
 nano::stat::detail to_stat_detail (block_source);
 
 /**