diff --git a/src/main/java/com/legacyminecraft/poseidon/PoseidonConfig.java b/src/main/java/com/legacyminecraft/poseidon/PoseidonConfig.java index 49e8ca2d..fdef4d09 100644 --- a/src/main/java/com/legacyminecraft/poseidon/PoseidonConfig.java +++ b/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."); diff --git a/src/main/java/com/legacyminecraft/poseidon/PoseidonServer.java b/src/main/java/com/legacyminecraft/poseidon/PoseidonServer.java index c3a85285..7a797b59 100644 --- a/src/main/java/com/legacyminecraft/poseidon/PoseidonServer.java +++ b/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 listenerPerformance = new HashMap(); + + private Map taskPerformance = new HashMap(); + + 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 commands) { } } + public Map getListenerPerformance() { + return listenerPerformance; + } + + public Map getTaskPerformance() { + return taskPerformance; + } + + // Generic method to sort any performance map + public Map getSortedPerformance(Map unsortedMap) { + return unsortedMap.entrySet() + .stream() + .sorted(Map.Entry.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 getSortedListenerPerformance() { + return getSortedPerformance(getListenerPerformance()); + } + + // Specific method to get sorted task performance + public Map getSortedTaskPerformance() { + return getSortedPerformance(getTaskPerformance()); + } + + public PoseidonConfig getConfig() { + return config; + } } diff --git a/src/main/java/com/legacyminecraft/poseidon/utility/PerformanceStatistic.java b/src/main/java/com/legacyminecraft/poseidon/utility/PerformanceStatistic.java new file mode 100644 index 00000000..8b345f5c --- /dev/null +++ b/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; + } +} diff --git a/src/main/java/net/minecraft/server/MinecraftServer.java b/src/main/java/net/minecraft/server/MinecraftServer.java index ca60a348..1b94cedd 100644 --- a/src/main/java/net/minecraft/server/MinecraftServer.java +++ b/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 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 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 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 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() { diff --git a/src/main/java/org/bukkit/craftbukkit/CraftServer.java b/src/main/java/org/bukkit/craftbukkit/CraftServer.java index 9a678ea6..1f4a284b 100644 --- a/src/main/java/org/bukkit/craftbukkit/CraftServer.java +++ b/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 worlds = new LinkedHashMap(); @@ -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(); diff --git a/src/main/java/org/bukkit/craftbukkit/scheduler/CraftScheduler.java b/src/main/java/org/bukkit/craftbukkit/scheduler/CraftScheduler.java index 9a4c16c2..2e33a912 100644 --- a/src/main/java/org/bukkit/craftbukkit/scheduler/CraftScheduler.java +++ b/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 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); diff --git a/src/main/java/org/bukkit/plugin/SimplePluginManager.java b/src/main/java/org/bukkit/plugin/SimplePluginManager.java index 88d3f062..e4627fcb 100644 --- a/src/main/java/org/bukkit/plugin/SimplePluginManager.java +++ b/src/main/java/org/bukkit/plugin/SimplePluginManager.java @@ -4,6 +4,7 @@ import com.google.common.collect.MapMaker; import com.legacyminecraft.poseidon.Poseidon; import com.legacyminecraft.poseidon.event.PoseidonCustomListener; +import com.legacyminecraft.poseidon.utility.PerformanceStatistic; import org.bukkit.Server; import org.bukkit.command.Command; import org.bukkit.command.PluginCommandYamlParser; @@ -56,10 +57,24 @@ public SimplePluginManager(Server instance, SimpleCommandMap commandMap) { defaultPerms.put(true, new HashSet()); defaultPerms.put(false, new HashSet()); + + // Project Poseidon Start + this.listenerPerformanceEnabled = Poseidon.getServer().getConfig().getConfigBoolean("settings.performance-monitoring.listener-reporting.enabled"); + this.printOnSlowListener = Poseidon.getServer().getConfig().getConfigBoolean("settings.performance-monitoring.listener-reporting.print-on-slow-listeners.enabled"); + this.printOnSlowListenerThreshold = Poseidon.getServer().getConfig().getConfigInteger("settings.performance-monitoring.listener-reporting.print-on-slow-listeners.value"); + + this.listenerPerformance = Poseidon.getServer().getListenerPerformance(); // Get the listener performance map from PoseidonServer for storing listener performance statistics + // Project Poseidon End } // Project Poseidon Start + private final boolean listenerPerformanceEnabled; // Project Poseidon + private final Map listenerPerformance; // Project Poseidon + + private final boolean printOnSlowListener; + private final int printOnSlowListenerThreshold; + @Override public void registerEvents(Listener listener, Plugin plugin) { if (!plugin.isEnabled()) { @@ -185,12 +200,12 @@ public Plugin[] loadPlugins(File directory) { /** * Loads the plugin in the specified file - * + *

* File must be valid according to the current enabled Plugin interfaces * * @param file File containing the plugin to load * @return The Plugin loaded, or null if it was invalid - * @throws InvalidPluginException Thrown when the specified file is not a valid plugin + * @throws InvalidPluginException Thrown when the specified file is not a valid plugin * @throws InvalidDescriptionException Thrown when the specified file contains an invalid description */ public synchronized Plugin loadPlugin(File file) throws InvalidPluginException, InvalidDescriptionException, UnknownDependencyException { @@ -199,13 +214,13 @@ public synchronized Plugin loadPlugin(File file) throws InvalidPluginException, /** * Loads the plugin in the specified file - * + *

* File must be valid according to the current enabled Plugin interfaces * - * @param file File containing the plugin to load + * @param file File containing the plugin to load * @param ignoreSoftDependencies Loader will ignore soft dependencies if this flag is set to true * @return The Plugin loaded, or null if it was invalid - * @throws InvalidPluginException Thrown when the specified file is not a valid plugin + * @throws InvalidPluginException Thrown when the specified file is not a valid plugin * @throws InvalidDescriptionException Thrown when the specified file contains an invalid description */ public synchronized Plugin loadPlugin(File file, boolean ignoreSoftDependencies) throws InvalidPluginException, InvalidDescriptionException, UnknownDependencyException { @@ -242,7 +257,7 @@ public synchronized Plugin loadPlugin(File file, boolean ignoreSoftDependencies) /** * Checks if the given plugin is loaded and returns it when applicable - * + *

* Please note that the name of the plugin is case-sensitive * * @param name Name of the plugin to check @@ -258,7 +273,7 @@ public synchronized Plugin[] getPlugins() { /** * Checks if the given plugin is enabled or not - * + *

* Please note that the name of the plugin is case-sensitive. * * @param name Name of the plugin to check @@ -292,15 +307,15 @@ public void enablePlugin(final Plugin plugin) { commandMap.registerAll(plugin.getDescription().getName(), pluginCommands); // Project Poseidon - Start - Hide commands - for(Command c : pluginCommands) { - if(c.isHidden()) { + for (Command c : pluginCommands) { + if (c.isHidden()) { Poseidon.getServer().addHiddenCommand(c.getLabel()); Poseidon.getServer().addHiddenCommands(c.getAliases()); } } // Project Poseidon - End - Hide commands } - + try { plugin.getPluginLoader().enablePlugin(plugin); } catch (Throwable ex) { @@ -310,7 +325,7 @@ public void enablePlugin(final Plugin plugin) { } public void disablePlugins() { - for (Plugin plugin: getPlugins()) { + for (Plugin plugin : getPlugins()) { disablePlugin(plugin); } } @@ -351,7 +366,7 @@ public void clearPlugins() { } /** - * Calls a player related event with the given details + * Calls a player related event with the given details and logs execution time, calling plugin, and listener class. * * @param event Event details */ @@ -360,8 +375,31 @@ public synchronized void callEvent(Event event) { if (eventListeners != null) { for (RegisteredListener registration : eventListeners) { + long startTime = System.currentTimeMillis(); // Start timing before event call + try { - registration.callEvent(event); + registration.callEvent(event); // Call the event + + // Project Poseidon - Start - Listener Performance Reporting + if (listenerPerformanceEnabled) { + long duration = System.currentTimeMillis() - startTime; // Calculate duration in milliseconds + + String listenerKey = registration.getListener().getClass().getName() + ":" + event.getType().toString(); + + listenerPerformance.computeIfAbsent(listenerKey, k -> new PerformanceStatistic()).update(duration); + + // If event took longer than the threshold, print the performance statistics for the listener + if (printOnSlowListener && duration > printOnSlowListenerThreshold) { + server.getLogger().log(Level.WARNING, String.format( + "[Poseidon] Event %s in %s took %d milliseconds. Statistics: %s", + event.getType(), + listenerKey, + duration, + listenerPerformance.get(listenerKey).printStats() + )); + } + } + // Project Poseidon - End - Listener Performance Reporting } catch (AuthorNagException ex) { Plugin plugin = registration.getPlugin(); @@ -374,10 +412,10 @@ public synchronized void callEvent(Event event) { author = plugin.getDescription().getAuthors().get(0); } server.getLogger().log(Level.SEVERE, String.format( - "Nag author: '%s' of '%s' about the following: %s", - author, - plugin.getDescription().getName(), - ex.getMessage() + "Nag author: '%s' of '%s' about the following: %s", + author, + plugin.getDescription().getName(), + ex.getMessage() )); } } catch (Throwable ex) { @@ -387,13 +425,14 @@ public synchronized void callEvent(Event event) { } } + /** * Registers the given event to the specified listener * - * @param type EventType to register + * @param type EventType to register * @param listener PlayerListener to register * @param priority Priority of this event - * @param plugin Plugin to register + * @param plugin Plugin to register */ public void registerEvent(Event.Type type, Listener listener, Priority priority, Plugin plugin) { if (!plugin.isEnabled()) { @@ -406,11 +445,11 @@ public void registerEvent(Event.Type type, Listener listener, Priority priority, /** * Registers the given event to the specified listener using a directly passed EventExecutor * - * @param type EventType to register + * @param type EventType to register * @param listener PlayerListener to register * @param executor EventExecutor to register * @param priority Priority of this event - * @param plugin Plugin to register + * @param plugin Plugin to register */ public void registerEvent(Event.Type type, Listener listener, EventExecutor executor, Priority priority, Plugin plugin) { if (!plugin.isEnabled()) {