Added cycle logging (#646)

* Added cycle logging

* Use properties for cycle logging

We may not want it since it can be kinda spammy, so we can toggle this feature. We probably want it though.

* Improved cycle logging

2006Scape Server/ServerConfig.Sample.json

@@ -23,5 +23,7 @@
   "timeout": 60,
   "item_requirements": true,
   "max_players": 200,
-  "website_integration": false
+  "website_integration": false,
+  "cycle_logging": true,
+  "cycle_logging_tick": 10
 }

2006Scape Server/src/main/java/com/rs2/ConfigLoader.java

@@ -72,6 +72,11 @@ public class ConfigLoader {
         }
         if (obj.has("website_integration"))
             Constants.WEBSITE_INTEGRATION = obj.getBoolean("website_integration");
+        
+        if (obj.has("cycle_logging")) 
+            Constants.CYCLE_LOGGING = obj.getBoolean("cycle_logging");
+        if (obj.has("cycle_logging_tick")) 
+            Constants.CYCLE_LOGGING_TICK = obj.getInt("cycle_logging_tick");
     }
 
     private static void initialize() {

2006Scape Server/src/main/java/com/rs2/Constants.java

@@ -39,11 +39,11 @@ public class Constants {
      * WEBSITE_INTEGRATION Enables/Disables Website Features(Total Accounts Registered & Players Online)
      */
     public static String SERVER_NAME = "2006Scape", WEBSITE_LINK = "https://2006Scape.org";
-    public static int WORLD = 1, HTTP_PORT = 8080, JAGGRAB_PORT = 43595, MAX_PLAYERS = 200, SAVE_TIMER = 120, TIMEOUT = 60, RESPAWN_X = 3222, RESPAWN_Y = 3218;
+    public static int WORLD = 1, HTTP_PORT = 8080, JAGGRAB_PORT = 43595, MAX_PLAYERS = 200, SAVE_TIMER = 120, TIMEOUT = 60, RESPAWN_X = 3222, RESPAWN_Y = 3218,  CYCLE_LOGGING_TICK = 10;
     public static boolean GUI_ENABLED = false, FILE_SERVER = true, SERVER_DEBUG = false, MEMBERS_ONLY = false, TUTORIAL_ISLAND = false,
             PARTY_ROOM_DISABLED = false, CLUES_ENABLED = true, ITEM_REQUIREMENTS = true,
             ADMIN_CAN_TRADE = false, ADMIN_DROP_ITEMS = false, ADMIN_CAN_SELL_ITEMS = false, VARIABLE_XP_RATE = false,
-            WEBSITE_INTEGRATION = false;
+            WEBSITE_INTEGRATION = false, CYCLE_LOGGING = true;
     public static int[] VARIABLE_XP_RATES = new int[] {1, 2, 5, 10};
     public static double TEST_VERSION = 2.3, XP_RATE = 1.0;
 

2006Scape Server/src/main/java/com/rs2/GameEngine.java

@@ -13,6 +13,9 @@ import java.util.concurrent.TimeUnit;
 import java.util.concurrent.locks.Lock;
 import java.util.concurrent.locks.ReentrantLock;
 
+import com.google.common.base.Stopwatch;
+import com.rs2.game.npcs.Npc;
+import com.rs2.game.npcs.NpcList;
 import com.rs2.gui.ControlPanel;
 
 import org.apollo.cache.IndexedFileSystem;
@@ -239,8 +242,10 @@ public class GameEngine {
 		 * scheduleAtFixedRate() does not invoke concurrent Runnables.
 		 */
 		scheduler.scheduleAtFixedRate(new Runnable() {
+			int gameTicksIncrementor;
+			final int printInfoTick = Constants.CYCLE_LOGGING_TICK;
 			public void run() {
-				//TODO debug Stopwatch stopwatch = Stopwatch.createStarted();
+				Stopwatch stopwatch = Stopwatch.createStarted();
 				/**
 				 * Main Server Tick
 				 */
@@ -248,17 +253,51 @@ public class GameEngine {
 					if (GameEngine.shutdownServer) {
 						scheduler.shutdown();
 					}
+					long startItemHandler = System.currentTimeMillis();
 					itemHandler.process();
+					long durationItemHandler = System.currentTimeMillis() - startItemHandler;
+					checkAndLogDuration("ItemHandler", durationItemHandler);
+					long startPlayerHandler = System.currentTimeMillis();
 					playerHandler.process();
+					long durationPlayerHandler = System.currentTimeMillis() - startPlayerHandler;
+					checkAndLogDuration("PlayerHandler", durationPlayerHandler);
+					long startNpcHandler = System.currentTimeMillis();
 					npcHandler.process();
+					long durationNpcHandler = System.currentTimeMillis() - startNpcHandler;
+					checkAndLogDuration("NpcHandler", durationNpcHandler);
+					long startShopHandler = System.currentTimeMillis();
 					shopHandler.process();
+					long durationShopHandler = System.currentTimeMillis() - startShopHandler;
+					checkAndLogDuration("ShopHandler", durationShopHandler);
+					long startObjectManager = System.currentTimeMillis();
 					objectManager.process();
+					long durationObjectManager = System.currentTimeMillis() - startObjectManager;
+					checkAndLogDuration("ObjectManager", durationObjectManager);
+					long startCastleWars = System.currentTimeMillis();
 					CastleWars.process();
+					long durationCastleWars = System.currentTimeMillis() - startCastleWars;
+					checkAndLogDuration("CastleWars", durationCastleWars);
+					long startFightPits = System.currentTimeMillis();
 					FightPits.process();
+					long durationFightPits = System.currentTimeMillis() - startFightPits;
+					checkAndLogDuration("FightPits", durationFightPits);
+					long startPestControl = System.currentTimeMillis();
 					pestControl.process();
+					long durationPestControl = System.currentTimeMillis() - startPestControl;
+					checkAndLogDuration("PestControl", durationPestControl);
+					long startObjectHandler = System.currentTimeMillis();
 					objectHandler.process();
+					long durationObjectHandler = System.currentTimeMillis() - startObjectHandler;
+					checkAndLogDuration("CastleWars", durationObjectHandler);
+					long startMageTrainingArena = System.currentTimeMillis();
 					MageTrainingArena.process();
+					long durationMageTrainingArena = System.currentTimeMillis() - startMageTrainingArena;
+					checkAndLogDuration("MageTrainingArena", durationMageTrainingArena);
+					long startCycleEventHandler = System.currentTimeMillis();
 					CycleEventHandler.getSingleton().process();
+					long durationCycleEventHandler = System.currentTimeMillis() - startCycleEventHandler;
+					checkAndLogDuration("CycleEventHandler", durationCycleEventHandler);
+					long startIntegrationEvents = System.currentTimeMillis();
 					if (Constants.WEBSITE_INTEGRATION) {
 						PlayersOnlineWebsite.addUpdatePlayersOnlineTask();
 						RegisteredAccsWebsite.addUpdateRegisteredUsersTask();
@@ -266,6 +305,9 @@ public class GameEngine {
 					if (DiscordActivity.playerCount) {
 						DiscordActivity.updateActivity();
 					}
+					long durationIntegrationEvents = System.currentTimeMillis() - startIntegrationEvents;
+					checkAndLogDuration("IntegrationEvents", durationIntegrationEvents);
+					long startSaveEvents = System.currentTimeMillis();
 					if (System.currentTimeMillis() - lastMassSave > 300000) {
 						for (Player p : PlayerHandler.players) {
 							if (p == null) {
@@ -276,9 +318,42 @@ public class GameEngine {
 							lastMassSave = System.currentTimeMillis();
 						}
 					}
+					long durationSaveEvents = System.currentTimeMillis() - startSaveEvents;
+					checkAndLogDuration("SaveEvents", durationSaveEvents);
+					long totalCycleDuration = stopwatch.elapsed(TimeUnit.MILLISECONDS);
+					//Technically, we could add commands to test both client lag (creating many tile objects) and server lag (creating a BCrypt hash on game thread)
+					if (totalCycleDuration > 500) {
+						System.err.println("ERROR: Cycle duration exceeded 500 ms!");
+					} else if (totalCycleDuration > 250) {
+						System.err.println("WARNING: Cycle duration exceeded 250 ms!");
+					} else if (totalCycleDuration > 100) {
+						System.out.println("NOTICE: Cycle duration exceeded 100 ms.");
+					}
+					gameTicksIncrementor++;
+					if (Constants.CYCLE_LOGGING && gameTicksIncrementor > 1 && gameTicksIncrementor % printInfoTick == 0) {
+						long totalMem = Runtime.getRuntime().totalMemory();
+						long freeMem = Runtime.getRuntime().freeMemory();
+						long maxMem = Runtime.getRuntime().maxMemory();
+						int playerCount = 0;
+						for (Player p : PlayerHandler.players) {
+							if (p != null) {
+								playerCount++;
+							}
+						}
+						int npcCount = 0;
+						for (Npc npc : NpcHandler.npcs) {
+							if (npc != null) {
+								npcCount++;
+							}
+						}
+						System.out.println("Cycle #" + gameTicksIncrementor + " took " + totalCycleDuration + " ms. Players: " + playerCount + ", NPCs: " + npcCount +
+								", [Durations: i: " + durationItemHandler + " ms, p: " + durationPlayerHandler + " ms, n: " + durationNpcHandler + " ms, s: " + durationShopHandler +
+								" ms, oh: " + durationObjectHandler + " ms, om: " + durationObjectManager + " ms], Memory: " + (totalMem - freeMem) / 1024 / 1024 + "MB/" +
+								totalMem / 1024 / 1024 + "MB. Max: " + maxMem / 1024 / 1024 + "MB, Threads: " + Thread.activeCount() + ".");
+					}
 				} catch (Exception ex) {
 					ex.printStackTrace();
-					System.out.println("A fatal exception has been thrown!");
+					System.err.println("A fatal exception has been thrown in the GameEngine cycle! Saving all players.");
 					for (Player p : PlayerHandler.players) {
 						if (p == null) {
 							continue;
@@ -294,7 +369,6 @@ public class GameEngine {
 					}
 					scheduler.shutdown(); // Kills the tickloop thread if Exception is thrown.
 				}
-				//TODO debug System.out.println("Cycle took " + stopwatch.elapsed(TimeUnit.MILLISECONDS) + " ms.");
 			}
 		}, 0, Constants.CYCLE_TIME, TimeUnit.MILLISECONDS);
 
@@ -316,6 +390,16 @@ public class GameEngine {
 		System.exit(0);
 	}
 	
+	private static void checkAndLogDuration(String processName, long duration) {
+		if (duration > 500) {
+			System.err.println("ERROR: " + processName + " duration exceeded 500 ms! Duration: " + duration + " ms.");
+		} else if (duration > 250) {
+			System.err.println("WARNING: " + processName + " duration exceeded 250 ms! Duration: " + duration + " ms.");
+		} else if (duration > 100) {
+			System.out.println("NOTICE: " + processName + " duration exceeded 100 ms. Duration: " + duration + " ms.");
+		}
+	}
+
 	public static boolean playerExecuted = false;
 	private static BufferedReader minuteFile;