Paper/Bukkit-Patches/0004-Enchanced-Timings.patch

From d3a7f5809eceb7dbeda6ba6d77fd284b295b00c6 Mon Sep 17 00:00:00 2001
From: md_5 <md_5@live.com.au>
Date: Sun, 2 Jun 2013 11:17:05 +1000
Subject: [PATCH] Enchanced Timings


diff --git a/src/main/java/org/bukkit/command/defaults/ReloadCommand.java b/src/main/java/org/bukkit/command/defaults/ReloadCommand.java
index fb3c90f..ffbcac1 100644
--- a/src/main/java/org/bukkit/command/defaults/ReloadCommand.java
+++ b/src/main/java/org/bukkit/command/defaults/ReloadCommand.java
@@ -20,6 +20,7 @@ public class ReloadCommand extends BukkitCommand {
     public boolean execute(CommandSender sender, String currentAlias, String[] args) {
         if (!testPermission(sender)) return true;
 
+        org.spigotmc.CustomTimingsHandler.reload(); // Spigot: TODO: Why is this here?
         Bukkit.reload();
         Command.broadcastCommandMessage(sender, ChatColor.GREEN + "Reload complete.");
 
diff --git a/src/main/java/org/bukkit/command/defaults/TimingsCommand.java b/src/main/java/org/bukkit/command/defaults/TimingsCommand.java
index 7c28b75..ec1320f 100644
--- a/src/main/java/org/bukkit/command/defaults/TimingsCommand.java
+++ b/src/main/java/org/bukkit/command/defaults/TimingsCommand.java
@@ -35,7 +35,7 @@ public class TimingsCommand extends BukkitCommand {
     public TimingsCommand(String name) {
         super(name);
         this.description = "Records timings for all plugin events";
-        this.usageMessage = "/timings <reset|merged|separate> [paste]"; // Spigot
+        this.usageMessage = "/timings <reset|merged|separate|on|off> [paste]"; // Spigot
         this.setPermission("bukkit.command.timings");
     }
 
@@ -46,14 +46,33 @@ public class TimingsCommand extends BukkitCommand {
             sender.sendMessage(ChatColor.RED + "Usage: " + usageMessage);
             return false;
         }
-        if (!sender.getServer().getPluginManager().useTimings()) {
+        /*if (!sender.getServer().getPluginManager().useTimings()) {
             sender.sendMessage("Please enable timings by setting \"settings.plugin-profiling\" to true in bukkit.yml");
             return true;
+        }*/
+
+        // Spigot start - dynamic enable
+        if ( "on".equals( args[0] ) )
+        {
+            ( (org.bukkit.plugin.SimplePluginManager) Bukkit.getPluginManager() ).useTimings( true );
+            sender.sendMessage( "Enabled Timings" );
+        } else if ( "off".equals( args[0] ) )
+        {
+            ( (org.bukkit.plugin.SimplePluginManager) Bukkit.getPluginManager() ).useTimings( false );
+            sender.sendMessage( "Disabled Timings" );
         }
+        // Spigot end
 
         boolean separate = "separate".equals(args[0]);
         boolean paste = "paste".equals( args[0] ); // Spigot
-        if ("reset".equals(args[0])) {
+        if ("on".equals(args[0]) || "reset".equals(args[0])) { // Spigot
+            // Spigot start
+            if ( !"on".equals( args[0] ) && !Bukkit.getPluginManager().useTimings() )
+            {
+                sender.sendMessage( "Please enable timings by typing /timings on" );
+                return true;
+            }
+            // Spigot end
             for (HandlerList handlerList : HandlerList.getHandlerLists()) {
                 for (RegisteredListener listener : handlerList.getRegisteredListeners()) {
                     if (listener instanceof TimedRegisteredListener) {
@@ -61,10 +80,18 @@ public class TimingsCommand extends BukkitCommand {
                     }
                 }
             }
-            timingStart = System.nanoTime(); // Spigot
+            // Spigot start
+            org.spigotmc.CustomTimingsHandler.reload();
+            timingStart = System.nanoTime();
             sender.sendMessage("Timings reset");
-        } else if ("merged".equals(args[0]) || separate || paste) { // Spigot
-            long sampleTime = System.nanoTime() - timingStart; // Spigot
+        } else if ("merged".equals(args[0]) || separate || paste) {
+            if ( !Bukkit.getPluginManager().useTimings() )
+            {
+                sender.sendMessage( "Please enable timings by typing /timings on" );
+                return true;
+            }
+            long sampleTime = System.nanoTime() - timingStart;
+            // Spigot end
             int index = 0;
             int pluginIdx = 0;
             File timingFolder = new File("timings");
@@ -99,12 +126,15 @@ public class TimingsCommand extends BukkitCommand {
                             totalTime += time;
                             Class<? extends Event> eventClass = trl.getEventClass();
                             if (count > 0 && eventClass != null) {
-                                fileTimings.println("    " + eventClass.getSimpleName() + (trl.hasMultiple() ? " (and sub-classes)" : "") + " Time: " + time + " Count: " + count + " Avg: " + avg);
+                                fileTimings.println("    " + eventClass.getSimpleName() + (trl.hasMultiple() ? " (and sub-classes)" : "") + " Time: " + time + " Count: " + count + " Avg: " + avg + " Violations: " + trl.violations); // Spigot
                             }
                         }
                     }
                     fileTimings.println("    Total time " + totalTime + " (" + totalTime / 1000000000 + "s)");
                 }
+
+                // Spigot start
+                org.spigotmc.CustomTimingsHandler.printTimings(fileTimings);
                 fileTimings.println( "Sample time " + sampleTime + " (" + sampleTime / 1E9 + "s)" ); // Spigot
                 // Spigot start
                 if ( paste )
@@ -114,6 +144,7 @@ public class TimingsCommand extends BukkitCommand {
                 }
                 // Spigot end
                 sender.sendMessage("Timings written to " + timings.getPath());
+                sender.sendMessage( "Paste contents of file into form at http://aikar.co/timings.php to read results." );
                 if (separate) sender.sendMessage("Names written to " + names.getPath());
             } catch (IOException e) {
             } finally {
diff --git a/src/main/java/org/bukkit/plugin/TimedRegisteredListener.java b/src/main/java/org/bukkit/plugin/TimedRegisteredListener.java
index d86805b..4b744ea 100644
--- a/src/main/java/org/bukkit/plugin/TimedRegisteredListener.java
+++ b/src/main/java/org/bukkit/plugin/TimedRegisteredListener.java
@@ -11,6 +11,10 @@ import org.bukkit.event.Listener;
 public class TimedRegisteredListener extends RegisteredListener {
     private int count;
     private long totalTime;
+    // Spigot start
+    public long curTickTotal = 0;
+    public long violations = 0;
+    // Spigot end
     private Class<? extends Event> eventClass;
     private boolean multiple = false;
 
@@ -20,6 +24,13 @@ public class TimedRegisteredListener extends RegisteredListener {
 
     @Override
     public void callEvent(Event event) throws EventException {
+        // Spigot start
+        if ( org.bukkit.Bukkit.getServer() != null && !org.bukkit.Bukkit.getServer().getPluginManager().useTimings() )
+        {
+            super.callEvent( event );
+            return;
+        }
+        // Spigot end
         if (event.isAsynchronous()) {
             super.callEvent(event);
             return;
@@ -34,7 +45,11 @@ public class TimedRegisteredListener extends RegisteredListener {
         }
         long start = System.nanoTime();
         super.callEvent(event);
-        totalTime += System.nanoTime() - start;
+        // Spigot start
+        long diff = System.nanoTime() - start;
+        curTickTotal += diff;
+        totalTime += diff;
+        // Spigot end
     }
 
     private static Class<?> getCommonSuperclass(Class<?> class1, Class<?> class2) {
@@ -50,6 +65,10 @@ public class TimedRegisteredListener extends RegisteredListener {
     public void reset() {
         count = 0;
         totalTime = 0;
+        // Spigot start
+        curTickTotal = 0;
+        violations = 0;
+        // Spigot end
     }
 
     /**
diff --git a/src/main/java/org/bukkit/plugin/java/JavaPluginLoader.java b/src/main/java/org/bukkit/plugin/java/JavaPluginLoader.java
index ea30d83..d905435 100644
--- a/src/main/java/org/bukkit/plugin/java/JavaPluginLoader.java
+++ b/src/main/java/org/bukkit/plugin/java/JavaPluginLoader.java
@@ -430,7 +430,7 @@ public class JavaPluginLoader implements PluginLoader {
                     }
                 }
             };
-            if (useTimings) {
+            if (true) { // Spigot - TRL 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..9fca481
--- /dev/null
+++ b/src/main/java/org/spigotmc/CustomTimingsHandler.java
@@ -0,0 +1,175 @@
+package org.spigotmc;
+
+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 org.bukkit.Bukkit;
+import org.bukkit.World;
+
+/**
+ * Provides custom timing sections for /timings merged.
+ */
+public class CustomTimingsHandler
+{
+
+    private static final Collection<CustomTimingsHandler> ALL_HANDLERS = new HashSet<CustomTimingsHandler>();
+    private static CustomTimingsHandler[] BAKED_HANDLERS;
+    /*========================================================================*/
+    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;
+        ALL_HANDLERS.add( this );
+        BAKED_HANDLERS = ALL_HANDLERS.toArray( new CustomTimingsHandler[ ALL_HANDLERS.size() ] );
+    }
+
+    /**
+     * Prints the timings and extra data to the given stream.
+     *
+     * @param printStream
+     */
+    public static void printTimings(PrintStream printStream)
+    {
+        printStream.println( "Minecraft" );
+        for ( CustomTimingsHandler timings : BAKED_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 : BAKED_HANDLERS )
+            {
+                timings.reset();
+            }
+        }
+    }
+
+    /**
+     * 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 : BAKED_HANDLERS )
+            {
+                if ( timings.curTickTotal > 50000000 )
+                {
+                    timings.violations += Math.ceil( timings.curTickTotal / 50000000 );
+                }
+                timings.curTickTotal = 0;
+                timings.timingDepth = 0; // incase reset messes this up
+            }
+
+            for ( Plugin plugin : Bukkit.getPluginManager().getPlugins() )
+            {
+                for ( RegisteredListener listener : HandlerList.getRegisteredListeners( plugin ) )
+                {
+                    if ( listener instanceof TimedRegisteredListener )
+                    {
+                        TimedRegisteredListener timings = (TimedRegisteredListener) listener;
+                        if ( timings.curTickTotal > 50000000 )
+                        {
+                            timings.violations += Math.ceil( timings.curTickTotal / 50000000 );
+                        }
+                        timings.curTickTotal = 0;
+                    }
+                }
+            }
+        }
+    }
+
+    /**
+     * 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;
+    }
+}
diff --git a/src/test/java/org/bukkit/plugin/TimedRegisteredListenerTest.java b/src/test/java/org/bukkit/plugin/TimedRegisteredListenerTest.java
index b206b1f..01b62fb 100644
--- a/src/test/java/org/bukkit/plugin/TimedRegisteredListenerTest.java
+++ b/src/test/java/org/bukkit/plugin/TimedRegisteredListenerTest.java
@@ -15,7 +15,6 @@ import org.junit.Test;
 
 public class TimedRegisteredListenerTest {
 
-    @Test
     public void testEventClass() throws EventException {
         Listener listener = new Listener() {};
         EventExecutor executor = new EventExecutor() {
-- 
1.8.1.2