Improve process_receive_many timing logging (#1476)

rai/node/logging.cpp

@@ -20,6 +20,7 @@ log_rpc_value (true),
 bulk_pull_logging_value (false),
 work_generation_time_value (true),
 upnp_details_logging_value (false),
+timing_logging_value (false),
 log_to_cerr_value (false),
 flush (true),
 max_size (16 * 1024 * 1024),
@@ -59,6 +60,7 @@ void rai::logging::serialize_json (boost::property_tree::ptree & tree_a) const
 	tree_a.put ("bulk_pull", bulk_pull_logging_value);
 	tree_a.put ("work_generation_time", work_generation_time_value);
 	tree_a.put ("upnp_details", upnp_details_logging_value);
+	tree_a.put ("timing", timing_logging_value);
 	tree_a.put ("log_to_cerr", log_to_cerr_value);
 	tree_a.put ("max_size", max_size);
 	tree_a.put ("rotation_size", rotation_size);
@@ -83,6 +85,7 @@ bool rai::logging::upgrade_json (unsigned version_a, boost::property_tree::ptree
 			result = true;
 		case 4:
 			tree_a.put ("upnp_details", "false");
+			tree_a.put ("timing", "false");
 			result = true;
 		case 5:
 			break;
@@ -126,6 +129,7 @@ bool rai::logging::deserialize_json (bool & upgraded_a, boost::property_tree::pt
 		bulk_pull_logging_value = tree_a.get<bool> ("bulk_pull");
 		work_generation_time_value = tree_a.get<bool> ("work_generation_time");
 		upnp_details_logging_value = tree_a.get<bool> ("upnp_details");
+		timing_logging_value = tree_a.get<bool> ("timing");
 		log_to_cerr_value = tree_a.get<bool> ("log_to_cerr");
 		max_size = tree_a.get<uintmax_t> ("max_size");
 		rotation_size = tree_a.get<uintmax_t> ("rotation_size", 4194304);
@@ -218,6 +222,11 @@ bool rai::logging::upnp_details_logging () const
 	return upnp_details_logging_value;
 }
 
+bool rai::logging::timing_logging () const
+{
+	return timing_logging_value;
+}
+
 bool rai::logging::log_to_cerr () const
 {
 	return log_to_cerr_value;

rai/node/logging.hpp

@@ -29,6 +29,7 @@ class logging
 	bool node_lifetime_tracing () const;
 	bool insufficient_work_logging () const;
 	bool upnp_details_logging () const;
+	bool timing_logging () const;
 	bool log_rpc () const;
 	bool bulk_pull_logging () const;
 	bool callback_logging () const;
@@ -51,6 +52,7 @@ class logging
 	bool bulk_pull_logging_value;
 	bool work_generation_time_value;
 	bool upnp_details_logging_value;
+	bool timing_logging_value;
 	bool log_to_cerr_value;
 	bool flush;
 	uintmax_t max_size;

rai/node/node.cpp

@@ -1280,11 +1280,11 @@ void rai::block_processor::process_blocks ()
 	}
 }
 
-bool rai::block_processor::should_log ()
+bool rai::block_processor::should_log (bool first_time)
 {
 	auto result (false);
 	auto now (std::chrono::steady_clock::now ());
-	if (next_log < now)
+	if (first_time || next_log < now)
 	{
 		next_log = now + std::chrono::seconds (15);
 		result = true;
@@ -1301,6 +1301,7 @@ bool rai::block_processor::have_blocks ()
 void rai::block_processor::verify_state_blocks (std::unique_lock<std::mutex> & lock_a, size_t max_count)
 {
 	assert (!mutex.try_lock ());
+	auto start_time (std::chrono::steady_clock::now ());
 	std::deque<std::pair<std::shared_ptr<rai::block>, std::chrono::steady_clock::time_point>> items;
 	if (max_count == std::numeric_limits<size_t>::max () || max_count >= state_blocks.size ())
 	{
@@ -1351,6 +1352,14 @@ void rai::block_processor::verify_state_blocks (std::unique_lock<std::mutex> & l
 		}
 		items.pop_front ();
 	}
+	if (node.config.logging.timing_logging ())
+	{
+		auto end_time (std::chrono::steady_clock::now ());
+		auto elapsed_time_ms (std::chrono::duration_cast<std::chrono::milliseconds> (end_time - start_time));
+		auto elapsed_time_ms_int (elapsed_time_ms.count ());
+
+		BOOST_LOG (node.log) << boost::str (boost::format ("Batch verified %1% state blocks in %2% milliseconds") % size % elapsed_time_ms_int);
+	}
 }
 
 void rai::block_processor::process_receive_many (std::unique_lock<std::mutex> & lock_a)
@@ -1367,11 +1376,30 @@ void rai::block_processor::process_receive_many (std::unique_lock<std::mutex> &
 	start_time = std::chrono::steady_clock::now ();
 	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 ()) && std::chrono::steady_clock::now () - start_time < node.config.block_processor_batch_max_time)
 	{
-		if ((blocks.size () + state_blocks.size ()) > 64 && should_log ())
+		auto log_this_record (false);
+		if (node.config.logging.timing_logging ())
+		{
+			if (should_log (first_time))
+			{
+				log_this_record = true;
+			}
+		}
+		else
 		{
-			BOOST_LOG (node.log) << boost::str (boost::format ("%1% blocks in processing queue") % (blocks.size () + state_blocks.size ()));
+			if (((blocks.size () + state_blocks.size () + forced.size ()) > 64 && should_log (false)))
+			{
+				log_this_record = true;
+			}
+		}
+
+		if (log_this_record)
+		{
+			first_time = false;
+			BOOST_LOG (node.log) << boost::str (boost::format ("%1% blocks (+ %2% state blocks) (+ %3% forced) in processing queue") % blocks.size () % state_blocks.size () % forced.size ());
 		}
 		std::pair<std::shared_ptr<rai::block>, std::chrono::steady_clock::time_point> block;
 		bool force (false);
@@ -1386,6 +1414,7 @@ void rai::block_processor::process_receive_many (std::unique_lock<std::mutex> &
 			block = std::make_pair (forced.front (), std::chrono::steady_clock::now ());
 			forced.pop_front ();
 			force = true;
+			number_of_forced_processed++;
 		}
 		lock_a.unlock ();
 		auto hash (block.first->hash ());
@@ -1403,6 +1432,7 @@ void rai::block_processor::process_receive_many (std::unique_lock<std::mutex> &
 		Because of that we should set set validated_state_block as "false" for forced state blocks (!force) */
 		bool validated_state_block (!force && block.first->type () == rai::block_type::state);
 		auto process_result (process_receive_one (transaction, block.first, block.second, validated_state_block));
+		number_of_blocks_processed++;
 		(void)process_result;
 		lock_a.lock ();
 		/* Verify more state blocks if blocks deque is empty
@@ -1413,6 +1443,15 @@ void rai::block_processor::process_receive_many (std::unique_lock<std::mutex> &
 		}
 	}
 	lock_a.unlock ();
+
+	if (node.config.logging.timing_logging ())
+	{
+		auto end_time (std::chrono::steady_clock::now ());
+		auto elapsed_time_ms (std::chrono::duration_cast<std::chrono::milliseconds> (end_time - start_time));
+		auto elapsed_time_ms_int (elapsed_time_ms.count ());
+
+		BOOST_LOG (node.log) << boost::str (boost::format ("Processed %1% blocks (%2% blocks were forced) in %3% milliseconds") % number_of_blocks_processed % number_of_forced_processed % elapsed_time_ms_int);
+	}
 }
 
 rai::process_return rai::block_processor::process_receive_one (rai::transaction const & transaction_a, std::shared_ptr<rai::block> block_a, std::chrono::steady_clock::time_point origination, bool validated_state_block)

rai/node/node.hpp

@@ -422,7 +422,7 @@ class block_processor
 	bool full ();
 	void add (std::shared_ptr<rai::block>, std::chrono::steady_clock::time_point);
 	void force (std::shared_ptr<rai::block>);
-	bool should_log ();
+	bool should_log (bool);
 	bool have_blocks ();
 	void process_blocks ();
 	rai::process_return process_receive_one (rai::transaction const &, std::shared_ptr<rai::block>, std::chrono::steady_clock::time_point = std::chrono::steady_clock::now (), bool = false);