From afce00a9908b2d6816ac5d1a0dacadf0b6841ecf Mon Sep 17 00:00:00 2001 From: BennyQBD Date: Wed, 18 Jun 2014 13:21:40 -0400 Subject: [PATCH] Included Basic Profiling Tools --- src/coreEngine.cpp | 25 +++++++++++++++++++---- src/game.cpp | 4 ++++ src/game.h | 8 +++++++- src/profiling.cpp | 45 +++++++++++++++++++++++++++++++++++++++++ src/profiling.h | 26 ++++++++++++++++++++++++ src/renderingEngine.cpp | 7 ++++++- src/renderingEngine.h | 6 ++++++ 7 files changed, 115 insertions(+), 6 deletions(-) create mode 100644 src/profiling.cpp create mode 100644 src/profiling.h diff --git a/src/coreEngine.cpp b/src/coreEngine.cpp index 10a3336..69d4e5e 100644 --- a/src/coreEngine.cpp +++ b/src/coreEngine.cpp @@ -38,6 +38,9 @@ void CoreEngine::Start() double unprocessedTime = 0; //Amount of passed time that the engine hasn't accounted for int frames = 0; //Number of frames rendered since last + ProfileTimer sleepTimer; + ProfileTimer swapBufferTimer; + ProfileTimer windowUpdateTimer; while(m_isRunning) { bool render = false; //Whether or not the game needs to be rerendered. @@ -51,11 +54,19 @@ void CoreEngine::Start() if(frameCounter >= 1.0) { - //The framecounter code here is a temporary, basic profiling tool. - //When proper profiling tools are implemented, this should probably be removed. + double totalTime = ((1000.0 * frameCounter)/((double)frames)); + double totalMeasuredTime = 0.0; - //printf("%i\n",frames); - printf("%f ms\n",1000.0/((double)frames)); + totalMeasuredTime += m_game->DisplayInputTime((double)frames); + totalMeasuredTime += m_game->DisplayUpdateTime((double)frames); + totalMeasuredTime += m_renderingEngine->DisplayRenderTime((double)frames); + totalMeasuredTime += sleepTimer.DisplayAndReset("Sleep Time: ", (double)frames); + totalMeasuredTime += windowUpdateTimer.DisplayAndReset("Window Update Time: ", (double)frames); + totalMeasuredTime += swapBufferTimer.DisplayAndReset("Buffer Swap Time: ", (double)frames); + totalMeasuredTime += m_renderingEngine->DisplayWindowSyncTime((double)frames); + + printf("Other Time: %f ms\n", (totalTime - totalMeasuredTime)); + printf("Total Time: %f ms\n\n", totalTime); frames = 0; frameCounter = 0; } @@ -67,12 +78,14 @@ void CoreEngine::Start() //unaccounted time can then be processed later, since it will remain stored in unprocessedTime. while(unprocessedTime > m_frameTime) { + windowUpdateTimer.StartInvocation(); m_window->Update(); if(m_window->IsCloseRequested()) { Stop(); } + windowUpdateTimer.StopInvocation(); //Input must be processed here because the window may have found new //input events from the OS when it updated. Since inputs can trigger @@ -94,14 +107,18 @@ void CoreEngine::Start() //The newly rendered image will be in the window's backbuffer, //so the buffers must be swapped to display the new image. + swapBufferTimer.StartInvocation(); m_window->SwapBuffers(); + swapBufferTimer.StopInvocation(); frames++; } else { //If no rendering is needed, sleep for some time so the OS //can use the processor for other tasks. + sleepTimer.StartInvocation(); Util::Sleep(1); + sleepTimer.StopInvocation(); } } } diff --git a/src/game.cpp b/src/game.cpp index 8a387d3..f52218b 100644 --- a/src/game.cpp +++ b/src/game.cpp @@ -4,12 +4,16 @@ void Game::ProcessInput(const Input& input, float delta) { + m_inputTimer.StartInvocation(); m_root.ProcessInputAll(input, delta); + m_inputTimer.StopInvocation(); } void Game::Update(float delta) { + m_updateTimer.StartInvocation(); m_root.UpdateAll(delta); + m_updateTimer.StopInvocation(); } void Game::Render(RenderingEngine* renderingEngine) diff --git a/src/game.h b/src/game.h index 7d819a3..78c0870 100644 --- a/src/game.h +++ b/src/game.h @@ -3,6 +3,7 @@ #include "gameObject.h" #include "coreEngine.h" +#include "profiling.h" class Game { @@ -15,6 +16,9 @@ class Game void Update(float delta); void Render(RenderingEngine* renderingEngine); + inline double DisplayInputTime(double dividend) { return m_inputTimer.DisplayAndReset("Input Time: ", dividend); } + inline double DisplayUpdateTime(double dividend) { return m_updateTimer.DisplayAndReset("Update Time: ", dividend); } + inline void SetEngine(CoreEngine* engine) { m_root.SetEngine(engine); } protected: void AddToScene(GameObject* child) { m_root.AddChild(child); } @@ -22,7 +26,9 @@ class Game Game(Game& game) {} void operator=(Game& game) {} - GameObject m_root; + ProfileTimer m_updateTimer; + ProfileTimer m_inputTimer; + GameObject m_root; }; #endif diff --git a/src/profiling.cpp b/src/profiling.cpp new file mode 100644 index 0000000..7817b82 --- /dev/null +++ b/src/profiling.cpp @@ -0,0 +1,45 @@ +#include "profiling.h" +#include "timing.h" +#include +#include + +void ProfileTimer::StartInvocation() +{ + m_startTime = Time::GetTime(); +} + +void ProfileTimer::StopInvocation() +{ + if(m_startTime == 0) + { + std::cout << "Error: StopInvocation called without matching start invocation" << std::endl; + assert(m_startTime != 0); + } + + m_numInvocations++; + m_totalTime += (Time::GetTime() - m_startTime); + m_startTime = 0; +} + +double ProfileTimer::GetTimeAndReset(double dividend) +{ + dividend = (dividend == 0) ? m_numInvocations : dividend; + double result = (m_totalTime == 0 && dividend == 0.0) ? 0.0 : (1000.0 * m_totalTime)/((double)dividend); + m_totalTime = 0.0; + m_numInvocations = 0; + + return result; +} + +double ProfileTimer::DisplayAndReset(const std::string& message, double dividend, int displayedMessageLength) +{ + std::string whiteSpace = ""; + for(int i = message.length(); i < displayedMessageLength; i++) + { + whiteSpace += " "; + } + + double time = GetTimeAndReset(dividend); + std::cout << message << whiteSpace << time << " ms" << std::endl; + return time; +} diff --git a/src/profiling.h b/src/profiling.h new file mode 100644 index 0000000..42a2c32 --- /dev/null +++ b/src/profiling.h @@ -0,0 +1,26 @@ +#ifndef PROFILING_H_INCLUDED +#define PROFILING_H_INCLUDED + +#include + +class ProfileTimer +{ +public: + ProfileTimer() : + m_numInvocations(0), + m_totalTime(0.0), + m_startTime(0) {} + + void StartInvocation(); + void StopInvocation(); + + double DisplayAndReset(const std::string& message, double dividend = 0, int displayedMessageLength = 40); + double GetTimeAndReset(double dividend = 0); +protected: +private: + int m_numInvocations; + double m_totalTime; + double m_startTime; +}; + +#endif // PROFILING_H_INCLUDED diff --git a/src/renderingEngine.cpp b/src/renderingEngine.cpp index dd3a63d..1f458d4 100644 --- a/src/renderingEngine.cpp +++ b/src/renderingEngine.cpp @@ -45,7 +45,7 @@ RenderingEngine::RenderingEngine(const Window& window) : SetFloat("fxaaReduceMin", 1.0f/128.0f); SetFloat("fxaaReduceMul", 1.0f/8.0f); - SetTexture("displayTexture", Texture(m_window->GetWidth(), m_window->GetHeight(), 0, GL_TEXTURE_2D, GL_LINEAR, GL_RGBA, GL_RGBA, false, GL_COLOR_ATTACHMENT0)); + SetTexture("displayTexture", Texture(m_window->GetWidth(), m_window->GetHeight(), 0, GL_TEXTURE_2D, GL_LINEAR, GL_RGBA, GL_RGBA, true, GL_COLOR_ATTACHMENT0)); glClearColor(0.0f, 0.0f, 0.0f, 0.0f); @@ -117,6 +117,7 @@ void RenderingEngine::ApplyFilter(const Shader& filter, const Texture& source, c void RenderingEngine::Render(const GameObject& object) { + m_renderProfileTimer.StartInvocation(); GetTexture("displayTexture").BindAsRenderTarget(); //m_window->BindAsRenderTarget(); //m_tempTarget->BindAsRenderTarget(); @@ -207,5 +208,9 @@ void RenderingEngine::Render(const GameObject& object) } SetVector3f("inverseFilterTextureSize", Vector3f(1.0f/GetTexture("displayTexture").GetWidth(), 1.0f/GetTexture("displayTexture").GetHeight(), 0.0f)); + m_renderProfileTimer.StopInvocation(); + + m_windowSyncProfileTimer.StartInvocation(); ApplyFilter(m_fxaaFilter, GetTexture("displayTexture"), 0); + m_windowSyncProfileTimer.StopInvocation(); } diff --git a/src/renderingEngine.h b/src/renderingEngine.h index 67a8aa1..46b3962 100644 --- a/src/renderingEngine.h +++ b/src/renderingEngine.h @@ -7,6 +7,7 @@ #include "material.h" #include "mesh.h" #include "window.h" +#include "profiling.h" #include #include class GameObject; @@ -28,6 +29,9 @@ class RenderingEngine : public MappedValues throw uniformType + " is not supported by the rendering engine"; } + inline double DisplayRenderTime(double dividend) { return m_renderProfileTimer.DisplayAndReset("Render Time: ", dividend); } + inline double DisplayWindowSyncTime(double dividend) { return m_windowSyncProfileTimer.DisplayAndReset("Window Sync Time: ", dividend); } + inline const BaseLight& GetActiveLight() const { return *m_activeLight; } inline unsigned int GetSamplerSlot(const std::string& samplerName) const { return m_samplerMap.find(samplerName)->second; } inline const Matrix4f& GetLightMatrix() const { return m_lightMatrix; } @@ -37,6 +41,8 @@ class RenderingEngine : public MappedValues static const int NUM_SHADOW_MAPS = 10; static const Matrix4f BIAS_MATRIX; + ProfileTimer m_renderProfileTimer; + ProfileTimer m_windowSyncProfileTimer; Transform m_planeTransform; Mesh m_plane;