diff --git a/dAuthServer/AuthServer.cpp b/dAuthServer/AuthServer.cpp index 6a6c0d434..128fb43bf 100644 --- a/dAuthServer/AuthServer.cpp +++ b/dAuthServer/AuthServer.cpp @@ -6,6 +6,7 @@ #include //DLU Includes: +#include "Profiler.h" #include "dCommonVars.h" #include "ConfigSync.h" #include "dServer.h" @@ -117,6 +118,7 @@ int main(int argc, char** argv) { Game::logger->Flush(); // once immediately before main loop while (!Game::ShouldShutdown()) { + Profiler::BeginFrame(); //Check if we're still connected to master: if (!Game::server->GetIsConnectedToMaster()) { framesSinceMasterDisconnect++; @@ -130,9 +132,13 @@ int main(int argc, char** argv) { //In world we'd update our other systems here. //Check for packets here: - Game::server->ReceiveFromMaster(); //ReceiveFromMaster also handles the master packets if needed. + { + Profiler::Scope scope("Master packets", Profiler::Phase::PACKETS); + Game::server->ReceiveFromMaster(); //ReceiveFromMaster also handles the master packets if needed. + } packet = Game::server->Receive(); if (packet) { + Profiler::PacketScope scope(packet->data, packet->length); HandlePacket(packet); Game::server->DeallocatePacket(packet); packet = nullptr; @@ -140,6 +146,7 @@ int main(int argc, char** argv) { //Push our log every 30s: if (framesSinceLastFlush >= logFlushTime) { + Profiler::Scope scope("Log flush", Profiler::Phase::LOG_FLUSH); Game::logger->Flush(); framesSinceLastFlush = 0; } else framesSinceLastFlush++; @@ -158,6 +165,7 @@ int main(int argc, char** argv) { framesSinceLastSQLPing = 0; } else framesSinceLastSQLPing++; + Profiler::EndFrame(); //Sleep our thread since auth can afford to. t += std::chrono::milliseconds(authFrameDelta); //Auth can run at a lower "fps" std::this_thread::sleep_until(t); diff --git a/dChatServer/ChatServer.cpp b/dChatServer/ChatServer.cpp index b1613a46b..c9d683c09 100644 --- a/dChatServer/ChatServer.cpp +++ b/dChatServer/ChatServer.cpp @@ -4,6 +4,8 @@ #include //DLU Includes: +#include "Profiler.h" +#include #include "dCommonVars.h" #include "ConfigSync.h" #include "dServer.h" @@ -149,6 +151,7 @@ int main(int argc, char** argv) { Game::logger->Flush(); // once immediately before main loop while (!Game::ShouldShutdown()) { + Profiler::BeginFrame(); //Check if we're still connected to master: if (!Game::server->GetIsConnectedToMaster()) { framesSinceMasterDisconnect++; @@ -161,16 +164,26 @@ int main(int argc, char** argv) { const float deltaTime = std::chrono::duration(currentTime - lastTime).count(); lastTime = currentTime; - Game::playerContainer.Update(deltaTime); + { + Profiler::Scope scope("Player container update", Profiler::Phase::ENTITIES); + Game::playerContainer.Update(deltaTime); + } //Check for packets here: //ReceiveFromMaster also handles the master packets if needed; it hands back the ones for us. + std::optional masterScope; + masterScope.emplace("Master packets", Profiler::Phase::PACKETS); if (auto* masterPacket = Game::server->ReceiveFromMaster()) { - HandleMasterPacket(masterPacket); + { + Profiler::PacketScope scope(masterPacket->data, masterPacket->length); + HandleMasterPacket(masterPacket); + } Game::server->DeallocateMasterPacket(masterPacket); } + masterScope.reset(); packet = Game::server->Receive(); if (packet) { + Profiler::PacketScope scope(packet->data, packet->length); HandlePacket(packet); Game::server->DeallocatePacket(packet); packet = nullptr; @@ -179,6 +192,7 @@ int main(int argc, char** argv) { //Push our log every 30s: if (framesSinceLastFlush >= logFlushTime) { + Profiler::Scope scope("Log flush", Profiler::Phase::LOG_FLUSH); Game::logger->Flush(); framesSinceLastFlush = 0; } else framesSinceLastFlush++; @@ -198,6 +212,7 @@ int main(int argc, char** argv) { framesSinceLastSQLPing = 0; } else framesSinceLastSQLPing++; + Profiler::EndFrame(); //Sleep our thread since auth can afford to. t += std::chrono::milliseconds(chatFrameDelta); //Chat can run at a lower "fps" std::this_thread::sleep_until(t); diff --git a/dDatabase/CDClientDatabase/CDClientDatabase.cpp b/dDatabase/CDClientDatabase/CDClientDatabase.cpp index 886030a1b..a6f8b6872 100644 --- a/dDatabase/CDClientDatabase/CDClientDatabase.cpp +++ b/dDatabase/CDClientDatabase/CDClientDatabase.cpp @@ -1,5 +1,11 @@ #include "CDClientDatabase.h" #include "CDComponentsRegistryTable.h" +#include "Profiler.h" + +#include +#include +#include +#include // Static Variables static CppSQLite3DB* conn = new CppSQLite3DB(); @@ -7,10 +13,58 @@ static CppSQLite3DB* conn = new CppSQLite3DB(); // Status Variables bool CDClientDatabase::isConnected = false; +namespace { + // Frame timing (Profiler.h): each CDClient statement the main thread runs, timed from its first step to its end, + // counted under the scope that ran it as "CDClient " (the first table after FROM) + std::vector> g_Running; + + const char* TableScope(const char* sql) { + if (!sql) return "CDClient"; + const std::string_view text(sql); + for (size_t i = 0; i + 5 < text.size(); i++) { + const bool from = (text[i] == 'F' || text[i] == 'f') && (text[i + 1] == 'R' || text[i + 1] == 'r') && (text[i + 2] == 'O' || text[i + 2] == 'o') && + (text[i + 3] == 'M' || text[i + 3] == 'm') && std::isspace(static_cast(text[i + 4])) && (i == 0 || std::isspace(static_cast(text[i - 1]))); + if (!from) continue; + size_t start = i + 5; + while (start < text.size() && std::isspace(static_cast(text[start]))) start++; + size_t end = start; + while (end < text.size() && (std::isalnum(static_cast(text[end])) || text[end] == '_')) end++; + if (end > start) return Profiler::Intern("CDClient " + std::string(text.substr(start, end - start))); + break; + } + return "CDClient"; + } + + int Trace(unsigned type, void*, void* p, void* x) { + if (!Profiler::IsMainThread()) return 0; + auto* statement = static_cast(p); + const auto now = Profiler::NowNs(); + if (type == SQLITE_TRACE_STMT) { + for (auto& [running, start] : g_Running) { + if (running == statement) { start = now; return 0; } + } + if (g_Running.size() < 64) g_Running.emplace_back(statement, now); + return 0; + } + if (type != SQLITE_TRACE_PROFILE) return 0; + // SQLite's own time as a fallback (coarse on some platforms) + int64_t duration = x ? static_cast(*static_cast(x)) : 0; + for (size_t i = 0; i < g_Running.size(); i++) { + if (g_Running[i].first != statement) continue; + duration = now - g_Running[i].second; + g_Running.erase(g_Running.begin() + static_cast(i)); + break; + } + Profiler::Local().Record(TableScope(sqlite3_sql(statement)), 0, duration, Profiler::Phase::CDCLIENT, now); + return 0; + } +} + //! Opens a connection with the CDClient void CDClientDatabase::Connect(const std::string& filename) { conn->open(filename.c_str()); isConnected = true; + sqlite3_trace_v2(conn->handle(), SQLITE_TRACE_STMT | SQLITE_TRACE_PROFILE, Trace, nullptr); } //! Queries the CDClient diff --git a/dDatabase/GameDatabase/MySQL/MySQLDatabase.h b/dDatabase/GameDatabase/MySQL/MySQLDatabase.h index 866487f25..c1a0b5a0b 100644 --- a/dDatabase/GameDatabase/MySQL/MySQLDatabase.h +++ b/dDatabase/GameDatabase/MySQL/MySQLDatabase.h @@ -1,6 +1,7 @@ #ifndef __MYSQLDATABASE__H__ #define __MYSQLDATABASE__H__ +#include "Profiler.h" #include #include @@ -518,6 +519,7 @@ private: // The return type is a PreparedStmtResultSet which keeps the PreparedStatement alive alongside the ResultSet. template inline PreparedStmtResultSet ExecuteSelect(const std::string& query, Args&&... args) { + Profiler::Scope profile("Database query", Profiler::Phase::DATABASE); PreparedStmtResultSet toReturn; toReturn.m_stmt.reset(CreatePreppedStmt(query)); SetParams(toReturn.m_stmt, std::forward(args)...); @@ -528,6 +530,7 @@ private: template inline void ExecuteDelete(const std::string& query, Args&&... args) { + Profiler::Scope profile("Database query", Profiler::Phase::DATABASE); std::unique_ptr preppedStmt(CreatePreppedStmt(query)); SetParams(preppedStmt, std::forward(args)...); DLU_SQL_TRY_CATCH_RETHROW(preppedStmt->execute()); @@ -535,6 +538,7 @@ private: template inline int32_t ExecuteUpdate(const std::string& query, Args&&... args) { + Profiler::Scope profile("Database query", Profiler::Phase::DATABASE); std::unique_ptr preppedStmt(CreatePreppedStmt(query)); SetParams(preppedStmt, std::forward(args)...); DLU_SQL_TRY_CATCH_RETHROW(return preppedStmt->executeUpdate()); @@ -542,6 +546,7 @@ private: template inline bool ExecuteInsert(const std::string& query, Args&&... args) { + Profiler::Scope profile("Database query", Profiler::Phase::DATABASE); std::unique_ptr preppedStmt(CreatePreppedStmt(query)); SetParams(preppedStmt, std::forward(args)...); DLU_SQL_TRY_CATCH_RETHROW(return preppedStmt->execute()); diff --git a/dDatabase/GameDatabase/SQLite/SQLiteDatabase.h b/dDatabase/GameDatabase/SQLite/SQLiteDatabase.h index f8a117d64..49de5fdd9 100644 --- a/dDatabase/GameDatabase/SQLite/SQLiteDatabase.h +++ b/dDatabase/GameDatabase/SQLite/SQLiteDatabase.h @@ -1,6 +1,7 @@ #ifndef SQLITEDATABASE_H #define SQLITEDATABASE_H +#include "Profiler.h" #include "CppSQLite3.h" #include "GameDatabase.h" @@ -502,6 +503,7 @@ private: // The return type is a unique_ptr to the result set, which is deleted automatically when it goes out of scope template inline std::pair ExecuteSelect(const std::string& query, Args&&... args) { + Profiler::Scope profile("Database query", Profiler::Phase::DATABASE); std::pair toReturn; toReturn.first = CreatePreppedStmt(query); SetParams(toReturn.first, std::forward(args)...); @@ -511,6 +513,7 @@ private: template inline void ExecuteDelete(const std::string& query, Args&&... args) { + Profiler::Scope profile("Database query", Profiler::Phase::DATABASE); auto preppedStmt = CreatePreppedStmt(query); SetParams(preppedStmt, std::forward(args)...); DLU_SQL_TRY_CATCH_RETHROW(preppedStmt.execDML()); @@ -518,6 +521,7 @@ private: template inline int32_t ExecuteUpdate(const std::string& query, Args&&... args) { + Profiler::Scope profile("Database query", Profiler::Phase::DATABASE); auto preppedStmt = CreatePreppedStmt(query); SetParams(preppedStmt, std::forward(args)...); DLU_SQL_TRY_CATCH_RETHROW(return preppedStmt.execDML()); @@ -525,6 +529,7 @@ private: template inline int ExecuteInsert(const std::string& query, Args&&... args) { + Profiler::Scope profile("Database query", Profiler::Phase::DATABASE); auto preppedStmt = CreatePreppedStmt(query); SetParams(preppedStmt, std::forward(args)...); DLU_SQL_TRY_CATCH_RETHROW(return preppedStmt.execDML()); diff --git a/dGame/Entity.cpp b/dGame/Entity.cpp index 3bc70aa6e..71bf23434 100644 --- a/dGame/Entity.cpp +++ b/dGame/Entity.cpp @@ -1152,6 +1152,7 @@ void Entity::Update(const float deltaTime) { // Remove the timer from the list of timers first so that scripts and events can remove timers without causing iterator invalidation auto timerName = timer.GetName(); m_Timers.erase(m_Timers.begin() + timerPosition); + Profiler::Scope profile("Script timer", Profiler::Phase::SCRIPTS); GetScript()->OnTimerDone(this, timerName); VanityUtilities::OnTimerDone(this, timerName); diff --git a/dGame/Entity.h b/dGame/Entity.h index cb297441f..ee830f4e5 100644 --- a/dGame/Entity.h +++ b/dGame/Entity.h @@ -14,6 +14,7 @@ #include "LDFFormat.h" #include "eKillType.h" #include "Observable.h" +#include "Profiler.h" namespace GameMessages { struct GameMsg; @@ -589,6 +590,8 @@ T Entity::GetNetworkVar(const std::u16string& name) { template inline ComponentType* Entity::AddComponent(VaArgs... args) { static_assert(std::is_base_of_v, "ComponentType must be a Component"); + // Frame timing: each component type's construction (loading a character's XML is in some of them) + Profiler::Scope profile(Profiler::COMPONENT, static_cast(ComponentType::ComponentType)); // Get the component if it already exists, or default construct a nullptr auto*& componentToReturn = m_Components[ComponentType::ComponentType]; diff --git a/dGame/EntityManager.cpp b/dGame/EntityManager.cpp index e1990181c..155fd053b 100644 --- a/dGame/EntityManager.cpp +++ b/dGame/EntityManager.cpp @@ -1,4 +1,5 @@ #include "EntityManager.h" +#include "Profiler.h" #include "RakNetTypes.h" #include "Game.h" #include "User.h" @@ -117,6 +118,7 @@ void EntityManager::Initialize() { } Entity* EntityManager::CreateEntity(EntityInfo info, User* user, Entity* parentEntity, const bool controller, const LWOOBJID explicitId) { + Profiler::Scope profile("CreateEntity"); // Determine the objectID for the new entity LWOOBJID id; @@ -286,11 +288,18 @@ void EntityManager::DeleteEntities() { } void EntityManager::UpdateEntities(const float deltaTime) { - for (auto* entity : m_Entities | std::views::values) { - entity->Update(deltaTime); + { + Profiler::Scope profile("Entity updates"); + for (auto* entity : m_Entities | std::views::values) { + entity->Update(deltaTime); + } } - SerializeEntities(); + { + Profiler::Scope profile("Serialize entities", Profiler::Phase::REPLICA); + SerializeEntities(); + } + Profiler::Scope profile("Kill and delete entities"); KillEntities(); DeleteEntities(); } diff --git a/dGame/dComponents/InventoryComponent.cpp b/dGame/dComponents/InventoryComponent.cpp index 4ac5a7bde..26aa1a871 100644 --- a/dGame/dComponents/InventoryComponent.cpp +++ b/dGame/dComponents/InventoryComponent.cpp @@ -1,4 +1,5 @@ #include "InventoryComponent.h" +#include "Profiler.h" #include "BrickByBrick.h" #include "Contraband.h" #include "EconomyLedger.h" @@ -668,6 +669,7 @@ namespace { } void InventoryComponent::LoadXml(const tinyxml2::XMLDocument& document) { + Profiler::Scope profile("InventoryComponent::LoadXml"); LoadPetXml(document); auto* inventoryElement = document.FirstChildElement("obj")->FirstChildElement("inv"); diff --git a/dUgcServer/UgcServer.cpp b/dUgcServer/UgcServer.cpp index 9a9cd9e0f..3529a11a3 100644 --- a/dUgcServer/UgcServer.cpp +++ b/dUgcServer/UgcServer.cpp @@ -12,6 +12,7 @@ #include #include +#include "Profiler.h" #include "AssetManager.h" #include "BinaryPathFinder.h" #include "CDClientDatabase.h" @@ -802,6 +803,7 @@ int main(int argc, char** argv) { const auto now = std::chrono::steady_clock::now(); if (now - lastTick < std::chrono::milliseconds(16)) continue; lastTick = now; + Profiler::FrameScope frame; Packet* packet = g_Server->ReceiveFromMaster(); while (packet) { diff --git a/dWeb/Web.cpp b/dWeb/Web.cpp index 96b04a269..197023d7f 100644 --- a/dWeb/Web.cpp +++ b/dWeb/Web.cpp @@ -1,3 +1,4 @@ +#include "Profiler.h" #include "Web.h" #include "Game.h" #include "magic_enum.hpp" @@ -499,6 +500,8 @@ void HandleHTTPMessage(mg_connection* connection, const mg_http_message* http_ms // Call handler only if all middleware passed. A failing handler (e.g. a database error) answers 500 // instead of taking the whole server down. if (chainPassed) { + // Frame timing: a handler runs on the main thread, between ticks or inside one + Profiler::Scope profile(Profiler::Intern(trafficRoute), Profiler::Phase::WEB); try { route.handle(reply, context); } catch (const std::exception& ex) { diff --git a/dWorldServer/WorldServer.cpp b/dWorldServer/WorldServer.cpp index 7712cf339..0e28f4aab 100644 --- a/dWorldServer/WorldServer.cpp +++ b/dWorldServer/WorldServer.cpp @@ -1,4 +1,6 @@ #include "DashboardActions.h" +#include "Profiler.h" +#include #include "ConfigSync.h" #include "EconomyLedger.h" #include "DashboardNotify.h" @@ -383,7 +385,11 @@ int main(int argc, char** argv) { Game::zoneManager = new dZoneManager(); //Load our level: if (zoneID != 0) { - dpWorld::Initialize(zoneID); + Profiler::Scope zoneLoad("Zone load"); + { + Profiler::Scope navmesh("Navmesh and physics load", Profiler::Phase::PHYSICS); + dpWorld::Initialize(zoneID); + } Game::zoneManager->Initialize(LWOZONEID(zoneID, g_InstanceID, cloneID)); g_CloneID = cloneID; } else { @@ -438,6 +444,7 @@ int main(int argc, char** argv) { Game::logger->Flush(); // once immediately before the main loop while (true) { + Profiler::BeginFrame(); Metrics::StartMeasurement(MetricVariable::Frame); Metrics::StartMeasurement(MetricVariable::GameLoop); @@ -508,15 +515,22 @@ int main(int argc, char** argv) { if (zoneID != 0 && deltaTime > 0.0f) { Metrics::StartMeasurement(MetricVariable::UpdateEntities); - Game::entityManager->UpdateEntities(deltaTime); + { + Profiler::Scope scope("Entities", Profiler::Phase::ENTITIES); + Game::entityManager->UpdateEntities(deltaTime); + } Metrics::EndMeasurement(MetricVariable::UpdateEntities); Metrics::StartMeasurement(MetricVariable::Physics); - dpWorld::StepWorld(deltaTime); + { + Profiler::Scope scope("Physics step", Profiler::Phase::PHYSICS); + dpWorld::StepWorld(deltaTime); + } Metrics::EndMeasurement(MetricVariable::Physics); Metrics::StartMeasurement(MetricVariable::Ghosting); if (std::chrono::duration(currentTime - ghostingLastTime).count() >= 1.0f) { + Profiler::Scope scope("Ghosting", Profiler::Phase::REPLICA); Game::entityManager->UpdateGhosting(); ghostingLastTime = currentTime; } @@ -534,7 +548,10 @@ int main(int argc, char** argv) { UgcManifest::Update(); Metrics::StartMeasurement(MetricVariable::UpdateSpawners); - Game::zoneManager->Update(deltaTime); + { + Profiler::Scope scope("Spawners", Profiler::Phase::ENTITIES); + Game::zoneManager->Update(deltaTime); + } Metrics::EndMeasurement(MetricVariable::UpdateSpawners); WorldMigration::Update(deltaTime); @@ -545,21 +562,33 @@ int main(int argc, char** argv) { Metrics::StartMeasurement(MetricVariable::PacketHandling); //Check for packets here: + std::optional packetScope; + packetScope.emplace("Master packets", Profiler::Phase::PACKETS); packet = Game::server->ReceiveFromMaster(); while (packet) { //We can get messages not handle-able by the dServer class, so handle them if we returned anything. - HandleMasterPacket(packet); + { + Profiler::PacketScope scope(packet->data, packet->length); + HandleMasterPacket(packet); + } Game::server->DeallocateMasterPacket(packet); packet = Game::server->ReceiveFromMaster(); } //Handle our chat packets: + packetScope.reset(); + packetScope.emplace("Chat packets", Profiler::Phase::PACKETS); packet = Game::chatServer->Receive(); while (packet) { ChatServerLink::CountReceived(packet->data, packet->length); - HandlePacketChat(packet); + { + Profiler::PacketScope scope(packet->data, packet->length); + HandlePacketChat(packet); + } Game::chatServer->DeallocatePacket(packet); packet = Game::chatServer->Receive(); } + packetScope.reset(); + packetScope.emplace("Client packets", Profiler::Phase::PACKETS); //Handle world-specific packets: float timeSpent = 0.0f; @@ -570,7 +599,10 @@ int main(int argc, char** argv) { packet = Game::server->Receive(); if (packet) { auto t1 = std::chrono::high_resolution_clock::now(); - HandlePacket(packet); + { + Profiler::PacketScope scope(packet->data, packet->length); + HandlePacket(packet); + } auto t2 = std::chrono::high_resolution_clock::now(); timeSpent += std::chrono::duration_cast>(t2 - t1).count(); @@ -581,17 +613,22 @@ int main(int argc, char** argv) { } } + packetScope.reset(); Metrics::EndMeasurement(MetricVariable::PacketHandling); Metrics::StartMeasurement(MetricVariable::UpdateReplica); //Update our replica objects: - Game::server->UpdateReplica(); + { + Profiler::Scope scope("Replica update", Profiler::Phase::REPLICA); + Game::server->UpdateReplica(); + } Metrics::EndMeasurement(MetricVariable::UpdateReplica); //Push our log every 15s: if (framesSinceLastFlush >= logFlushTime) { + Profiler::Scope scope("Log flush", Profiler::Phase::LOG_FLUSH); Game::logger->Flush(); framesSinceLastFlush = 0; } else framesSinceLastFlush++; @@ -612,6 +649,7 @@ int main(int argc, char** argv) { //Save all connected users every 10 minutes: if (framesSinceLastUsersSave >= saveTime && zoneID != 0) { + Profiler::Scope scope("Save all characters", Profiler::Phase::DATABASE); UserManager::Instance()->SaveAllActiveCharacters(); framesSinceLastUsersSave = 0; @@ -635,6 +673,7 @@ int main(int argc, char** argv) { } else framesSinceLastSQLPing++; Metrics::EndMeasurement(MetricVariable::GameLoop); + Profiler::EndFrame(); Metrics::StartMeasurement(MetricVariable::Sleep); @@ -930,6 +969,7 @@ void HandleMasterPacket(Packet* packet) { // Creates the player's entity and sends the client everything in the world: after the client loaded the zone // (LEVEL_LOAD_COMPLETE), or at once when it kept its scene (an experimental seamless migration) void LoadPlayer(const SystemAddress& sysAddr) { + Profiler::Scope scope("LoadPlayer"); User* user = UserManager::Instance()->GetUser(sysAddr); if (user) { Character* c = user->GetLastUsedChar(); diff --git a/thirdparty/SQLite/CppSQLite3.h b/thirdparty/SQLite/CppSQLite3.h index 3e3faac03..a378e195f 100644 --- a/thirdparty/SQLite/CppSQLite3.h +++ b/thirdparty/SQLite/CppSQLite3.h @@ -314,6 +314,9 @@ public: void interrupt() { sqlite3_interrupt(mpDB); } + // The connection, for sqlite3_* calls this wrapper has no method for (e.g. sqlite3_trace_v2) + sqlite3* handle() { return mpDB; } + void setBusyTimeout(int nMillisecs); static const char* SQLiteVersion() { return SQLITE_VERSION; }