From abc261c03aa43c34849431276b6aef89bc2f561a Mon Sep 17 00:00:00 2001 From: mlangkabel Date: Fri, 5 Jun 2026 16:38:36 +0200 Subject: [PATCH] add tracing for performance profiling --- src/lib/ecs/system/AiSystem.cpp | 6 + src/lib/ecs/system/CombatSystem.cpp | 3 + src/lib/ecs/system/DynamicBodySystem.cpp | 3 + src/lib/ecs/system/MovementIntentSystem.cpp | 3 + src/lib/ecs/system/ScrapSystem.cpp | 3 + src/lib/ecs/system/ShipSystem.cpp | 3 + src/lib/sim/BeltSystem.cpp | 3 + src/lib/sim/BuildingSystem.cpp | 6 + src/lib/sim/Simulation.cpp | 4 + src/lib/sim/WaveSystem.cpp | 3 + src/lib/utility/CMakeLists.txt | 2 + src/lib/utility/tracing.cpp | 279 ++++++++++++++++++++ src/lib/utility/tracing.h | 156 +++++++++++ 13 files changed, 474 insertions(+) create mode 100644 src/lib/utility/tracing.cpp create mode 100644 src/lib/utility/tracing.h diff --git a/src/lib/ecs/system/AiSystem.cpp b/src/lib/ecs/system/AiSystem.cpp index 2032d4b..e9940f6 100644 --- a/src/lib/ecs/system/AiSystem.cpp +++ b/src/lib/ecs/system/AiSystem.cpp @@ -28,6 +28,7 @@ #include "ShipIdentityComponent.h" #include "StationBodyComponent.h" #include "ThreatResponseBehaviorComponent.h" +#include "tracing.h" // --------------------------------------------------------------------------- // Shared helpers for repair targeting @@ -72,6 +73,7 @@ static std::vector buildRepairables(EntityAdmin& admin) void AiSystem::tickHomeReturnBehavior(EntityAdmin& admin) { + TRACE(); admin.forEach( [](entt::entity /*e*/, const HomeReturnBehaviorComponent& homeReturnBehavior, const HealthComponent& h, MovementIntentComponent& intent) @@ -92,6 +94,7 @@ void AiSystem::tickHomeReturnBehavior(EntityAdmin& admin) void AiSystem::tickThreatResponseBehavior(EntityAdmin& admin, const BuildingSystem& buildings) { + TRACE(); // Snapshot all combatant entities for target acquisition. struct CombatantInfo { @@ -219,6 +222,7 @@ void AiSystem::tickThreatResponseBehavior(EntityAdmin& admin, const BuildingSyst void AiSystem::tickRepairBehavior(EntityAdmin& admin, BuildingSystem& buildings) { + TRACE(); std::vector repairables = buildRepairables(admin); // Snapshot enemy ships for threat detection. @@ -327,6 +331,7 @@ void AiSystem::tickRepairBehavior(EntityAdmin& admin, BuildingSystem& buildings) void AiSystem::tickRepairTools(EntityAdmin& admin) { + TRACE(); const std::vector repairables = buildRepairables(admin); admin.forEach( @@ -389,6 +394,7 @@ void AiSystem::tickRepairTools(EntityAdmin& admin) void AiSystem::tickSalvageBehavior(EntityAdmin& admin, ScrapSystem& scraps, BuildingSystem& buildings) { + TRACE(); // Snapshot enemy ships for threat detection. struct EnemyShipPos { diff --git a/src/lib/ecs/system/CombatSystem.cpp b/src/lib/ecs/system/CombatSystem.cpp index bd42a8b..884d86a 100644 --- a/src/lib/ecs/system/CombatSystem.cpp +++ b/src/lib/ecs/system/CombatSystem.cpp @@ -8,6 +8,7 @@ #include "SensorRangeComponent.h" #include "ShipIdentityComponent.h" #include "ThreatResponseBehaviorComponent.h" +#include "tracing.h" #include "WeaponComponent.h" static constexpr Tick kWeaponImpactDelayTicks = 5; @@ -22,6 +23,7 @@ void CombatSystem::tick(Tick currentTick, BuildingSystem& /*buildings*/, std::vector& outFireEvents) { + TRACE(); // All weapons (ships and stations) are child entities linked via ModuleOwnerComponent. admin.forEach( [&](entt::entity /*e*/, WeaponComponent& weapon, const ModuleOwnerComponent& owner) @@ -124,6 +126,7 @@ void CombatSystem::resolveWeapon( void CombatSystem::applyPendingDamage(Tick currentTick, EntityAdmin& admin) { + TRACE(); std::vector::iterator it = m_pendingDamage.begin(); while (it != m_pendingDamage.end()) { diff --git a/src/lib/ecs/system/DynamicBodySystem.cpp b/src/lib/ecs/system/DynamicBodySystem.cpp index 1a85c9a..0aab334 100644 --- a/src/lib/ecs/system/DynamicBodySystem.cpp +++ b/src/lib/ecs/system/DynamicBodySystem.cpp @@ -9,6 +9,7 @@ #include "EntityAdmin.h" #include "FacingComponent.h" #include "PositionComponent.h" +#include "tracing.h" static float wrapAngle(float a) { @@ -21,6 +22,7 @@ static float wrapAngle(float a) void DynamicBodySystem::tick(EntityAdmin& admin) { + TRACE(); admin.forEach( [](entt::entity /*e*/, PositionComponent& pos, FacingComponent& facing, DynamicBodyComponent& body) @@ -49,3 +51,4 @@ void DynamicBodySystem::tick(EntityAdmin& admin) body.angularAcceleration = 0.0f; }); } + diff --git a/src/lib/ecs/system/MovementIntentSystem.cpp b/src/lib/ecs/system/MovementIntentSystem.cpp index 81a7daf..8acf04e 100644 --- a/src/lib/ecs/system/MovementIntentSystem.cpp +++ b/src/lib/ecs/system/MovementIntentSystem.cpp @@ -10,6 +10,7 @@ #include "FacingComponent.h" #include "MovementIntentComponent.h" #include "PositionComponent.h" +#include "tracing.h" static float wrapAngle(float a) { @@ -22,6 +23,7 @@ static float wrapAngle(float a) void MovementIntentSystem::tick(EntityAdmin& admin) { + TRACE(); admin.forEach( [](entt::entity /*e*/, const PositionComponent& pos, const FacingComponent& facing, @@ -115,3 +117,4 @@ void MovementIntentSystem::tick(EntityAdmin& admin) body.linearAcceleration = mainDelta + maneuverDelta; }); } + diff --git a/src/lib/ecs/system/ScrapSystem.cpp b/src/lib/ecs/system/ScrapSystem.cpp index 6f5228c..841021b 100644 --- a/src/lib/ecs/system/ScrapSystem.cpp +++ b/src/lib/ecs/system/ScrapSystem.cpp @@ -4,6 +4,7 @@ #include "EntityAdmin.h" #include "PositionComponent.h" #include "ScrapDataComponent.h" +#include "tracing.h" ScrapSystem::ScrapSystem(EntityAdmin& admin) : m_admin(admin) @@ -17,6 +18,7 @@ entt::entity ScrapSystem::spawn(QVector2D position, int amount, Tick despawnAt) void ScrapSystem::tickDespawn(Tick currentTick) { + TRACE(); std::vector expired; m_admin.forEach( [&expired, currentTick](entt::entity e, DespawnAtComponent& d) @@ -54,3 +56,4 @@ std::vector ScrapSystem::allScrapInfo() const }); return result; } + diff --git a/src/lib/ecs/system/ShipSystem.cpp b/src/lib/ecs/system/ShipSystem.cpp index cc12634..701c434 100644 --- a/src/lib/ecs/system/ShipSystem.cpp +++ b/src/lib/ecs/system/ShipSystem.cpp @@ -20,6 +20,7 @@ #include "SensorRangeComponent.h" #include "Tick.h" #include "ThreatResponseBehaviorComponent.h" +#include "tracing.h" #include "WeaponComponent.h" ShipSystem::ShipSystem(const GameConfig& config, EntityAdmin& admin) @@ -334,6 +335,7 @@ void ShipSystem::despawn(entt::entity entity) void ShipSystem::clearMovementIntents() { + TRACE(); m_admin.forEach( [](entt::entity /*e*/, MovementIntentComponent& i) { @@ -348,6 +350,7 @@ void ShipSystem::setRallyPoint(QVector2D point) void ShipSystem::triggerRallyDeparture() { + TRACE(); std::vector toRemove; m_admin.forEach( [&toRemove](entt::entity e, const RallyBehaviorComponent& /*rb*/, diff --git a/src/lib/sim/BeltSystem.cpp b/src/lib/sim/BeltSystem.cpp index 46dcbcb..7d847cb 100644 --- a/src/lib/sim/BeltSystem.cpp +++ b/src/lib/sim/BeltSystem.cpp @@ -3,6 +3,7 @@ #include #include "Tick.h" +#include "tracing.h" // --------------------------------------------------------------------------- // Helpers @@ -396,6 +397,7 @@ void BeltSystem::clearTiles(const std::vector& tiles) void BeltSystem::tick() { + TRACE(); advanceProgress(); advanceTunnelProgress(); moveItemsToNextTile(); @@ -960,3 +962,4 @@ void BeltSystem::forEachVisualItem(QRect viewportTiles, } } } + diff --git a/src/lib/sim/BuildingSystem.cpp b/src/lib/sim/BuildingSystem.cpp index b4ce084..87c64b7 100644 --- a/src/lib/sim/BuildingSystem.cpp +++ b/src/lib/sim/BuildingSystem.cpp @@ -6,6 +6,7 @@ #include #include "SurfaceMask.h" +#include "tracing.h" BuildingSystem::BuildingSystem(const GameConfig& config, BeltSystem& belts, @@ -410,6 +411,7 @@ void BuildingSystem::setShipLayout(BuildingId id, const ShipLayoutConfig& layout void BuildingSystem::tickConstruction(Tick currentTick) { + TRACE(); if (m_constructionQueue.empty()) { return; @@ -516,6 +518,7 @@ void BuildingSystem::tickConstruction(Tick currentTick) void BuildingSystem::tickBeltPull() { + TRACE(); for (Building& building : m_buildings) { // HQ: pull building_block items and add to global stock. @@ -591,6 +594,7 @@ void BuildingSystem::tickBeltPull() void BuildingSystem::tickProduction(Tick currentTick) { + TRACE(); for (Building& building : m_buildings) { // Skip types without a recipe-based production loop. @@ -694,6 +698,7 @@ void BuildingSystem::tickProduction(Tick currentTick) void BuildingSystem::tickShipyardProduction(Tick currentTick) { + TRACE(); for (Building& building : m_buildings) { if (building.type != BuildingType::Shipyard) @@ -795,6 +800,7 @@ void BuildingSystem::tickShipyardProduction(Tick currentTick) void BuildingSystem::tickBeltPush() { + TRACE(); for (Building& building : m_buildings) { if (building.outputBuffer.items.empty()) diff --git a/src/lib/sim/Simulation.cpp b/src/lib/sim/Simulation.cpp index 37506f1..26ef183 100644 --- a/src/lib/sim/Simulation.cpp +++ b/src/lib/sim/Simulation.cpp @@ -16,6 +16,7 @@ #include "ShipSystem.h" #include "StationBodyComponent.h" #include "SurfaceMask.h" +#include "tracing.h" #include "WaveSystem.h" #include "WeaponComponent.h" @@ -198,6 +199,8 @@ void Simulation::tick() m_scrapSystem->tickDespawn(m_currentTick); ++m_currentTick; + + PRINT_TRACES(); } // --------------------------------------------------------------------------- @@ -361,6 +364,7 @@ void Simulation::placeEnemyStationSet(int generation) void Simulation::tickDeathsAndLoot() { + TRACE(); // --- Dead ships --- std::vector deadShips; m_admin.forEach( diff --git a/src/lib/sim/WaveSystem.cpp b/src/lib/sim/WaveSystem.cpp index 811e20c..9fedf6d 100644 --- a/src/lib/sim/WaveSystem.cpp +++ b/src/lib/sim/WaveSystem.cpp @@ -3,6 +3,7 @@ #include #include "ShipSystem.h" +#include "tracing.h" WaveSystem::WaveSystem(const GameConfig& config, std::mt19937& rng) : m_config(config) @@ -15,6 +16,7 @@ WaveSystem::WaveSystem(const GameConfig& config, std::mt19937& rng) void WaveSystem::tickWaveScheduler(Tick currentTick, ShipSystem& ships, int worldHeightTiles) { + TRACE(); // 1. Advance boss countdown. --m_bossCountdownTicks; @@ -75,6 +77,7 @@ void WaveSystem::tickWaveScheduler(Tick currentTick, ShipSystem& ships, void WaveSystem::tickThreatAccumulation() { + TRACE(); const double x = static_cast(m_bossWaveCounter); const double rate = m_config.world.waves.threatRateFormula.evaluate(x); if (rate > 0.0) diff --git a/src/lib/utility/CMakeLists.txt b/src/lib/utility/CMakeLists.txt index 5250dc2..a5ec098 100644 --- a/src/lib/utility/CMakeLists.txt +++ b/src/lib/utility/CMakeLists.txt @@ -4,12 +4,14 @@ add_subdirectory(random) SET(HDRS ${HDRS} + ${CMAKE_CURRENT_SOURCE_DIR}/tracing.h ${CMAKE_CURRENT_SOURCE_DIR}/utilityRandom.h PARENT_SCOPE ) SET(SRCS ${SRCS} + ${CMAKE_CURRENT_SOURCE_DIR}/tracing.cpp ${CMAKE_CURRENT_SOURCE_DIR}/utilityRandom.cpp PARENT_SCOPE ) diff --git a/src/lib/utility/tracing.cpp b/src/lib/utility/tracing.cpp new file mode 100644 index 0000000..d685d90 --- /dev/null +++ b/src/lib/utility/tracing.cpp @@ -0,0 +1,279 @@ +#include "tracing.h" + +#include +#include + +std::shared_ptr Tracer::s_instance; +long long int Tracer::s_nextTraceId = 0; + +Tracer* Tracer::getInstance() +{ + if (!s_instance) + { + s_instance = std::shared_ptr(new Tracer()); + } + + return s_instance.get(); +} + +std::shared_ptr Tracer::startEvent(const std::string& eventName) +{ + std::lock_guard lock(m_mutex); + + const std::thread::id id = std::this_thread::get_id(); + + std::shared_ptr event = + std::make_shared(eventName, s_nextTraceId++, m_startedEvents[id].size()); + + m_events[id].push_back(event); + m_startedEvents[id].push(event.get()); + + return event; +} + +void Tracer::finishEvent(std::shared_ptr event) +{ + std::lock_guard lock(m_mutex); + + const std::thread::id id = std::this_thread::get_id(); + + m_startedEvents[id].pop(); +} + +void Tracer::printTraces() +{ + std::lock_guard lock(m_mutex); + + size_t unfinishEvents = 0; + for (auto& p : m_startedEvents) + { + unfinishEvents += p.second.size(); + } + + if (unfinishEvents > 0) + { + std::cout << "TRACING: Trace events are still running." << std::endl; + return; + } + else if (m_events.empty()) + { + std::cout << "TRACING: No trace events collected." << std::endl; + return; + } + + + std::cout << "TRACING\n--------------------------\n" << std::endl; + + std::cout << "HISTORY:\n\n"; + std::cout << " time name function"; + std::cout << " location\n"; + std::cout << "-----------------------------------------------------------------"; + std::cout << "------------------------------------------------------------\n"; + + for (auto& p : m_events) + { + std::cout << "thread: " << p.first << std::endl; + + for (const std::shared_ptr& event : p.second) + { + std::cout.width(8 + 2 * event->depth); + std::cout << std::right /*<< std::setprecision(3)*/ << std::fixed << event->time; + + std::cout.width(17 - 2 * event->depth); + std::cout << " "; + + std::cout.width(25); + std::cout << std::left << event->eventName; + + std::cout.width(50); + std::cout << (event->functionName + "()") << event->locationName << std::endl; + } + + std::cout << std::endl; + } + + std::cout << "\nREPORT:\n\n"; + std::cout << " time count name function"; + std::cout << " location\n"; + std::cout << "-----------------------------------------------------------------"; + std::cout << "------------------------------------------------------------\n"; + + struct AccumulatedTraceEvent + { + TraceEvent* event; + size_t count; + float time; + }; + + std::map accumulatedEvents; + + for (auto& p : m_events) + { + for (const std::shared_ptr& event : p.second) + { + const std::string name = event->eventName + event->functionName + event->locationName; + + std::pair::iterator, bool> p = + accumulatedEvents.emplace(name, AccumulatedTraceEvent()); + + AccumulatedTraceEvent* acc = &p.first->second; + if (p.second) + { + acc->event = event.get(); + acc->time = event->time; + acc->count = 1; + } + else + { + acc->time += event->time; + acc->count++; + } + } + } + + std::multiset> sortedEvents( + [](const AccumulatedTraceEvent& a, const AccumulatedTraceEvent& b) + { + return a.time > b.time; + } + ); + + for (const std::pair& p : accumulatedEvents) + { + sortedEvents.insert(p.second); + } + + for (const AccumulatedTraceEvent& acc : sortedEvents) + { + std::cout.width(8); + std::cout << std::right/* << std::setprecision(3)*/ << std::fixed << acc.time; + + std::cout.width(10); + std::cout << acc.count << " "; + + std::cout.width(25); + std::cout << std::left << acc.event->eventName; + + std::cout.width(50); + std::cout << (acc.event->functionName + "()") << acc.event->locationName << std::endl; + } + + std::cout << std::endl; + + m_events.clear(); +} + +Tracer::Tracer() +{ +} + + +std::shared_ptr AccumulatingTracer::s_instance; +long long int AccumulatingTracer::s_nextTraceId = 0; + +AccumulatingTracer* AccumulatingTracer::getInstance() +{ + if (!s_instance) + { + s_instance = std::shared_ptr(new AccumulatingTracer()); + } + + return s_instance.get(); +} + +std::shared_ptr AccumulatingTracer::startEvent(const std::string& eventName) +{ + std::lock_guard lock(m_mutex); + + const std::thread::id id = std::this_thread::get_id(); + + std::shared_ptr event = + std::make_shared(eventName, s_nextTraceId++, m_startedEvents[id].size()); + + m_startedEvents[id].push(event.get()); + + return event; +} + +void AccumulatingTracer::finishEvent(std::shared_ptr event) +{ + std::lock_guard lock(m_mutex); + + const std::thread::id id = std::this_thread::get_id(); + + m_startedEvents[id].pop(); + + const std::string name = event->eventName + event->functionName + event->locationName; + + std::pair::iterator, bool> p = + m_accumulatedEvents.emplace(name, AccumulatedTraceEvent()); + + AccumulatedTraceEvent* acc = &p.first->second; + if (p.second) + { + acc->event = TraceEvent(*(event.get())); + acc->time = event->time; + acc->count = 1; + } + else + { + acc->time += event->time; + acc->count++; + } +} + +void AccumulatingTracer::printTraces() +{ + std::lock_guard lock(m_mutex); + + for (auto& p : m_startedEvents) + { + if (!p.second.empty()) + { + std::cout << "TRACING: Trace events are still running." << std::endl; + } + } + + std::cout << "\nREPORT:\n\n"; + std::cout << " time count name function"; + std::cout << " location\n"; + std::cout << "-----------------------------------------------------------------"; + std::cout << "------------------------------------------------------------\n"; + + std::multiset> sortedEvents( + [](const AccumulatedTraceEvent& a, const AccumulatedTraceEvent& b) + { + return a.time > b.time; + } + ); + + for (const std::pair& p : m_accumulatedEvents) + { + sortedEvents.insert(p.second); + } + + for (const AccumulatedTraceEvent& acc : sortedEvents) + { + std::cout.width(8); + std::cout << std::right/* << std::setprecision(3)*/ << std::fixed << acc.time; + + std::cout.width(10); + std::cout << acc.count << " "; + + std::cout.width(25); + std::cout << std::left << acc.event.eventName; + + std::cout.width(50); + std::cout << (acc.event.functionName + "()") << acc.event.locationName << std::endl; + } + + std::cout << std::endl; + + m_accumulatedEvents.clear(); +} + +AccumulatingTracer::AccumulatingTracer() +{ +} diff --git a/src/lib/utility/tracing.h b/src/lib/utility/tracing.h new file mode 100644 index 0000000..cb9d765 --- /dev/null +++ b/src/lib/utility/tracing.h @@ -0,0 +1,156 @@ +#ifndef TRACING_H +#define TRACING_H + + +//#define TRACING_ENABLED +//#define USE_ACCUMULATED_TRACING + + +#include +#include +#include +#include + +#include +#include + +struct TraceEvent +{ +public: + TraceEvent() + : eventName("") + , id(0) + , depth(0) + , time(0.0) + { + } + + TraceEvent(const std::string& eventName, long long int id, size_t depth) + : eventName(eventName) + , id(id) + , depth(depth) + , time(0.0) + { + } + + std::string eventName; + long long int id; + size_t depth; + + std::string functionName; + std::string locationName; + + double time; +}; + + +class Tracer +{ +public: + static Tracer* getInstance(); + + std::shared_ptr startEvent(const std::string& eventName); + void finishEvent(std::shared_ptr event); + + void printTraces(); + +private: + static std::shared_ptr s_instance; + static long long int s_nextTraceId; + + Tracer(); + Tracer(const Tracer&) = delete; + void operator=(const Tracer&) = delete; + + std::map>> m_events; + std::map> m_startedEvents; + + std::mutex m_mutex; +}; + + +class AccumulatingTracer +{ +public: + static AccumulatingTracer* getInstance(); + + std::shared_ptr startEvent(const std::string& eventName); + void finishEvent(std::shared_ptr event); + + void printTraces(); + +private: + struct AccumulatedTraceEvent + { + TraceEvent event; + size_t count; + double time; + }; + + static std::shared_ptr s_instance; + static long long int s_nextTraceId; + + AccumulatingTracer(); + AccumulatingTracer(const AccumulatingTracer&) = delete; + void operator=(const AccumulatingTracer&) = delete; + + std::map m_accumulatedEvents; + std::map> m_startedEvents; + + std::mutex m_mutex; +}; + + +template +class ScopedTrace +{ +public: + ScopedTrace(const std::string& eventName, const std::string& fileName, int lineNumber, const std::string& functionName); + ~ScopedTrace(); + +private: + std::shared_ptr m_event; + QDateTime m_timeStamp; +}; + +template +ScopedTrace::ScopedTrace( + const std::string& eventName, const std::string& fileName, int lineNumber, const std::string& functionName) +{ + m_event = TracerType::getInstance()->startEvent(eventName); + m_event->functionName = functionName; + m_event->locationName = QFileInfo(QString::fromStdString(fileName)).fileName().toStdString() + ":" + std::to_string(lineNumber); + + m_timeStamp = QDateTime::currentDateTime(); +} + +template +ScopedTrace::~ScopedTrace() +{ + m_event->time = m_timeStamp.msecsTo(QDateTime::currentDateTime()); + TracerType::getInstance()->finishEvent(m_event); +} + + +#ifdef TRACING_ENABLED + #ifdef USE_ACCUMULATED_TRACING + #define TRACE(__name__) \ + ScopedTrace __trace__(std::string(__name__), __FILE__, __LINE__, __FUNCTION__) + + #define PRINT_TRACES() \ + AccumulatingTracer::getInstance()->printTraces() + #else + #define TRACE(__name__) \ + ScopedTrace __trace__(std::string(__name__), __FILE__, __LINE__, __FUNCTION__) + + #define PRINT_TRACES() \ + Tracer::getInstance()->printTraces() + #endif + + +#else + #define TRACE(__name__) + #define PRINT_TRACES() +#endif + +#endif // TRACING_H