Merge pull request #569 from OpenVicProject/timing-cleanup

Timing cleanup

Author: Hop311

src/headless/main.cpp

@@ -24,7 +24,9 @@
 
 using namespace OpenVic;
 
-inline static void print_bytes(std::string_view prefix, const std::source_location& location = std::source_location::current()) {
+inline static void print_memory_usage(
+	std::string_view prefix, std::source_location const& location = std::source_location::current()
+) {
 #ifdef DEBUG_ENABLED // memory tracking will return 0 without DEBUG_ENABLED
 	Logger::info<std::string_view&, const char(&)[16], uint64_t&&, const char(&)[7]>(
 		prefix, " Memory Usage: ", OpenVic::utility::MemoryTracker::get_memory_usage(), " Bytes", location
@@ -79,8 +81,12 @@ static void print_rgo(ProvinceInstance const& province) {
 using pathing_rng_t = std::mt19937;
 using pathing_rng_seed_t = pathing_rng_t::result_type;
 
+using testing_clock_t = std::chrono::high_resolution_clock;
+using test_time_point_t = testing_clock_t::time_point;
+using test_duration_t = testing_clock_t::duration;
+
 template<size_t TestCount>
-static std::chrono::nanoseconds run_pathing_test(AStarPathing& pathing, std::optional<pathing_rng_seed_t> seed) {
+static test_duration_t run_pathing_test(AStarPathing& pathing, std::optional<pathing_rng_seed_t> seed) {
 	PointMap const& points = pathing.get_point_map();
 
 	if (!seed.has_value()) {
@@ -107,11 +113,11 @@ static std::chrono::nanoseconds run_pathing_test(AStarPathing& pathing, std::opt
 		from_to_tests[index] = { from, to };
 	}
 
-	auto start_time = std::chrono::high_resolution_clock::now();
+	const test_time_point_t start_time = testing_clock_t::now();
 	for (auto [index, pair] : from_to_tests | ranges::views::enumerate) {
 		test_results[index] = pathing.get_id_path(pair.first.key(), pair.second.key());
 	}
-	auto end_time = std::chrono::high_resolution_clock::now();
+	const test_time_point_t end_time = testing_clock_t::now();
 
 	for (auto [index, test] : test_results | ranges::views::enumerate) {
 		Logger::info("-Start Test ", index + 1, "-");
@@ -162,7 +168,7 @@ static bool run_headless(fs::path const& root, memory::vector<memory::string>& m
 		}
 	);
 
-	print_bytes("Definition Setup");
+	print_memory_usage("Definition Setup");
 
 	if (run_tests) {
 		Testing testing { game_manager.get_definition_manager() };
@@ -177,15 +183,15 @@ static bool run_headless(fs::path const& root, memory::vector<memory::string>& m
 		game_manager.get_definition_manager().get_history_manager().get_bookmark_manager().get_bookmark_by_index(0)
 	);
 
-	print_bytes("Instance Setup");
+	print_memory_usage("Instance Setup");
 
 	Logger::info("===== Starting game session... =====");
 	ret &= game_manager.start_game_session();
 
 	// This triggers a gamestate update
 	ret &= game_manager.update_clock();
 
-	print_bytes("Game Session Post-Start");
+	print_memory_usage("Game Session Post-Start");
 
 	// TODO - REMOVE TEST CODE
 	Logger::info("===== Ranking system test... =====");
@@ -232,29 +238,60 @@ static bool run_headless(fs::path const& root, memory::vector<memory::string>& m
 		// Set to std::nullopt to use a different random seed on each run
 		static constexpr std::optional<pathing_rng_seed_t> LAND_SEED = 1836, SEA_SEED = 1861;
 
+		using test_time_units_t = std::chrono::milliseconds;
+
 		Logger::info("===== Land Pathfinding test... =====");
-		std::chrono::nanoseconds ns = run_pathing_test<TESTS>(
+		test_duration_t duration = std::chrono::duration_cast<test_time_units_t>(run_pathing_test<TESTS>(
 			game_manager.get_instance_manager()->get_map_instance().get_land_pathing(), LAND_SEED
-		);
-		Logger::info("Ran ", TESTS, " land pathing tests in ", ns);
+		));
+		Logger::info("Ran ", TESTS, " land pathing tests in ", duration);
 
 		Logger::info("===== Sea Pathfinding test... =====");
-		ns = run_pathing_test<TESTS>(
+		duration = std::chrono::duration_cast<test_time_units_t>(run_pathing_test<TESTS>(
 			game_manager.get_instance_manager()->get_map_instance().get_sea_pathing(), SEA_SEED
-		);
-		Logger::info("Ran ", TESTS, " sea pathing tests in ", ns);
+		));
+		Logger::info("Ran ", TESTS, " sea pathing tests in ", duration);
 	}
 
 	if (ret) {
+		static constexpr size_t TICK_COUNT = 10;
+
 		Logger::info("===== Game Tick test... =====");
 		size_t ticks_passed = 0;
-		auto start_time = std::chrono::high_resolution_clock::now();
-		while (ticks_passed++ < 10) {
+		test_duration_t min_tick_duration = test_duration_t::max(), max_tick_duration = test_duration_t::min(),
+			total_tick_duration;
+		const test_time_point_t start_time = testing_clock_t::now();
+		while (++ticks_passed < TICK_COUNT) {
+			const test_time_point_t tick_start = testing_clock_t::now();
 			game_manager.get_instance_manager()->force_tick_and_update();
-			print_bytes("Tick Finished");
+			const test_time_point_t tick_end = testing_clock_t::now();
+
+			const test_duration_t tick_duration = tick_end - tick_start;
+
+			min_tick_duration = std::min(min_tick_duration, tick_duration);
+			max_tick_duration = std::max(max_tick_duration, tick_duration);
+
+			total_tick_duration += tick_duration;
+
+			print_memory_usage(fmt::format("Tick {} finished", ticks_passed));
+		}
+		const test_time_point_t end_time = testing_clock_t::now();
+		const test_duration_t duration = end_time - start_time;
+
+		if (ticks_passed != 0 && duration != test_duration_t::zero()) {
+			const test_duration_t tick_tps = total_tick_duration / ticks_passed;
+			const test_duration_t total_tps = duration / ticks_passed;
+			Logger::info(
+				"Ran ", ticks_passed, " / ", TICK_COUNT, " ticks, total time ", duration, " at, ", total_tps,
+				" per tick, tick time only ", total_tick_duration, " at ", tick_tps,  " per tick. Tick lengths ranged from ",
+				min_tick_duration, " to ", max_tick_duration, "."
+			);
+		} else {
+			Logger::error(
+				"No ticks passed (", ticks_passed, ", expected ", TICK_COUNT, ") or zero duration measured (", duration, ")!"
+			);
+			ret = false;
 		}
-		auto end_time = std::chrono::high_resolution_clock::now();
-		Logger::info("Ran ", --ticks_passed, " ticks in ", end_time - start_time);
 	}
 
 	Logger::info("===== Ending game session... =====");
@@ -283,7 +320,8 @@ int main(int argc, char const* argv[]) {
 	 * message and the help text are displayed, along with returning false to signify the program should exit.
 	 */
 	const auto _read = [&root, &argn, argc, argv, program_name](
-		std::string_view command, std::string_view path_use, auto path_transform) -> bool {
+		std::string_view command, std::string_view path_use, std::invocable<fs::path> auto path_transform
+	) -> bool {
 		if (root.empty()) {
 			if (++argn < argc) {
 				char const* path = argv[argn];

src/openvic-simulation/misc/SimulationClock.cpp

@@ -11,6 +11,10 @@ SimulationClock::SimulationClock(
 	reset();
 }
 
+SimulationClock::time_point_t SimulationClock::get_now() const {
+	return clock_t::now();
+}
+
 void SimulationClock::set_paused(bool new_paused) {
 	if (paused != new_paused) {
 		toggle_paused();
@@ -46,25 +50,23 @@ bool SimulationClock::can_decrease_simulation_speed() const {
 
 void SimulationClock::conditionally_advance_game() {
 	if (!paused) {
-		const time_point_t current_time = std::chrono::high_resolution_clock::now();
-		const std::chrono::milliseconds time_since_last_tick =
-			std::chrono::duration_cast<std::chrono::milliseconds>(current_time - last_tick_time);
-		if (time_since_last_tick >= GAME_SPEEDS[current_speed]) {
-			last_tick_time = current_time;
+		const time_point_t current_time = get_now();
+		if (next_tick_time <= current_time) {
+			next_tick_time = current_time + GAME_SPEEDS[current_speed];
 			tick_function();
 		}
 	}
 	update_function();
 }
 
 void SimulationClock::force_advance_game() {
-	last_tick_time = std::chrono::high_resolution_clock::now();
+	next_tick_time = get_now() + GAME_SPEEDS[current_speed];
 	tick_function();
 	update_function();
 }
 
 void SimulationClock::reset() {
 	paused = true;
 	current_speed = 0;
-	last_tick_time = std::chrono::high_resolution_clock::now();
+	next_tick_time = get_now();
 }

src/openvic-simulation/misc/SimulationClock.hpp

@@ -13,25 +13,32 @@ namespace OpenVic {
 	public:
 		using tick_function_t = fu2::function_base<true, true, fu2::capacity_can_hold<void*>, false, false, void()>;
 		using update_function_t = fu2::function_base<true, true, fu2::capacity_can_hold<void*>, false, false, void()>;
+
+		using clock_t = std::chrono::high_resolution_clock;
+		using time_point_t = clock_t::time_point;
+		using duration_t = clock_t::duration;
+
+		static constexpr size_t NUM_SPEEDS = 5;
 		using speed_t = int8_t;
+		using speed_rates_t = std::array<duration_t, NUM_SPEEDS>;
 
 		/* Minimum number of milliseconds before the simulation advances
 		 * (in descending duration order, hence increasing speed order). */
-		static constexpr std::chrono::milliseconds GAME_SPEEDS[] {
-			std::chrono::milliseconds { 3000 }, std::chrono::milliseconds { 2000 }, std::chrono::milliseconds { 1000 },
-			std::chrono::milliseconds { 100 }, std::chrono::milliseconds { 1 }
-		};
+		static constexpr speed_rates_t GAME_SPEEDS = []() constexpr -> speed_rates_t {
+			using namespace std::chrono_literals;
+			return {
+				3s, 2s, 1s, 100ms, 1ms
+			};
+		}();
 		static constexpr speed_t MIN_SPEED = 0, MAX_SPEED = std::size(GAME_SPEEDS) - 1;
 
 	private:
-		using time_point_t = std::chrono::time_point<std::chrono::high_resolution_clock>;
-
 		/* Advance simulation (triggered while unpaused at interval determined by speed). */
 		tick_function_t tick_function;
 		/* Refresh game state (triggered with every call to conditionally_advance_game). */
 		update_function_t update_function;
 
-		time_point_t last_tick_time;
+		time_point_t next_tick_time;
 		speed_t PROPERTY_CUSTOM_NAME(current_speed, get_simulation_speed, 0);
 		bool PROPERTY_CUSTOM_PREFIX(paused, is, true);
 
@@ -41,6 +48,8 @@ namespace OpenVic {
 			tick_function_t new_tick_function, update_function_t new_update_function
 		);
 
+		time_point_t get_now() const;
+
 		void set_paused(bool new_paused);
 		void toggle_paused();