Add performance monitoring for event listeners and tasks (#124)

This commit introduces a performance monitoring feature to Project Poseidon, aimed at enhancing server administration capabilities by tracking the execution times of synchronous event listeners and server tasks. This update provides tools for real-time performance insights and statistical reporting, facilitating the identification and management of performance issues.

Key Features:
- Real-time monitoring and alerts for performance thresholds.
- Configurable settings to tailor monitoring to specific server needs.
- Detailed performance statistics available at server shutdown.

Files Modified:
- `PoseidonConfig.java`: Added configuration options for monitoring.
- `PerformanceStatistic.java`: New class for handling performance data.
- `PoseidonServer.java`, `MinecraftServer.java`, `CraftServer.java`, `CraftScheduler.java`: Integrated performance monitoring.
- `SimplePluginManager.java`: Updated to monitor event handling performance.

src/main/java/com/legacyminecraft/poseidon/PoseidonConfig.java

@@ -109,6 +109,23 @@ private void write() {
         generateConfigOption("settings.watchdog.debug-timeout.value", 30);
         generateConfigOption("settings.watchdog.debug-timeout.info", "debug-timeout can be used to print a stack trace at a lower interval then the main timeout allowing admins to locate blocking tasks that cause hangs over a certain duration. Only enable this if you have experienced temporary hangs/server freezes.");
 
+        // Performance Monitoring
+        generateConfigOption("settings.performance-monitoring.listener-reporting.info", "This setting will cause the server to record listener execution times.");
+        generateConfigOption("settings.performance-monitoring.listener-reporting.enabled", true);
+        generateConfigOption("settings.performance-monitoring.listener-reporting.print-statistics-on-shutdown.info", "Prints the listener statistics to the console on server shutdown.");
+        generateConfigOption("settings.performance-monitoring.listener-reporting.print-statistics-on-shutdown.enabled", false);
+        generateConfigOption("settings.performance-monitoring.listener-reporting.print-on-slow-listeners.info", "Print to console when a listener takes longer than the specified time in milliseconds. It isn't recommended to set this any lower then 10ms to prevent console spam.");
+        generateConfigOption("settings.performance-monitoring.listener-reporting.print-on-slow-listeners.enabled", true);
+        generateConfigOption("settings.performance-monitoring.listener-reporting.print-on-slow-listeners.value", 100); // Default to two Minecraft tick
+
+        generateConfigOption("settings.performance-monitoring.task-reporting.info", "This setting will cause the server to record synchronous task execution times.");
+        generateConfigOption("settings.performance-monitoring.task-reporting.enabled", true);
+        generateConfigOption("settings.performance-monitoring.task-reporting.print-statistics-on-shutdown.info", "Prints the task statistics to the console on server shutdown.");
+        generateConfigOption("settings.performance-monitoring.task-reporting.print-statistics-on-shutdown.enabled", false);
+        generateConfigOption("settings.performance-monitoring.task-reporting.print-on-slow-tasks.info", "Print to console when a task takes longer than the specified time in milliseconds. It isn't recommended to set this any lower then 10ms to prevent console spam.");
+        generateConfigOption("settings.performance-monitoring.task-reporting.print-on-slow-tasks.enabled", true);
+        generateConfigOption("settings.performance-monitoring.task-reporting.print-on-slow-tasks.value", 100); // Default to two Minecraft tick
+
         //Packet Events
         generateConfigOption("settings.packet-events.enabled", false);
         generateConfigOption("settings.packet-events.info", "This setting causes the server to fire a Bukkit event for each packet received and sent to a player once they have finished the initial login process. This only needs to be enabled if you have a plugin that uses this specific feature.");

src/main/java/com/legacyminecraft/poseidon/PoseidonServer.java

@@ -1,5 +1,6 @@
 package com.legacyminecraft.poseidon;
 
+import com.legacyminecraft.poseidon.utility.PerformanceStatistic;
 import com.legacyminecraft.poseidon.utility.PoseidonVersionChecker;
 import com.legacyminecraft.poseidon.watchdog.WatchDogThread;
 import com.projectposeidon.johnymuffin.UUIDManager;
@@ -10,6 +11,9 @@
 
 import java.io.IOException;
 import java.io.InputStream;
+import java.util.*;
+import java.util.logging.Logger;
+import java.util.stream.Collectors;
 import java.util.ArrayList;
 import java.util.Arrays;
 import java.util.List;
@@ -28,9 +32,16 @@ public final class PoseidonServer {
     private PoseidonVersionChecker poseidonVersionChecker;
     private WatchDogThread watchDogThread;
 
+    private Map<String, PerformanceStatistic> listenerPerformance = new HashMap<String, PerformanceStatistic>();
+
+    private Map<String, PerformanceStatistic> taskPerformance = new HashMap<String, PerformanceStatistic>();
+
+    private PoseidonConfig config;
+
     public PoseidonServer(MinecraftServer server, CraftServer craftServer) {
         this.server = server;
         this.craftServer = craftServer;
+        this.config = PoseidonConfig.getInstance();
 
         loadVersionProperties();
 
@@ -84,7 +95,7 @@ private void initializeUpdateChecker() {
             return;
         }
 
-        if(!getBuildType().equalsIgnoreCase("production")) {
+        if (!getBuildType().equalsIgnoreCase("production")) {
             getLogger().warning("[Poseidon] Version checker is disabled as this is a " + getBuildType() + " build. The updater will only check for updates on production builds.");
             return;
         }
@@ -103,9 +114,10 @@ public void run() {
 
     public void shutdownServer() {
         if (!serverInitialized) {
-            throw new UnsupportedOperationException("Server not initialized");
+//            throw new UnsupportedOperationException("Server not initialized");
+            return;
         }
-
+      
         getLogger().info("[Poseidon] Stopping Project Poseidon Modules!");
 
         UUIDManager.getInstance().saveJsonArray();
@@ -169,7 +181,6 @@ public boolean isCommandHidden(String cmdName) {
         return hiddenCommands.contains(cmdName.toLowerCase());
     }
 
-
     /**
      * Hides the command from param from being logged to server console
      *
@@ -197,4 +208,40 @@ public void addHiddenCommands(List<String> commands) {
         }
     }
 
+    public Map<String, PerformanceStatistic> getListenerPerformance() {
+        return listenerPerformance;
+    }
+
+    public Map<String, PerformanceStatistic> getTaskPerformance() {
+        return taskPerformance;
+    }
+
+    // Generic method to sort any performance map
+    public Map<String, PerformanceStatistic> getSortedPerformance(Map<String, PerformanceStatistic> unsortedMap) {
+        return unsortedMap.entrySet()
+                .stream()
+                .sorted(Map.Entry.<String, PerformanceStatistic>comparingByValue(
+                        Comparator.comparingLong(PerformanceStatistic::getAverageExecutionTime).reversed()
+                ))
+                .collect(Collectors.toMap(
+                        Map.Entry::getKey,
+                        Map.Entry::getValue,
+                        (e1, e2) -> e1, // if same key, keep the first
+                        LinkedHashMap::new
+                ));
+    }
+
+    // Specific method to get sorted listener performance
+    public Map<String, PerformanceStatistic> getSortedListenerPerformance() {
+        return getSortedPerformance(getListenerPerformance());
+    }
+
+    // Specific method to get sorted task performance
+    public Map<String, PerformanceStatistic> getSortedTaskPerformance() {
+        return getSortedPerformance(getTaskPerformance());
+    }
+
+    public PoseidonConfig getConfig() {
+        return config;
+    }
 }

src/main/java/com/legacyminecraft/poseidon/utility/PerformanceStatistic.java

@@ -0,0 +1,50 @@
+package com.legacyminecraft.poseidon.utility;
+
+public class PerformanceStatistic {
+    private long minTime = Long.MAX_VALUE;
+    private long maxTime = 0;
+    private long totalTime = 0;
+    private long count = 0;
+
+    // Update the stats with a new execution time
+    public void update(long duration) {
+        if (duration < minTime) {
+            minTime = duration;
+        }
+        if (duration > maxTime) {
+            maxTime = duration;
+        }
+        totalTime += duration;
+        count++;
+    }
+
+    // Retrieve the average execution time
+    long getAverageTime() {
+        return count > 0 ? totalTime / count : 0;
+    }
+
+    // Print the statistics for this listener
+    public String printStats() {
+        return String.format("Called: %d times, Min: %dms, Avg: %dms, Max: %dms", count, minTime, getAverageTime(), maxTime);
+    }
+
+    public long getEventCount() {
+        return count;
+    }
+
+    public long getTotalExecutionTime() {
+        return totalTime;
+    }
+
+    public long getAverageExecutionTime() {
+        return getAverageTime();
+    }
+
+    public long getMinExecutionTime() {
+        return minTime;
+    }
+
+    public long getMaxExecutionTime() {
+        return maxTime;
+    }
+}

src/main/java/net/minecraft/server/MinecraftServer.java

@@ -4,6 +4,7 @@
 import com.legacyminecraft.poseidon.PoseidonConfig;
 import com.legacyminecraft.poseidon.PoseidonPlugin;
 import com.legacyminecraft.poseidon.util.ServerLogRotator;
+import com.legacyminecraft.poseidon.utility.PerformanceStatistic;
 import com.legacyminecraft.poseidon.utility.PoseidonVersionChecker;
 import com.projectposeidon.johnymuffin.UUIDManager;
 import com.legacyminecraft.poseidon.watchdog.WatchDogThread;
@@ -381,6 +382,74 @@ public void stop() { // CraftBukkit - private -> public
             this.saveChunks();
         }
         // CraftBukkit end
+
+        // Poseidon Start
+        Map<String, PerformanceStatistic> listenerStatistics = new HashMap<>();
+
+        // Only get the Listener Statistics if the Poseidon Server is not null. Prevents null pointer exceptions.
+        if (Poseidon.getServer() != null && Poseidon.getServer().getConfig().getConfigBoolean("settings.performance-monitoring.listener-reporting.print-statistics-on-shutdown.enabled")) {
+            listenerStatistics = Poseidon.getServer().getSortedListenerPerformance();
+        }
+
+        // Check if the statistics map is not empty
+        if (listenerStatistics != null && !listenerStatistics.isEmpty()) {
+            log.info("[Poseidon] Listener statistics from this session:");
+
+            // Iterate over each listener and log their statistics
+            for (Map.Entry<String, PerformanceStatistic> entry : listenerStatistics.entrySet()) {
+                String listener = entry.getKey();
+                PerformanceStatistic stats = entry.getValue();
+
+                if (stats.getMaxExecutionTime() == 0) {
+                    continue;
+                }
+
+                if (stats != null) {
+                    log.info(String.format("[Poseidon] Listener: %s - Processed %d events, Total Execution Time: %d ms, Avg Time: %d ms",
+                            listener,
+                            stats.getEventCount(),
+                            stats.getTotalExecutionTime(),
+                            stats.getAverageExecutionTime()));
+                } else {
+                    log.warning("[Poseidon] No statistics available for listener: " + listener);
+                }
+            }
+        }
+
+
+        // Check if the statistics map is not empty
+
+        Map<String, PerformanceStatistic> taskStatistics = new HashMap<>();
+
+        // Only get the Task Statistics if the Poseidon Server is not null. Prevents null pointer exceptions.
+        if (Poseidon.getServer() != null && Poseidon.getServer().getConfig().getConfigBoolean("settings.performance-monitoring.listener-reporting.print-statistics-on-shutdown.enabled")) {
+            taskStatistics = Poseidon.getServer().getSortedTaskPerformance();
+        }
+
+        if (taskStatistics != null && !taskStatistics.isEmpty()) {
+            log.info("[Poseidon] Synchronous task statistics from this session:");
+
+            // Iterate over each task and log their statistics
+            for (Map.Entry<String, PerformanceStatistic> entry : taskStatistics.entrySet()) {
+                String task = entry.getKey();
+                PerformanceStatistic stats = entry.getValue();
+
+                if (stats.getMaxExecutionTime() == 0) {
+                    continue;
+                }
+
+                if (stats != null) {
+                    log.info(String.format("[Poseidon] Task: %s - Processed %d events, Total Execution Time: %d ms, Avg Time: %d ms",
+                            task,
+                            stats.getEventCount(),
+                            stats.getTotalExecutionTime(),
+                            stats.getAverageExecutionTime()));
+                } else {
+                    log.warning("[Poseidon] No statistics available for task: " + task);
+                }
+            }
+        }
+        // Poseidon End
     }
 
     public void a() {

src/main/java/org/bukkit/craftbukkit/CraftServer.java

@@ -65,9 +65,9 @@ public final class CraftServer implements Server {
     private final String protocolVersion = "1.7.3";
     private final String GameVersion = "b1.7.3";
     private final ServicesManager servicesManager = new SimpleServicesManager();
-    private final BukkitScheduler scheduler = new CraftScheduler(this);
+    private final BukkitScheduler scheduler;
     private final SimpleCommandMap commandMap = new SimpleCommandMap(this);
-    private final PluginManager pluginManager = new SimplePluginManager(this, commandMap);
+    private final PluginManager pluginManager;
     protected final MinecraftServer console;
     protected final ServerConfigurationManager server;
     private final Map<String, World> worlds = new LinkedHashMap<String, World>();
@@ -88,6 +88,9 @@ public CraftServer(MinecraftServer console, ServerConfigurationManager server) {
         Poseidon.setServer(poseidonServer);
         //Project Poseidon End
 
+        this.pluginManager = new SimplePluginManager(this, commandMap); //Project Poseidon - This must run after PoseidonServer is set
+        this.scheduler = new CraftScheduler(this); //Project Poseidon - This must run after PoseidonServer is set
+
         configuration = new Configuration((File) console.options.valueOf("bukkit-settings"));
         loadConfig();
         loadPlugins();

src/main/java/org/bukkit/craftbukkit/scheduler/CraftScheduler.java

@@ -1,5 +1,7 @@
 package org.bukkit.craftbukkit.scheduler;
 
+import com.legacyminecraft.poseidon.Poseidon;
+import com.legacyminecraft.poseidon.utility.PerformanceStatistic;
 import org.bukkit.craftbukkit.CraftServer;
 import org.bukkit.plugin.Plugin;
 import org.bukkit.scheduler.BukkitScheduler;
@@ -106,8 +108,25 @@ public CraftScheduler(CraftServer server) {
         Thread t = new Thread(this);
         t.start();
 
+        // Project Poseidon - Start - Synchronous task performance reporting
+        this.taskPerformanceEnabled = Poseidon.getServer().getConfig().getConfigBoolean("settings.performance-monitoring.task-reporting.enabled");
+        this.printOnSlowTask = Poseidon.getServer().getConfig().getConfigBoolean("settings.performance-monitoring.task-reporting.print-on-slow-tasks.enabled");
+        this.printOnSlowTaskThreshold = Poseidon.getServer().getConfig().getConfigInteger("settings.performance-monitoring.task-reporting.print-on-slow-tasks.value");
+
+        this.taskPerformance = Poseidon.getServer().getTaskPerformance();
+        // Project Poseidon - End - Synchronous task performance reporting
     }
 
+    // Project Poseidon - Start - Synchronous task performance reporting
+    private final boolean taskPerformanceEnabled; // Project Poseidon
+    private final Map<String, PerformanceStatistic> taskPerformance; // Project Poseidon
+
+    private final boolean printOnSlowTask;
+    private final int printOnSlowTaskThreshold;
+
+    // Project Poseidon - End - Synchronous task performance reporting
+
+
     // If the main thread cannot obtain the lock, it doesn't wait
     public void mainThreadHeartbeat(long currentTick) {
         if (syncedTasksLock.tryLock()) {
@@ -125,8 +144,31 @@ public void mainThreadHeartbeat(long currentTick) {
                 long breakTime = System.currentTimeMillis() + 35; // max time spent in loop = 35ms
                 while (!syncedTasks.isEmpty() && System.currentTimeMillis() <= breakTime) {
                     CraftTask task = syncedTasks.removeFirst();
+                    long startTime = System.currentTimeMillis(); // Poseidon - Synchronous task performance reporting
                     try {
                         task.getTask().run();
+
+                        // Poseidon - Start - Synchronous task performance reporting
+                        if(taskPerformanceEnabled) {
+                            long duration = System.currentTimeMillis() - startTime;  // Calculate duration in milliseconds
+
+                            String taskKey = (task == null || task.getOwner() == null || task.getOwner().getDescription() == null || task.getOwner().getDescription().getName() == null)
+                                    ? "Unknown"
+                                    : task.getOwner().getDescription().getName();
+
+                            taskPerformance.computeIfAbsent(taskKey, k -> new PerformanceStatistic()).update(duration);
+
+                            // If task took longer than the threshold, print the performance statistics for the listener
+                            if (printOnSlowTask && duration > printOnSlowTaskThreshold) {
+                                server.getLogger().log(Level.WARNING, String.format(
+                                        "[Poseidon] Synchronous task from plugin %s took %d milliseconds. Statistics: %s",
+                                        taskKey,
+                                        duration,
+                                        taskPerformance.get(taskKey).printStats()
+                                ));
+                            }
+                        }
+                        // Poseidon - End - Synchronous task performance reporting
                     } catch (Throwable t) {
                         // Bad plugin!
                         logger.log(Level.WARNING, "Task of '" + task.getOwner().getDescription().getName() + "' generated an exception", t);