From 4e1535ca99f7e201ddde6af82a396ab883dfa62a Mon Sep 17 00:00:00 2001 From: Daniel Evans Date: Tue, 28 Aug 2018 19:35:49 +0100 Subject: [PATCH 1/8] rwgame: Refactor run() into seperate methods to ease profiling --- rwgame/RWGame.cpp | 174 +++++++++++++++++++++++++--------------------- rwgame/RWGame.hpp | 6 ++ 2 files changed, 100 insertions(+), 80 deletions(-) diff --git a/rwgame/RWGame.cpp b/rwgame/RWGame.cpp index 624e041d..506d1a60 100644 --- a/rwgame/RWGame.cpp +++ b/rwgame/RWGame.cpp @@ -367,45 +367,7 @@ int RWGame::run() { while (StateManager::currentState() && running) { RW_PROFILE_FRAME_BOUNDARY(); - RW_PROFILE_BEGIN("Input"); - SDL_Event event; - while (SDL_PollEvent(&event)) { - switch (event.type) { - case SDL_QUIT: - running = false; - break; - - case SDL_WINDOWEVENT: - switch (event.window.event) { - case SDL_WINDOWEVENT_FOCUS_GAINED: - inFocus = true; - break; - - case SDL_WINDOWEVENT_FOCUS_LOST: - inFocus = false; - break; - } - break; - - case SDL_KEYDOWN: - globalKeyEvent(event); - break; - - case SDL_MOUSEMOTION: - event.motion.xrel *= MOUSE_SENSITIVITY_SCALE; - event.motion.yrel *= MOUSE_SENSITIVITY_SCALE; - break; - } - - GameInput::updateGameInputState(&getState()->input[0], event); - - RW_PROFILE_BEGIN("State"); - if (StateManager::currentState()) { - StateManager::currentState()->handleEvent(event); - } - RW_PROFILE_END() - } - RW_PROFILE_END(); + running = updateInput(); auto currentFrame = chrono::steady_clock::now(); auto frameTime = @@ -420,48 +382,10 @@ int RWGame::run() { frameTime = 0.1f; } - auto deltaTimeWithTimeScale = - deltaTime * world->state->basic.timeScale; - - RW_PROFILE_BEGIN("Update"); - while (accumulatedTime >= deltaTime) { - if (!StateManager::currentState()) { - break; - } - - RW_PROFILE_BEGIN("physics"); - world->dynamicsWorld->stepSimulation( - deltaTimeWithTimeScale, kMaxPhysicsSubSteps, deltaTime); - RW_PROFILE_END(); - - RW_PROFILE_BEGIN("state"); - StateManager::get().tick(deltaTimeWithTimeScale); - RW_PROFILE_END(); - - RW_PROFILE_BEGIN("engine"); - tick(deltaTimeWithTimeScale); - RW_PROFILE_END(); - - getState()->swapInputState(); - - accumulatedTime -= deltaTime; - } - RW_PROFILE_END(); + accumulatedTime = tickWorld(deltaTime, accumulatedTime); } - RW_PROFILE_BEGIN("Render"); - RW_PROFILE_BEGIN("engine"); render(1, frameTime); - RW_PROFILE_END(); - - RW_PROFILE_BEGIN("state"); - if (StateManager::currentState()) { - StateManager::get().draw(&renderer); - } - RW_PROFILE_END(); - RW_PROFILE_END(); - - renderProfile(); getWindow().swap(); @@ -476,6 +400,79 @@ int RWGame::run() { return 0; } +float RWGame::tickWorld(const float deltaTime, float accumulatedTime) { + auto deltaTimeWithTimeScale = + deltaTime * world->state->basic.timeScale; + + RW_PROFILE_BEGIN("Update"); + while (accumulatedTime >= deltaTime) { + if (!StateManager::currentState()) { + break; + } + + RW_PROFILE_BEGIN("physics"); + world->dynamicsWorld->stepSimulation( + deltaTimeWithTimeScale, kMaxPhysicsSubSteps, deltaTime); + RW_PROFILE_END(); + + RW_PROFILE_BEGIN("state"); + StateManager::get().tick(deltaTimeWithTimeScale); + RW_PROFILE_END(); + + RW_PROFILE_BEGIN("engine"); + tick(deltaTimeWithTimeScale); + RW_PROFILE_END(); + + getState()->swapInputState(); + + accumulatedTime -= deltaTime; + } + RW_PROFILE_END(); + return accumulatedTime; +} + +bool RWGame::updateInput() { + RW_PROFILE_BEGIN("Input"); + SDL_Event event; + while (SDL_PollEvent(&event)) { + switch (event.type) { + case SDL_QUIT: + return false; + + case SDL_WINDOWEVENT: + switch (event.window.event) { + case SDL_WINDOWEVENT_FOCUS_GAINED: + inFocus = true; + break; + + case SDL_WINDOWEVENT_FOCUS_LOST: + inFocus = false; + break; + } + break; + + case SDL_KEYDOWN: + globalKeyEvent(event); + break; + + case SDL_MOUSEMOTION: + event.motion.xrel *= MOUSE_SENSITIVITY_SCALE; + event.motion.yrel *= MOUSE_SENSITIVITY_SCALE; + break; + } + + GameInput::updateGameInputState(&getState()->input[0], event); + + RW_PROFILE_BEGIN("State"); + if (StateManager::currentState()) { + StateManager::currentState()->handleEvent(event); + } + RW_PROFILE_END() + } + RW_PROFILE_END(); + return true; +} + void RWGame::tick(float dt) { State* currState = StateManager::get().states.back().get(); @@ -572,6 +569,9 @@ void RWGame::tick(float dt) { } void RWGame::render(float alpha, float time) { + RW_PROFILE_BEGIN("Render"); + RW_PROFILE_BEGIN("engine"); + lastDraws = getRenderer().getRenderer()->getDrawCount(); getRenderer().getRenderer()->swap(); @@ -606,6 +606,22 @@ void RWGame::render(float alpha, float time) { renderer.getRenderer()->popDebugGroup(); + renderDebugView(time, viewCam); + + if (!world->isPaused()) drawOnScreenText(world.get(), &renderer); + RW_PROFILE_END(); + + RW_PROFILE_BEGIN("state"); + if (StateManager::currentState()) { + StateManager::get().draw(&renderer); + } + RW_PROFILE_END(); + RW_PROFILE_END(); + + renderProfile(); +} + +void RWGame::renderDebugView(float time, ViewCamera &viewCam) { RW_PROFILE_BEGIN("debug"); switch (debugview_) { case DebugViewMode::General: @@ -625,8 +641,6 @@ void RWGame::render(float alpha, float time) { break; } RW_PROFILE_END(); - - if (!world->isPaused()) drawOnScreenText(world.get(), &renderer); } void RWGame::renderDebugStats(float time) { diff --git a/rwgame/RWGame.hpp b/rwgame/RWGame.hpp index e60865ff..28c7f4ab 100644 --- a/rwgame/RWGame.hpp +++ b/rwgame/RWGame.hpp @@ -132,6 +132,12 @@ private: void handleCheatInput(char symbol); void globalKeyEvent(const SDL_Event& event); + + bool updateInput(); + + float tickWorld(const float deltaTime, float accumulatedTime); + + void renderDebugView(float time, ViewCamera &viewCam); }; #endif From b9ef99e752424619c30ea6676c6f6276ebbee251 Mon Sep 17 00:00:00 2001 From: Daniel Evans Date: Tue, 28 Aug 2018 23:45:05 +0100 Subject: [PATCH 2/8] Extract GameRenderer object handling into seperate method --- rwengine/src/render/GameRenderer.cpp | 178 ++++++++++++++------------- rwengine/src/render/GameRenderer.hpp | 2 + 2 files changed, 92 insertions(+), 88 deletions(-) diff --git a/rwengine/src/render/GameRenderer.cpp b/rwengine/src/render/GameRenderer.cpp index f67398ae..f30d31e9 100644 --- a/rwengine/src/render/GameRenderer.cpp +++ b/rwengine/src/render/GameRenderer.cpp @@ -247,94 +247,7 @@ void GameRenderer::renderWorld(GameWorld* world, const ViewCamera& camera, culled = 0; - renderer->useProgram(worldProg.get()); - - //=============================================================== - // Render List Construction - //--------------------------------------------------------------- - - RW_PROFILE_BEGIN("RenderList"); - - // This is sequential at the moment, it should be easy to make it - // run in parallel with a good threading system. - RenderList renderList; - // Naive optimisation, assume 50% hitrate - renderList.reserve(world->allObjects.size() * 0.5f); - - RW_PROFILE_BEGIN("Build"); - - ObjectRenderer objectRenderer(_renderWorld, - (cullOverride ? cullingCamera : _camera), - _renderAlpha, getMissingTexture()); - - // World Objects - for (auto object : world->allObjects) { - objectRenderer.buildRenderList(object, renderList); - } - - // Area indicators - auto sphereModel = getSpecialModel(ZoneCylinderA); - for (auto& i : world->getAreaIndicators()) { - glm::mat4 m(1.f); - m = glm::translate(m, i.position); - m = glm::scale( - m, glm::vec3(i.radius + - 0.15f * glm::sin(_renderWorld->getGameTime() * 5.f))); - - objectRenderer.renderClump(sphereModel.get(), m, nullptr, renderList); - } - - // Render arrows above anything that isn't radar only (or hidden) - auto arrowModel = getSpecialModel(Arrow); - for (auto& blip : world->state->radarBlips) { - auto dm = blip.second.display; - if (dm == BlipData::Hide || dm == BlipData::RadarOnly) { - continue; - } - - glm::mat4 model{1.0f}; - - if (blip.second.target > 0) { - auto object = world->getBlipTarget(blip.second); - if (object) { - model = object->getTimeAdjustedTransform(_renderAlpha); - } - } else { - model = glm::translate(model, blip.second.coord); - } - - float a = world->getGameTime() * glm::pi(); - model = glm::translate(model, - glm::vec3(0.f, 0.f, 2.5f + glm::sin(a) * 0.5f)); - model = glm::rotate(model, a, glm::vec3(0.f, 0.f, 1.f)); - model = glm::scale(model, glm::vec3(1.5f, 1.5f, 1.5f)); - objectRenderer.renderClump(arrowModel.get(), model, nullptr, renderList); - } - - RW_PROFILE_END(); - culled += objectRenderer.culled; - renderer->pushDebugGroup("Objects"); - renderer->pushDebugGroup("RenderList"); - // Also parallelizable - RW_PROFILE_BEGIN("Sort"); - // Earlier position in the array means earlier object's rendering - // Transparent objects should be sorted and rendered after opaque - std::sort(renderList.begin(), renderList.end(), - [](const Renderer::RenderInstruction& a, - const Renderer::RenderInstruction& b) { - if (a.drawInfo.blendMode==BlendMode::BLEND_NONE && b.drawInfo.blendMode!=BlendMode::BLEND_NONE) return true; - if (a.drawInfo.blendMode!=BlendMode::BLEND_NONE && b.drawInfo.blendMode==BlendMode::BLEND_NONE) return false; - return (a.sortKey > b.sortKey); - }); - RW_PROFILE_END(); - RW_PROFILE_BEGIN("Draw"); - renderer->drawBatched(renderList); - RW_PROFILE_END(); - - renderer->popDebugGroup(); - profObjects = renderer->popDebugGroup(); - - RW_PROFILE_END(); + renderObjects(world); renderer->pushDebugGroup("Water"); @@ -392,6 +305,95 @@ void GameRenderer::renderWorld(GameWorld* world, const ViewCamera& camera, renderPostProcess(); } +void GameRenderer::renderObjects(const GameWorld *world) { + renderer->useProgram(worldProg.get()); + + RW_PROFILE_BEGIN("RenderList"); + + // This is sequential at the moment, it should be easy to make it + // run in parallel with a good threading system. + RenderList renderList; + // Naive optimisation, assume 50% hitrate + renderList.reserve(world->allObjects.size() * 0.5f); + + RW_PROFILE_BEGIN("Build"); + + ObjectRenderer objectRenderer(_renderWorld, + (cullOverride ? cullingCamera : _camera), + _renderAlpha, getMissingTexture()); + + // World Objects + for (auto object : world->allObjects) { + objectRenderer.buildRenderList(object, renderList); + } + + // Area indicators + auto sphereModel = getSpecialModel(ZoneCylinderA); + for (auto &i : world->getAreaIndicators()) { + glm::mat4 m(1.f); + m = translate(m, i.position); + m = scale( + m, glm::vec3(i.radius + + 0.15f * sin(_renderWorld->getGameTime() * 5.f))); + + objectRenderer.renderClump(sphereModel.get(), m, nullptr, renderList); + } + + // Render arrows above anything that isn't radar only (or hidden) + auto arrowModel = getSpecialModel(Arrow); + for (auto &blip : world->state->radarBlips) { + auto dm = blip.second.display; + if (dm == BlipData::Hide || dm == BlipData::RadarOnly) { + continue; + } + + glm::mat4 model{1.0f}; + + if (blip.second.target > 0) { + auto object = world->getBlipTarget(blip.second); + if (object) { + model = object->getTimeAdjustedTransform(_renderAlpha); + } + } else { + model = translate(model, blip.second.coord); + } + + float a = world->getGameTime() * glm::pi(); + model = translate(model, + glm::vec3(0.f, 0.f, 2.5f + sin(a) * 0.5f)); + model = rotate(model, a, glm::vec3(0.f, 0.f, 1.f)); + model = scale(model, glm::vec3(1.5f, 1.5f, 1.5f)); + objectRenderer.renderClump(arrowModel.get(), model, nullptr, renderList); + } + + RW_PROFILE_END(); + culled += objectRenderer.culled; + renderer->pushDebugGroup("Objects"); + renderer->pushDebugGroup("RenderList"); + // Also parallelizable + RW_PROFILE_BEGIN("Sort"); + // Earlier position in the array means earlier object's rendering + // Transparent objects should be sorted and rendered after opaque + sort(renderList.begin(), renderList.end(), + [](const Renderer::RenderInstruction &a, + const Renderer::RenderInstruction &b) { + if (a.drawInfo.blendMode == BlendMode::BLEND_NONE && b.drawInfo.blendMode != BlendMode::BLEND_NONE) + return true; + if (a.drawInfo.blendMode != BlendMode::BLEND_NONE && b.drawInfo.blendMode == BlendMode::BLEND_NONE) + return false; + return (a.sortKey > b.sortKey); + }); + RW_PROFILE_END(); + RW_PROFILE_BEGIN("Draw"); + renderer->drawBatched(renderList); + RW_PROFILE_END(); + + renderer->popDebugGroup(); + profObjects = renderer->popDebugGroup(); + + RW_PROFILE_END(); +} + void GameRenderer::renderSplash(GameWorld* world, GLuint splashTexName, glm::u16vec3 fc) { float fadeTimer = world->getGameTime() - world->state->fadeStart; diff --git a/rwengine/src/render/GameRenderer.hpp b/rwengine/src/render/GameRenderer.hpp index 5fc84fcc..65915cbf 100644 --- a/rwengine/src/render/GameRenderer.hpp +++ b/rwengine/src/render/GameRenderer.hpp @@ -172,6 +172,8 @@ private: } void drawRect(const glm::vec4& colour, TextureData* texture, glm::vec4& extents); + + void renderObjects(const GameWorld *world); }; #endif From 63a2caa4718e7ff0e8c84a24177c36ef1991d535 Mon Sep 17 00:00:00 2001 From: Daniel Evans Date: Wed, 29 Aug 2018 21:06:03 +0100 Subject: [PATCH 3/8] Add microprofile to rwengine dependencies --- .gitmodules | 3 +++ CMakeLists.txt | 2 ++ external/CMakeLists.txt | 3 +++ external/microprofile/CMakeLists.txt | 23 +++++++++++++++++++++++ external/microprofile/microprofile | 1 + rwengine/CMakeLists.txt | 7 +++++++ 6 files changed, 39 insertions(+) create mode 100644 .gitmodules create mode 100644 external/CMakeLists.txt create mode 100644 external/microprofile/CMakeLists.txt create mode 160000 external/microprofile/microprofile diff --git a/.gitmodules b/.gitmodules new file mode 100644 index 00000000..b044f920 --- /dev/null +++ b/.gitmodules @@ -0,0 +1,3 @@ +[submodule "external/microprofile/microprofile"] + path = external/microprofile/microprofile + url = https://github.com/jonasmr/microprofile.git diff --git a/CMakeLists.txt b/CMakeLists.txt index ee3345e1..2d5fa344 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -65,6 +65,8 @@ endif() # Create a rw_interface TARGET that holds all compiler options include("${PROJECT_SOURCE_DIR}/cmake_configure.cmake") +add_subdirectory(external) + add_subdirectory(rwcore) add_subdirectory(rwengine) add_subdirectory(rwgame) diff --git a/external/CMakeLists.txt b/external/CMakeLists.txt new file mode 100644 index 00000000..de3bbe45 --- /dev/null +++ b/external/CMakeLists.txt @@ -0,0 +1,3 @@ +if(ENABLE_PROFILING) + add_subdirectory(microprofile) +endif() diff --git a/external/microprofile/CMakeLists.txt b/external/microprofile/CMakeLists.txt new file mode 100644 index 00000000..3552df52 --- /dev/null +++ b/external/microprofile/CMakeLists.txt @@ -0,0 +1,23 @@ +add_library(microprofile STATIC + microprofile/microprofile.h + microprofile/microprofile_html.h + microprofile/microprofile.cpp +) + +target_include_directories(microprofile + PUBLIC + "${CMAKE_CURRENT_SOURCE_DIR}/microprofile" +) + +target_compile_definitions(microprofile + PUBLIC + MICROPROFILE_GPU_TIMERS=0 +) + +find_package(Threads REQUIRED) +target_link_libraries(microprofile + PUBLIC + Threads::Threads +) + +add_library(microprofile::microprofile ALIAS microprofile) diff --git a/external/microprofile/microprofile b/external/microprofile/microprofile new file mode 160000 index 00000000..b49ae802 --- /dev/null +++ b/external/microprofile/microprofile @@ -0,0 +1 @@ +Subproject commit b49ae80262b206a579808dc3e442f0d8aafe81e9 diff --git a/rwengine/CMakeLists.txt b/rwengine/CMakeLists.txt index 546f090a..07c132e7 100644 --- a/rwengine/CMakeLists.txt +++ b/rwengine/CMakeLists.txt @@ -151,6 +151,13 @@ target_link_libraries(rwengine OpenAL::OpenAL ) +if (ENABLE_PROFILING) + target_link_libraries(rwengine + PUBLIC + microprofile::microprofile + ) +endif() + target_include_directories(rwengine PUBLIC "${CMAKE_CURRENT_SOURCE_DIR}/src" From 080a0fe050ac81a3483a3cc6fdbab1bd28da917a Mon Sep 17 00:00:00 2001 From: Daniel Evans Date: Thu, 30 Aug 2018 15:47:12 +0100 Subject: [PATCH 4/8] Use microprofile for profiling --- rwengine/src/core/Profiler.hpp | 81 +++++---------------------- rwengine/src/engine/GameData.cpp | 3 + rwengine/src/render/GameRenderer.cpp | 13 +---- rwgame/RWGame.cpp | 84 ++++------------------------ rwgame/RWGame.hpp | 1 - 5 files changed, 31 insertions(+), 151 deletions(-) diff --git a/rwengine/src/core/Profiler.hpp b/rwengine/src/core/Profiler.hpp index 5ae25d93..b3312dae 100644 --- a/rwengine/src/core/Profiler.hpp +++ b/rwengine/src/core/Profiler.hpp @@ -2,73 +2,22 @@ #define _RWENGINE_PROFILER_HPP_ #ifdef RW_PROFILER -#include -#include -#include -#include -#include -#define time_unit std::chrono::microseconds - -#include - -namespace perf { - -struct ProfileEntry { - std::string label; - int64_t start; - int64_t end; - std::vector childProfiles; -}; - -class Profiler { - ProfileEntry frame; - std::chrono::high_resolution_clock::time_point frameBegin; - std::stack currentStack; - -public: - static Profiler& get() { - static Profiler profile; - return profile; - } - - const ProfileEntry& getFrame() const { - return frame; - } - - void startFrame() { - frameBegin = std::chrono::high_resolution_clock::now(); - frame = {"Frame", 0, 0, {}}; - } - - void beginEvent(const std::string& label) { - auto now = std::chrono::duration_cast( - std::chrono::high_resolution_clock::now() - frameBegin); - currentStack.push({label, now.count(), 0, {}}); - } - - void endEvent() { - auto now = std::chrono::duration_cast( - std::chrono::high_resolution_clock::now() - frameBegin); - RW_CHECK(currentStack.size() > 0, "Perf stack is empty"); - currentStack.top().end = now.count(); - if (currentStack.size() == 1) { - frame.childProfiles.push_back(currentStack.top()); - currentStack.pop(); - } else { - auto tmp = currentStack.top(); - currentStack.pop(); - currentStack.top().childProfiles.push_back(std::move(tmp)); - } - } -}; -} -#define RW_PROFILE_FRAME_BOUNDARY() perf::Profiler::get().startFrame(); -#define RW_PROFILE_BEGIN(label) perf::Profiler::get().beginEvent(label); -#define RW_PROFILE_END() perf::Profiler::get().endEvent(); +#include +#define RW_PROFILE_THREAD(name) MicroProfileOnThreadCreate(name) +#define RW_PROFILE_FRAME_BOUNDARY() MicroProfileFlip(nullptr) +#define RW_PROFILE_SCOPE(label) MICROPROFILE_SCOPEI("Default", label, MP_YELLOW) +#define RW_PROFILE_COUNTER_ADD(name, qty) MICROPROFILE_COUNTER_ADD(name, qty) +#define RW_PROFILE_COUNTER_SET(name, qty) MICROPROFILE_COUNTER_SET(name, qty) +#define RW_TIMELINE_ENTER(name, color) MICROPROFILE_TIMELINE_ENTER_STATIC(color, name) +#define RW_TIMELINE_LEAVE(name) MICROPROFILE_TIMELINE_LEAVE_STATIC(name) #else -#define RW_PROFILE_FRAME_BOUNDARY() -#define RW_PROFILE_BEGIN(label) -#define RW_PROFILE_END() +#define RW_PROFILE_THREAD(name) do {} while (0) +#define RW_PROFILE_FRAME_BOUNDARY() do {} while (0) +#define RW_PROFILE_SCOPE(label) do {} while (0) +#define RW_PROFILE_COUNTER_ADD(name, qty) do {} while (0) +#define RW_PROFILE_COUNTER_SET(name, qty) do {} while (0) +#define RW_TIMELINE_ENTER(name, color) do {} while (0) +#define RW_TIMELINE_LEAVE(name) do {} while (0) #endif #endif diff --git a/rwengine/src/engine/GameData.cpp b/rwengine/src/engine/GameData.cpp index b6d5779e..2658e66b 100644 --- a/rwengine/src/engine/GameData.cpp +++ b/rwengine/src/engine/GameData.cpp @@ -18,6 +18,7 @@ #include #include "core/Logger.hpp" +#include "core/Profiler.hpp" #include "engine/GameState.hpp" #include "engine/GameWorld.hpp" #include "loaders/LoaderCOL.hpp" @@ -349,6 +350,7 @@ void GameData::loadWater(const std::string& path) { } void GameData::loadTXD(const std::string& name) { + RW_PROFILE_COUNTER_ADD("loadTXD", 1); auto slot = name; auto ext = name.find(".txd"); if (ext != std::string::npos) { @@ -368,6 +370,7 @@ void GameData::loadTXD(const std::string& name) { } TextureArchive GameData::loadTextureArchive(const std::string& name) { + RW_PROFILE_COUNTER_ADD("loadTextureArchive", 1); /// @todo refactor loadTXD to use correct file locations auto file = index.openFile(name); if (!file.data) { diff --git a/rwengine/src/render/GameRenderer.cpp b/rwengine/src/render/GameRenderer.cpp index f30d31e9..a3748dfe 100644 --- a/rwengine/src/render/GameRenderer.cpp +++ b/rwengine/src/render/GameRenderer.cpp @@ -306,9 +306,9 @@ void GameRenderer::renderWorld(GameWorld* world, const ViewCamera& camera, } void GameRenderer::renderObjects(const GameWorld *world) { - renderer->useProgram(worldProg.get()); + RW_PROFILE_SCOPE(__func__); - RW_PROFILE_BEGIN("RenderList"); + renderer->useProgram(worldProg.get()); // This is sequential at the moment, it should be easy to make it // run in parallel with a good threading system. @@ -316,8 +316,6 @@ void GameRenderer::renderObjects(const GameWorld *world) { // Naive optimisation, assume 50% hitrate renderList.reserve(world->allObjects.size() * 0.5f); - RW_PROFILE_BEGIN("Build"); - ObjectRenderer objectRenderer(_renderWorld, (cullOverride ? cullingCamera : _camera), _renderAlpha, getMissingTexture()); @@ -366,12 +364,10 @@ void GameRenderer::renderObjects(const GameWorld *world) { objectRenderer.renderClump(arrowModel.get(), model, nullptr, renderList); } - RW_PROFILE_END(); culled += objectRenderer.culled; renderer->pushDebugGroup("Objects"); renderer->pushDebugGroup("RenderList"); // Also parallelizable - RW_PROFILE_BEGIN("Sort"); // Earlier position in the array means earlier object's rendering // Transparent objects should be sorted and rendered after opaque sort(renderList.begin(), renderList.end(), @@ -383,15 +379,10 @@ void GameRenderer::renderObjects(const GameWorld *world) { return false; return (a.sortKey > b.sortKey); }); - RW_PROFILE_END(); - RW_PROFILE_BEGIN("Draw"); renderer->drawBatched(renderList); - RW_PROFILE_END(); renderer->popDebugGroup(); profObjects = renderer->popDebugGroup(); - - RW_PROFILE_END(); } void GameRenderer::renderSplash(GameWorld* world, GLuint splashTexName, glm::u16vec3 fc) { diff --git a/rwgame/RWGame.cpp b/rwgame/RWGame.cpp index 506d1a60..d348a341 100644 --- a/rwgame/RWGame.cpp +++ b/rwgame/RWGame.cpp @@ -45,6 +45,9 @@ RWGame::RWGame(Logger& log, int argc, char* argv[]) : GameBase(log, argc, argv) , data(&log, config.getGameDataPath()) , renderer(&log, &data) { + RW_PROFILE_THREAD("Main"); + RW_TIMELINE_ENTER("Startup", MP_YELLOW); + bool newgame = options.count("newgame"); bool test = options.count("test"); std::string startSave( @@ -106,6 +109,7 @@ RWGame::RWGame(Logger& log, int argc, char* argv[]) }); log.info("Game", "Started"); + RW_TIMELINE_LEAVE("Startup"); } RWGame::~RWGame() { @@ -401,38 +405,31 @@ int RWGame::run() { } float RWGame::tickWorld(const float deltaTime, float accumulatedTime) { + RW_PROFILE_SCOPE(__func__); auto deltaTimeWithTimeScale = deltaTime * world->state->basic.timeScale; - RW_PROFILE_BEGIN("Update"); while (accumulatedTime >= deltaTime) { if (!StateManager::currentState()) { break; } - RW_PROFILE_BEGIN("physics"); world->dynamicsWorld->stepSimulation( deltaTimeWithTimeScale, kMaxPhysicsSubSteps, deltaTime); - RW_PROFILE_END(); - RW_PROFILE_BEGIN("state"); StateManager::get().tick(deltaTimeWithTimeScale); - RW_PROFILE_END(); - RW_PROFILE_BEGIN("engine"); tick(deltaTimeWithTimeScale); - RW_PROFILE_END(); getState()->swapInputState(); accumulatedTime -= deltaTime; } - RW_PROFILE_END(); return accumulatedTime; } bool RWGame::updateInput() { - RW_PROFILE_BEGIN("Input"); + RW_PROFILE_SCOPE(__func__); SDL_Event event; while (SDL_PollEvent(&event)) { switch (event.type) { @@ -463,17 +460,16 @@ bool RWGame::updateInput() { GameInput::updateGameInputState(&getState()->input[0], event); - RW_PROFILE_BEGIN("State"); if (StateManager::currentState()) { + RW_PROFILE_SCOPE("State"); StateManager::currentState()->handleEvent(event); } - RW_PROFILE_END() } - RW_PROFILE_END(); return true; } void RWGame::tick(float dt) { + RW_PROFILE_SCOPE(__func__); State* currState = StateManager::get().states.back().get(); static float clockAccumulator = 0.f; @@ -569,8 +565,7 @@ void RWGame::tick(float dt) { } void RWGame::render(float alpha, float time) { - RW_PROFILE_BEGIN("Render"); - RW_PROFILE_BEGIN("engine"); + RW_PROFILE_SCOPE(__func__); lastDraws = getRenderer().getRenderer()->getDrawCount(); @@ -600,29 +595,22 @@ void RWGame::render(float alpha, float time) { renderer.getRenderer()->pushDebugGroup("World"); - RW_PROFILE_BEGIN("world"); renderer.renderWorld(world.get(), viewCam, alpha); - RW_PROFILE_END(); renderer.getRenderer()->popDebugGroup(); renderDebugView(time, viewCam); if (!world->isPaused()) drawOnScreenText(world.get(), &renderer); - RW_PROFILE_END(); - RW_PROFILE_BEGIN("state"); if (StateManager::currentState()) { + RW_PROFILE_SCOPE("state"); StateManager::get().draw(&renderer); } - RW_PROFILE_END(); - RW_PROFILE_END(); - - renderProfile(); } void RWGame::renderDebugView(float time, ViewCamera &viewCam) { - RW_PROFILE_BEGIN("debug"); + RW_PROFILE_SCOPE(__func__); switch (debugview_) { case DebugViewMode::General: renderDebugStats(time); @@ -640,7 +628,6 @@ void RWGame::renderDebugView(float time, ViewCamera &viewCam) { default: break; } - RW_PROFILE_END(); } void RWGame::renderDebugStats(float time) { @@ -851,55 +838,6 @@ void RWGame::renderDebugObjects(float time, ViewCamera& camera) { } } -void RWGame::renderProfile() { -#ifdef RW_PROFILER - auto& frame = perf::Profiler::get().getFrame(); - constexpr float upperlimit = 30000.f; - constexpr float lineHeight = 15.f; - static std::vector perf_colours; - if (perf_colours.size() == 0) { - float c = 8.f; - for (int r = 0; r < c; ++r) { - for (int g = 0; g < c; ++g) { - for (int b = 0; b < c; ++b) { - perf_colours.emplace_back(r / c, g / c, b / c, 1.f); - } - } - } - } - - float xscale = renderer.getRenderer()->getViewport().x / upperlimit; - TextRenderer::TextInfo ti; - ti.align = TextRenderer::TextInfo::TextAlignment::Left; - ti.font = FONT_ARIAL; - ti.size = lineHeight - 2.f; - ti.baseColour = glm::u8vec3(255); - std::function renderEntry = - [&](const perf::ProfileEntry& entry, int depth) { - int g = 0; - for (auto& event : entry.childProfiles) { - auto duration = event.end - event.start; - float y = 60.f + (depth * (lineHeight + 5.f)); - renderer.drawColour( - perf_colours[(std::hash()(entry.label) * - (g++)) % - perf_colours.size()], - {xscale * event.start, y, xscale * duration, lineHeight}); - ti.screenPosition.x = xscale * (event.start); - ti.screenPosition.y = y + 2.f; - ti.text = GameStringUtil::fromString( - event.label + " " + std::to_string(duration) + " us ", ti.font); - renderer.text.renderText(ti); - renderEntry(event, depth + 1); - } - }; - renderEntry(frame, 0); - ti.screenPosition = glm::vec2(xscale * (16000), 40.f); - ti.text = GameStringUtil::fromString(".16 ms", ti.font); - renderer.text.renderText(ti); -#endif -} - void RWGame::globalKeyEvent(const SDL_Event& event) { const auto toggle_debug = [&](DebugViewMode m) { debugview_ = debugview_ == m ? DebugViewMode::Disabled : m; diff --git a/rwgame/RWGame.hpp b/rwgame/RWGame.hpp index 28c7f4ab..8eab6aff 100644 --- a/rwgame/RWGame.hpp +++ b/rwgame/RWGame.hpp @@ -127,7 +127,6 @@ private: void renderDebugStats(float time); void renderDebugPaths(float time); void renderDebugObjects(float time, ViewCamera& camera); - void renderProfile(); void handleCheatInput(char symbol); From 1efe3840b8beb36a2ea1d8b92d74503fe3936e4d Mon Sep 17 00:00:00 2001 From: Daniel Evans Date: Fri, 31 Aug 2018 16:29:31 +0100 Subject: [PATCH 5/8] Increase profiler coverage in GameRenderer/OpenGLRenderer --- rwengine/src/render/GameRenderer.cpp | 20 ++++++++++++++------ rwengine/src/render/GameRenderer.hpp | 2 ++ rwengine/src/render/OpenGLRenderer.cpp | 2 ++ 3 files changed, 18 insertions(+), 6 deletions(-) diff --git a/rwengine/src/render/GameRenderer.cpp b/rwengine/src/render/GameRenderer.cpp index a3748dfe..cd0d8ce9 100644 --- a/rwengine/src/render/GameRenderer.cpp +++ b/rwengine/src/render/GameRenderer.cpp @@ -309,7 +309,18 @@ void GameRenderer::renderObjects(const GameWorld *world) { RW_PROFILE_SCOPE(__func__); renderer->useProgram(worldProg.get()); + RenderList renderList = createObjectRenderList(world); + renderer->pushDebugGroup("Objects"); + renderer->pushDebugGroup("RenderList"); + renderer->drawBatched(renderList); + + renderer->popDebugGroup(); + profObjects = renderer->popDebugGroup(); +} + +RenderList GameRenderer::createObjectRenderList(const GameWorld *world) { + RW_PROFILE_SCOPE(__func__); // This is sequential at the moment, it should be easy to make it // run in parallel with a good threading system. RenderList renderList; @@ -363,10 +374,9 @@ void GameRenderer::renderObjects(const GameWorld *world) { model = scale(model, glm::vec3(1.5f, 1.5f, 1.5f)); objectRenderer.renderClump(arrowModel.get(), model, nullptr, renderList); } - culled += objectRenderer.culled; - renderer->pushDebugGroup("Objects"); - renderer->pushDebugGroup("RenderList"); + + RW_PROFILE_SCOPE("sortRenderList"); // Also parallelizable // Earlier position in the array means earlier object's rendering // Transparent objects should be sorted and rendered after opaque @@ -379,10 +389,8 @@ void GameRenderer::renderObjects(const GameWorld *world) { return false; return (a.sortKey > b.sortKey); }); - renderer->drawBatched(renderList); - renderer->popDebugGroup(); - profObjects = renderer->popDebugGroup(); + return renderList; } void GameRenderer::renderSplash(GameWorld* world, GLuint splashTexName, glm::u16vec3 fc) { diff --git a/rwengine/src/render/GameRenderer.hpp b/rwengine/src/render/GameRenderer.hpp index 65915cbf..e2550bf0 100644 --- a/rwengine/src/render/GameRenderer.hpp +++ b/rwengine/src/render/GameRenderer.hpp @@ -174,6 +174,8 @@ private: void drawRect(const glm::vec4& colour, TextureData* texture, glm::vec4& extents); void renderObjects(const GameWorld *world); + + RenderList createObjectRenderList(const GameWorld *world); }; #endif diff --git a/rwengine/src/render/OpenGLRenderer.cpp b/rwengine/src/render/OpenGLRenderer.cpp index ce91c06d..a3459519 100644 --- a/rwengine/src/render/OpenGLRenderer.cpp +++ b/rwengine/src/render/OpenGLRenderer.cpp @@ -6,6 +6,7 @@ #include #include +#include #include #include @@ -315,6 +316,7 @@ void OpenGLRenderer::drawArrays(const glm::mat4& model, DrawBuffer* draw, } void OpenGLRenderer::drawBatched(const RenderList& list) { + RW_PROFILE_SCOPE(__func__); #if 0 // Needs shader changes // Determine how many batches we need to process the entire list auto entries = list.size(); From 14885c24dc4e8d2268dfd0ef94c554e3a75d7509 Mon Sep 17 00:00:00 2001 From: Daniel Evans Date: Fri, 31 Aug 2018 16:34:50 +0100 Subject: [PATCH 6/8] Move opengl debuging from RW_PROFILER, it interferes with CPU timing. --- rwengine/src/render/OpenGLRenderer.cpp | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/rwengine/src/render/OpenGLRenderer.cpp b/rwengine/src/render/OpenGLRenderer.cpp index a3459519..a214f23a 100644 --- a/rwengine/src/render/OpenGLRenderer.cpp +++ b/rwengine/src/render/OpenGLRenderer.cpp @@ -129,7 +129,7 @@ void OpenGLRenderer::useDrawBuffer(DrawBuffer* dbuff) { glBindVertexArray(dbuff->getVAOName()); currentDbuff = dbuff; bufferCounter++; -#ifdef RW_PROFILER +#ifdef RW_GRAPHICS_STATS if (currentDebugDepth > 0) { profileInfo[currentDebugDepth - 1].buffers++; } @@ -146,7 +146,7 @@ void OpenGLRenderer::useTexture(GLuint unit, GLuint tex) { glBindTexture(GL_TEXTURE_2D, tex); currentTextures[unit] = tex; textureCounter++; -#ifdef RW_PROFILER +#ifdef RW_GRAPHICS_STATS if (currentDebugDepth > 0) { profileInfo[currentDebugDepth - 1].textures++; } @@ -292,7 +292,7 @@ void OpenGLRenderer::setDrawState(const glm::mat4& model, DrawBuffer* draw, uploadUBO(UBOObject, objectData); drawCounter++; -#ifdef RW_PROFILER +#ifdef RW_GRAPHICS_STATS if (currentDebugDepth > 0) { profileInfo[currentDebugDepth - 1].draws++; profileInfo[currentDebugDepth - 1].primitives += p.count; @@ -423,7 +423,7 @@ void OpenGLRenderer::uploadUBOEntry(Buffer &buffer, const void *data, size_t siz } void OpenGLRenderer::pushDebugGroup(const std::string& title) { -#ifdef RW_PROFILER +#ifdef RW_GRAPHICS_STATS if (ogl_ext_KHR_debug) { glPushDebugGroup(GL_DEBUG_SOURCE_APPLICATION, 0, -1, title.c_str()); ProfileInfo& prof = profileInfo[currentDebugDepth]; @@ -442,7 +442,7 @@ void OpenGLRenderer::pushDebugGroup(const std::string& title) { } const Renderer::ProfileInfo& OpenGLRenderer::popDebugGroup() { -#ifdef RW_PROFILER +#ifdef RW_GRAPHICS_STATS if (ogl_ext_KHR_debug) { glPopDebugGroup(); currentDebugDepth--; From be55b616f7bb773ada355e12f2f899c7a3c4b67c Mon Sep 17 00:00:00 2001 From: Daniel Evans Date: Fri, 31 Aug 2018 20:01:50 +0100 Subject: [PATCH 7/8] Add additional profiler scopes for increased resolution --- rwengine/src/core/Profiler.hpp | 2 + rwengine/src/engine/GameWorld.cpp | 8 ++++ rwengine/src/script/ScriptMachine.cpp | 2 + rwgame/RWGame.cpp | 59 ++++++++++++++++++--------- rwgame/RWGame.hpp | 2 + 5 files changed, 53 insertions(+), 20 deletions(-) diff --git a/rwengine/src/core/Profiler.hpp b/rwengine/src/core/Profiler.hpp index b3312dae..ee4d47b8 100644 --- a/rwengine/src/core/Profiler.hpp +++ b/rwengine/src/core/Profiler.hpp @@ -6,6 +6,7 @@ #define RW_PROFILE_THREAD(name) MicroProfileOnThreadCreate(name) #define RW_PROFILE_FRAME_BOUNDARY() MicroProfileFlip(nullptr) #define RW_PROFILE_SCOPE(label) MICROPROFILE_SCOPEI("Default", label, MP_YELLOW) +#define RW_PROFILE_SCOPEC(label, colour) MICROPROFILE_SCOPEI("Default", label, colour) #define RW_PROFILE_COUNTER_ADD(name, qty) MICROPROFILE_COUNTER_ADD(name, qty) #define RW_PROFILE_COUNTER_SET(name, qty) MICROPROFILE_COUNTER_SET(name, qty) #define RW_TIMELINE_ENTER(name, color) MICROPROFILE_TIMELINE_ENTER_STATIC(color, name) @@ -14,6 +15,7 @@ #define RW_PROFILE_THREAD(name) do {} while (0) #define RW_PROFILE_FRAME_BOUNDARY() do {} while (0) #define RW_PROFILE_SCOPE(label) do {} while (0) +#define RW_PROFILE_SCOPEC(label, colour) do {} while (0) #define RW_PROFILE_COUNTER_ADD(name, qty) do {} while (0) #define RW_PROFILE_COUNTER_SET(name, qty) do {} while (0) #define RW_TIMELINE_ENTER(name, color) do {} while (0) diff --git a/rwengine/src/engine/GameWorld.cpp b/rwengine/src/engine/GameWorld.cpp index 27c4d54a..4c02c163 100644 --- a/rwengine/src/engine/GameWorld.cpp +++ b/rwengine/src/engine/GameWorld.cpp @@ -7,6 +7,7 @@ #include +#include "core/Profiler.hpp" #include "core/Logger.hpp" #include "engine/GameData.hpp" @@ -653,6 +654,7 @@ void handleInstanceResponse(InstanceObject* instance, const btManifoldPoint& mp, bool GameWorld::ContactProcessedCallback(btManifoldPoint& mp, void* body0, void* body1) { + RW_PROFILE_SCOPEC(__func__, MP_GOLDENROD1); auto obA = static_cast(body0); auto obB = static_cast(body1); @@ -689,18 +691,24 @@ bool GameWorld::ContactProcessedCallback(btManifoldPoint& mp, void* body0, void GameWorld::PhysicsTickCallback(btDynamicsWorld* physWorld, btScalar timeStep) { + RW_PROFILE_SCOPEC(__func__, MP_CYAN); GameWorld* world = static_cast(physWorld->getWorldUserInfo()); + RW_PROFILE_COUNTER_SET("physicsTick/vehiclePool", world->vehiclePool.objects.size()); for (auto& p : world->vehiclePool.objects) { + RW_PROFILE_SCOPEC("VehicleObject", MP_THISTLE1); VehicleObject* object = static_cast(p.second); object->tickPhysics(timeStep); } + RW_PROFILE_COUNTER_SET("physicsTick/pedestrianPool", world->pedestrianPool.objects.size()); for (auto& p : world->pedestrianPool.objects) { + RW_PROFILE_SCOPEC("CharacterObject", MP_THISTLE1); CharacterObject* object = static_cast(p.second); object->tickPhysics(timeStep); } + RW_PROFILE_COUNTER_SET("physicsTick/instancePool", world->instancePool.objects.size()); for (auto& p : world->instancePool.objects) { InstanceObject* object = static_cast(p.second); object->tickPhysics(timeStep); diff --git a/rwengine/src/script/ScriptMachine.cpp b/rwengine/src/script/ScriptMachine.cpp index bd6fcb20..25ea79ee 100644 --- a/rwengine/src/script/ScriptMachine.cpp +++ b/rwengine/src/script/ScriptMachine.cpp @@ -6,6 +6,7 @@ #include "ai/PlayerController.hpp" #include "core/Logger.hpp" +#include "core/Profiler.hpp" #include "engine/GameState.hpp" #include "engine/GameWorld.hpp" #include "script/SCMFile.hpp" @@ -226,6 +227,7 @@ SCMByte* ScriptMachine::getGlobals() { } void ScriptMachine::execute(float dt) { + RW_PROFILE_SCOPEC(__func__, MP_ORANGERED); int ms = dt * 1000.f; for (auto t = _activeThreads.begin(); t != _activeThreads.end(); ++t) { auto& thread = *t; diff --git a/rwgame/RWGame.cpp b/rwgame/RWGame.cpp index d348a341..77c3ce76 100644 --- a/rwgame/RWGame.cpp +++ b/rwgame/RWGame.cpp @@ -370,6 +370,7 @@ int RWGame::run() { bool running = true; while (StateManager::currentState() && running) { RW_PROFILE_FRAME_BOUNDARY(); + RW_PROFILE_SCOPE("Main Loop"); running = updateInput(); @@ -405,7 +406,7 @@ int RWGame::run() { } float RWGame::tickWorld(const float deltaTime, float accumulatedTime) { - RW_PROFILE_SCOPE(__func__); + RW_PROFILE_SCOPEC(__func__, MP_GREEN); auto deltaTimeWithTimeScale = deltaTime * world->state->basic.timeScale; @@ -414,8 +415,11 @@ float RWGame::tickWorld(const float deltaTime, float accumulatedTime) { break; } - world->dynamicsWorld->stepSimulation( - deltaTimeWithTimeScale, kMaxPhysicsSubSteps, deltaTime); + { + RW_PROFILE_SCOPEC("stepSimulation", MP_DARKORANGE1); + world->dynamicsWorld->stepSimulation( + deltaTimeWithTimeScale, kMaxPhysicsSubSteps, deltaTime); + } StateManager::get().tick(deltaTimeWithTimeScale); @@ -521,22 +525,7 @@ void RWGame::tick(float dt) { } } - world->updateEffects(); - - for (auto& object : world->allObjects) { - object->_updateLastTransform(); - object->tick(dt); - } - - for (auto& g : world->garages) { - g->tick(dt); - } - - for (auto& p : world->payphones) { - p->tick(dt); - } - - world->destroyQueuedObjects(); + tickObjects(dt); state.text.tick(dt); @@ -564,8 +553,38 @@ void RWGame::tick(float dt) { } } +void RWGame::tickObjects(float dt) const { + RW_PROFILE_SCOPEC(__func__, MP_MAGENTA1); + world->updateEffects(); + + { + RW_PROFILE_SCOPEC("allObjects", MP_HOTPINK1); + RW_PROFILE_COUNTER_SET("tickObjects/allObjects", world->allObjects.size()); + for (auto &object : world->allObjects) { + object->_updateLastTransform(); + object->tick(dt); + } + } + + { + RW_PROFILE_SCOPEC("garages", MP_HOTPINK2); + for (auto &g : world->garages) { + g->tick(dt); + } + } + + { + RW_PROFILE_SCOPEC("payphones", MP_HOTPINK3); + for (auto &p : world->payphones) { + p->tick(dt); + } + } + + world->destroyQueuedObjects(); +} + void RWGame::render(float alpha, float time) { - RW_PROFILE_SCOPE(__func__); + RW_PROFILE_SCOPEC(__func__, MP_CORNFLOWERBLUE); lastDraws = getRenderer().getRenderer()->getDrawCount(); diff --git a/rwgame/RWGame.hpp b/rwgame/RWGame.hpp index 8eab6aff..e9d553ab 100644 --- a/rwgame/RWGame.hpp +++ b/rwgame/RWGame.hpp @@ -137,6 +137,8 @@ private: float tickWorld(const float deltaTime, float accumulatedTime); void renderDebugView(float time, ViewCamera &viewCam); + + void tickObjects(float dt) const; }; #endif From 9f1628ee585e24e847e925e0884fe8c0bfbd01e8 Mon Sep 17 00:00:00 2001 From: Daniel Evans Date: Sat, 1 Sep 2018 21:46:58 +0100 Subject: [PATCH 8/8] CI: enable profiling path --- .appveyor.yml | 1 + cmake/ctest/build.ctest | 1 + 2 files changed, 2 insertions(+) diff --git a/.appveyor.yml b/.appveyor.yml index 95d115ea..f2fe74b4 100644 --- a/.appveyor.yml +++ b/.appveyor.yml @@ -42,6 +42,7 @@ install: - for /f %%i in ('git rev-parse HEAD') do set COMMIT_HASH=%%i - echo APPVEYOR_REPO_COMMIT=%APPVEYOR_REPO_COMMIT%, COMMIT_HASH=%COMMIT_HASH% - if NOT "%APPVEYOR_REPO_COMMIT%" == "%COMMIT_HASH%" echo "Appveyor git hash does not match git checkout hash" + - git submodule update --init --recursive build_script: - ctest -VV -S "%APPVEYOR_BUILD_FOLDER%/cmake/ctest/script_ci.ctest" diff --git a/cmake/ctest/build.ctest b/cmake/ctest/build.ctest index b75e5b3c..2b0f2ff3 100644 --- a/cmake/ctest/build.ctest +++ b/cmake/ctest/build.ctest @@ -169,6 +169,7 @@ set(_CONFIGURE_OPTIONS "-DCMAKE_BUILD_TYPE=${_CMAKE_BUILD_TYPE}" "-DENABLE_SANITIZERS=${ENABLE_SANITIZERS}" "-DUSE_CONAN=${USE_CONAN}" + "-DENABLE_PROFILING=TRUE" ) message(STATUS "Configuring...")