feat(Core/Metrics): implement real time statistic visualization (#8663)

src/server/database/Database/DatabaseWorkerPool.cpp

@@ -430,6 +430,12 @@ void DatabaseWorkerPool<T>::Enqueue(SQLOperation* op)
     _queue->Push(op);
 }
 
+template <class T>
+size_t DatabaseWorkerPool<T>::QueueSize() const
+{
+    return _queue->Size();
+}
+
 template <class T>
 T* DatabaseWorkerPool<T>::GetFreeConnection()
 {

src/server/database/Database/DatabaseWorkerPool.h

@@ -213,6 +213,8 @@ public:
 #endif
     }
 
+    size_t QueueSize() const;
+
 private:
     uint32 OpenConnections(InternalIndex type, uint8 numConnections);
 

src/server/game/Handlers/CharacterHandler.cpp

@@ -29,12 +29,14 @@
 #include "GuildMgr.h"
 #include "Language.h"
 #include "Log.h"
+#include "Metric.h"
 #include "ObjectAccessor.h"
 #include "ObjectMgr.h"
 #include "Opcodes.h"
 #include "Pet.h"
 #include "Player.h"
 #include "PlayerDump.h"
+#include "QueryHolder.h"
 #include "Realm.h"
 #include "ReputationMgr.h"
 #include "ScriptMgr.h"
@@ -43,15 +45,14 @@
 #include "SocialMgr.h"
 #include "SpellAuraEffects.h"
 #include "SpellAuras.h"
+#include "StringConvert.h"
+#include "Tokenize.h"
 #include "Transport.h"
 #include "UpdateMask.h"
 #include "Util.h"
 #include "World.h"
 #include "WorldPacket.h"
 #include "WorldSession.h"
-#include "QueryHolder.h"
-#include "StringConvert.h"
-#include "Tokenize.h"
 
 #ifdef ELUNA
 #include "LuaEngine.h"
@@ -1087,6 +1088,8 @@ void WorldSession::HandlePlayerLoginFromDB(LoginQueryHolder const& holder)
         pCurrChar->RemoveAtLoginFlag(AT_LOGIN_FIRST);
         sScriptMgr->OnFirstLogin(pCurrChar);
     }
+
+    METRIC_EVENT("player_events", "Login", pCurrChar->GetName());
 }
 
 void WorldSession::HandlePlayerLoginToCharInWorld(Player* pCurrChar)

src/server/game/Maps/Map.cpp

@@ -28,6 +28,7 @@
 #include "LFGMgr.h"
 #include "Map.h"
 #include "MapInstanced.h"
+#include "Metric.h"
 #include "Object.h"
 #include "ObjectAccessor.h"
 #include "ObjectMgr.h"
@@ -868,6 +869,14 @@ void Map::Update(const uint32 t_diff, const uint32 s_diff, bool  /*thread*/)
     HandleDelayedVisibility();
 
     sScriptMgr->OnMapUpdate(this, t_diff);
+
+    METRIC_VALUE("map_creatures", uint64(GetObjectsStore().Size<Creature>()),
+        METRIC_TAG("map_id", std::to_string(GetId())),
+        METRIC_TAG("map_instanceid", std::to_string(GetInstanceId())));
+
+    METRIC_VALUE("map_gameobjects", uint64(GetObjectsStore().Size<GameObject>()),
+        METRIC_TAG("map_id", std::to_string(GetId())),
+        METRIC_TAG("map_instanceid", std::to_string(GetInstanceId())));
 }
 
 void Map::HandleDelayedVisibility()

src/server/game/Maps/MapUpdater.cpp

@@ -19,6 +19,7 @@
 #include "LFGMgr.h"
 #include "Map.h"
 #include "MapUpdater.h"
+#include "Metric.h"
 
 class UpdateRequest
 {
@@ -39,9 +40,11 @@ public:
 
     void call() override
     {
+        METRIC_TIMER("map_update_time_diff", METRIC_TAG("map_id", std::to_string(m_map.GetId())));
         m_map.Update(m_diff, s_diff);
         m_updater.update_finished();
     }
+
 private:
     Map& m_map;
     MapUpdater& m_updater;

src/server/game/Movement/MovementGenerators/PathGenerator.cpp

@@ -20,6 +20,7 @@
 #include "Geometry.h"
 #include "Log.h"
 #include "Map.h"
+#include "Metric.h"
 #include "MMapFactory.h"
 #include "MMapMgr.h"
 #include "PathGenerator.h"
@@ -61,6 +62,8 @@ bool PathGenerator::CalculatePath(float x, float y, float z, float destX, float
     if (!Acore::IsValidMapCoord(destX, destY, destZ) || !Acore::IsValidMapCoord(x, y, z))
         return false;
 
+    METRIC_DETAILED_EVENT("mmap_events", "CalculatePath", "");
+
     G3D::Vector3 dest(destX, destY, destZ);
     SetEndPosition(dest);
 

src/server/game/Server/WorldSession.cpp

@@ -30,6 +30,7 @@
 #include "Hyperlinks.h"
 #include "Log.h"
 #include "MapMgr.h"
+#include "Metric.h"
 #include "ObjectAccessor.h"
 #include "ObjectMgr.h"
 #include "Opcodes.h"
@@ -319,6 +320,8 @@ bool WorldSession::Update(uint32 diff, PacketFilter& updater)
         OpcodeClient opcode = static_cast<OpcodeClient>(packet->GetOpcode());
         ClientOpcodeHandler const* opHandle = opcodeTable[opcode];
 
+        METRIC_DETAILED_TIMER("worldsession_update_opcode_time", METRIC_TAG("opcode", opHandle->Name));
+
         try
         {
             switch (opHandle->Status)
@@ -441,6 +444,8 @@ bool WorldSession::Update(uint32 diff, PacketFilter& updater)
 
     _recvQueue.readd(requeuePackets.begin(), requeuePackets.end());
 
+    METRIC_VALUE("processed_packets", processedPackets);
+
     if (!updater.ProcessUnsafe()) // <=> updater is of type MapSessionFilter
     {
         // Send time sync packet every 10s.
@@ -671,6 +676,8 @@ void WorldSession::LogoutPlayer(bool save)
         //! Call script hook before deletion
         sScriptMgr->OnPlayerLogout(_player);
 
+        METRIC_EVENT("player_events", "Logout", _player->GetName());
+
         LOG_INFO("entities.player", "Account: %d (IP: %s) Logout Character:[%s] (%s) Level: %d",
             GetAccountId(), GetRemoteAddress().c_str(), _player->GetName().c_str(), _player->GetGUID().ToString().c_str(), _player->getLevel());
 

src/server/game/World/World.cpp

@@ -60,6 +60,7 @@
 #include "LootMgr.h"
 #include "MMapFactory.h"
 #include "MapMgr.h"
+#include "Metric.h"
 #include "ObjectMgr.h"
 #include "Opcodes.h"
 #include "OutdoorPvPMgr.h"
@@ -437,6 +438,7 @@ void World::LoadConfigSettings(bool reload)
         }
 
         sLog->LoadFromConfig();
+        sMetric->LoadFromConfigs();
     }
 
     // Set realm id and enable db logging
@@ -2107,10 +2109,13 @@ void World::SetInitialWorldSettings()
     }
 
     uint32 startupDuration = GetMSTimeDiffToNow(startupBegin);
+
     LOG_INFO("server.loading", " ");
     LOG_INFO("server.loading", "WORLD: World initialized in %u minutes %u seconds", (startupDuration / 60000), ((startupDuration % 60000) / 1000)); // outError for red color in console
     LOG_INFO("server.loading", " ");
 
+    METRIC_EVENT("events", "World initialized", "World initialized in " + std::to_string(startupDuration / 60000) + " minutes " + std::to_string((startupDuration % 60000) / 1000) + " seconds");
+
     if (sConfigMgr->isDryRun())
     {
         LOG_INFO("server.loading", "AzerothCore dry run completed, terminating.");
@@ -2199,6 +2204,8 @@ void World::LoadAutobroadcasts()
 /// Update the World !
 void World::Update(uint32 diff)
 {
+    METRIC_TIMER("world_update_time_total");
+
     m_updateTime = diff;
 
     if (m_int_configs[CONFIG_INTERVAL_LOG_UPDATE])
@@ -2238,26 +2245,45 @@ void World::Update(uint32 diff)
     ///- Update the game time and check for shutdown time
     _UpdateGameTime();
 
-    /// Handle daily quests reset time
-    if (m_gameTime > m_NextDailyQuestReset)
-        ResetDailyQuests();
+    {
+        METRIC_TIMER("world_update_time", METRIC_TAG("type", "Check quest reset times"));
 
-    /// Handle weekly quests reset time
-    if (m_gameTime > m_NextWeeklyQuestReset)
-        ResetWeeklyQuests();
+        /// Handle daily quests reset time
+        if (m_gameTime > m_NextDailyQuestReset)
+        {
+            ResetDailyQuests();
+        }
 
-    /// Handle monthly quests reset time
-    if (m_gameTime > m_NextMonthlyQuestReset)
-        ResetMonthlyQuests();
+        /// Handle weekly quests reset time
+        if (m_gameTime > m_NextWeeklyQuestReset)
+        {
+            ResetWeeklyQuests();
+        }
+
+        /// Handle monthly quests reset time
+        if (m_gameTime > m_NextMonthlyQuestReset)
+        {
+            ResetMonthlyQuests();
+        }
+    }
 
     if (m_gameTime > m_NextRandomBGReset)
+    {
+        METRIC_TIMER("world_update_time", METRIC_TAG("type", "Reset random BG"));
         ResetRandomBG();
+    }
 
     if (m_gameTime > m_NextCalendarOldEventsDeletionTime)
+    {
+        METRIC_TIMER("world_update_time", METRIC_TAG("type", "Delete old calendar events"));
         CalendarDeleteOldEvents();
+    }
 
     if (m_gameTime > m_NextGuildReset)
+    {
+        METRIC_TIMER("world_update_time", METRIC_TAG("type", "Reset guild cap"));
         ResetGuildCap();
+    }
 
     // pussywizard:
     // acquire mutex now, this is kind of waiting for listing thread to finish it's work (since it can't process next packet)
@@ -2269,6 +2295,8 @@ void World::Update(uint32 diff)
         // pussywizard: handle auctions when the timer has passed
         if (m_timers[WUPDATE_AUCTIONS].Passed())
         {
+            METRIC_TIMER("world_update_time", METRIC_TAG("type", "Update expired auctions"));
+
             m_timers[WUPDATE_AUCTIONS].Reset();
 
             // pussywizard: handle expired auctions, auctions expired when realm was offline are also handled here (not during loading when many required things aren't loaded yet)
@@ -2283,8 +2311,13 @@ void World::Update(uint32 diff)
             mail_expire_check_timer = m_gameTime + 6 * 3600;
         }
 
-        UpdateSessions(diff);
+        {
+            /// <li> Handle session updates when the timer has passed
+            METRIC_TIMER("world_update_time", METRIC_TAG("type", "Update sessions"));
+            UpdateSessions(diff);
+        }
     }
+
     // end of section with mutex
     AsyncAuctionListingMgr::SetAuctionListingAllowed(true);
 
@@ -2300,6 +2333,8 @@ void World::Update(uint32 diff)
     {
         if (m_timers[WUPDATE_CLEANDB].Passed())
         {
+            METRIC_TIMER("world_update_time", METRIC_TAG("type", "Clean logs table"));
+
             m_timers[WUPDATE_CLEANDB].Reset();
 
             LoginDatabasePreparedStatement* stmt = LoginDatabase.GetPreparedStatement(LOGIN_DEL_OLD_LOGS);
@@ -2311,33 +2346,58 @@ void World::Update(uint32 diff)
         }
     }
 
-    sLFGMgr->Update(diff, 0); // pussywizard: remove obsolete stuff before finding compatibility during map update
+    {
+        METRIC_TIMER("world_update_time", METRIC_TAG("type", "Update LFG 0"));
+        sLFGMgr->Update(diff, 0); // pussywizard: remove obsolete stuff before finding compatibility during map update
+    }
 
-    sMapMgr->Update(diff);
+    ///- Update objects when the timer has passed (maps, transport, creatures, ...)
+    {
+        METRIC_TIMER("world_update_time", METRIC_TAG("type", "Update maps"));
+        sMapMgr->Update(diff);
+    }
 
     if (sWorld->getBoolConfig(CONFIG_AUTOBROADCAST))
     {
         if (m_timers[WUPDATE_AUTOBROADCAST].Passed())
         {
+            METRIC_TIMER("world_update_time", METRIC_TAG("type", "Send autobroadcast"));
             m_timers[WUPDATE_AUTOBROADCAST].Reset();
             SendAutoBroadcast();
         }
     }
 
-    sBattlegroundMgr->Update(diff);
+    {
+        METRIC_TIMER("world_update_time", METRIC_TAG("type", "Update battlegrounds"));
+        sBattlegroundMgr->Update(diff);
+    }
 
-    sOutdoorPvPMgr->Update(diff);
+    {
+        METRIC_TIMER("world_update_time", METRIC_TAG("type", "Update outdoor pvp"));
+        sOutdoorPvPMgr->Update(diff);
+    }
 
-    sBattlefieldMgr->Update(diff);
+    {
+        METRIC_TIMER("world_update_time", METRIC_TAG("type", "Update battlefields"));
+        sBattlefieldMgr->Update(diff);
+    }
 
-    sLFGMgr->Update(diff, 2); // pussywizard: handle created proposals
+    {
+        METRIC_TIMER("world_update_time", METRIC_TAG("type", "Update LFG 2"));
+        sLFGMgr->Update(diff, 2); // pussywizard: handle created proposals
+    }
 
-    // execute callbacks from sql queries that were queued recently
-    ProcessQueryCallbacks();
+    {
+        METRIC_TIMER("world_update_time", METRIC_TAG("type", "Process query callbacks"));
+        // execute callbacks from sql queries that were queued recently
+        ProcessQueryCallbacks();
+    }
 
     /// <li> Update uptime table
     if (m_timers[WUPDATE_UPTIME].Passed())
     {
+        METRIC_TIMER("world_update_time", METRIC_TAG("type", "Update uptime"));
+
         uint32 tmpDiff = uint32(m_gameTime - m_startTime);
         uint32 maxOnlinePlayers = GetMaxPlayerCount();
 
@@ -2356,6 +2416,7 @@ void World::Update(uint32 diff)
     ///- Erase corpses once every 20 minutes
     if (m_timers[WUPDATE_CORPSES].Passed())
     {
+        METRIC_TIMER("world_update_time", METRIC_TAG("type", "Remove old corpses"));
         m_timers[WUPDATE_CORPSES].Reset();
         sMapMgr->DoForAllMaps([](Map* map)
         {
@@ -2366,6 +2427,7 @@ void World::Update(uint32 diff)
     ///- Process Game events when necessary
     if (m_timers[WUPDATE_EVENTS].Passed())
     {
+        METRIC_TIMER("world_update_time", METRIC_TAG("type", "Update game events"));
         m_timers[WUPDATE_EVENTS].Reset();                   // to give time for Update() to be processed
         uint32 nextGameEvent = sGameEventMgr->Update();
         m_timers[WUPDATE_EVENTS].SetInterval(nextGameEvent);
@@ -2375,6 +2437,7 @@ void World::Update(uint32 diff)
     ///- Ping to keep MySQL connections alive
     if (m_timers[WUPDATE_PINGDB].Passed())
     {
+        METRIC_TIMER("world_update_time", METRIC_TAG("type", "Ping MySQL"));
         m_timers[WUPDATE_PINGDB].Reset();
         LOG_DEBUG("sql.driver", "Ping MySQL to keep connection alive");
         CharacterDatabase.KeepAlive();
@@ -2382,15 +2445,34 @@ void World::Update(uint32 diff)
         WorldDatabase.KeepAlive();
     }
 
-    // update the instance reset times
-    sInstanceSaveMgr->Update();
+    {
+        METRIC_TIMER("world_update_time", METRIC_TAG("type", "Update instance reset times"));
+        // update the instance reset times
+        sInstanceSaveMgr->Update();
+    }
 
-    // And last, but not least handle the issued cli commands
-    ProcessCliCommands();
+    {
+        METRIC_TIMER("world_update_time", METRIC_TAG("type", "Process cli commands"));
+        // And last, but not least handle the issued cli commands
+        ProcessCliCommands();
+    }
 
-    sScriptMgr->OnWorldUpdate(diff);
+    {
+        METRIC_TIMER("world_update_time", METRIC_TAG("type", "Update world scripts"));
+        sScriptMgr->OnWorldUpdate(diff);
+    }
 
-    SavingSystemMgr::Update(diff);
+    {
+        METRIC_TIMER("world_update_time", METRIC_TAG("type", "Update saving system"));
+        SavingSystemMgr::Update(diff);
+    }
+
+    {
+        METRIC_TIMER("world_update_time", METRIC_TAG("type", "Update metrics"));
+        // Stats logger update
+        sMetric->Update();
+        METRIC_VALUE("update_time_diff", diff);
+    }
 }
 
 void World::ForceGameEventUpdate()
@@ -2710,10 +2792,18 @@ void World::SendServerMessage(ServerMessageType type, const char* text, Player*
 
 void World::UpdateSessions(uint32 diff)
 {
-    ///- Add new sessions
-    WorldSession* sess = nullptr;
-    while (addSessQueue.next(sess))
-        AddSession_ (sess);
+    {
+        METRIC_DETAILED_NO_THRESHOLD_TIMER("world_update_time",
+            METRIC_TAG("type", "Add sessions"),
+            METRIC_TAG("parent_type", "Update sessions"));
+
+        ///- Add new sessions
+        WorldSession* sess = nullptr;
+        while (addSessQueue.next(sess))
+        {
+            AddSession_(sess);
+        }
+    }
 
     ///- Then send an update signal to remaining ones
     for (SessionMap::iterator itr = m_sessions.begin(), next; itr != m_sessions.end(); itr = next)
@@ -2745,6 +2835,9 @@ void World::UpdateSessions(uint32 diff)
             continue;
         }
 
+        [[maybe_unused]] uint32 currentSessionId = itr->first;
+        METRIC_DETAILED_TIMER("world_update_sessions_time", METRIC_TAG("account_id", std::to_string(currentSessionId)));
+
         if (!pSession->Update(diff, updater))
         {
             if (!RemoveQueuedPlayer(pSession) && getIntConfig(CONFIG_INTERVAL_DISCONNECT_TOLERANCE))

src/server/scripts/Commands/cs_server.cpp

@@ -219,6 +219,10 @@ public:
         handler->PSendSysMessage("Using World DB Revision: %s", sWorld->GetWorldDBRevision());
         handler->PSendSysMessage("Using Character DB Revision: %s", sWorld->GetCharacterDBRevision());
         handler->PSendSysMessage("Using Auth DB Revision: %s", sWorld->GetAuthDBRevision());
+
+        handler->PSendSysMessage("LoginDatabase queue size: %zu", LoginDatabase.QueueSize());
+        handler->PSendSysMessage("CharacterDatabase queue size: %zu", CharacterDatabase.QueueSize());
+        handler->PSendSysMessage("WorldDatabase queue size: %zu", WorldDatabase.QueueSize());
         return true;
     }
 

src/server/worldserver/Main.cpp

@@ -37,6 +37,7 @@
 #include "GitRevision.h"
 #include "IoContext.h"
 #include "MapMgr.h"
+#include "Metric.h"
 #include "MySQLThreading.h"
 #include "ObjectAccessor.h"
 #include "OpenSSLCrypto.h"
@@ -288,6 +289,22 @@ int main(int argc, char** argv)
 
     LoadRealmInfo(*ioContext);
 
+    sMetric->Initialize(realm.Name, *ioContext, []()
+    {
+        METRIC_VALUE("online_players", sWorld->GetPlayerCount());
+        METRIC_VALUE("db_queue_login", uint64(LoginDatabase.QueueSize()));
+        METRIC_VALUE("db_queue_character", uint64(CharacterDatabase.QueueSize()));
+        METRIC_VALUE("db_queue_world", uint64(WorldDatabase.QueueSize()));
+    });
+
+    METRIC_EVENT("events", "Worldserver started", "");
+
+    std::shared_ptr<void> sMetricHandle(nullptr, [](void*)
+    {
+        METRIC_EVENT("events", "Worldserver shutdown", "");
+        sMetric->Unload();
+    });
+
     // Loading modules configs
     sConfigMgr->PrintLoadedModulesConfigs();
 

src/server/worldserver/worldserver.conf.dist

@@ -31,6 +31,7 @@
 #    LOGGING SYSTEM SETTINGS
 #    PACKET SPOOF PROTECTION SETTINGS
 #    DEBUG
+#    METRIC SETTINGS
 #
 ###################################################################################################
 
@@ -3821,3 +3822,58 @@ Debug.Arena = 0
 
 #
 ###################################################################################################
+
+###################################################################################################
+# METRIC SETTINGS
+#
+# These settings control the statistics sent to the metric database (currently InfluxDB)
+#
+#    Metric.Enable
+#        Description: Enables statistics sent to the metric database.
+#        Default:     0 - (Disabled)
+#                     1 - (Enabled)
+#
+
+Metric.Enable = 0
+
+#
+#    Metric.Interval
+#        Description: Interval between every batch of data sent in seconds
+#        Default:     10 seconds
+#
+
+Metric.Interval = 10
+
+#
+#    Metric.ConnectionInfo
+#        Description: Connection settings for metric database (currently InfluxDB).
+#        Example:     "hostname;port;database"
+#        Default:     "127.0.0.1;8086;worldserver"
+#
+
+Metric.ConnectionInfo = "127.0.0.1;8086;worldserver"
+
+#
+#    Metric.OverallStatusInterval
+#        Description: Interval between every gathering of overall worldserver status data in seconds
+#        Default:     1 second
+#
+
+Metric.OverallStatusInterval = 1
+
+#
+#  Metric threshold values: Given a metric "name"
+#    Metric.Threshold.name
+#        Description: Skips sending statistics with a value lower than the config value.
+#                     If the threshold is commented out, the metric will be ignored.
+#                     Only metrics logged with METRIC_DETAILED_TIMER in the sources are affected.
+#                     Disabled by default. Requires WITH_DETAILED_METRICS CMake flag.
+#
+#        Format:      Value as integer
+#
+
+#Metric.Threshold.world_update_sessions_time = 100
+#Metric.Threshold.worldsession_update_opcode_time = 50
+
+#
+###################################################################################################