Merge pull request #4887 from pwojcikdev/monitor-improve-logging
Improve monitor logging
This commit is contained in:
		
				commit
				
					
						0e51c11caa
					
				
			
		
					 3 changed files with 33 additions and 32 deletions
				
			
		| 
						 | 
					@ -5,11 +5,11 @@
 | 
				
			||||||
TEST (assert_DeathTest, debug_assert)
 | 
					TEST (assert_DeathTest, debug_assert)
 | 
				
			||||||
{
 | 
					{
 | 
				
			||||||
	debug_assert (true);
 | 
						debug_assert (true);
 | 
				
			||||||
	ASSERT_DEATH (debug_assert (false), ".*Assertion \\(false\\) failed.*");
 | 
						ASSERT_DEATH (debug_assert (false, "test"), ".*Assertion `false` failed: test.*");
 | 
				
			||||||
}
 | 
					}
 | 
				
			||||||
 | 
					
 | 
				
			||||||
TEST (assert_DeathTest, release_assert)
 | 
					TEST (assert_DeathTest, release_assert)
 | 
				
			||||||
{
 | 
					{
 | 
				
			||||||
	release_assert (true);
 | 
						release_assert (true);
 | 
				
			||||||
	ASSERT_DEATH (release_assert (false), ".*Assertion \\(false\\) failed.*");
 | 
						ASSERT_DEATH (release_assert (false, "test"), ".*Assertion `false` failed: test.*");
 | 
				
			||||||
}
 | 
					}
 | 
				
			||||||
| 
						 | 
					@ -14,11 +14,12 @@
 | 
				
			||||||
void assert_internal (char const * check_expr, char const * func, char const * file, unsigned int line, bool is_release_assert, std::string_view error_msg)
 | 
					void assert_internal (char const * check_expr, char const * func, char const * file, unsigned int line, bool is_release_assert, std::string_view error_msg)
 | 
				
			||||||
{
 | 
					{
 | 
				
			||||||
	std::stringstream ss;
 | 
						std::stringstream ss;
 | 
				
			||||||
	ss << "Assertion (" << check_expr << ") failed";
 | 
						ss << "Assertion `" << check_expr << "` failed";
 | 
				
			||||||
	if (!error_msg.empty ())
 | 
						if (!error_msg.empty ())
 | 
				
			||||||
	{
 | 
						{
 | 
				
			||||||
		ss << ": " << error_msg << "\n";
 | 
							ss << ": " << error_msg;
 | 
				
			||||||
	}
 | 
						}
 | 
				
			||||||
 | 
						ss << "\n";
 | 
				
			||||||
	ss << file << ":" << line << " [" << func << "]"
 | 
						ss << file << ":" << line << " [" << func << "]"
 | 
				
			||||||
	   << "'\n";
 | 
						   << "'\n";
 | 
				
			||||||
 | 
					
 | 
				
			||||||
| 
						 | 
					
 | 
				
			||||||
| 
						 | 
					@ -64,28 +64,31 @@ void nano::monitor::run_one ()
 | 
				
			||||||
	// - election stats over last 5m (confirmed, dropped)
 | 
						// - election stats over last 5m (confirmed, dropped)
 | 
				
			||||||
 | 
					
 | 
				
			||||||
	auto const now = std::chrono::steady_clock::now ();
 | 
						auto const now = std::chrono::steady_clock::now ();
 | 
				
			||||||
 | 
					
 | 
				
			||||||
	auto blocks_cemented = node.ledger.cemented_count ();
 | 
						auto blocks_cemented = node.ledger.cemented_count ();
 | 
				
			||||||
	auto blocks_total = node.ledger.block_count ();
 | 
						auto blocks_total = node.ledger.block_count ();
 | 
				
			||||||
 | 
					
 | 
				
			||||||
	// Wait for node to warm up before logging
 | 
						// TODO: Maybe emphasize somehow that confirmed doesn't need to be equal to total; backlog is OK
 | 
				
			||||||
 | 
						logger.info (nano::log::type::monitor, "Blocks confirmed: {} | total: {} (backlog: {})",
 | 
				
			||||||
 | 
						blocks_cemented,
 | 
				
			||||||
 | 
						blocks_total,
 | 
				
			||||||
 | 
						blocks_total - blocks_cemented);
 | 
				
			||||||
 | 
					
 | 
				
			||||||
 | 
						// Wait for node to warm up before logging rates
 | 
				
			||||||
	if (last_time != std::chrono::steady_clock::time_point{})
 | 
						if (last_time != std::chrono::steady_clock::time_point{})
 | 
				
			||||||
	{
 | 
						{
 | 
				
			||||||
		// TODO: Maybe emphasize somehow that confirmed doesn't need to be equal to total; backlog is OK
 | 
					 | 
				
			||||||
		logger.info (nano::log::type::monitor, "Blocks confirmed: {} | total: {}",
 | 
					 | 
				
			||||||
		blocks_cemented,
 | 
					 | 
				
			||||||
		blocks_total);
 | 
					 | 
				
			||||||
 | 
					 | 
				
			||||||
		// Calculate the rates
 | 
							// Calculate the rates
 | 
				
			||||||
		auto elapsed_seconds = std::chrono::duration_cast<std::chrono::seconds> (now - last_time).count ();
 | 
							auto elapsed_seconds = std::chrono::duration_cast<std::chrono::seconds> (now - last_time).count ();
 | 
				
			||||||
		auto blocks_confirmed_rate = static_cast<double> (blocks_cemented - last_blocks_cemented) / elapsed_seconds;
 | 
							auto blocks_confirmed_rate = static_cast<double> (blocks_cemented - last_blocks_cemented) / elapsed_seconds;
 | 
				
			||||||
		auto blocks_checked_rate = static_cast<double> (blocks_total - last_blocks_total) / elapsed_seconds;
 | 
							auto blocks_checked_rate = static_cast<double> (blocks_total - last_blocks_total) / elapsed_seconds;
 | 
				
			||||||
 | 
					
 | 
				
			||||||
		logger.info (nano::log::type::monitor, "Blocks rate (average over last {}s): confirmed {:.2f}/s | total {:.2f}/s",
 | 
							logger.info (nano::log::type::monitor, "Blocks rate (avg over {}s): confirmed {:.2f}/s | total {:.2f}/s",
 | 
				
			||||||
		elapsed_seconds,
 | 
							elapsed_seconds,
 | 
				
			||||||
		blocks_confirmed_rate,
 | 
							blocks_confirmed_rate,
 | 
				
			||||||
		blocks_checked_rate);
 | 
							blocks_checked_rate);
 | 
				
			||||||
 | 
						}
 | 
				
			||||||
 | 
					
 | 
				
			||||||
		logger.info (nano::log::type::monitor, "Peers: {} (realtime: {} | bootstrap: {} | inbound connections: {} | outbound connections: {})",
 | 
						logger.info (nano::log::type::monitor, "Peers: {} (realtime: {} | bootstrap: {}) (inbound: {} | outbound: {})",
 | 
				
			||||||
	node.network.size (),
 | 
						node.network.size (),
 | 
				
			||||||
	node.tcp_listener.realtime_count (),
 | 
						node.tcp_listener.realtime_count (),
 | 
				
			||||||
	node.tcp_listener.bootstrap_count (),
 | 
						node.tcp_listener.bootstrap_count (),
 | 
				
			||||||
| 
						 | 
					@ -102,7 +105,6 @@ void nano::monitor::run_one ()
 | 
				
			||||||
	node.active.size (nano::election_behavior::priority),
 | 
						node.active.size (nano::election_behavior::priority),
 | 
				
			||||||
	node.active.size (nano::election_behavior::hinted),
 | 
						node.active.size (nano::election_behavior::hinted),
 | 
				
			||||||
	node.active.size (nano::election_behavior::optimistic));
 | 
						node.active.size (nano::election_behavior::optimistic));
 | 
				
			||||||
	}
 | 
					 | 
				
			||||||
 | 
					
 | 
				
			||||||
	last_time = now;
 | 
						last_time = now;
 | 
				
			||||||
	last_blocks_cemented = blocks_cemented;
 | 
						last_blocks_cemented = blocks_cemented;
 | 
				
			||||||
| 
						 | 
					@ -124,9 +126,7 @@ nano::error nano::monitor_config::serialize (nano::tomlconfig & toml) const
 | 
				
			||||||
nano::error nano::monitor_config::deserialize (nano::tomlconfig & toml)
 | 
					nano::error nano::monitor_config::deserialize (nano::tomlconfig & toml)
 | 
				
			||||||
{
 | 
					{
 | 
				
			||||||
	toml.get ("enable", enable);
 | 
						toml.get ("enable", enable);
 | 
				
			||||||
	auto interval_l = interval.count ();
 | 
						toml.get_duration ("interval", interval);
 | 
				
			||||||
	toml.get ("interval", interval_l);
 | 
					 | 
				
			||||||
	interval = std::chrono::seconds{ interval_l };
 | 
					 | 
				
			||||||
 | 
					
 | 
				
			||||||
	return toml.get_error ();
 | 
						return toml.get_error ();
 | 
				
			||||||
}
 | 
					}
 | 
				
			||||||
		Loading…
	
	Add table
		Add a link
		
	
		Reference in a new issue