add tracing for performance profiling

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<RepairableInfo> buildRepairables(EntityAdmin& admin)
 
 void AiSystem::tickHomeReturnBehavior(EntityAdmin& admin)
 {
+	TRACE();
     admin.forEach<HomeReturnBehaviorComponent, HealthComponent, MovementIntentComponent>(
         [](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<RepairableInfo> 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<RepairableInfo> repairables = buildRepairables(admin);
 
     admin.forEach<RepairToolComponent, ModuleOwnerComponent>(
@@ -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
     {

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<FireEvent>& outFireEvents)
 {
+	TRACE();
     // All weapons (ships and stations) are child entities linked via ModuleOwnerComponent.
     admin.forEach<WeaponComponent, ModuleOwnerComponent>(
         [&](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<PendingDamage>::iterator it = m_pendingDamage.begin();
     while (it != m_pendingDamage.end())
     {

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<PositionComponent, FacingComponent, DynamicBodyComponent>(
         [](entt::entity /*e*/, PositionComponent& pos, FacingComponent& facing,
            DynamicBodyComponent& body)
@@ -49,3 +51,4 @@ void DynamicBodySystem::tick(EntityAdmin& admin)
             body.angularAcceleration = 0.0f;
         });
 }
+

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<PositionComponent, FacingComponent, DynamicBodyComponent,
                   MovementIntentComponent>(
         [](entt::entity /*e*/, const PositionComponent& pos, const FacingComponent& facing,
@@ -115,3 +117,4 @@ void MovementIntentSystem::tick(EntityAdmin& admin)
             body.linearAcceleration = mainDelta + maneuverDelta;
         });
 }
+

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<entt::entity> expired;
     m_admin.forEach<DespawnAtComponent>(
         [&expired, currentTick](entt::entity e, DespawnAtComponent& d)
@@ -54,3 +56,4 @@ std::vector<ScrapInfo> ScrapSystem::allScrapInfo() const
         });
     return result;
 }
+

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<MovementIntentComponent>(
         [](entt::entity /*e*/, MovementIntentComponent& i)
         {
@@ -348,6 +350,7 @@ void ShipSystem::setRallyPoint(QVector2D point)
 
 void ShipSystem::triggerRallyDeparture()
 {
+	TRACE();
     std::vector<entt::entity> toRemove;
     m_admin.forEach<RallyBehaviorComponent, FactionComponent>(
         [&toRemove](entt::entity e, const RallyBehaviorComponent& /*rb*/,

src/lib/sim/BeltSystem.cpp

@@ -3,6 +3,7 @@
 #include <algorithm>
 
 #include "Tick.h"
+#include "tracing.h"
 
 // ---------------------------------------------------------------------------
 // Helpers
@@ -396,6 +397,7 @@ void BeltSystem::clearTiles(const std::vector<QPoint>& tiles)
 
 void BeltSystem::tick()
 {
+	TRACE();
     advanceProgress();
     advanceTunnelProgress();
     moveItemsToNextTile();
@@ -960,3 +962,4 @@ void BeltSystem::forEachVisualItem(QRect viewportTiles,
         }
     }
 }
+

src/lib/sim/BuildingSystem.cpp

@@ -6,6 +6,7 @@
 #include <set>
 
 #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())

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<entt::entity> deadShips;
     m_admin.forEach<ShipIdentityComponent, HealthComponent>(

src/lib/sim/WaveSystem.cpp

@@ -3,6 +3,7 @@
 #include <algorithm>
 
 #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<double>(m_bossWaveCounter);
     const double rate = m_config.world.waves.threatRateFormula.evaluate(x);
     if (rate > 0.0)

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
 )

src/lib/utility/tracing.cpp

@@ -0,0 +1,279 @@
+#include "tracing.h"
+
+#include <iostream>
+#include <set>
+
+std::shared_ptr<Tracer> Tracer::s_instance;
+long long int Tracer::s_nextTraceId = 0;
+
+Tracer* Tracer::getInstance()
+{
+	if (!s_instance)
+	{
+		s_instance = std::shared_ptr<Tracer>(new Tracer());
+	}
+
+	return s_instance.get();
+}
+
+std::shared_ptr<TraceEvent> Tracer::startEvent(const std::string& eventName)
+{
+	std::lock_guard<std::mutex> lock(m_mutex);
+
+	const std::thread::id id = std::this_thread::get_id();
+
+	std::shared_ptr<TraceEvent> event =
+		std::make_shared<TraceEvent>(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<TraceEvent> event)
+{
+	std::lock_guard<std::mutex> lock(m_mutex);
+
+	const std::thread::id id = std::this_thread::get_id();
+
+	m_startedEvents[id].pop();
+}
+
+void Tracer::printTraces()
+{
+	std::lock_guard<std::mutex> 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<TraceEvent>& 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<std::string, AccumulatedTraceEvent> accumulatedEvents;
+
+	for (auto& p : m_events)
+	{
+		for (const std::shared_ptr<TraceEvent>& event : p.second)
+		{
+			const std::string name = event->eventName + event->functionName + event->locationName;
+
+			std::pair<std::map<std::string, AccumulatedTraceEvent>::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<AccumulatedTraceEvent,
+		std::function<bool(const AccumulatedTraceEvent&, const AccumulatedTraceEvent&)>> sortedEvents(
+			[](const AccumulatedTraceEvent& a, const AccumulatedTraceEvent& b)
+	{
+		return a.time > b.time;
+	}
+	);
+
+	for (const std::pair<std::string, AccumulatedTraceEvent>& 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> AccumulatingTracer::s_instance;
+long long int AccumulatingTracer::s_nextTraceId = 0;
+
+AccumulatingTracer* AccumulatingTracer::getInstance()
+{
+	if (!s_instance)
+	{
+		s_instance = std::shared_ptr<AccumulatingTracer>(new AccumulatingTracer());
+	}
+
+	return s_instance.get();
+}
+
+std::shared_ptr<TraceEvent> AccumulatingTracer::startEvent(const std::string& eventName)
+{
+	std::lock_guard<std::mutex> lock(m_mutex);
+
+	const std::thread::id id = std::this_thread::get_id();
+
+	std::shared_ptr<TraceEvent> event =
+		std::make_shared<TraceEvent>(eventName, s_nextTraceId++, m_startedEvents[id].size());
+
+	m_startedEvents[id].push(event.get());
+
+	return event;
+}
+
+void AccumulatingTracer::finishEvent(std::shared_ptr<TraceEvent> event)
+{
+	std::lock_guard<std::mutex> 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<std::map<std::string, AccumulatedTraceEvent>::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<std::mutex> 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<AccumulatedTraceEvent,
+			std::function<bool (const AccumulatedTraceEvent&, const AccumulatedTraceEvent&)>> sortedEvents(
+		[](const AccumulatedTraceEvent& a, const AccumulatedTraceEvent& b)
+		{
+			return a.time > b.time;
+		}
+	);
+
+	for (const std::pair<std::string, AccumulatedTraceEvent>& 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()
+{
+}

src/lib/utility/tracing.h

@@ -0,0 +1,156 @@
+#ifndef TRACING_H
+#define TRACING_H
+
+
+//#define TRACING_ENABLED
+//#define USE_ACCUMULATED_TRACING
+
+
+#include <map>
+#include <mutex>
+#include <stack>
+#include <thread>
+
+#include <QDateTime>
+#include <QFileInfo>
+
+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<TraceEvent> startEvent(const std::string& eventName);
+	void finishEvent(std::shared_ptr<TraceEvent> event);
+
+	void printTraces();
+
+private:
+	static std::shared_ptr<Tracer> s_instance;
+	static long long int s_nextTraceId;
+
+	Tracer();
+	Tracer(const Tracer&) = delete;
+	void operator=(const Tracer&) = delete;
+
+	std::map<std::thread::id, std::vector<std::shared_ptr<TraceEvent>>> m_events;
+	std::map<std::thread::id, std::stack<TraceEvent*>> m_startedEvents;
+
+	std::mutex m_mutex;
+};
+
+
+class AccumulatingTracer
+{
+public:
+	static AccumulatingTracer* getInstance();
+
+	std::shared_ptr<TraceEvent> startEvent(const std::string& eventName);
+	void finishEvent(std::shared_ptr<TraceEvent> event);
+
+	void printTraces();
+
+private:
+	struct AccumulatedTraceEvent
+	{
+		TraceEvent event;
+		size_t count;
+		double time;
+	};
+
+	static std::shared_ptr<AccumulatingTracer> s_instance;
+	static long long int s_nextTraceId;
+
+	AccumulatingTracer();
+	AccumulatingTracer(const AccumulatingTracer&) = delete;
+	void operator=(const AccumulatingTracer&) = delete;
+
+	std::map<std::string, AccumulatedTraceEvent> m_accumulatedEvents;
+	std::map<std::thread::id, std::stack<TraceEvent*>> m_startedEvents;
+
+	std::mutex m_mutex;
+};
+
+
+template <typename TracerType>
+class ScopedTrace
+{
+public:
+	ScopedTrace(const std::string& eventName, const std::string& fileName, int lineNumber, const std::string& functionName);
+	~ScopedTrace();
+
+private:
+	std::shared_ptr<TraceEvent> m_event;
+	QDateTime m_timeStamp;
+};
+
+template <typename TracerType>
+ScopedTrace<TracerType>::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 <typename TracerType>
+ScopedTrace<TracerType>::~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<AccumulatingTracer> __trace__(std::string(__name__), __FILE__, __LINE__, __FUNCTION__)
+
+		#define PRINT_TRACES() \
+				AccumulatingTracer::getInstance()->printTraces()
+	#else
+		#define TRACE(__name__) \
+			ScopedTrace<Tracer> __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