From 8503b29f9f06b27f5ed1dc7a3f758e41f3c06c90 Mon Sep 17 00:00:00 2001 From: Mag-nus Date: Wed, 3 Apr 2019 20:05:35 -0500 Subject: [PATCH 1/2] /serverperformancemonitor command Optional parameters are: start stop reset If no parameters are present, the current performance metrics are spit out. When disabled, overhead is the cost of some simple function calls and a bool check. When enabled, the additional cost is stopwatch events. In comparisson to the work that ACE does for normal processing, the work done when serverperformance is enabled is nearly 0. Default is disabled. Enable it to start up automatically in the config.js. This is recommend for most servers. Enable it at runtime using /serverperformance start --- Source/ACE.Common/GameConfiguration.cs | 4 + Source/ACE.Common/RateMonitor.cs | 22 +- .../Command/Handlers/AdminCommands.cs | 43 ++- Source/ACE.Server/Config.js.example | 1 + Source/ACE.Server/Entity/Landblock.cs | 14 + .../Managers/ServerPerformanceMonitor.cs | 254 ++++++++++++++++++ Source/ACE.Server/Managers/WorldManager.cs | 53 ++-- Source/ACE.Server/Program.cs | 6 + changelog.md | 4 + 9 files changed, 375 insertions(+), 26 deletions(-) create mode 100644 Source/ACE.Server/Managers/ServerPerformanceMonitor.cs diff --git a/Source/ACE.Common/GameConfiguration.cs b/Source/ACE.Common/GameConfiguration.cs index 686b6a1cbb..daa23d472b 100644 --- a/Source/ACE.Common/GameConfiguration.cs +++ b/Source/ACE.Common/GameConfiguration.cs @@ -15,6 +15,10 @@ public class GameConfiguration public string DatFilesDirectory { get; set; } + [System.ComponentModel.DefaultValue(false)] + [JsonProperty(DefaultValueHandling = DefaultValueHandling.Populate)] + public bool ServerPerformanceMonitorAutoStart { get; set; } + [System.ComponentModel.DefaultValue(false)] [JsonProperty(DefaultValueHandling = DefaultValueHandling.Populate)] public bool WorldDatabasePrecaching { get; set; } diff --git a/Source/ACE.Common/RateMonitor.cs b/Source/ACE.Common/RateMonitor.cs index d7e52a5bcc..268a333c93 100644 --- a/Source/ACE.Common/RateMonitor.cs +++ b/Source/ACE.Common/RateMonitor.cs @@ -30,12 +30,27 @@ public class RateMonitor /// public double AverageEventDuration => TotalSeconds / TotalEvents; + public void ResetEvent() + { + stopwatch.Reset(); + } + public void RegisterEventStart() { stopwatch.Reset(); stopwatch.Start(); } + public void PauseEvent() + { + stopwatch.Stop(); + } + + public void ResumeEvent() + { + stopwatch.Start(); + } + /// /// returns the elapsed seconds for this event /// @@ -43,7 +58,12 @@ public double RegisterEventEnd() { stopwatch.Stop(); - LastEvent = stopwatch.Elapsed.TotalSeconds; + return RegisterEvent(stopwatch.Elapsed.TotalSeconds); + } + + public double RegisterEvent(double totalSeconds) + { + LastEvent = totalSeconds; TotalEvents++; TotalSeconds += LastEvent; diff --git a/Source/ACE.Server/Command/Handlers/AdminCommands.cs b/Source/ACE.Server/Command/Handlers/AdminCommands.cs index 95a87338f3..e3bcc13cec 100644 --- a/Source/ACE.Server/Command/Handlers/AdminCommands.cs +++ b/Source/ACE.Server/Command/Handlers/AdminCommands.cs @@ -2060,8 +2060,10 @@ public static void HandleServerStatus(Session session, params string[] parameter sb.Append($"{activeLandblocks.Count:N0} active landblocks - Players: {players:N0}, Creatures: {creatures:N0}, Missiles: {missiles:N0}, Other: {other:N0}, Total: {total:N0}.{'\n'}"); // 11 total blocks loaded. 11 active. 0 pending dormancy. 0 dormant. 314 unloaded. // 11 total blocks loaded. 11 active. 0 pending dormancy. 0 dormant. 314 unloaded. - sb.Append($"UpdateGameWorld {(DateTime.UtcNow - WorldManager.UpdateGameWorld5MinLastReset).TotalMinutes:N2} min - {WorldManager.UpdateGameWorld5MinRM}.{'\n'}"); - sb.Append($"UpdateGameWorld {(DateTime.UtcNow - WorldManager.UpdateGameWorld60MinLastReset).TotalMinutes:N2} min - {WorldManager.UpdateGameWorld60MinRM}.{'\n'}"); + if (ServerPerformanceMonitor.IsRunning) + sb.Append($"Server Performance Monitor - UpdateGameWorld ~5m {ServerPerformanceMonitor.GetMonitor5m(ServerPerformanceMonitor.MonitorType.UpdateGameWorld_Entire).AverageEventDuration:N3}, ~1h {ServerPerformanceMonitor.GetMonitor1h(ServerPerformanceMonitor.MonitorType.UpdateGameWorld_Entire).AverageEventDuration:N3} s{'\n'}"); + else + sb.Append($"Server Performance Monitor - Not running. To start use /serverperformance start{'\n'}"); sb.Append($"World DB Cache Counts - Weenies: {DatabaseManager.World.GetWeenieCacheCount():N0}, LandblockInstances: {DatabaseManager.World.GetLandblockInstancesCacheCount():N0}, PointsOfInterest: {DatabaseManager.World.GetPointsOfInterestCacheCount():N0}, Cookbooks: {DatabaseManager.World.GetCookbookCacheCount():N0}, Spells: {DatabaseManager.World.GetSpellCacheCount():N0}, Encounters: {DatabaseManager.World.GetEncounterCacheCount():N0}, Events: {DatabaseManager.World.GetEventsCacheCount():N0}{'\n'}"); sb.Append($"Shard DB Counts - Biotas: {DatabaseManager.Shard.GetBiotaCount():N0}{'\n'}"); @@ -2072,6 +2074,43 @@ public static void HandleServerStatus(Session session, params string[] parameter CommandHandlerHelper.WriteOutputInfo(session, $"{sb}"); } + // serverstatus + [CommandHandler("serverperformance", AccessLevel.Advocate, CommandHandlerFlag.None, 0, "Displays a summary of server performance statistics")] + public static void HandleServerPerformance(Session session, params string[] parameters) + { + if (parameters != null && parameters.Length == 1) + { + if (parameters[0].ToLower() == "start") + { + ServerPerformanceMonitor.Start(); + CommandHandlerHelper.WriteOutputInfo(session, "Server Performance Monitor started"); + return; + } + + if (parameters[0].ToLower() == "stop") + { + ServerPerformanceMonitor.Stop(); + CommandHandlerHelper.WriteOutputInfo(session, "Server Performance Monitor stopped"); + return; + } + + if (parameters[0].ToLower() == "reset") + { + ServerPerformanceMonitor.Reset(); + CommandHandlerHelper.WriteOutputInfo(session, "Server Performance Monitor reset"); + return; + } + } + + if (!ServerPerformanceMonitor.IsRunning) + { + CommandHandlerHelper.WriteOutputInfo(session, "Server Performance Monitor not running. To start use /serverperformance start"); + return; + } + + CommandHandlerHelper.WriteOutputInfo(session, ServerPerformanceMonitor.ToString()); + } + [CommandHandler("modifybool", AccessLevel.Admin, CommandHandlerFlag.None, 2, "Modifies a server property that is a bool", "modifybool (string) (bool)")] public static void HandleModifyServerBoolProperty(Session session, params string[] paramters) { diff --git a/Source/ACE.Server/Config.js.example b/Source/ACE.Server/Config.js.example index a8fe93af33..90895ea9f6 100644 --- a/Source/ACE.Server/Config.js.example +++ b/Source/ACE.Server/Config.js.example @@ -16,6 +16,7 @@ }, "DatFilesDirectory": "c:\\ACE\\", "ShutdownInterval": "60", + "ServerPerformanceMonitorAutoStart": false, "WorldDatabasePrecaching": false, "LandblockPreloading": true, "PreloadedLandblocks": [ diff --git a/Source/ACE.Server/Entity/Landblock.cs b/Source/ACE.Server/Entity/Landblock.cs index 8ab7a62881..5d51897b5b 100644 --- a/Source/ACE.Server/Entity/Landblock.cs +++ b/Source/ACE.Server/Entity/Landblock.cs @@ -306,15 +306,20 @@ private void LoadScenery() public void Tick(double currentUnixTime) { + ServerPerformanceMonitor.ResumeEvent(ServerPerformanceMonitor.MonitorType.Landblock_Tick_RunActions); actionQueue.RunActions(); + ServerPerformanceMonitor.PauseEvent(ServerPerformanceMonitor.MonitorType.Landblock_Tick_RunActions); ProcessPendingWorldObjectAdditionsAndRemovals(); // When a WorldObject Ticks, it can end up adding additional WorldObjects to this landblock + ServerPerformanceMonitor.ResumeEvent(ServerPerformanceMonitor.MonitorType.Landblock_Tick_Player_Tick); foreach (var player in players) player.Player_Tick(currentUnixTime); + ServerPerformanceMonitor.PauseEvent(ServerPerformanceMonitor.MonitorType.Landblock_Tick_Player_Tick); + ServerPerformanceMonitor.ResumeEvent(ServerPerformanceMonitor.MonitorType.Landblock_Tick_Monster_Tick); while (sortedCreaturesByNextTick.Count > 0) // Monster_Tick() { var first = sortedCreaturesByNextTick.First.Value; @@ -331,7 +336,9 @@ public void Tick(double currentUnixTime) break; } } + ServerPerformanceMonitor.PauseEvent(ServerPerformanceMonitor.MonitorType.Landblock_Tick_Monster_Tick); + ServerPerformanceMonitor.ResumeEvent(ServerPerformanceMonitor.MonitorType.Landblock_Tick_WorldObject_Heartbeat); while (sortedWorldObjectsByNextHeartbeat.Count > 0) // Heartbeat() { var first = sortedWorldObjectsByNextHeartbeat.First.Value; @@ -348,7 +355,9 @@ public void Tick(double currentUnixTime) break; } } + ServerPerformanceMonitor.PauseEvent(ServerPerformanceMonitor.MonitorType.Landblock_Tick_WorldObject_Heartbeat); + ServerPerformanceMonitor.ResumeEvent(ServerPerformanceMonitor.MonitorType.Landblock_Tick_GeneratorHeartbeat); while (sortedGeneratorsByNextGeneratorHeartbeat.Count > 0) // GeneratorHeartbeat() { var first = sortedGeneratorsByNextGeneratorHeartbeat.First.Value; @@ -365,8 +374,10 @@ public void Tick(double currentUnixTime) break; } } + ServerPerformanceMonitor.PauseEvent(ServerPerformanceMonitor.MonitorType.Landblock_Tick_GeneratorHeartbeat); // Heartbeat + ServerPerformanceMonitor.ResumeEvent(ServerPerformanceMonitor.MonitorType.Landblock_Tick_Heartbeat); if (lastHeartBeat + heartbeatInterval <= DateTime.UtcNow) { var thisHeartBeat = DateTime.UtcNow; @@ -385,8 +396,10 @@ public void Tick(double currentUnixTime) lastHeartBeat = thisHeartBeat; } + ServerPerformanceMonitor.PauseEvent(ServerPerformanceMonitor.MonitorType.Landblock_Tick_Heartbeat); // Database Save + ServerPerformanceMonitor.ResumeEvent(ServerPerformanceMonitor.MonitorType.Landblock_Tick_Database_Save); if (lastDatabaseSave + databaseSaveInterval <= DateTime.UtcNow) { ProcessPendingWorldObjectAdditionsAndRemovals(); @@ -394,6 +407,7 @@ public void Tick(double currentUnixTime) SaveDB(); lastDatabaseSave = DateTime.UtcNow; } + ServerPerformanceMonitor.PauseEvent(ServerPerformanceMonitor.MonitorType.Landblock_Tick_Database_Save); } private void ProcessPendingWorldObjectAdditionsAndRemovals() diff --git a/Source/ACE.Server/Managers/ServerPerformanceMonitor.cs b/Source/ACE.Server/Managers/ServerPerformanceMonitor.cs new file mode 100644 index 0000000000..76b071f5bf --- /dev/null +++ b/Source/ACE.Server/Managers/ServerPerformanceMonitor.cs @@ -0,0 +1,254 @@ +using System; +using System.Text; + +using ACE.Common; + +namespace ACE.Server.Managers +{ + public static class ServerPerformanceMonitor + { + public static bool IsRunning; + + + public enum MonitorType + { + // These are all found in WorldManager.UpdateWorld() + PlayerManager_Tick, + InboundClientMessageQueue_RunActions, + actionQueue_RunActions, + DelayManager_RunActions, + UpdateGameWorld, + DoSessionWork, + + // These are all found in WorldManager.UpdateGameWorld() + UpdateGameWorld_Entire, + UpdateGameWorld_HandlePhysics, + UpdateGameWorld_RelocateObjectForPhysics, + UpdateGameWorld_landblock_Tick, + + // These are all found in Landblock.Tick() + Landblock_Tick_RunActions, + Landblock_Tick_Player_Tick, + Landblock_Tick_Monster_Tick, + Landblock_Tick_WorldObject_Heartbeat, + Landblock_Tick_GeneratorHeartbeat, + Landblock_Tick_Heartbeat, + Landblock_Tick_Database_Save, + + // These are all found in WorldManager.DoSessionWork() + DoSessionWork_TickInbound, + DoSessionWork_TickOutbound, + DoSessionWork_RemoveSessions, + + MonitorMaxItems // Keep this at the end to properly size our monitors array + } + + private static readonly RateMonitor[] monitors5m = new RateMonitor[(int)MonitorType.MonitorMaxItems]; + private static readonly RateMonitor[] monitors1h = new RateMonitor[(int)MonitorType.MonitorMaxItems]; + private static readonly RateMonitor[] monitors24h = new RateMonitor[(int)MonitorType.MonitorMaxItems]; + + private static readonly TimeSpan last5mClearInterval = TimeSpan.FromMinutes(5); + private static readonly TimeSpan last1hClearInteval = TimeSpan.FromHours(1); + private static readonly TimeSpan last24hClearInterval = TimeSpan.FromHours(24); + + private static DateTime last5mClear = DateTime.MinValue; + private static DateTime last1hClear = DateTime.MinValue; + private static DateTime last24hClear = DateTime.MinValue; + + private static TimeSpan Monitors5mRunTime => DateTime.UtcNow - last5mClear; + private static TimeSpan Monitors1hRunTime => DateTime.UtcNow - last1hClear; + private static TimeSpan Monitors24hRunTime => DateTime.UtcNow - last24hClear; + + + static ServerPerformanceMonitor() + { + for (int i = 0; i < monitors5m.Length; i++) + { + monitors5m[i] = new RateMonitor(); + monitors1h[i] = new RateMonitor(); + monitors24h[i] = new RateMonitor(); + } + } + + + public static void Start() + { + if (IsRunning) + return; + + Reset(); + + IsRunning = true; + } + + public static void Stop() + { + if (!IsRunning) + return; + + IsRunning = false; + } + + public static void Tick() + { + if (!IsRunning) + return; + + // check to see if we should clear history + if (DateTime.UtcNow - last5mClear >= last5mClearInterval) + { + foreach (var monitor in monitors5m) + monitor.ClearEventHistory(); + + last5mClear = DateTime.UtcNow; + } + + if (DateTime.UtcNow - last1hClear >= last1hClearInteval) + { + foreach (var monitor in monitors1h) + monitor.ClearEventHistory(); + + last1hClear = DateTime.UtcNow; + } + + if (DateTime.UtcNow - last24hClear >= last24hClearInterval) + { + foreach (var monitor in monitors24h) + monitor.ClearEventHistory(); + + last24hClear = DateTime.UtcNow; + } + } + + public static void Reset() + { + if (!IsRunning) + return; + + for (int i = 0; i < monitors5m.Length; i++) + { + monitors5m[i].ClearEventHistory(); + monitors1h[i].ClearEventHistory(); + monitors24h[i].ClearEventHistory(); + } + } + + + public static void RegisterEventStart(MonitorType monitorType) + { + if (!IsRunning) + return; + + monitors24h[(int)monitorType].RegisterEventStart(); + monitors1h[(int)monitorType].RegisterEventStart(); + monitors5m[(int)monitorType].RegisterEventStart(); + + // Reset cumulative monitors + if (monitorType == MonitorType.UpdateGameWorld_Entire) + { + for (int i = (int) MonitorType.Landblock_Tick_RunActions; i <= (int) MonitorType.Landblock_Tick_Database_Save; i++) + { + monitors5m[i].ResetEvent(); + monitors1h[i].ResetEvent(); + monitors24h[i].ResetEvent(); + } + } + } + + public static void RegisterEventEnd(MonitorType monitorType) + { + if (!IsRunning) + return; + + monitors5m[(int)monitorType].RegisterEventEnd(); + monitors1h[(int)monitorType].RegisterEventEnd(); + monitors24h[(int)monitorType].RegisterEventEnd(); + + // Register end for cumulative monitors + if (monitorType == MonitorType.UpdateGameWorld_Entire) + { + for (int i = (int)MonitorType.Landblock_Tick_RunActions; i <= (int)MonitorType.Landblock_Tick_Database_Save; i++) + { + monitors5m[i].RegisterEventEnd(); + monitors1h[i].RegisterEventEnd(); + monitors24h[i].RegisterEventEnd(); + } + } + } + + + public static void ResumeEvent(MonitorType monitorType) + { + if (!IsRunning) + return; + + monitors24h[(int)monitorType].ResumeEvent(); + monitors1h[(int)monitorType].ResumeEvent(); + monitors5m[(int)monitorType].ResumeEvent(); + } + + public static void PauseEvent(MonitorType monitorType) + { + if (!IsRunning) + return; + + monitors5m[(int)monitorType].PauseEvent(); + monitors1h[(int)monitorType].PauseEvent(); + monitors24h[(int)monitorType].PauseEvent(); + } + + + public static RateMonitor GetMonitor5m(MonitorType monitorType) + { + return monitors5m[(int) monitorType]; + } + + public static RateMonitor GetMonitor1h(MonitorType monitorType) + { + return monitors1h[(int)monitorType]; + } + + public static RateMonitor GetMonitor24h(MonitorType monitorType) + { + return monitors24h[(int)monitorType]; + } + + + public new static string ToString() + { + var sb = new StringBuilder(); + + sb.Append($"Monitoring Durations: ~5m {Monitors5mRunTime.TotalMinutes:N2} min, ~1h {Monitors1hRunTime.TotalMinutes:N2} min, ~24h {Monitors24hRunTime.TotalMinutes:N2} min{'\n'}"); + sb.Append($"~5m Hits Avg Long Last - ~1h Hits Avg Long Last - ~24h Hits Avg Long Last (s) - Name{'\n'}"); + + sb.Append($"Calls from WorldManager.UpdateWorld(){'\n'}"); + for (int i = (int)MonitorType.PlayerManager_Tick; i <= (int)MonitorType.DoSessionWork; i++) + AddMonitorOutputToStringBuilder(monitors5m[i], monitors1h[i], monitors24h[i], (MonitorType)i, sb); + + sb.Append($"WorldManager.UpdateGameWorld() time not including throttled returns{'\n'}"); + AddMonitorOutputToStringBuilder(monitors5m[(int)MonitorType.UpdateGameWorld_Entire], monitors1h[(int)MonitorType.UpdateGameWorld_Entire], monitors24h[(int)MonitorType.UpdateGameWorld_Entire], MonitorType.UpdateGameWorld_Entire, sb); + + sb.Append($"Calls from WorldManager.UpdateGameWorld(){'\n'}"); + for (int i = (int)MonitorType.UpdateGameWorld_HandlePhysics; i <= (int)MonitorType.UpdateGameWorld_landblock_Tick; i++) + AddMonitorOutputToStringBuilder(monitors5m[i], monitors1h[i], monitors24h[i], (MonitorType)i, sb); + + sb.Append($"Calls from Landblock.Tick() - Cumulative over a single UpdateGameWorld Tick{'\n'}"); + for (int i = (int)MonitorType.Landblock_Tick_RunActions; i <= (int)MonitorType.Landblock_Tick_Database_Save; i++) + AddMonitorOutputToStringBuilder(monitors5m[i], monitors1h[i], monitors24h[i], (MonitorType)i, sb); + + sb.Append($"Calls from WorldManager.DoSessionWork(){'\n'}"); + for (int i = (int)MonitorType.DoSessionWork_TickInbound; i <= (int)MonitorType.DoSessionWork_RemoveSessions; i++) + AddMonitorOutputToStringBuilder(monitors5m[i], monitors1h[i], monitors24h[i], (MonitorType)i, sb); + + return sb.ToString(); + } + + private static void AddMonitorOutputToStringBuilder(RateMonitor monitor5m, RateMonitor monitor1h, RateMonitor monitor24h, MonitorType monitorType, StringBuilder sb) + { + sb.Append($"{monitor5m.TotalEvents.ToString().PadLeft(7)} {monitor5m.AverageEventDuration:N4} {monitor5m.LongestEvent:N3} {monitor5m.LastEvent:N3} - " + + $"{monitor1h.TotalEvents.ToString().PadLeft(7)} {monitor1h.AverageEventDuration:N4} {monitor1h.LongestEvent:N3} {monitor1h.LastEvent:N3} - " + + $"{monitor24h.TotalEvents.ToString().PadLeft(7)} {monitor24h.AverageEventDuration:N4} {monitor24h.LongestEvent:N3} {monitor24h.LastEvent:N3} - " + + $"{monitorType}{'\n'}"); + } + } +} diff --git a/Source/ACE.Server/Managers/WorldManager.cs b/Source/ACE.Server/Managers/WorldManager.cs index fd2fbe3db3..94da357801 100644 --- a/Source/ACE.Server/Managers/WorldManager.cs +++ b/Source/ACE.Server/Managers/WorldManager.cs @@ -32,7 +32,7 @@ namespace ACE.Server.Managers { - public class WorldManager + public static class WorldManager { private static readonly ILog log = LogManager.GetLogger(System.Reflection.MethodBase.GetCurrentMethod().DeclaringType); private static readonly ILog packetLog = LogManager.GetLogger(System.Reflection.Assembly.GetEntryAssembly(), "Packets"); @@ -514,18 +514,32 @@ private static void UpdateWorld() worldTickTimer.Restart(); + ServerPerformanceMonitor.RegisterEventStart(ServerPerformanceMonitor.MonitorType.PlayerManager_Tick); PlayerManager.Tick(); + ServerPerformanceMonitor.RegisterEventEnd(ServerPerformanceMonitor.MonitorType.PlayerManager_Tick); + ServerPerformanceMonitor.RegisterEventStart(ServerPerformanceMonitor.MonitorType.InboundClientMessageQueue_RunActions); InboundClientMessageQueue.RunActions(); + ServerPerformanceMonitor.RegisterEventEnd(ServerPerformanceMonitor.MonitorType.InboundClientMessageQueue_RunActions); // This will consist of PlayerEnterWorld actions, as well as other game world actions that require thread safety + ServerPerformanceMonitor.RegisterEventStart(ServerPerformanceMonitor.MonitorType.actionQueue_RunActions); actionQueue.RunActions(); + ServerPerformanceMonitor.RegisterEventEnd(ServerPerformanceMonitor.MonitorType.actionQueue_RunActions); + ServerPerformanceMonitor.RegisterEventStart(ServerPerformanceMonitor.MonitorType.DelayManager_RunActions); DelayManager.RunActions(); + ServerPerformanceMonitor.RegisterEventEnd(ServerPerformanceMonitor.MonitorType.DelayManager_RunActions); + ServerPerformanceMonitor.RegisterEventStart(ServerPerformanceMonitor.MonitorType.UpdateGameWorld); var gameWorldUpdated = UpdateGameWorld(); + ServerPerformanceMonitor.RegisterEventEnd(ServerPerformanceMonitor.MonitorType.UpdateGameWorld); + ServerPerformanceMonitor.RegisterEventStart(ServerPerformanceMonitor.MonitorType.DoSessionWork); int sessionCount = DoSessionWork(); + ServerPerformanceMonitor.RegisterEventEnd(ServerPerformanceMonitor.MonitorType.DoSessionWork); + + ServerPerformanceMonitor.Tick(); // We only relax the CPU if our game world is able to update at the target rate. // We do not sleep if our game world just updated. This is to prevent the scenario where our game world can't keep up. We don't want to add further delays. @@ -540,11 +554,6 @@ private static void UpdateWorld() WorldActive = false; } - public static readonly RateMonitor UpdateGameWorld5MinRM = new RateMonitor(); - public static DateTime UpdateGameWorld5MinLastReset = DateTime.UtcNow; - public static readonly RateMonitor UpdateGameWorld60MinRM = new RateMonitor(); - public static DateTime UpdateGameWorld60MinLastReset = DateTime.UtcNow; - /// /// Projected to run at a reasonable rate for gameplay (30-60fps) /// @@ -555,13 +564,15 @@ public static bool UpdateGameWorld() updateGameWorldRateLimiter.RegisterEvent(); - UpdateGameWorld5MinRM.RegisterEventStart(); - UpdateGameWorld60MinRM.RegisterEventStart(); + ServerPerformanceMonitor.RegisterEventStart(ServerPerformanceMonitor.MonitorType.UpdateGameWorld_Entire); // update positions through physics engine + ServerPerformanceMonitor.RegisterEventStart(ServerPerformanceMonitor.MonitorType.UpdateGameWorld_HandlePhysics); var movedObjects = HandlePhysics(Timers.PortalYearTicks); + ServerPerformanceMonitor.RegisterEventEnd(ServerPerformanceMonitor.MonitorType.UpdateGameWorld_HandlePhysics); // iterate through objects that have changed landblocks + ServerPerformanceMonitor.RegisterEventStart(ServerPerformanceMonitor.MonitorType.UpdateGameWorld_RelocateObjectForPhysics); foreach (var movedObject in movedObjects) { // NOTE: The object's Location can now be null, if a player logs out, or an item is picked up @@ -570,33 +581,23 @@ public static bool UpdateGameWorld() // assume adjacency move here? LandblockManager.RelocateObjectForPhysics(movedObject, true); } + ServerPerformanceMonitor.RegisterEventEnd(ServerPerformanceMonitor.MonitorType.UpdateGameWorld_RelocateObjectForPhysics); // Tick all of our Landblocks and WorldObjects + ServerPerformanceMonitor.RegisterEventStart(ServerPerformanceMonitor.MonitorType.UpdateGameWorld_landblock_Tick); var activeLandblocks = LandblockManager.GetActiveLandblocks(); foreach (var landblock in activeLandblocks) landblock.Tick(Time.GetUnixTime()); + ServerPerformanceMonitor.RegisterEventEnd(ServerPerformanceMonitor.MonitorType.UpdateGameWorld_landblock_Tick); // clean up inactive landblocks LandblockManager.UnloadLandblocks(); - UpdateGameWorld5MinRM.RegisterEventEnd(); - UpdateGameWorld60MinRM.RegisterEventEnd(); - - if (UpdateGameWorld5MinRM.TotalSeconds > 300) - { - UpdateGameWorld5MinRM.ClearEventHistory(); - UpdateGameWorld5MinLastReset = DateTime.UtcNow; - } - - if (UpdateGameWorld60MinRM.TotalSeconds > 3600) - { - UpdateGameWorld60MinRM.ClearEventHistory(); - UpdateGameWorld60MinLastReset = DateTime.UtcNow; - } - HouseManager.Tick(); + ServerPerformanceMonitor.RegisterEventEnd(ServerPerformanceMonitor.MonitorType.UpdateGameWorld_Entire); + return true; } @@ -700,16 +701,21 @@ public static int DoSessionWork() sessionCount = sessions.Count; // The session tick inbound processes all inbound GameAction messages + ServerPerformanceMonitor.RegisterEventStart(ServerPerformanceMonitor.MonitorType.DoSessionWork_TickInbound); foreach (var s in sessions) s.TickInbound(); + ServerPerformanceMonitor.RegisterEventEnd(ServerPerformanceMonitor.MonitorType.DoSessionWork_TickInbound); // Do not combine the above and below loops. All inbound messages should be processed first and then all outbound messages should be processed second. // The session tick outbound processes pending actions and handles outgoing messages + ServerPerformanceMonitor.RegisterEventStart(ServerPerformanceMonitor.MonitorType.DoSessionWork_TickOutbound); foreach (var s in sessions) s.TickOutbound(); + ServerPerformanceMonitor.RegisterEventEnd(ServerPerformanceMonitor.MonitorType.DoSessionWork_TickOutbound); // Removes sessions in the NetworkTimeout state, including sessions that have reached a timeout limit. + ServerPerformanceMonitor.RegisterEventStart(ServerPerformanceMonitor.MonitorType.DoSessionWork_RemoveSessions); for (int i = sessions.Count - 1; i >= 0; i--) { var sesh = sessions[i]; @@ -723,6 +729,7 @@ public static int DoSessionWork() break; } } + ServerPerformanceMonitor.RegisterEventEnd(ServerPerformanceMonitor.MonitorType.DoSessionWork_RemoveSessions); } finally { diff --git a/Source/ACE.Server/Program.cs b/Source/ACE.Server/Program.cs index d9919d37f0..1d93d03923 100644 --- a/Source/ACE.Server/Program.cs +++ b/Source/ACE.Server/Program.cs @@ -82,6 +82,12 @@ public static void Main(string[] args) log.Info("Initializing GuidManager..."); GuidManager.Initialize(); + if (ConfigManager.Config.Server.ServerPerformanceMonitorAutoStart) + { + log.Info("Server Performance Monitor auto starting..."); + ServerPerformanceMonitor.Start(); + } + if (ConfigManager.Config.Server.WorldDatabasePrecaching) { log.Info("Precaching Weenies..."); diff --git a/changelog.md b/changelog.md index 3a01507c20..5812498dfa 100644 --- a/changelog.md +++ b/changelog.md @@ -1,5 +1,9 @@ # ACEmulator Change Log +### 2019-04-03 +[Mag-nus] +* /serverperformance command added. Optional parameters: start, stop, reset + ### 2019-04-02 [Ripley] * Change the way GiveObjecttoNPC and HandleNPCReceiveItem deal with emotes. From 80a7a0492933d2f5cc5ce1711e7b106033868b8b Mon Sep 17 00:00:00 2001 From: Mag-nus Date: Thu, 4 Apr 2019 06:37:22 -0500 Subject: [PATCH 2/2] Fix Reset --- Source/ACE.Server/Managers/ServerPerformanceMonitor.cs | 10 +++++++--- 1 file changed, 7 insertions(+), 3 deletions(-) diff --git a/Source/ACE.Server/Managers/ServerPerformanceMonitor.cs b/Source/ACE.Server/Managers/ServerPerformanceMonitor.cs index 76b071f5bf..38fe1be5f7 100644 --- a/Source/ACE.Server/Managers/ServerPerformanceMonitor.cs +++ b/Source/ACE.Server/Managers/ServerPerformanceMonitor.cs @@ -51,9 +51,9 @@ public enum MonitorType private static readonly TimeSpan last1hClearInteval = TimeSpan.FromHours(1); private static readonly TimeSpan last24hClearInterval = TimeSpan.FromHours(24); - private static DateTime last5mClear = DateTime.MinValue; - private static DateTime last1hClear = DateTime.MinValue; - private static DateTime last24hClear = DateTime.MinValue; + private static DateTime last5mClear; + private static DateTime last1hClear; + private static DateTime last24hClear; private static TimeSpan Monitors5mRunTime => DateTime.UtcNow - last5mClear; private static TimeSpan Monitors1hRunTime => DateTime.UtcNow - last1hClear; @@ -131,6 +131,10 @@ public static void Reset() monitors1h[i].ClearEventHistory(); monitors24h[i].ClearEventHistory(); } + + last5mClear = DateTime.UtcNow; + last1hClear = DateTime.UtcNow; + last24hClear = DateTime.UtcNow; }