From 8436d82f19ccc283c93fa2a2a2df7621437dd5ae Mon Sep 17 00:00:00 2001 From: Aikar Date: Sun, 2 Jun 2013 10:42:57 +1000 Subject: [PATCH] Spigot Timings Adds performance tracking timings all around the Minecraft Server, and improves the usability of the /timings command Plugins can track their own timings with CustomTimingsHandler diff --git a/src/main/java/org/bukkit/Bukkit.java b/src/main/java/org/bukkit/Bukkit.java index 1eaf92d..7b25817 100644 --- a/src/main/java/org/bukkit/Bukkit.java +++ b/src/main/java/org/bukkit/Bukkit.java @@ -301,6 +301,7 @@ public final class Bukkit { */ public static void reload() { server.reload(); + org.spigotmc.CustomTimingsHandler.reload(); // Spigot } /** diff --git a/src/main/java/org/bukkit/command/Command.java b/src/main/java/org/bukkit/command/Command.java index 87c33d9..31e4f66 100644 --- a/src/main/java/org/bukkit/command/Command.java +++ b/src/main/java/org/bukkit/command/Command.java @@ -31,6 +31,7 @@ public abstract class Command { protected String usageMessage; private String permission; private String permissionMessage; + public org.spigotmc.CustomTimingsHandler timings; // Spigot protected Command(String name) { this(name, "", "/" + name, new ArrayList()); @@ -44,6 +45,7 @@ public abstract class Command { this.usageMessage = usageMessage; this.aliases = aliases; this.activeAliases = new ArrayList(aliases); + this.timings = new org.spigotmc.CustomTimingsHandler("** Command: " + name); // Spigot } /** @@ -200,6 +202,7 @@ public abstract class Command { public boolean setLabel(String name) { this.nextLabel = name; if (!isRegistered()) { + this.timings = new org.spigotmc.CustomTimingsHandler("** Command: " + name); // Spigot this.label = name; return true; } diff --git a/src/main/java/org/bukkit/command/SimpleCommandMap.java b/src/main/java/org/bukkit/command/SimpleCommandMap.java index d75380c..f15b95d 100644 --- a/src/main/java/org/bukkit/command/SimpleCommandMap.java +++ b/src/main/java/org/bukkit/command/SimpleCommandMap.java @@ -176,11 +176,15 @@ public class SimpleCommandMap implements CommandMap { } try { + target.timings.startTiming(); // Spigot // Note: we don't return the result of target.execute as thats success / failure, we return handled (true) or not handled (false) target.execute(sender, sentCommandLabel, Arrays_copyOfRange(args, 1, args.length)); + target.timings.stopTiming(); // Spigot } catch (CommandException ex) { + target.timings.stopTiming(); // Spigot throw ex; } catch (Throwable ex) { + target.timings.stopTiming(); // Spigot throw new CommandException("Unhandled exception executing '" + commandLine + "' in " + target, ex); } diff --git a/src/main/java/org/bukkit/command/defaults/TimingsCommand.java b/src/main/java/org/bukkit/command/defaults/TimingsCommand.java index 05cfcb0..22926d6 100644 --- a/src/main/java/org/bukkit/command/defaults/TimingsCommand.java +++ b/src/main/java/org/bukkit/command/defaults/TimingsCommand.java @@ -19,23 +19,97 @@ import org.bukkit.util.StringUtil; import com.google.common.collect.ImmutableList; +// Spigot start +import java.io.ByteArrayOutputStream; +import java.io.OutputStream; +import java.net.HttpURLConnection; +import java.net.URL; +import java.net.URLEncoder; +import java.util.logging.Level; + +import org.bukkit.command.RemoteConsoleCommandSender; +import org.bukkit.plugin.SimplePluginManager; +import org.spigotmc.CustomTimingsHandler; +// Spigot end + public class TimingsCommand extends BukkitCommand { - private static final List TIMINGS_SUBCOMMANDS = ImmutableList.of("merged", "reset", "separate"); + private static final List TIMINGS_SUBCOMMANDS = ImmutableList.of("report", "reset", "on", "off", "paste"); // Spigot + public static long timingStart = 0; // Spigot public TimingsCommand(String name) { super(name); - this.description = "Records timings for all plugin events"; - this.usageMessage = "/timings "; + this.description = "Manages Spigot Timings data to see performance of the server."; // Spigot + this.usageMessage = "/timings "; // Spigot this.setPermission("bukkit.command.timings"); } + // Spigot start - redesigned Timings Command + public void executeSpigotTimings(CommandSender sender, String[] args) { + if ( "on".equals( args[0] ) ) + { + ( (SimplePluginManager) Bukkit.getPluginManager() ).useTimings( true ); + CustomTimingsHandler.reload(); + sender.sendMessage( "Enabled Timings & Reset" ); + return; + } else if ( "off".equals( args[0] ) ) + { + ( (SimplePluginManager) Bukkit.getPluginManager() ).useTimings( false ); + sender.sendMessage( "Disabled Timings" ); + return; + } + + if ( !Bukkit.getPluginManager().useTimings() ) + { + sender.sendMessage( "Please enable timings by typing /timings on" ); + return; + } + + boolean paste = "paste".equals( args[0] ); + if ("reset".equals(args[0])) { + CustomTimingsHandler.reload(); + sender.sendMessage("Timings reset"); + } else if ("merged".equals(args[0]) || "report".equals(args[0]) || paste) { + long sampleTime = System.nanoTime() - timingStart; + int index = 0; + File timingFolder = new File("timings"); + timingFolder.mkdirs(); + File timings = new File(timingFolder, "timings.txt"); + ByteArrayOutputStream bout = ( paste ) ? new ByteArrayOutputStream() : null; + while (timings.exists()) timings = new File(timingFolder, "timings" + (++index) + ".txt"); + PrintStream fileTimings = null; + try { + fileTimings = ( paste ) ? new PrintStream( bout ) : new PrintStream( timings ); + + CustomTimingsHandler.printTimings(fileTimings); + fileTimings.println( "Sample time " + sampleTime + " (" + sampleTime / 1E9 + "s)" ); + + if ( paste ) + { + new PasteThread( sender, bout ).start(); + return; + } + + sender.sendMessage("Timings written to " + timings.getPath()); + sender.sendMessage( "Paste contents of file into form at http://www.spigotmc.org/go/timings to read results." ); + + } catch (IOException e) { + } finally { + if (fileTimings != null) { + fileTimings.close(); + } + } + } + } + // Spigot end + @Override public boolean execute(CommandSender sender, String currentAlias, String[] args) { if (!testPermission(sender)) return true; - if (args.length != 1) { + if (args.length < 1) { // Spigot sender.sendMessage(ChatColor.RED + "Usage: " + usageMessage); return false; } + if (true) { executeSpigotTimings(sender, args); return true; } // Spigot if (!sender.getServer().getPluginManager().useTimings()) { sender.sendMessage("Please enable timings by setting \"settings.plugin-profiling\" to true in bukkit.yml"); return true; @@ -118,4 +192,55 @@ public class TimingsCommand extends BukkitCommand { } return ImmutableList.of(); } + + // Spigot start + private static class PasteThread extends Thread + { + + private final CommandSender sender; + private final ByteArrayOutputStream bout; + + public PasteThread(CommandSender sender, ByteArrayOutputStream bout) + { + super( "Timings paste thread" ); + this.sender = sender; + this.bout = bout; + } + + @Override + public synchronized void start() { + if (sender instanceof RemoteConsoleCommandSender) { + run(); + } else { + super.start(); + } + } + + @Override + public void run() + { + try + { + HttpURLConnection con = (HttpURLConnection) new URL( "http://paste.ubuntu.com/" ).openConnection(); + con.setDoOutput( true ); + con.setRequestMethod( "POST" ); + con.setInstanceFollowRedirects( false ); + + OutputStream out = con.getOutputStream(); + out.write( "poster=Spigot&syntax=text&content=".getBytes( "UTF-8" ) ); + out.write( URLEncoder.encode( bout.toString( "UTF-8" ), "UTF-8" ).getBytes( "UTF-8" ) ); + out.close(); + con.getInputStream().close(); + + String location = con.getHeaderField( "Location" ); + String pasteID = location.substring( "http://paste.ubuntu.com/".length(), location.length() - 1 ); + sender.sendMessage( ChatColor.GREEN + "View timings results can be viewed at http://www.spigotmc.org/go/timings?url=" + pasteID ); + } catch ( IOException ex ) + { + sender.sendMessage( ChatColor.RED + "Error pasting timings, check your console for more information" ); + Bukkit.getServer().getLogger().log( Level.WARNING, "Could not paste timings", ex ); + } + } + } + // Spigot end } diff --git a/src/main/java/org/bukkit/plugin/SimplePluginManager.java b/src/main/java/org/bukkit/plugin/SimplePluginManager.java index d2fe422..1d51908 100644 --- a/src/main/java/org/bukkit/plugin/SimplePluginManager.java +++ b/src/main/java/org/bukkit/plugin/SimplePluginManager.java @@ -295,6 +295,7 @@ public final class SimplePluginManager implements PluginManager { } } + org.bukkit.command.defaults.TimingsCommand.timingStart = System.nanoTime(); // Spigot return result.toArray(new Plugin[result.size()]); } diff --git a/src/main/java/org/bukkit/plugin/java/JavaPluginLoader.java b/src/main/java/org/bukkit/plugin/java/JavaPluginLoader.java index b178c0d..fe723c9 100644 --- a/src/main/java/org/bukkit/plugin/java/JavaPluginLoader.java +++ b/src/main/java/org/bukkit/plugin/java/JavaPluginLoader.java @@ -39,6 +39,7 @@ import org.bukkit.plugin.PluginLoader; import org.bukkit.plugin.RegisteredListener; import org.bukkit.plugin.TimedRegisteredListener; import org.bukkit.plugin.UnknownDependencyException; +import org.spigotmc.CustomTimingsHandler; // Spigot import org.yaml.snakeyaml.error.YAMLException; /** @@ -49,6 +50,7 @@ public final class JavaPluginLoader implements PluginLoader { private final Pattern[] fileFilters = new Pattern[] { Pattern.compile("\\.jar$"), }; private final Map> classes = new HashMap>(); private final Map loaders = new LinkedHashMap(); + public static final CustomTimingsHandler pluginParentTimer = new CustomTimingsHandler("** Plugins"); // Spigot /** * This class was not meant to be constructed explicitly @@ -283,13 +285,19 @@ public final class JavaPluginLoader implements PluginLoader { } } + final CustomTimingsHandler timings = new CustomTimingsHandler("Plugin: " + plugin.getDescription().getFullName() + " Event: " + listener.getClass().getName() + "::" + method.getName()+"("+eventClass.getSimpleName()+")", pluginParentTimer); // Spigot EventExecutor executor = new EventExecutor() { public void execute(Listener listener, Event event) throws EventException { try { if (!eventClass.isAssignableFrom(event.getClass())) { return; } + // Spigot start + boolean isAsync = event.isAsynchronous(); + if (!isAsync) timings.startTiming(); method.invoke(listener, event); + if (!isAsync) timings.stopTiming(); + // Spigot end } catch (InvocationTargetException ex) { throw new EventException(ex.getCause()); } catch (Throwable t) { @@ -297,7 +305,7 @@ public final class JavaPluginLoader implements PluginLoader { } } }; - if (useTimings) { + if (false) { // Spigot - RL handles useTimings check now eventSet.add(new TimedRegisteredListener(listener, executor, eh.priority(), plugin, eh.ignoreCancelled())); } else { eventSet.add(new RegisteredListener(listener, executor, eh.priority(), plugin, eh.ignoreCancelled())); diff --git a/src/main/java/org/spigotmc/CustomTimingsHandler.java b/src/main/java/org/spigotmc/CustomTimingsHandler.java new file mode 100644 index 0000000..8d98297 --- /dev/null +++ b/src/main/java/org/spigotmc/CustomTimingsHandler.java @@ -0,0 +1,165 @@ +package org.spigotmc; + +import org.bukkit.command.defaults.TimingsCommand; +import org.bukkit.event.HandlerList; +import org.bukkit.plugin.Plugin; +import org.bukkit.plugin.RegisteredListener; +import org.bukkit.plugin.TimedRegisteredListener; +import java.io.PrintStream; +import java.util.Collection; +import java.util.HashSet; +import java.util.List; +import java.util.Queue; +import java.util.concurrent.ConcurrentLinkedQueue; + +import org.bukkit.Bukkit; +import org.bukkit.World; + +/** + * Provides custom timing sections for /timings merged. + */ +public class CustomTimingsHandler +{ + + private static Queue HANDLERS = new ConcurrentLinkedQueue(); + /*========================================================================*/ + private final String name; + private final CustomTimingsHandler parent; + private long count = 0; + private long start = 0; + private long timingDepth = 0; + private long totalTime = 0; + private long curTickTotal = 0; + private long violations = 0; + + public CustomTimingsHandler(String name) + { + this( name, null ); + } + + public CustomTimingsHandler(String name, CustomTimingsHandler parent) + { + this.name = name; + this.parent = parent; + HANDLERS.add( this ); + } + + /** + * Prints the timings and extra data to the given stream. + * + * @param printStream + */ + public static void printTimings(PrintStream printStream) + { + printStream.println( "Minecraft" ); + for ( CustomTimingsHandler timings : HANDLERS ) + { + long time = timings.totalTime; + long count = timings.count; + if ( count == 0 ) + { + continue; + } + long avg = time / count; + + printStream.println( " " + timings.name + " Time: " + time + " Count: " + count + " Avg: " + avg + " Violations: " + timings.violations ); + } + printStream.println( "# Version " + Bukkit.getVersion() ); + int entities = 0; + int livingEntities = 0; + for ( World world : Bukkit.getWorlds() ) + { + entities += world.getEntities().size(); + livingEntities += world.getLivingEntities().size(); + } + printStream.println( "# Entities " + entities ); + printStream.println( "# LivingEntities " + livingEntities ); + } + + /** + * Resets all timings. + */ + public static void reload() + { + if ( Bukkit.getPluginManager().useTimings() ) + { + for ( CustomTimingsHandler timings : HANDLERS ) + { + timings.reset(); + } + } + TimingsCommand.timingStart = System.nanoTime(); + } + + /** + * Ticked every tick by CraftBukkit to count the number of times a timer + * caused TPS loss. + */ + public static void tick() + { + if ( Bukkit.getPluginManager().useTimings() ) + { + for ( CustomTimingsHandler timings : HANDLERS ) + { + if ( timings.curTickTotal > 50000000 ) + { + timings.violations += Math.ceil( timings.curTickTotal / 50000000 ); + } + timings.curTickTotal = 0; + timings.timingDepth = 0; // incase reset messes this up + } + } + } + + /** + * Starts timing to track a section of code. + */ + public void startTiming() + { + // If second condtion fails we are already timing + if ( Bukkit.getPluginManager().useTimings() && ++timingDepth == 1 ) + { + start = System.nanoTime(); + if ( parent != null && ++parent.timingDepth == 1 ) + { + parent.start = start; + } + } + } + + /** + * Stops timing a section of code. + */ + public void stopTiming() + { + if ( Bukkit.getPluginManager().useTimings() ) + { + if ( --timingDepth != 0 || start == 0 ) + { + return; + } + long diff = System.nanoTime() - start; + totalTime += diff; + curTickTotal += diff; + count++; + start = 0; + if ( parent != null ) + { + parent.stopTiming(); + } + } + } + + /** + * Reset this timer, setting all values to zero. + */ + public void reset() + { + count = 0; + violations = 0; + curTickTotal = 0; + totalTime = 0; + start = 0; + timingDepth = 0; + } +} -- 1.9.1