Merge pull request #316 from Laguna1989/feature/TimeMeasurement

Add time measurement feature

ext/sfml/CMakeLists.txt

@@ -2,7 +2,7 @@ message(STATUS "Fetching sfml")
 cmake_policy(SET CMP0135 OLD)
 FetchContent_Declare(
         SFML
-        URL "https://github.com/SFML/SFML/archive/2.6.0.zip"
+        URL "https://github.com/SFML/SFML/archive/2.6.1.zip"
 )
 
 FetchContent_GetProperties(SFML)

impl/jamtemplate/common/audio/audio/audio_impl.cpp

@@ -1,4 +1,5 @@
 #include "audio_impl.hpp"
+#include "performance_measurement.hpp"
 #include <audio/sound/intro_looping_sound_with_effect.hpp>
 #include <audio/sound/sound.hpp>
 #include <audio/sound/sound_group.hpp>
@@ -23,6 +24,7 @@ jt::AudioImpl::~AudioImpl() { m_temporarySounds.clear(); }
 
 void jt::AudioImpl::update(float elapsed)
 {
+    TimeMeasureObject obj { "jt::AudioImpl::update" };
     cleanUpUnusedSounds();
 
     for (auto const& snd : m_temporarySounds) {

impl/jamtemplate/common/game_base.cpp

@@ -1,4 +1,5 @@
 #include "game_base.hpp"
+#include "performance_measurement.hpp"
 #include <build_info.hpp>
 #include <string>
 
@@ -19,6 +20,7 @@ jt::GameBase::GameBase(jt::GfxInterface& gfx, jt::InputManagerInterface& input,
 
 void jt::GameBase::runOneFrame()
 {
+    TimeMeasureObject obj { "jt::GameBase::runOneFrame" };
     m_logger.verbose("runOneFrame", { "jt" });
     m_actionCommandManager.update();
 
@@ -81,10 +83,26 @@ jt::ActionCommandManagerInterface& jt::GameBase::actionCommandManager()
 
 jt::CacheInterface& jt::GameBase::cache() { return m_cache; }
 
+std::string getTimeString()
+{
+    auto t = std::time(nullptr);
+    auto tm = *std::localtime(&t);
+    std::stringstream ss;
+    ss << std::put_time(&tm, "%Y-%m-%d_%H-%M-%S");
+    return ss.str();
+}
+
 void jt::GameBase::doUpdate(float const elapsed)
 {
+    TimeMeasureObject obj { "jt::GameBase::doUpdate" };
     m_logger.verbose("update game", { "jt" });
+    if (m_inputManager.keyboard()->justPressed(jt::KeyCode::F10)) {
+        std::cout << "write file\n";
+        std::ofstream ofs { "tracing" + getTimeString() + ".json" };
+        ofs << jt::getTracingJson(jt::getMeasurementData());
+    }
     m_stateManager.update(getPtr(), elapsed);
+
     m_audio.update(elapsed);
     gfx().update(elapsed);
 
@@ -99,6 +117,7 @@ void jt::GameBase::doUpdate(float const elapsed)
 
 void jt::GameBase::doDraw() const
 {
+    TimeMeasureObject obj { "jt::GameBase::doDraw" };
     m_logger.verbose("draw game", { "jt" });
     gfx().window().startRenderGui();
     gfx().clear();

impl/jamtemplate/common/input/gamepad/gamepad_input.cpp

@@ -1,10 +1,10 @@
 #include "gamepad_input.hpp"
+#include "performance_measurement.hpp"
 #include <input/input_helper.hpp>
 
 jt::GamepadInput::GamepadInput(int gamepadId, AxisFunc axisFunc, ButtonCheckFunction buttonFunc)
     : m_axisFunc { axisFunc }
 {
-
     if (m_axisFunc == nullptr) {
         m_axisFunc = [gamepadId](auto k) { return libAxisValue(gamepadId, k); };
     }
@@ -23,11 +23,13 @@ jt::GamepadInput::GamepadInput(int gamepadId, AxisFunc axisFunc, ButtonCheckFunc
 
 void jt::GamepadInput::update()
 {
+    TimeMeasureObject obj { "jt::GamepadInput::update" };
     jt::inputhelper::updateValues(m_pressed, m_released, m_justPressed, m_justReleased,
         [this](auto k) { return m_buttonFunc(k); });
 }
 
 jt::Vector2f jt::GamepadInput::getAxisRaw(jt::GamepadAxisCode axis) { return m_axisFunc(axis); }
+
 jt::Vector2f jt::GamepadInput::getAxis(jt::GamepadAxisCode axis)
 {
     auto v = getAxisRaw(axis);
@@ -43,6 +45,9 @@ jt::Vector2f jt::GamepadInput::getAxis(jt::GamepadAxisCode axis)
 void jt::GamepadInput::reset() { }
 
 bool jt::GamepadInput::pressed(GamepadButtonCode b) { return m_pressed[b]; }
+
 bool jt::GamepadInput::released(GamepadButtonCode b) { return m_released[b]; }
+
 bool jt::GamepadInput::justPressed(GamepadButtonCode b) { return m_justPressed[b]; }
+
 bool jt::GamepadInput::justReleased(GamepadButtonCode b) { return m_justReleased[b]; }

impl/jamtemplate/common/input/input_helper.hpp

@@ -10,7 +10,7 @@ namespace inputhelper {
 template <typename CheckFuncArg, typename KeyTypeJT>
 void updateValues(std::map<KeyTypeJT, bool>& pressed, std::map<KeyTypeJT, bool>& released,
     std::map<KeyTypeJT, bool>& justPressed, std::map<KeyTypeJT, bool>& justReleased,
-    CheckFuncArg check)
+    CheckFuncArg const& check)
 {
     for (auto const& kvp : pressed) {
         auto const key = kvp.first;

impl/jamtemplate/common/input/input_manager.cpp

@@ -1,6 +1,7 @@
 #include "input_manager.hpp"
 #include "input/keyboard/keyboard_input_null.hpp"
 #include "input/mouse/mouse_input_null.hpp"
+#include "performance_measurement.hpp"
 #include <input/gamepad/gamepad_input_null.hpp>
 
 jt::InputManager::InputManager(std::shared_ptr<jt::MouseInterface> mouse,
@@ -38,6 +39,7 @@ void jt::InputManager::reset()
 void jt::InputManager::update(
     bool /*shouldProcessKeys*/, bool /*shouldProcessMouse*/, MousePosition const& mp, float elapsed)
 {
+    TimeMeasureObject obj { "jt::InputManager::update" };
     if (m_mouse) [[likely]] {
         m_mouse->updateMousePosition(mp);
         m_mouse->updateButtons();

impl/jamtemplate/common/input/keyboard/keyboard_input.cpp

@@ -1,4 +1,5 @@
 #include "keyboard_input.hpp"
+#include "performance_measurement.hpp"
 #include <input/control_commands/control_command_null.hpp>
 #include <input/input_helper.hpp>
 #include <utility>
@@ -22,6 +23,7 @@ jt::KeyboardInput::KeyboardInput(KeyboardKeyCheckFunction checkFunc)
 
 void jt::KeyboardInput::updateKeys()
 {
+    TimeMeasureObject obj { "jt::KeyboardInput::updateKeys" };
     jt::inputhelper::updateValues(m_pressed, m_released, m_justPressed, m_justReleased,
         [this](auto k) { return m_checkFunc(k); });
 }

impl/jamtemplate/common/input/keyboard/keyboard_input_selected_keys.cpp

@@ -1,4 +1,5 @@
 #include "keyboard_input_selected_keys.hpp"
+#include "performance_measurement.hpp"
 #include <input/control_commands/control_command_null.hpp>
 #include <input/input_helper.hpp>
 
@@ -23,6 +24,7 @@ void jt::KeyboardInputSelectedKeys::listenForKey(jt::KeyCode k)
 
 void jt::KeyboardInputSelectedKeys::updateKeys()
 {
+    TimeMeasureObject obj { "jt::KeyboardInputSelectedKeys::updateKeys" };
     jt::inputhelper::updateValues(m_pressed, m_released, m_justPressed, m_justReleased,
         [this](auto k) { return m_checkFunc(k); });
 }

impl/jamtemplate/common/input/mouse/mouse_input.cpp

@@ -1,4 +1,5 @@
 #include "mouse_input.hpp"
+#include "performance_measurement.hpp"
 #include <input/input_helper.hpp>
 
 jt::MouseInput::MouseInput(MouseButtonCheckFunction checkFunction)
@@ -19,6 +20,7 @@ jt::MouseInput::MouseInput(MouseButtonCheckFunction checkFunction)
 
 void jt::MouseInput::updateMousePosition(jt::MousePosition const& mp)
 {
+    TimeMeasureObject obj { "jt::MouseInput::updateMousePosition" };
     m_mouseWorldX = mp.window_x;
     m_mouseWorldY = mp.window_y;
 
@@ -28,6 +30,7 @@ void jt::MouseInput::updateMousePosition(jt::MousePosition const& mp)
 
 void jt::MouseInput::updateButtons()
 {
+    TimeMeasureObject obj { "jt::MouseInput::updateButtons" };
     jt::inputhelper::updateValues(m_mousePressed, m_mouseReleased, m_mouseJustPressed,
         m_mouseJustReleased, [this](auto b) { return m_checkFunction(b); });
 }

impl/jamtemplate/common/performance_measurement.cpp

@@ -1,8 +1,67 @@
 #include "performance_measurement.hpp"
+#include <nlohmann.hpp>
+#include <sstream>
+#include <thread>
 
-float jt::getDurationInSecondsSince(std::chrono::time_point<std::chrono::system_clock> const& since)
+std::atomic<size_t> g_index;
+std::vector<jt::TimeMeasureObjectData> g_profilingData(1000);
+
+float jt::getDurationInSecondsSince(std::chrono::time_point<std::chrono::steady_clock> const& since)
 {
-    auto const now = std::chrono::system_clock::now();
+    auto const now = std::chrono::steady_clock::now();
     return std::chrono::duration_cast<std::chrono::microseconds>(now - since).count() / 1000.0f
         / 1000.0f;
 }
+
+std::string to_string(std::thread::id id)
+{
+    std::stringstream ss;
+    ss << id;
+    return ss.str();
+}
+
+void jt::to_json(nlohmann::json& j, jt::TimeMeasureObjectData const& data)
+{
+    std::int64_t const start = std::chrono::time_point_cast<std::chrono::nanoseconds>(data.start)
+                                   .time_since_epoch()
+                                   .count();
+    std::int64_t const duration
+        = std::chrono::duration_cast<std::chrono::nanoseconds>(data.end - data.start).count();
+
+    j["pid"] = 1;
+    j["tid"] = to_string(data.threadId);
+    j["cat"] = "PERF";
+    j["displayTimeUnit"] = "ns";
+    j["ph"] = "X";
+    j["ts"] = start;
+    j["dur"] = duration;
+    j["name"] = data.name;
+}
+
+std::string jt::getTracingJson(std::vector<TimeMeasureObjectData> const& data)
+{
+    nlohmann::json j;
+    j["traceEvents"] = data;
+    return j.dump(4);
+}
+
+std::vector<jt::TimeMeasureObjectData> jt::getMeasurementData() { return g_profilingData; }
+
+jt::TimeMeasureObject::TimeMeasureObject(std::string const& str)
+    : m_start { std::chrono::steady_clock::now() }
+    , m_name { str }
+{
+}
+
+jt::TimeMeasureObject::~TimeMeasureObject()
+{
+    TimeMeasureObjectData measurement;
+    measurement.name = m_name;
+    measurement.start = m_start;
+    measurement.end = std::chrono::steady_clock::now();
+    measurement.threadId = std::this_thread::get_id();
+
+    std::size_t const index = g_index.fetch_add(1) % g_profilingData.size();
+
+    g_profilingData[index] = measurement;
+}

impl/jamtemplate/common/performance_measurement.hpp

@@ -1,15 +1,18 @@
 #ifndef JAMTEMPLATE_PERFORMANCE_MEASUREMENT_HPP
 #define JAMTEMPLATE_PERFORMANCE_MEASUREMENT_HPP
 
+#include <nlohmann.hpp>
 #include <chrono>
 #include <functional>
+#include <string>
+#include <thread>
 
 namespace jt {
 
 /// Helper function to measure time since a time point.
 /// \param since start time
 /// \return the duration in seconds since the passed value
-float getDurationInSecondsSince(std::chrono::time_point<std::chrono::system_clock> const& since);
+float getDurationInSecondsSince(std::chrono::time_point<std::chrono::steady_clock> const& since);
 
 /// Generic Template to allow for partial specialization. Specialization is needed for void return
 /// type.
@@ -37,7 +40,7 @@ struct MeasureTimeGeneric<R(Args...)> {
     /// \return the return value of the function to be measured
     R operator()(Args... args) const
     {
-        auto const start = std::chrono::system_clock::now();
+        auto const start = std::chrono::steady_clock::now();
         R const result = m_func(args...);
         m_elapsedTimeInSeconds += getDurationInSecondsSince(start);
         return result;
@@ -76,7 +79,7 @@ struct MeasureTimeGeneric<void(Args...)> {
     /// \return the return value of the function to be measured
     void operator()(Args... args) const
     {
-        auto const start = std::chrono::system_clock::now();
+        auto const start = std::chrono::steady_clock::now();
         m_func(args...);
         m_elapsedTimeInSeconds += getDurationInSecondsSince(start);
     }
@@ -111,6 +114,28 @@ auto makeMeasureTimeGeneric(std::function<R(Args...)> const& func)
     return MeasureTimeGeneric<R(Args...)> { func };
 }
 
+struct TimeMeasureObject {
+    explicit TimeMeasureObject(std::string const& str);
+    ~TimeMeasureObject();
+
+private:
+    std::chrono::time_point<std::chrono::steady_clock> m_start;
+    std::string m_name;
+};
+
+struct TimeMeasureObjectData {
+    std::string name;
+    std::chrono::time_point<std::chrono::steady_clock> start;
+    std::chrono::time_point<std::chrono::steady_clock> end;
+    std::thread::id threadId;
+};
+
+void to_json(nlohmann::json& j, TimeMeasureObjectData const& data);
+
+std::string getTracingJson(std::vector<TimeMeasureObjectData> const& data);
+
+std::vector<TimeMeasureObjectData> getMeasurementData();
+
 } // namespace jt
 
 #endif // JAMTEMPLATE_PERFORMANCE_MEASUREMENT_HPP

impl/jamtemplate/common/state_manager/state_manager.cpp

@@ -1,4 +1,5 @@
 #include "state_manager.hpp"
+#include "performance_measurement.hpp"
 #include <game_interface.hpp>
 #include <state_manager/state_manager_transition_none.hpp>
 #include <stdexcept>
@@ -50,6 +51,7 @@ void jt::StateManager::doSwitchState(std::weak_ptr<jt::GameInterface> gameInstan
 
 void jt::StateManager::update(std::weak_ptr<jt::GameInterface> gameInstance, float elapsed)
 {
+    TimeMeasureObject obj { "jt::StateManager::update" };
     getTransition()->update(elapsed);
     if (m_nextState != nullptr) {
         if (getTransition()->triggerStateChange()) {
@@ -79,6 +81,7 @@ std::shared_ptr<jt::StateManagerTransitionInterface> jt::StateManager::getTransi
 
 void jt::StateManager::draw(std::shared_ptr<jt::RenderTargetInterface> rt)
 {
+    TimeMeasureObject obj { "jt::StateManager::draw" };
     getCurrentState()->draw();
     if (getTransition()->isInProgress()) {
         getTransition()->draw(rt);

impl/jamtemplate/sfml/gfx_impl.cpp

@@ -1,4 +1,5 @@
 #include "gfx_impl.hpp"
+#include "performance_measurement.hpp"
 #include <math_helper.hpp>
 #include <rect_lib.hpp>
 #include <sprite.hpp>
@@ -44,6 +45,7 @@ void jt::GfxImpl::reset() { m_camera.reset(); }
 
 void jt::GfxImpl::update(float elapsed)
 {
+    TimeMeasureObject obj { "jt::GfxImpl::update" };
     m_camera.update(elapsed);
 
     m_target->forall([this](auto t) { t->setView(*m_view); });

impl/jamtemplate/sfml/mouse_input_lib.cpp

@@ -12,6 +12,6 @@ sf::Mouse::Button toLib(jt::MouseButtonCode key) noexcept
 
 bool jt::libKeyValue(jt::MouseButtonCode b)
 {
-    auto const libkey = toLib(b);
-    return sf::Mouse::isButtonPressed(libkey);
+    auto const libKey = toLib(b);
+    return sf::Mouse::isButtonPressed(libKey);
 }

impl/jamtemplate/sfml/render_window_lib.cpp

@@ -1,4 +1,5 @@
 #include "render_window_lib.hpp"
+#include "performance_measurement.hpp"
 #include <sprite.hpp>
 #include <imgui-SFML.h>
 #include <imgui.h>
@@ -47,6 +48,7 @@ jt::Vector2f jt::RenderWindow::getSize() const noexcept { return m_size; }
 
 void jt::RenderWindow::draw(std::unique_ptr<jt::Sprite>& spr)
 {
+    TimeMeasureObject obj { "jt::RenderWindow::draw" };
     if (!spr) [[unlikely]] {
         throw std::invalid_argument { "Cannot draw nullptr sprite" };
     }
@@ -55,6 +57,7 @@ void jt::RenderWindow::draw(std::unique_ptr<jt::Sprite>& spr)
 
 void jt::RenderWindow::display()
 {
+    TimeMeasureObject obj { "jt::RenderWindow::display" };
     if (m_renderGui) {
         m_hasBeenUpdatedAlready = false;
         ImGui::SFML::Render(*m_window.get());