Skip to content

Commit db69643

Browse files
ipkpjersiipkpjersi
authored
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
1 parent 4377501 commit db69643

File tree

4 files changed

+97
-6
lines changed

4 files changed

+97
-6
lines changed

‎2006Scape Server/ServerConfig.Sample.json

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -23,5 +23,7 @@
2323
"timeout": 60,
2424
"item_requirements": true,
2525
"max_players": 200,
26-
"website_integration": false
26+
"website_integration": false,
27+
"cycle_logging": true,
28+
"cycle_logging_tick": 10
2729
}

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

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -72,6 +72,11 @@ public static void loadSettings(String config) throws IOException {
7272
}
7373
if (obj.has("website_integration"))
7474
Constants.WEBSITE_INTEGRATION = obj.getBoolean("website_integration");
75+
76+
if (obj.has("cycle_logging"))
77+
Constants.CYCLE_LOGGING = obj.getBoolean("cycle_logging");
78+
if (obj.has("cycle_logging_tick"))
79+
Constants.CYCLE_LOGGING_TICK = obj.getInt("cycle_logging_tick");
7580
}
7681

7782
private static void initialize() {

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

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -39,11 +39,11 @@ public class Constants {
3939
* WEBSITE_INTEGRATION Enables/Disables Website Features(Total Accounts Registered & Players Online)
4040
*/
4141
public static String SERVER_NAME = "2006Scape", WEBSITE_LINK = "https://2006Scape.org";
42-
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;
42+
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;
4343
public static boolean GUI_ENABLED = false, FILE_SERVER = true, SERVER_DEBUG = false, MEMBERS_ONLY = false, TUTORIAL_ISLAND = false,
4444
PARTY_ROOM_DISABLED = false, CLUES_ENABLED = true, ITEM_REQUIREMENTS = true,
4545
ADMIN_CAN_TRADE = false, ADMIN_DROP_ITEMS = false, ADMIN_CAN_SELL_ITEMS = false, VARIABLE_XP_RATE = false,
46-
WEBSITE_INTEGRATION = false;
46+
WEBSITE_INTEGRATION = false, CYCLE_LOGGING = true;
4747
public static int[] VARIABLE_XP_RATES = new int[] {1, 2, 5, 10};
4848
public static double TEST_VERSION = 2.3, XP_RATE = 1.0;
4949

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

Lines changed: 87 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -13,6 +13,9 @@
1313
import java.util.concurrent.locks.Lock;
1414
import java.util.concurrent.locks.ReentrantLock;
1515

16+
import com.google.common.base.Stopwatch;
17+
import com.rs2.game.npcs.Npc;
18+
import com.rs2.game.npcs.NpcList;
1619
import com.rs2.gui.ControlPanel;
1720

1821
import org.apollo.cache.IndexedFileSystem;
@@ -239,33 +242,72 @@ public static void main(java.lang.String[] args)
239242
* scheduleAtFixedRate() does not invoke concurrent Runnables.
240243
*/
241244
scheduler.scheduleAtFixedRate(new Runnable() {
245+
int gameTicksIncrementor;
246+
final int printInfoTick = Constants.CYCLE_LOGGING_TICK;
242247
public void run() {
243-
//TODO debug Stopwatch stopwatch = Stopwatch.createStarted();
248+
Stopwatch stopwatch = Stopwatch.createStarted();
244249
/**
245250
* Main Server Tick
246251
*/
247252
try {
248253
if (GameEngine.shutdownServer) {
249254
scheduler.shutdown();
250255
}
256+
long startItemHandler = System.currentTimeMillis();
251257
itemHandler.process();
258+
long durationItemHandler = System.currentTimeMillis() - startItemHandler;
259+
checkAndLogDuration("ItemHandler", durationItemHandler);
260+
long startPlayerHandler = System.currentTimeMillis();
252261
playerHandler.process();
262+
long durationPlayerHandler = System.currentTimeMillis() - startPlayerHandler;
263+
checkAndLogDuration("PlayerHandler", durationPlayerHandler);
264+
long startNpcHandler = System.currentTimeMillis();
253265
npcHandler.process();
266+
long durationNpcHandler = System.currentTimeMillis() - startNpcHandler;
267+
checkAndLogDuration("NpcHandler", durationNpcHandler);
268+
long startShopHandler = System.currentTimeMillis();
254269
shopHandler.process();
270+
long durationShopHandler = System.currentTimeMillis() - startShopHandler;
271+
checkAndLogDuration("ShopHandler", durationShopHandler);
272+
long startObjectManager = System.currentTimeMillis();
255273
objectManager.process();
274+
long durationObjectManager = System.currentTimeMillis() - startObjectManager;
275+
checkAndLogDuration("ObjectManager", durationObjectManager);
276+
long startCastleWars = System.currentTimeMillis();
256277
CastleWars.process();
278+
long durationCastleWars = System.currentTimeMillis() - startCastleWars;
279+
checkAndLogDuration("CastleWars", durationCastleWars);
280+
long startFightPits = System.currentTimeMillis();
257281
FightPits.process();
282+
long durationFightPits = System.currentTimeMillis() - startFightPits;
283+
checkAndLogDuration("FightPits", durationFightPits);
284+
long startPestControl = System.currentTimeMillis();
258285
pestControl.process();
286+
long durationPestControl = System.currentTimeMillis() - startPestControl;
287+
checkAndLogDuration("PestControl", durationPestControl);
288+
long startObjectHandler = System.currentTimeMillis();
259289
objectHandler.process();
290+
long durationObjectHandler = System.currentTimeMillis() - startObjectHandler;
291+
checkAndLogDuration("CastleWars", durationObjectHandler);
292+
long startMageTrainingArena = System.currentTimeMillis();
260293
MageTrainingArena.process();
294+
long durationMageTrainingArena = System.currentTimeMillis() - startMageTrainingArena;
295+
checkAndLogDuration("MageTrainingArena", durationMageTrainingArena);
296+
long startCycleEventHandler = System.currentTimeMillis();
261297
CycleEventHandler.getSingleton().process();
298+
long durationCycleEventHandler = System.currentTimeMillis() - startCycleEventHandler;
299+
checkAndLogDuration("CycleEventHandler", durationCycleEventHandler);
300+
long startIntegrationEvents = System.currentTimeMillis();
262301
if (Constants.WEBSITE_INTEGRATION) {
263302
PlayersOnlineWebsite.addUpdatePlayersOnlineTask();
264303
RegisteredAccsWebsite.addUpdateRegisteredUsersTask();
265304
}
266305
if (DiscordActivity.playerCount) {
267306
DiscordActivity.updateActivity();
268307
}
308+
long durationIntegrationEvents = System.currentTimeMillis() - startIntegrationEvents;
309+
checkAndLogDuration("IntegrationEvents", durationIntegrationEvents);
310+
long startSaveEvents = System.currentTimeMillis();
269311
if (System.currentTimeMillis() - lastMassSave > 300000) {
270312
for (Player p : PlayerHandler.players) {
271313
if (p == null) {
@@ -276,9 +318,42 @@ public void run() {
276318
lastMassSave = System.currentTimeMillis();
277319
}
278320
}
321+
long durationSaveEvents = System.currentTimeMillis() - startSaveEvents;
322+
checkAndLogDuration("SaveEvents", durationSaveEvents);
323+
long totalCycleDuration = stopwatch.elapsed(TimeUnit.MILLISECONDS);
324+
//Technically, we could add commands to test both client lag (creating many tile objects) and server lag (creating a BCrypt hash on game thread)
325+
if (totalCycleDuration > 500) {
326+
System.err.println("ERROR: Cycle duration exceeded 500 ms!");
327+
} else if (totalCycleDuration > 250) {
328+
System.err.println("WARNING: Cycle duration exceeded 250 ms!");
329+
} else if (totalCycleDuration > 100) {
330+
System.out.println("NOTICE: Cycle duration exceeded 100 ms.");
331+
}
332+
gameTicksIncrementor++;
333+
if (Constants.CYCLE_LOGGING && gameTicksIncrementor > 1 && gameTicksIncrementor % printInfoTick == 0) {
334+
long totalMem = Runtime.getRuntime().totalMemory();
335+
long freeMem = Runtime.getRuntime().freeMemory();
336+
long maxMem = Runtime.getRuntime().maxMemory();
337+
int playerCount = 0;
338+
for (Player p : PlayerHandler.players) {
339+
if (p != null) {
340+
playerCount++;
341+
}
342+
}
343+
int npcCount = 0;
344+
for (Npc npc : NpcHandler.npcs) {
345+
if (npc != null) {
346+
npcCount++;
347+
}
348+
}
349+
System.out.println("Cycle #" + gameTicksIncrementor + " took " + totalCycleDuration + " ms. Players: " + playerCount + ", NPCs: " + npcCount +
350+
", [Durations: i: " + durationItemHandler + " ms, p: " + durationPlayerHandler + " ms, n: " + durationNpcHandler + " ms, s: " + durationShopHandler +
351+
" ms, oh: " + durationObjectHandler + " ms, om: " + durationObjectManager + " ms], Memory: " + (totalMem - freeMem) / 1024 / 1024 + "MB/" +
352+
totalMem / 1024 / 1024 + "MB. Max: " + maxMem / 1024 / 1024 + "MB, Threads: " + Thread.activeCount() + ".");
353+
}
279354
} catch (Exception ex) {
280355
ex.printStackTrace();
281-
System.out.println("A fatal exception has been thrown!");
356+
System.err.println("A fatal exception has been thrown in the GameEngine cycle! Saving all players.");
282357
for (Player p : PlayerHandler.players) {
283358
if (p == null) {
284359
continue;
@@ -294,7 +369,6 @@ public void run() {
294369
}
295370
scheduler.shutdown(); // Kills the tickloop thread if Exception is thrown.
296371
}
297-
//TODO debug System.out.println("Cycle took " + stopwatch.elapsed(TimeUnit.MILLISECONDS) + " ms.");
298372
}
299373
}, 0, Constants.CYCLE_TIME, TimeUnit.MILLISECONDS);
300374

@@ -315,6 +389,16 @@ public void run() {
315389

316390
System.exit(0);
317391
}
392+
393+
private static void checkAndLogDuration(String processName, long duration) {
394+
if (duration > 500) {
395+
System.err.println("ERROR: " + processName + " duration exceeded 500 ms! Duration: " + duration + " ms.");
396+
} else if (duration > 250) {
397+
System.err.println("WARNING: " + processName + " duration exceeded 250 ms! Duration: " + duration + " ms.");
398+
} else if (duration > 100) {
399+
System.out.println("NOTICE: " + processName + " duration exceeded 100 ms. Duration: " + duration + " ms.");
400+
}
401+
}
318402

319403
public static boolean playerExecuted = false;
320404
private static BufferedReader minuteFile;

0 commit comments

Comments
 (0)