Paper/Bukkit-Patches/0002-Spigot-Timings.patch

From 1a8060d85c71cd9047243fd1fb8d8484601abf99 Mon Sep 17 00:00:00 2001
From: Aikar <aikar@aikar.co>
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<String>());
@@ -44,6 +45,7 @@ public abstract class Command {
         this.usageMessage = usageMessage;
         this.aliases = aliases;
         this.activeAliases = new ArrayList<String>(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<String> TIMINGS_SUBCOMMANDS = ImmutableList.of("merged", "reset", "separate");
+    private static final List<String> 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 <reset|merged|separate>";
+        this.description = "Manages Spigot Timings data to see performance of the server."; // Spigot
+        this.usageMessage = "/timings <reset|report|on|off|paste>"; // 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..6611342 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<String, Class<?>> classes = new HashMap<String, Class<?>>();
     private final Map<String, PluginClassLoader> loaders = new LinkedHashMap<String, PluginClassLoader>();
+    public static final CustomTimingsHandler pluginParentTimer = new CustomTimingsHandler("** Plugins"); // Spigot
 
     /**
      * This class was not meant to be constructed explicitly
@@ -283,13 +285,16 @@ 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;
                         }
+                        timings.startTiming(); // Spigot
                         method.invoke(listener, event);
+                        timings.stopTiming(); // Spigot
                     } catch (InvocationTargetException ex) {
                         throw new EventException(ex.getCause());
                     } catch (Throwable t) {
@@ -297,7 +302,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<CustomTimingsHandler> HANDLERS = new ConcurrentLinkedQueue<CustomTimingsHandler>();
+    /*========================================================================*/
+    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