PaperMC/Bukkit-Patches/0003-Improved-Timings-System.patch

From 33ffd896356f9cff9cde44e093bade06e801e39c Mon Sep 17 00:00:00 2001
From: Aikar <aikar@aikar.co>
Date: Wed, 9 Jan 2013 22:18:26 -0500
Subject: [PATCH] Improved Timings System

Enables "Timings on Demand" so you can enable/disable timings without server restart.
Tracks timings on sync events a plugin registers (Single and Repeating)
Tracks how many ticks a timed area has caused the server to lose due to taking too long.
Enables automatically pasting to paste.ubuntu.com so you can quickly review the results on aikar.co/timings.php

diff --git a/src/main/java/org/bukkit/CustomTimingsHandler.java b/src/main/java/org/bukkit/CustomTimingsHandler.java
new file mode 100644
index 0000000..8c00824
--- /dev/null
+++ b/src/main/java/org/bukkit/CustomTimingsHandler.java
@@ -0,0 +1,134 @@
+package org.bukkit;
+
+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.concurrent.ConcurrentLinkedQueue;
+
+/**
+ * Provides custom timing sections for /timings merged
+ */
+public class CustomTimingsHandler {
+
+    final public String name;
+    public long count = 0;
+    public long start = 0;
+    public long timingDepth = 0;
+    public long totalTime = 0;
+    public long curTickTotal = 0;
+    public long violations = 0;
+    CustomTimingsHandler parent = null;
+
+    final public static ConcurrentLinkedQueue<CustomTimingsHandler> allList = new ConcurrentLinkedQueue<CustomTimingsHandler>();
+
+    public CustomTimingsHandler(String name) {
+        this.name = name;
+        allList.add(this);
+    }
+    public CustomTimingsHandler(String name, CustomTimingsHandler parent) {
+        this(name);
+        this.parent = parent;
+    }
+
+    /**
+     * Prints the timings and extra data to the printstream
+     * @param printStream
+     */
+    public static void printTimings(PrintStream printStream) {
+        printStream.println("Minecraft");
+        for (CustomTimingsHandler timings : allList) {
+            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.getServer().getPluginManager().useTimings()) return;
+        for (CustomTimingsHandler timings : allList) {
+            timings.reset();
+        }
+    }
+
+    /**
+     * Ticked every tick by CraftBukkit to count the number of times a timer caused TPS loss.
+     */
+    public static void tick() {
+        if (!Bukkit.getServer().getPluginManager().useTimings()) return;
+        for (CustomTimingsHandler timings : allList) {
+            if (timings.curTickTotal > 50000000) {
+                timings.violations += Math.ceil(timings.curTickTotal / 50000000);
+            }
+            timings.curTickTotal = 0;
+        }
+
+        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 (!Bukkit.getServer().getPluginManager().useTimings()) return;
+
+        if (++timingDepth != 1) {
+            return; // Already timing.
+        }
+        start = System.nanoTime();
+
+        if (parent != null && ++parent.timingDepth == 1) {
+            parent.start = start;
+        }
+    }
+
+    public void stopTiming() {
+        if (!Bukkit.getServer().getPluginManager().useTimings()) return;
+        if (--timingDepth != 0 || start == 0) {
+            return;
+        }
+        long diff = System.nanoTime() - start;
+        totalTime += diff;
+        curTickTotal += diff;
+        count++;
+        start = 0;
+        if (parent != null) {
+            parent.stopTiming();
+        }
+    }
+
+    public void reset() {
+        count = 0;
+        violations = 0;
+        curTickTotal = 0;
+        totalTime = 0;
+    }
+}
+
diff --git a/src/main/java/org/bukkit/command/defaults/ReloadCommand.java b/src/main/java/org/bukkit/command/defaults/ReloadCommand.java
index fb3c90f..89c8414 100644
--- a/src/main/java/org/bukkit/command/defaults/ReloadCommand.java
+++ b/src/main/java/org/bukkit/command/defaults/ReloadCommand.java
@@ -6,6 +6,7 @@ import org.bukkit.Bukkit;
 import org.bukkit.ChatColor;
 import org.bukkit.command.Command;
 import org.bukkit.command.CommandSender;
+import org.bukkit.CustomTimingsHandler;
 
 public class ReloadCommand extends BukkitCommand {
     public ReloadCommand(String name) {
@@ -20,6 +21,7 @@ public class ReloadCommand extends BukkitCommand {
     public boolean execute(CommandSender sender, String currentAlias, String[] args) {
         if (!testPermission(sender)) return true;
 
+        CustomTimingsHandler.reload(); // Spigot
         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 94cd62c..426f9b4 100644
--- a/src/main/java/org/bukkit/command/defaults/TimingsCommand.java
+++ b/src/main/java/org/bukkit/command/defaults/TimingsCommand.java
@@ -10,40 +10,59 @@ import org.apache.commons.lang.Validate;
 import org.bukkit.Bukkit;
 import org.bukkit.ChatColor;
 import org.bukkit.command.CommandSender;
+import org.bukkit.CustomTimingsHandler;
 import org.bukkit.event.Event;
 import org.bukkit.event.HandlerList;
 import org.bukkit.plugin.Plugin;
 import org.bukkit.plugin.RegisteredListener;
+import org.bukkit.plugin.SimplePluginManager; // Spigot
 import org.bukkit.plugin.TimedRegisteredListener;
 import org.bukkit.util.StringUtil;
 
 import com.google.common.collect.ImmutableList;
+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;
 
 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("merged", "reset", "separate", "paste", "on", "off"); // 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.usageMessage = "/timings <reset|merged|separate|paste|on|off>"; // Spigot
         this.setPermission("bukkit.command.timings");
     }
 
     @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 (!sender.getServer().getPluginManager().useTimings()) {
+        // Spigot start - this is dynamic now
+        /*if (!sender.getServer().getPluginManager().useTimings()) {
             sender.sendMessage("Please enable timings by setting \"settings.plugin-profiling\" to true in bukkit.yml");
             return true;
+        }*/
+        if ("on".equals(args[0])) {
+            ((SimplePluginManager)Bukkit.getServer().getPluginManager()).useTimings(true);
+            sender.sendMessage("Enabled Timings");
+        } else if ("off".equals(args[0])) {
+            ((SimplePluginManager)Bukkit.getServer().getPluginManager()).useTimings(false);
+            sender.sendMessage("Disabled Timings");
         }
+        // Spigot end
 
         boolean separate = "separate".equals(args[0]);
-        if ("reset".equals(args[0])) {
+        boolean paste = "paste".equals(args[0]); // Spigot
+        if ("on".equals(args[0]) || "reset".equals(args[0])) { // Spigot
+            if (!"on".equals(args[0]) && !Bukkit.getServer().getPluginManager().useTimings()) {sender.sendMessage("Please enable timings by typing /timings on"); return true; } // Spigot
             for (HandlerList handlerList : HandlerList.getHandlerLists()) {
                 for (RegisteredListener listener : handlerList.getRegisteredListeners()) {
                     if (listener instanceof TimedRegisteredListener) {
@@ -51,10 +70,11 @@ public class TimingsCommand extends BukkitCommand {
                     }
                 }
             }
+            CustomTimingsHandler.reload(); // Spigot
             timingStart = System.nanoTime(); // Spigot
             sender.sendMessage("Timings reset");
-        } else if ("merged".equals(args[0]) || separate) {
-
+        } else if ("merged".equals(args[0]) || separate || paste) { // Spigot
+            if (!Bukkit.getServer().getPluginManager().useTimings()) {sender.sendMessage("Please enable timings by typing /timings on"); return true; } // Spigot
             long sampleTime = System.nanoTime() - timingStart; // Spigot
             int index = 0;
             int pluginIdx = 0;
@@ -62,11 +82,12 @@ public class TimingsCommand extends BukkitCommand {
             timingFolder.mkdirs();
             File timings = new File(timingFolder, "timings.txt");
             File names = null;
+            ByteArrayOutputStream bout = (paste) ? new ByteArrayOutputStream() : null; // Spigot
             while (timings.exists()) timings = new File(timingFolder, "timings" + (++index) + ".txt");
             PrintStream fileTimings = null;
             PrintStream fileNames = null;
             try {
-                fileTimings = new PrintStream(timings);
+                fileTimings = (paste) ? new PrintStream(bout) : new PrintStream(timings);
                 if (separate) {
                     names = new File(timingFolder, "names" + index + ".txt");
                     fileNames = new PrintStream(names);
@@ -89,14 +110,23 @@ public class TimingsCommand extends BukkitCommand {
                             totalTime += time;
                             Event event = trl.getEvent();
                             if (count > 0 && event != null) {
-                                fileTimings.println("    " + event.getClass().getSimpleName() + (trl.hasMultiple() ? " (and others)" : "") + " Time: " + time + " Count: " + count + " Avg: " + avg);
+                                fileTimings.println("    " + event.getClass().getSimpleName() + (trl.hasMultiple() ? " (and others)" : "") + " Time: " + time + " Count: " + count + " Avg: " + avg + " Violations: " + trl.violations); // Spigot
                             }
                         }
                     }
                     fileTimings.println("    Total time " + totalTime + " (" + totalTime / 1000000000 + "s)");
                 }
-                fileTimings.println("Sample time " + sampleTime + " (" + sampleTime / 1000000000 + "s)"); // Spigot
-                sender.sendMessage("Timings written to " + timings.getPath());
+
+                // Spigot start
+                CustomTimingsHandler.printTimings(fileTimings);
+                fileTimings.println("Sample time " + sampleTime + " (" + sampleTime / 1000000000 + "s)");
+                if (paste) {
+                    new PasteThread(sender, bout).start();
+                } else {
+                    sender.sendMessage("Timings written to " + timings.getPath());
+                    sender.sendMessage("Paste contents of file into form at http://aikar.co/timings.php to read results.");
+                }
+                // Spigot end
                 if (separate) sender.sendMessage("Names written to " + names.getPath());
             } catch (IOException e) {
             } finally {
@@ -122,4 +152,42 @@ 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 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 + "Your timings have been pasted to " + location);
+                sender.sendMessage(ChatColor.GREEN + "You can view the results at http://aikar.co/timings.php?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/TimedRegisteredListener.java b/src/main/java/org/bukkit/plugin/TimedRegisteredListener.java
index ed25e17..47dab3e 100644
--- a/src/main/java/org/bukkit/plugin/TimedRegisteredListener.java
+++ b/src/main/java/org/bukkit/plugin/TimedRegisteredListener.java
@@ -1,5 +1,6 @@
 package org.bukkit.plugin;
 
+import org.bukkit.Bukkit; // Spigot
 import org.bukkit.event.Event;
 import org.bukkit.event.EventException;
 import org.bukkit.event.EventPriority;
@@ -11,6 +12,8 @@ import org.bukkit.event.Listener;
 public class TimedRegisteredListener extends RegisteredListener {
     private int count;
     private long totalTime;
+    public long curTickTotal = 0; // Spigot
+    public long violations = 0; // Spigot
     private Event event;
     private boolean multiple = false;
 
@@ -20,6 +23,7 @@ public class TimedRegisteredListener extends RegisteredListener {
 
     @Override
     public void callEvent(Event event) throws EventException {
+        if (!Bukkit.getServer().getPluginManager().useTimings()) { super.callEvent(event);return; } // Spigot
         if (event.isAsynchronous()) {
             super.callEvent(event);
             return;
@@ -33,7 +37,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
     }
 
     /**
@@ -42,6 +50,8 @@ public class TimedRegisteredListener extends RegisteredListener {
     public void reset() {
         count = 0;
         totalTime = 0;
+        curTickTotal = 0; // Spigot
+        violations = 0; // Spigot
     }
 
     /**
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()));
-- 
1.8.2.1