[ClientProfilerWindow] Added.

CMakeLists.txt

@@ -27,6 +27,7 @@ set(DEBUG_GCC_FLAGS
 	-Wall -Wextra -Wconversion -Wno-unused-parameter
 	-Wfatal-errors
 	-DGK_DEBUG
+	-DOM_PROFILER_ENABLED
 )
 
 set(RELEASE_GCC_FLAGS

source/client/core/ClientApplication.cpp

@@ -118,6 +118,10 @@ bool ClientApplication::init() {
 	m_resourceHandler.add<Font>("font-ascii", "texture-font", "resources/textures/font.properties");
 	m_resourceHandler.add<TextureAtlas>("atlas-blocks");
 
+#ifdef OM_PROFILER_ENABLED
+	ClientProfiler::setInstance(&m_profiler);
+#endif
+
 	auto &titleScreen = m_stateStack.push<TitleScreenState>(m_port);
 	if (m_argumentParser.getArgument("singleplayer").isFound)
 		titleScreen.startSingleplayer(false);
@@ -128,6 +132,8 @@ bool ClientApplication::init() {
 }
 
 void ClientApplication::handleEvents() {
+	OM_PROFILE_START("OS events");
+
 	gk::CoreApplication::handleEvents();
 
 	if ((Config::isFullscreenModeEnabled && m_window.getWindowMode() != gk::Window::Mode::Fullscreen)
@@ -141,6 +147,8 @@ void ClientApplication::handleEvents() {
 
 	if (Config::isVerticalSyncEnabled != m_window.isVerticalSyncEnabled())
 		m_window.setVerticalSyncEnabled(Config::isVerticalSyncEnabled);
+
+	OM_PROFILE_END("OS events");
 }
 
 void ClientApplication::onEvent(const SDL_Event &event) {
@@ -156,6 +164,45 @@ void ClientApplication::onExit() {
 	m_keyboardHandler.saveKeysToFile("config/keys.lua");
 }
 
+void ClientApplication::mainLoop() {
+	m_clock.startFpsTimer();
+
+	// FIXME: The window should probably be closed after the main loop ends
+	while(m_window.isOpen() && !m_stateStack.empty() && !hasBeenInterrupted) {
+		OM_PROFILE_BEGIN_TICK();
+
+		handleEvents();
+
+		m_eventHandler.processEvents();
+
+		m_clock.updateGame([&] {
+			OM_PROFILE_START("Update");
+
+			if (!m_stateStack.empty())
+				m_stateStack.top().update();
+
+			m_stateStack.clearDeletedStates();
+
+			OM_PROFILE_END("Update");
+		});
+
+		m_clock.drawGame([&] {
+			m_window.clear();
+
+			OM_PROFILE_START("Draw");
+
+			if(!m_stateStack.empty())
+				m_window.draw(m_stateStack.top(), m_renderStates);
+
+			OM_PROFILE_END("Draw");
+
+			m_window.display();
+		});
+
+		OM_PROFILE_END_TICK();
+	}
+}
+
 void ClientApplication::initOpenGL() {
 	// Enable textures
 	glCheck(glEnable(GL_TEXTURE_2D));

source/client/core/ClientApplication.hpp

@@ -29,6 +29,7 @@
 
 #include <gk/core/CoreApplication.hpp>
 
+#include "ClientProfiler.hpp"
 #include "KeyboardHandler.hpp"
 
 class ClientApplication : public gk::CoreApplication {
@@ -43,12 +44,18 @@ class ClientApplication : public gk::CoreApplication {
 		void onEvent(const SDL_Event &event) override;
 		void onExit() override;
 
+		void mainLoop() override;
+
 		static void initOpenGL();
 
 		KeyboardHandler m_keyboardHandler;
 
 		std::string m_host = "localhost";
 		u16 m_port = 4242;
+
+#ifdef OM_PROFILER_ENABLED
+		ClientProfiler m_profiler;
+#endif
 };
 
 #endif // CLIENTAPPLICATION_HPP_

source/client/core/ClientProfiler.cpp

@@ -29,32 +29,35 @@
 
 #include "ClientProfiler.hpp"
 
+u64 ClientProfiler::tickCount = 0;
+
 ClientProfiler *ClientProfiler::s_instance = nullptr;
 
 void ClientProfiler::onBeginTick() {
 	m_ticks.emplace_back();
-	m_ticks.back().begin = gk::GameClock::getInstance().getTicks(true);
+	m_ticks.back().begin = std::chrono::system_clock::now();
 }
 
 void ClientProfiler::onEndTick() {
-	m_ticks.back().end = gk::GameClock::getInstance().getTicks(true);
+	m_ticks.back().end = std::chrono::system_clock::now();
+	++tickCount;
 }
 
 void ClientProfiler::startAction(const std::string &name) {
 	m_ticks.back().actions[name].durations.emplace_back();
-	m_ticks.back().actions[name].durations.back().first = gk::GameClock::getInstance().getTicks(true);
+	m_ticks.back().actions[name].durations.back().first = std::chrono::system_clock::now();
 }
 
 void ClientProfiler::endAction(const std::string &name) {
-	m_ticks.back().actions[name].durations.back().second = gk::GameClock::getInstance().getTicks(true);
+	m_ticks.back().actions[name].durations.back().second = std::chrono::system_clock::now();
 }
 
 void ClientProfiler::dump(u64 tickDurationMin) {
 	std::unordered_map<std::string, std::pair<u64, u64>> maxActionDuration;
 
 	u64 i = 0;
 	for (auto &tick : m_ticks) {
-		u64 tickDuration = tick.end - tick.begin;
+		u64 tickDuration = std::chrono::duration_cast<std::chrono::milliseconds>(tick.end - tick.begin).count();
 		if (tickDuration < tickDurationMin) continue;
 
 		gkDebug() << "Tick" << i++ << "took" << tickDuration << "ms";
@@ -63,7 +66,7 @@ void ClientProfiler::dump(u64 tickDurationMin) {
 			for (auto &[actionName, action] : tick.actions) {
 				u64 j = 0;
 				for (auto &[begin, end] : action.durations) {
-					u64 actionDuration = end - begin;
+					u64 actionDuration = std::chrono::duration_cast<std::chrono::milliseconds>(end - begin).count();
 
 					if (maxActionDuration.find(actionName) == maxActionDuration.end())
 						maxActionDuration.emplace(actionName, std::make_pair(actionDuration, 0));

source/client/core/ClientProfiler.hpp

@@ -27,19 +27,36 @@
 #ifndef CLIENTPROFILER_HPP_
 #define CLIENTPROFILER_HPP_
 
+#include <chrono>
 #include <deque>
 #include <string>
 #include <unordered_map>
 
 #include <gk/core/IntTypes.hpp>
 
+#ifdef OM_PROFILER_ENABLED
+# define OM_PROFILE_START(name) ClientProfiler::getInstance().startAction(name);
+# define OM_PROFILE_END(name) ClientProfiler::getInstance().endAction(name);
+
+# define OM_PROFILE_BEGIN_TICK() ClientProfiler::getInstance().onBeginTick();
+# define OM_PROFILE_END_TICK() ClientProfiler::getInstance().onEndTick();
+#else
+# define OM_PROFILE_START(name) {}
+# define OM_PROFILE_END(name) {}
+
+# define OM_PROFILE_BEGIN_TICK() {}
+# define OM_PROFILE_END_TICK() {}
+#endif
+
+using TimePoint = std::chrono::time_point<std::chrono::system_clock>;
+
 struct ClientAction {
-	std::deque<std::pair<u64, u64>> durations;
+	std::deque<std::pair<TimePoint, TimePoint>> durations;
 };
 
 struct ClientTick {
-	u64 begin;
-	u64 end;
+	TimePoint begin;
+	TimePoint end;
 	std::unordered_map<std::string, ClientAction> actions;
 };
 
@@ -53,13 +70,20 @@ class ClientProfiler {
 		void startAction(const std::string &name);
 		void endAction(const std::string &name);
 
+		// FIXME: m_ticks.size() - 1 is actually the current tick
+		const ClientTick &getLastTick() const { return m_ticks.at(m_ticks.size() - 2); };
+
+		std::size_t getTickCount() const { return m_ticks.size(); }
+
 		static ClientProfiler &getInstance() { return *s_instance; }
 		static void setInstance(ClientProfiler *instance) { s_instance = instance; }
 
+		static u64 tickCount;
+
 	private:
 		static ClientProfiler *s_instance;
 
-		std::deque<ClientTick> m_ticks;
+		std::deque<ClientTick> m_ticks; // TODO: Use a std::vector
 };
 
 #endif // CLIENTPROFILER_HPP_

source/client/core/Config.cpp

@@ -69,6 +69,7 @@ u8 Config::mouseSensitivity = 8;
 // Debug
 bool Config::isChunkMinimapEnabled = false;
 bool Config::isLightmapViewerEnabled = false;
+bool Config::isProfilerWindowEnabled = false;
 
 // Other
 std::string Config::defaultUsername = "";
@@ -114,6 +115,7 @@ void Config::loadConfigFromFile(const char *filename) {
 
 			isChunkMinimapEnabled = lua["isChunkMinimapEnabled"].get_or(isChunkMinimapEnabled);
 			isLightmapViewerEnabled = lua["isLightmapViewerEnabled"].get_or(isLightmapViewerEnabled);
+			isProfilerWindowEnabled = lua["isProfilerWindowEnabled"].get_or(isProfilerWindowEnabled);
 
 			defaultUsername = lua["defaultUsername"].get_or(defaultUsername);
 			defaultServerAddress = lua["defaultServerAddress"].get_or(defaultServerAddress);
@@ -156,6 +158,7 @@ void Config::saveConfigToFile(const char *filename) {
 	file << std::endl;
 	file << "isChunkMinimapEnabled = " << (isChunkMinimapEnabled ? "true" : "false") << std::endl;
 	file << "isLightmapViewerEnabled = " << (isLightmapViewerEnabled ? "true" : "false") << std::endl;
+	file << "isProfilerWindowEnabled = " << (isProfilerWindowEnabled ? "true" : "false") << std::endl;
 	file << std::endl;
 	file << "defaultUsername = \"" << defaultUsername << "\"" << std::endl;
 	file << "defaultServerAddress = \"" << defaultServerAddress << "\"" << std::endl;

source/client/core/Config.hpp

@@ -64,6 +64,7 @@ namespace Config {
 	// Debug
 	extern bool isChunkMinimapEnabled;
 	extern bool isLightmapViewerEnabled;
+	extern bool isProfilerWindowEnabled;
 
 	// Other
 	extern std::string defaultUsername;

source/client/hud/DebugProfilerWindow.cpp

@@ -0,0 +1,117 @@
+/*
+ * =====================================================================================
+ *
+ *  OpenMiner
+ *
+ *  Copyright (C) 2018-2020 Unarelith, Quentin Bazin <[email protected]>
+ *  Copyright (C) 2019-2020 the OpenMiner contributors (see CONTRIBUTORS.md)
+ *
+ *  This file is part of OpenMiner.
+ *
+ *  OpenMiner is free software; you can redistribute it and/or
+ *  modify it under the terms of the GNU Lesser General Public
+ *  License as published by the Free Software Foundation; either
+ *  version 2.1 of the License, or (at your option) any later version.
+ *
+ *  OpenMiner is distributed in the hope that it will be useful,
+ *  but WITHOUT ANY WARRANTY; without even the implied warranty of
+ *  MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
+ *  Lesser General Public License for more details.
+ *
+ *  You should have received a copy of the GNU Lesser General Public License
+ *  along with OpenMiner; if not, write to the Free Software Foundation, Inc.,
+ *  51 Franklin Street, Fifth Floor, Boston, MA  02110-1301 USA
+ *
+ * =====================================================================================
+ */
+#include <map>
+#include <sstream>
+
+#include "DebugProfilerWindow.hpp"
+
+DebugProfilerWindow::DebugProfilerWindow() {
+#ifndef OM_PROFILER_ENABLED
+	m_text.setString("Profiler disabled.\nPlease recompile with -DOM_PROFILER_ENABLED to enable it.");
+#endif
+}
+
+void DebugProfilerWindow::onEvent(const SDL_Event &event) {
+	if (event.type == SDL_KEYDOWN) {
+		switch (event.key.keysym.sym) {
+			case SDLK_a: m_mode = DebugProfilerWindowMode::Total; break;
+			case SDLK_p: m_mode = DebugProfilerWindowMode::Prev; break;
+			case SDLK_s: m_mode = DebugProfilerWindowMode::Min; break;
+			case SDLK_l: m_mode = DebugProfilerWindowMode::Max; break;
+		}
+	}
+}
+
+void DebugProfilerWindow::update() {
+#ifdef OM_PROFILER_ENABLED
+	ClientProfiler &profiler = ClientProfiler::getInstance();
+	std::size_t ticks = profiler.getTickCount();
+
+	// FIXME: Some information may be lost here
+	const ClientTick &tick = profiler.getLastTick();
+	if (&tick == m_lastTick) return;
+	m_lastTick = &tick;
+
+	m_snapshot.addTick(tick);
+
+	constexpr std::size_t updateDisplayFrequency = 60;
+	if (ticks - m_lastUpdate >= updateDisplayFrequency) {
+		m_lastUpdate = ticks;
+
+		std::stringstream stream;
+		stream << "In the last " << updateDisplayFrequency << " ticks:\n";
+		stream << "Tick count: " << m_snapshot.tickCount() << "\n";
+		stream << "- [A] Total: " << (float)m_snapshot.totalTicksDuration() / 1000.f << " ms ("
+			<< (float)m_snapshot.totalTicksDuration() / 1000.0f / updateDisplayFrequency << " ms/t)\n";
+
+		stream << "- [P] Prev: " << (float)m_snapshot.previousTickDuration() / 1000.f << " ms\n";
+		stream << "- [S] Min: " << (float)m_snapshot.shortestPreviousTickDuration() / 1000.f << " ms\n";
+		stream << "- [L] Max: " << (float)m_snapshot.longestPreviousTickDuration() / 1000.f << " ms\n";
+
+		if (m_mode == DebugProfilerWindowMode::Total)
+			stream << "Total actions during those ticks:\n";
+		else if (m_mode == DebugProfilerWindowMode::Prev)
+			stream << "Actions for last tick:\n";
+		else if (m_mode == DebugProfilerWindowMode::Min)
+			stream << "Actions for shortest tick since last update:\n";
+		else if (m_mode == DebugProfilerWindowMode::Max)
+			stream << "Actions for longest tick since last update:\n";
+
+		std::map<u64, std::pair<std::string, const DebugProfilerSnapshotValue &>> snapshotData;
+		for (auto &[valueName, value] : m_snapshot.values()) {
+			if (value.hasDataForTick(&tick) || m_mode == DebugProfilerWindowMode::Total) {
+				std::pair<std::string, const DebugProfilerSnapshotValue &> pair{valueName, value};
+				if (m_mode == DebugProfilerWindowMode::Total)
+					snapshotData.emplace(value.totalTime(nullptr), pair);
+				else
+					snapshotData.emplace(value.totalTime(&tick), pair);
+			}
+		}
+
+		for (auto &[displayedValue, value] : snapshotData) {
+			stream << "- " << value.first << " (";
+			if (m_mode == DebugProfilerWindowMode::Total)
+				stream << value.second.wholeSnapshotCallCount();
+			else
+				stream << value.second.lastTickCallCount();
+			stream << "): " << (float)displayedValue / 1000.f << " ms ("
+				<< (float)value.second.totalTime(nullptr) / 1000.f / updateDisplayFrequency << " ms/t)\n";
+		}
+
+		m_text.setString(stream.str());
+
+		m_snapshot.reset();
+	}
+#endif
+}
+
+void DebugProfilerWindow::draw(gk::RenderTarget &target, gk::RenderStates states) const {
+	states.transform *= getTransform();
+
+	target.draw(m_text, states);
+}
+