Core/Metric: Add more metrics about World::Update() loop (#25098)

* Core/Metric: Add more metrics about World::Update() loop

* Add new Performance profiling grafana dashboard

* Add new cmake setting WITHOUT_METRICS that disables all metrics

As new metrics are added, someone might want to disable them if unused.

* Add more metrics about World::Update() loop

* Remove old performance profiling features

Remove "server set difftime" command, "-RecordUpdateTimeDiffInterval" and "MinRecordUpdateTimeDiff" worldserver config settings and their related code.
The whole UpdateTime class could be removed too.

* Update and rename 2020_07_99_99_world.sql to 2020_07_24_00_world.sql

8 files changed, 96 insertions, 141 deletions

diff --git a/src/common/Metric/Metric.cpp b/src/common/Metric/Metric.cpp
index 07db8e83f4d..d22839e8a79 100644
--- a/src/common/Metric/Metric.cpp
+++ b/src/common/Metric/Metric.cpp
@@ -137,7 +137,7 @@ void Metric::SendBatch()
             batchedData << ",realm=" << _realmName;
 
         for (MetricTag const& tag : data->Tags)
-            batchedData << "," << tag.first << "=" << tag.second;
+            batchedData << "," << tag.first << "=" << FormatInfluxDBTagValue(tag.second);
 
         batchedData << " ";
 
diff --git a/src/common/Metric/Metric.h b/src/common/Metric/Metric.h
index 5038338421c..33bdf3b4ed7 100644
--- a/src/common/Metric/Metric.h
+++ b/src/common/Metric/Metric.h
@@ -158,10 +158,16 @@ MetricStopWatch<LoggerType> MakeMetricStopWatch(LoggerType&& loggerFunc)
 
 #define TC_METRIC_TAG(name, value) { name, value }
 
-#ifdef PERFORMANCE_PROFILING
+#define TC_METRIC_DO_CONCAT(a, b) a##b
+#define TC_METRIC_CONCAT(a, b) TC_METRIC_DO_CONCAT(a, b)
+#define TC_METRIC_UNIQUE_NAME(name) TC_METRIC_CONCAT(name, __LINE__)
+
+#if defined PERFORMANCE_PROFILING || defined WITHOUT_METRICS
 #define TC_METRIC_EVENT(category, title, description) ((void)0)
 #define TC_METRIC_VALUE(category, value) ((void)0)
-#elif TRINITY_PLATFORM != TRINITY_PLATFORM_WINDOWS
+#define TC_METRIC_TIMER(category, ...) ((void)0)
+#else
+#  if TRINITY_PLATFORM != TRINITY_PLATFORM_WINDOWS
 #define TC_METRIC_EVENT(category, title, description)                  \
         do {                                                           \
             if (sMetric->IsEnabled())                                  \
@@ -172,7 +178,7 @@ MetricStopWatch<LoggerType> MakeMetricStopWatch(LoggerType&& loggerFunc)
             if (sMetric->IsEnabled())                                  \
                 sMetric->LogValue(category, value, { __VA_ARGS__ });   \
         } while (0)
-#else
+#  else
 #define TC_METRIC_EVENT(category, title, description)                  \
         __pragma(warning(push))                                        \
         __pragma(warning(disable:4127))                                \
@@ -189,11 +195,12 @@ MetricStopWatch<LoggerType> MakeMetricStopWatch(LoggerType&& loggerFunc)
                 sMetric->LogValue(category, value, { __VA_ARGS__ });   \
         } while (0)                                                    \
         __pragma(warning(pop))
-#endif
+#  endif
 #define TC_METRIC_TIMER(category, ...)                           \
-        MetricStopWatch __tc_metric_stop_watch = MakeMetricStopWatch([&](TimePoint start) \
+        MetricStopWatch TC_METRIC_UNIQUE_NAME(__tc_metric_stop_watch) = MakeMetricStopWatch([&](TimePoint start) \
         {                                                                                                             \
             sMetric->LogValue(category, std::chrono::steady_clock::now() - start, { __VA_ARGS__ });               \
         });
+#endif
 
 #endif // METRIC_H__
diff --git a/src/server/game/Accounts/RBAC.h b/src/server/game/Accounts/RBAC.h
index 046cc0373a2..9e248e7f0c0 100644
--- a/src/server/game/Accounts/RBAC.h
+++ b/src/server/game/Accounts/RBAC.h
@@ -632,7 +632,7 @@ enum RBACPermissions
     RBAC_PERM_COMMAND_SERVER_RESTART_CANCEL                  = 728,
     RBAC_PERM_COMMAND_SERVER_SET                             = 729,
     RBAC_PERM_COMMAND_SERVER_SET_CLOSED                      = 730,
-    RBAC_PERM_COMMAND_SERVER_SET_DIFFTIME                    = 731,
+    RBAC_PERM_COMMAND_SERVER_SET_DIFFTIME                    = 731, // reserved
     RBAC_PERM_COMMAND_SERVER_SET_LOGLEVEL                    = 732,
     RBAC_PERM_COMMAND_SERVER_SET_MOTD                        = 733,
     RBAC_PERM_COMMAND_SERVER_SHUTDOWN                        = 734,
diff --git a/src/server/game/Time/UpdateTime.cpp b/src/server/game/Time/UpdateTime.cpp
index c4dada2853e..8e72e2c6c75 100644
--- a/src/server/game/Time/UpdateTime.cpp
+++ b/src/server/game/Time/UpdateTime.cpp
@@ -31,7 +31,6 @@ UpdateTime::UpdateTime()
     _maxUpdateTime = 0;
     _maxUpdateTimeOfLastTable = 0;
     _maxUpdateTimeOfCurrentTable = 0;
-    _recordedTime = 0;
 
     _updateTimeDataTable = { };
 }
@@ -92,47 +91,3 @@ void UpdateTime::UpdateWithDiff(uint32 diff)
     else if (_updateTimeTableIndex)
         _averageUpdateTime = _totalUpdateTime / _updateTimeTableIndex;
 }
-
-void UpdateTime::RecordUpdateTimeReset()
-{
-    _recordedTime = getMSTime();
-}
-
-void UpdateTime::_RecordUpdateTimeDuration(std::string const& text, uint32 minUpdateTime)
-{
-    uint32 thisTime = getMSTime();
-    uint32 diff = getMSTimeDiff(_recordedTime, thisTime);
-
-    if (diff > minUpdateTime)
-        TC_LOG_INFO("misc", "Recored Update Time of %s: %u.", text.c_str(), diff);
-
-    _recordedTime = thisTime;
-}
-
-void WorldUpdateTime::LoadFromConfig()
-{
-    _recordUpdateTimeInverval = sConfigMgr->GetIntDefault("RecordUpdateTimeDiffInterval", 60000);
-    _recordUpdateTimeMin = sConfigMgr->GetIntDefault("MinRecordUpdateTimeDiff", 100);
-}
-
-void WorldUpdateTime::SetRecordUpdateTimeInterval(uint32 t)
-{
-    _recordUpdateTimeInverval = t;
-}
-
-void WorldUpdateTime::RecordUpdateTime(uint32 gameTimeMs, uint32 diff, uint32 sessionCount)
-{
-    if (_recordUpdateTimeInverval > 0 && diff > _recordUpdateTimeMin)
-    {
-        if (getMSTimeDiff(_lastRecordTime, gameTimeMs) > _recordUpdateTimeInverval)
-        {
-            TC_LOG_DEBUG("misc", "Update time diff: %u. Players online: %u.", GetAverageUpdateTime(), sessionCount);
-            _lastRecordTime = gameTimeMs;
-        }
-    }
-}
-
-void WorldUpdateTime::RecordUpdateTimeDuration(std::string const& text)
-{
-    _RecordUpdateTimeDuration(text, _recordUpdateTimeMin);
-}
diff --git a/src/server/game/Time/UpdateTime.h b/src/server/game/Time/UpdateTime.h
index 139566fd468..ab51c08fdd9 100644
--- a/src/server/game/Time/UpdateTime.h
+++ b/src/server/game/Time/UpdateTime.h
@@ -37,13 +37,9 @@ class TC_GAME_API UpdateTime
 
         void UpdateWithDiff(uint32 diff);
 
-        void RecordUpdateTimeReset();
-
     protected:
         UpdateTime();
 
-        void _RecordUpdateTimeDuration(std::string const& text, uint32 minUpdateTime);
-
     private:
         DiffTableArray _updateTimeDataTable;
         uint32 _averageUpdateTime;
@@ -52,23 +48,12 @@ class TC_GAME_API UpdateTime
         uint32 _maxUpdateTime;
         uint32 _maxUpdateTimeOfLastTable;
         uint32 _maxUpdateTimeOfCurrentTable;
-
-        uint32 _recordedTime;
 };
 
 class TC_GAME_API WorldUpdateTime : public UpdateTime
 {
     public:
-        WorldUpdateTime() : UpdateTime(), _recordUpdateTimeInverval(0), _recordUpdateTimeMin(0), _lastRecordTime(0) { }
-        void LoadFromConfig();
-        void SetRecordUpdateTimeInterval(uint32 t);
-        void RecordUpdateTime(uint32 gameTimeMs, uint32 diff, uint32 sessionCount);
-        void RecordUpdateTimeDuration(std::string const& text);
-
-    private:
-        uint32 _recordUpdateTimeInverval;
-        uint32 _recordUpdateTimeMin;
-        uint32 _lastRecordTime;
+        WorldUpdateTime() : UpdateTime() { }
 };
 
 TC_GAME_API extern WorldUpdateTime sWorldUpdateTime;
diff --git a/src/server/game/World/World.cpp b/src/server/game/World/World.cpp
index b39b2a84d87..fe1abc71094 100644
--- a/src/server/game/World/World.cpp
+++ b/src/server/game/World/World.cpp
@@ -481,9 +481,6 @@ void World::LoadConfigSettings(bool reload)
         sMetric->LoadFromConfigs();
     }
 
-    // load update time related configs
-    sWorldUpdateTime.LoadFromConfig();
-
     ///- Read the player limit and the Message of the day from the config file
     SetPlayerAmountLimit(sConfigMgr->GetIntDefault("PlayerLimit", 100));
     Motd::SetMotd(sConfigMgr->GetStringDefault("Motd", "Welcome to a Trinity Core Server."));
@@ -2284,15 +2281,13 @@ void World::LoadAutobroadcasts()
 /// Update the World !
 void World::Update(uint32 diff)
 {
+    TC_METRIC_TIMER("world_update_time_total");
     ///- Update the game time and check for shutdown time
     _UpdateGameTime();
     time_t currentGameTime = GameTime::GetGameTime();
 
     sWorldUpdateTime.UpdateWithDiff(diff);
 
-    // Record update if recording set in log and diff is greater then minimum set in log
-    sWorldUpdateTime.RecordUpdateTime(GameTime::GetGameTimeMS(), diff, GetActiveSessionCount());
-
     ///- Update the different timers
     for (int i = 0; i < WUPDATE_COUNT; ++i)
     {
@@ -2305,6 +2300,7 @@ void World::Update(uint32 diff)
     ///- Update Who List Storage
     if (m_timers[WUPDATE_WHO_LIST].Passed())
     {
+        TC_METRIC_TIMER("world_update_time", TC_METRIC_TAG("type", "Update who list"));
         m_timers[WUPDATE_WHO_LIST].Reset();
         sWhoListStorageMgr->Update();
     }
@@ -2315,6 +2311,7 @@ void World::Update(uint32 diff)
 
         if (sWorld->getBoolConfig(CONFIG_PRESERVE_CUSTOM_CHANNELS))
         {
+            TC_METRIC_TIMER("world_update_time", TC_METRIC_TAG("type", "Save custom channels"));
             ChannelMgr* mgr1 = ASSERT_NOTNULL(ChannelMgr::forTeam(ALLIANCE));
             mgr1->SaveToDB();
             ChannelMgr* mgr2 = ASSERT_NOTNULL(ChannelMgr::forTeam(HORDE));
@@ -2323,20 +2320,33 @@ void World::Update(uint32 diff)
         }
     }
 
-    CheckQuestResetTimes();
+    {
+        TC_METRIC_TIMER("world_update_time", TC_METRIC_TAG("type", "Check quest reset times"));
+        CheckQuestResetTimes();
+    }
 
     if (currentGameTime > m_NextRandomBGReset)
+    {
+        TC_METRIC_TIMER("world_update_time", TC_METRIC_TAG("type", "Reset random BG"));
         ResetRandomBG();
+    }
 
     if (currentGameTime > m_NextCalendarOldEventsDeletionTime)
+    {
+        TC_METRIC_TIMER("world_update_time", TC_METRIC_TAG("type", "Delete old calendar events"));
         CalendarDeleteOldEvents();
+    }
 
     if (currentGameTime > m_NextGuildReset)
+    {
+        TC_METRIC_TIMER("world_update_time", TC_METRIC_TAG("type", "Reset guild cap"));
         ResetGuildCap();
+    }
 
     /// <ul><li> Handle auctions when the timer has passed
     if (m_timers[WUPDATE_AUCTIONS].Passed())
     {
+        TC_METRIC_TIMER("world_update_time", TC_METRIC_TAG("type", "Update expired auctions"));
         m_timers[WUPDATE_AUCTIONS].Reset();
 
         ///- Update mails (return old mails with item, or delete them)
@@ -2353,6 +2363,7 @@ void World::Update(uint32 diff)
 
     if (m_timers[WUPDATE_AUCTIONS_PENDING].Passed())
     {
+        TC_METRIC_TIMER("world_update_time", TC_METRIC_TAG("type", "Update pending auctions"));
         m_timers[WUPDATE_AUCTIONS_PENDING].Reset();
 
         sAuctionMgr->UpdatePendingAuctions();
@@ -2361,6 +2372,7 @@ void World::Update(uint32 diff)
     /// <li> Handle AHBot operations
     if (m_timers[WUPDATE_AHBOT].Passed())
     {
+        TC_METRIC_TIMER("world_update_time", TC_METRIC_TAG("type", "Update AHBot"));
         sAuctionBot->Update();
         m_timers[WUPDATE_AHBOT].Reset();
     }
@@ -2368,18 +2380,21 @@ void World::Update(uint32 diff)
     /// <li> Handle file changes
     if (m_timers[WUPDATE_CHECK_FILECHANGES].Passed())
     {
+        TC_METRIC_TIMER("world_update_time", TC_METRIC_TAG("type", "Update HotSwap"));
         sScriptReloadMgr->Update();
         m_timers[WUPDATE_CHECK_FILECHANGES].Reset();
     }
 
-    /// <li> Handle session updates when the timer has passed
-    sWorldUpdateTime.RecordUpdateTimeReset();
-    UpdateSessions(diff);
-    sWorldUpdateTime.RecordUpdateTimeDuration("UpdateSessions");
+    {
+        /// <li> Handle session updates when the timer has passed
+        TC_METRIC_TIMER("world_update_time", TC_METRIC_TAG("type", "Update sessions"));
+        UpdateSessions(diff);
+    }
 
     /// <li> Update uptime table
     if (m_timers[WUPDATE_UPTIME].Passed())
     {
+        TC_METRIC_TIMER("world_update_time", TC_METRIC_TAG("type", "Update uptime"));
         uint32 tmpDiff = GameTime::GetUptime();
         uint32 maxOnlinePlayers = GetMaxPlayerCount();
 
@@ -2400,6 +2415,7 @@ void World::Update(uint32 diff)
     {
         if (m_timers[WUPDATE_CLEANDB].Passed())
         {
+            TC_METRIC_TIMER("world_update_time", TC_METRIC_TAG("type", "Clean logs table"));
             m_timers[WUPDATE_CLEANDB].Reset();
 
             LoginDatabasePreparedStatement* stmt = LoginDatabase.GetPreparedStatement(LOGIN_DEL_OLD_LOGS);
@@ -2414,48 +2430,64 @@ void World::Update(uint32 diff)
 
     /// <li> Handle all other objects
     ///- Update objects when the timer has passed (maps, transport, creatures, ...)
-    sWorldUpdateTime.RecordUpdateTimeReset();
-    sMapMgr->Update(diff);
-    sWorldUpdateTime.RecordUpdateTimeDuration("UpdateMapMgr");
+    {
+        TC_METRIC_TIMER("world_update_time", TC_METRIC_TAG("type", "Update maps"));
+        sMapMgr->Update(diff);
+    }
 
     if (sWorld->getBoolConfig(CONFIG_AUTOBROADCAST))
     {
         if (m_timers[WUPDATE_AUTOBROADCAST].Passed())
         {
+            TC_METRIC_TIMER("world_update_time", TC_METRIC_TAG("type", "Send autobroadcast"));
             m_timers[WUPDATE_AUTOBROADCAST].Reset();
             SendAutoBroadcast();
         }
     }
 
-    sBattlegroundMgr->Update(diff);
-    sWorldUpdateTime.RecordUpdateTimeDuration("UpdateBattlegroundMgr");
+    {
+        TC_METRIC_TIMER("world_update_time", TC_METRIC_TAG("type", "Update battlegrounds"));
+        sBattlegroundMgr->Update(diff);
+    }
 
-    sOutdoorPvPMgr->Update(diff);
-    sWorldUpdateTime.RecordUpdateTimeDuration("UpdateOutdoorPvPMgr");
+    {
+        TC_METRIC_TIMER("world_update_time", TC_METRIC_TAG("type", "Update outdoor pvp"));
+        sOutdoorPvPMgr->Update(diff);
+    }
 
-    sBattlefieldMgr->Update(diff);
-    sWorldUpdateTime.RecordUpdateTimeDuration("BattlefieldMgr");
+    {
+        TC_METRIC_TIMER("world_update_time", TC_METRIC_TAG("type", "Update battlefields"));
+        sBattlefieldMgr->Update(diff);
+    }
 
     ///- Delete all characters which have been deleted X days before
     if (m_timers[WUPDATE_DELETECHARS].Passed())
     {
+        TC_METRIC_TIMER("world_update_time", TC_METRIC_TAG("type", "Delete old characters"));
         m_timers[WUPDATE_DELETECHARS].Reset();
         Player::DeleteOldCharacters();
     }
 
-    sGroupMgr->Update(diff);
-    sWorldUpdateTime.RecordUpdateTimeDuration("UpdateGroupMgr");
+    {
+        TC_METRIC_TIMER("world_update_time", TC_METRIC_TAG("type", "Update groups"));
+        sGroupMgr->Update(diff);
+    }
 
-    sLFGMgr->Update(diff);
-    sWorldUpdateTime.RecordUpdateTimeDuration("UpdateLFGMgr");
+    {
+        TC_METRIC_TIMER("world_update_time", TC_METRIC_TAG("type", "Update LFG"));
+        sLFGMgr->Update(diff);
+    }
 
-    // execute callbacks from sql queries that were queued recently
-    ProcessQueryCallbacks();
-    sWorldUpdateTime.RecordUpdateTimeDuration("ProcessQueryCallbacks");
+    {
+        TC_METRIC_TIMER("world_update_time", TC_METRIC_TAG("type", "Process query callbacks"));
+        // execute callbacks from sql queries that were queued recently
+        ProcessQueryCallbacks();
+    }
 
     ///- Erase corpses once every 20 minutes
     if (m_timers[WUPDATE_CORPSES].Passed())
     {
+        TC_METRIC_TIMER("world_update_time", TC_METRIC_TAG("type", "Remove old corpses"));
         m_timers[WUPDATE_CORPSES].Reset();
         sMapMgr->DoForAllMaps([](Map* map)
         {
@@ -2466,6 +2498,7 @@ void World::Update(uint32 diff)
     ///- Process Game events when necessary
     if (m_timers[WUPDATE_EVENTS].Passed())
     {
+        TC_METRIC_TIMER("world_update_time", TC_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);
@@ -2475,6 +2508,7 @@ void World::Update(uint32 diff)
     ///- Ping to keep MySQL connections alive
     if (m_timers[WUPDATE_PINGDB].Passed())
     {
+        TC_METRIC_TIMER("world_update_time", TC_METRIC_TAG("type", "Ping MySQL"));
         m_timers[WUPDATE_PINGDB].Reset();
         TC_LOG_DEBUG("misc", "Ping MySQL to keep connection alive");
         CharacterDatabase.KeepAlive();
@@ -2482,8 +2516,11 @@ void World::Update(uint32 diff)
         WorldDatabase.KeepAlive();
     }
 
-    // update the instance reset times
-    sInstanceSaveMgr->Update();
+    {
+        TC_METRIC_TIMER("world_update_time", TC_METRIC_TAG("type", "Update instance reset times"));
+        // update the instance reset times
+        sInstanceSaveMgr->Update();
+    }
 
     // Check for shutdown warning
     if (_guidWarn && !_guidAlert)
@@ -2495,14 +2532,23 @@ void World::Update(uint32 diff)
             SendGuidWarning();
     }
 
-    // And last, but not least handle the issued cli commands
-    ProcessCliCommands();
+    {
+        TC_METRIC_TIMER("world_update_time", TC_METRIC_TAG("type", "Process cli commands"));
+        // And last, but not least handle the issued cli commands
+        ProcessCliCommands();
+    }
 
-    sScriptMgr->OnWorldUpdate(diff);
+    {
+        TC_METRIC_TIMER("world_update_time", TC_METRIC_TAG("type", "Update world scripts"));
+        sScriptMgr->OnWorldUpdate(diff);
+    }
 
-    // Stats logger update
-    sMetric->Update();
-    TC_METRIC_VALUE("update_time_diff", diff);
+    {
+        TC_METRIC_TIMER("world_update_time", TC_METRIC_TAG("type", "Update metrics"));
+        // Stats logger update
+        sMetric->Update();
+        TC_METRIC_VALUE("update_time_diff", diff);
+    }
 }
 
 void World::ForceGameEventUpdate()
diff --git a/src/server/scripts/Commands/cs_server.cpp b/src/server/scripts/Commands/cs_server.cpp
index dca410d2027..1bcff8d97f5 100644
--- a/src/server/scripts/Commands/cs_server.cpp
+++ b/src/server/scripts/Commands/cs_server.cpp
@@ -84,7 +84,6 @@ public:
 
         static std::vector<ChatCommand> serverSetCommandTable =
         {
-            { "difftime", rbac::RBAC_PERM_COMMAND_SERVER_SET_DIFFTIME, true, &HandleServerSetDiffTimeCommand, "" },
             { "loglevel", rbac::RBAC_PERM_COMMAND_SERVER_SET_LOGLEVEL, true, &HandleServerSetLogLevelCommand, "" },
             { "motd",     rbac::RBAC_PERM_COMMAND_SERVER_SET_MOTD,     true, &HandleServerSetMotdCommand,     "" },
             { "closed",   rbac::RBAC_PERM_COMMAND_SERVER_SET_CLOSED,   true, &HandleServerSetClosedCommand,   "" },
@@ -439,26 +438,6 @@ public:
         return true;
     }
 
-    // set diff time record interval
-    static bool HandleServerSetDiffTimeCommand(ChatHandler* /*handler*/, char const* args)
-    {
-        if (!*args)
-            return false;
-
-        char* newTimeStr = strtok((char*)args, " ");
-        if (!newTimeStr)
-            return false;
-
-        int32 newTime = atoi(newTimeStr);
-        if (newTime < 0)
-            return false;
-
-        sWorldUpdateTime.SetRecordUpdateTimeInterval(newTime);
-        printf("Record diff every %i ms\n", newTime);
-
-        return true;
-    }
-
 private:
     static bool ParseExitCode(char const* exitCodeStr, int32& exitCode)
     {
diff --git a/src/server/worldserver/worldserver.conf.dist b/src/server/worldserver/worldserver.conf.dist
index 998f40cbaca..d5d11cf956d 100644
--- a/src/server/worldserver/worldserver.conf.dist
+++ b/src/server/worldserver/worldserver.conf.dist
@@ -3226,23 +3226,6 @@ ShowMuteInWorld = 0
 ShowBanInWorld = 0
 
 #
-#     RecordUpdateTimeDiffInterval
-#        Description: Time (in milliseconds) update time diff is written to the log file.
-#                     Update diff can be used as a performance indicator. Diff < 300: good
-#                     performance. Diff > 600 bad performance, may be caused by high CPU usage.
-#        Default:     60000 - (Enabled, 1 minute)
-#                     0     - (Disabled)
-
-RecordUpdateTimeDiffInterval = 60000
-
-#
-#     MinRecordUpdateTimeDiff
-#        Description: Only record update time diff which is greater than this value.
-#        Default:     100
-
-MinRecordUpdateTimeDiff = 100
-
-#
 #     PlayerStart.String
 #        Description: String to be displayed at first login of newly created characters.
 #         Default:    "" - (Disabled)