feat(servers): time the main loops' phases and the known heavy spots

Frames and phase scopes in the world, auth, chat and UGC loops (packets per type, entities, physics, ghosting, replica, spawners, log flush, saves, web requests by route). Scopes at LoadPlayer, CreateEntity, each component's construction, InventoryComponent::LoadXml, script timers and a world's zone load; game database queries in the query helpers; CDClient statements timed through sqlite3_trace_v2 as CDClient <table> (CppSQLite3DB gets a handle accessor). Task 96.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
This commit is contained in:
Aaron Kimbrell
2026-09-29 22:06:31 -05:00
parent 63666c3c6b
commit d4e9423264
13 changed files with 164 additions and 14 deletions

View File

@@ -6,6 +6,7 @@
#include <thread>
//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);

View File

@@ -4,6 +4,8 @@
#include <thread>
//DLU Includes:
#include "Profiler.h"
#include <optional>
#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<float>(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<Profiler::Scope> 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);

View File

@@ -1,5 +1,11 @@
#include "CDClientDatabase.h"
#include "CDComponentsRegistryTable.h"
#include "Profiler.h"
#include <cctype>
#include <string_view>
#include <utility>
#include <vector>
// 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 <table>" (the first table after FROM)
std::vector<std::pair<sqlite3_stmt*, int64_t>> 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<unsigned char>(text[i + 4])) && (i == 0 || std::isspace(static_cast<unsigned char>(text[i - 1])));
if (!from) continue;
size_t start = i + 5;
while (start < text.size() && std::isspace(static_cast<unsigned char>(text[start]))) start++;
size_t end = start;
while (end < text.size() && (std::isalnum(static_cast<unsigned char>(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<sqlite3_stmt*>(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<int64_t>(*static_cast<sqlite3_int64*>(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<std::ptrdiff_t>(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

View File

@@ -1,6 +1,7 @@
#ifndef __MYSQLDATABASE__H__
#define __MYSQLDATABASE__H__
#include "Profiler.h"
#include <conncpp.hpp>
#include <memory>
@@ -518,6 +519,7 @@ private:
// The return type is a PreparedStmtResultSet which keeps the PreparedStatement alive alongside the ResultSet.
template<typename... Args>
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>(args)...);
@@ -528,6 +530,7 @@ private:
template<typename... Args>
inline void ExecuteDelete(const std::string& query, Args&&... args) {
Profiler::Scope profile("Database query", Profiler::Phase::DATABASE);
std::unique_ptr<sql::PreparedStatement> preppedStmt(CreatePreppedStmt(query));
SetParams(preppedStmt, std::forward<Args>(args)...);
DLU_SQL_TRY_CATCH_RETHROW(preppedStmt->execute());
@@ -535,6 +538,7 @@ private:
template<typename... Args>
inline int32_t ExecuteUpdate(const std::string& query, Args&&... args) {
Profiler::Scope profile("Database query", Profiler::Phase::DATABASE);
std::unique_ptr<sql::PreparedStatement> preppedStmt(CreatePreppedStmt(query));
SetParams(preppedStmt, std::forward<Args>(args)...);
DLU_SQL_TRY_CATCH_RETHROW(return preppedStmt->executeUpdate());
@@ -542,6 +546,7 @@ private:
template<typename... Args>
inline bool ExecuteInsert(const std::string& query, Args&&... args) {
Profiler::Scope profile("Database query", Profiler::Phase::DATABASE);
std::unique_ptr<sql::PreparedStatement> preppedStmt(CreatePreppedStmt(query));
SetParams(preppedStmt, std::forward<Args>(args)...);
DLU_SQL_TRY_CATCH_RETHROW(return preppedStmt->execute());

View File

@@ -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<typename... Args>
inline std::pair<CppSQLite3Statement, CppSQLite3Query> ExecuteSelect(const std::string& query, Args&&... args) {
Profiler::Scope profile("Database query", Profiler::Phase::DATABASE);
std::pair<CppSQLite3Statement, CppSQLite3Query> toReturn;
toReturn.first = CreatePreppedStmt(query);
SetParams(toReturn.first, std::forward<Args>(args)...);
@@ -511,6 +513,7 @@ private:
template<typename... Args>
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>(args)...);
DLU_SQL_TRY_CATCH_RETHROW(preppedStmt.execDML());
@@ -518,6 +521,7 @@ private:
template<typename... Args>
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>(args)...);
DLU_SQL_TRY_CATCH_RETHROW(return preppedStmt.execDML());
@@ -525,6 +529,7 @@ private:
template<typename... Args>
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>(args)...);
DLU_SQL_TRY_CATCH_RETHROW(return preppedStmt.execDML());

View File

@@ -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);

View File

@@ -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<typename ComponentType, typename... VaArgs>
inline ComponentType* Entity::AddComponent(VaArgs... args) {
static_assert(std::is_base_of_v<Component, ComponentType>, "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<uint64_t>(ComponentType::ComponentType));
// Get the component if it already exists, or default construct a nullptr
auto*& componentToReturn = m_Components[ComponentType::ComponentType];

View File

@@ -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();
}

View File

@@ -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");

View File

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

View File

@@ -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) {

View File

@@ -1,4 +1,6 @@
#include "DashboardActions.h"
#include "Profiler.h"
#include <optional>
#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<float>(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<Profiler::Scope> 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<std::chrono::duration<float>>(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();

View File

@@ -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; }