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

By: Aikar <aikar@aikar.co>

paper-api/src/main/java/org/bukkit/Bukkit.java

@@ -868,6 +868,7 @@ public final class Bukkit {
      */
     public static void reload() {
         server.reload();
+        org.spigotmc.CustomTimingsHandler.reload(); // Spigot
     }
 
     /**

paper-api/src/main/java/org/bukkit/Server.java

@@ -1856,6 +1856,10 @@ public interface Server extends PluginMessageRecipient {
     // Spigot start
     public class Spigot {
 
+        @NotNull
+        public org.bukkit.configuration.file.YamlConfiguration getConfig() {
+            throw new UnsupportedOperationException("Not supported yet.");
+        }
     }
 
     @NotNull

paper-api/src/main/java/org/bukkit/command/Command.java

@@ -33,6 +33,7 @@ public abstract class Command {
     protected String usageMessage;
     private String permission;
     private String permissionMessage;
+    public org.spigotmc.CustomTimingsHandler timings; // Spigot
 
     protected Command(@NotNull String name) {
         this(name, "", "/" + name, new ArrayList<String>());
@@ -46,6 +47,7 @@ public abstract class Command {
         this.usageMessage = (usageMessage == null) ? "/" + name : usageMessage;
         this.aliases = aliases;
         this.activeAliases = new ArrayList<String>(aliases);
+        this.timings = new org.spigotmc.CustomTimingsHandler("** Command: " + name); // Spigot
     }
 
     /**
@@ -243,6 +245,7 @@ public abstract class Command {
         }
         this.nextLabel = name;
         if (!isRegistered()) {
+            this.timings = new org.spigotmc.CustomTimingsHandler("** Command: " + name); // Spigot
             this.label = name;
             return true;
         }

paper-api/src/main/java/org/bukkit/command/SimpleCommandMap.java

@@ -145,11 +145,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);
         }
 

paper-api/src/main/java/org/bukkit/command/defaults/TimingsCommand.java

@@ -18,23 +18,102 @@ import org.bukkit.plugin.TimedRegisteredListener;
 import org.bukkit.util.StringUtil;
 import org.jetbrains.annotations.NotNull;
 
+// Spigot start
+// CHECKSTYLE:OFF
+import java.io.ByteArrayOutputStream;
+import java.io.OutputStream;
+import java.net.HttpURLConnection;
+import java.net.URL;
+import java.util.logging.Level;
+import org.bukkit.command.RemoteConsoleCommandSender;
+import org.bukkit.plugin.SimplePluginManager;
+import org.spigotmc.CustomTimingsHandler;
+// CHECKSTYLE:ON
+// 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(@NotNull 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(@NotNull CommandSender sender, @NotNull 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)");
+
+                fileTimings.println("<spigotConfig>");
+                fileTimings.println(Bukkit.spigot().getConfig().saveToString());
+                fileTimings.println("</spigotConfig>");
+
+                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(@NotNull CommandSender sender, @NotNull String currentAlias, @NotNull String[] args) {
         if (!testPermission(sender)) return true;
-        if (args.length != 1) {
+        if (args.length < 1) { // Spigot
             sender.sendMessage(ChatColor.RED + "Usage: " + usageMessage);
             return false;
         }
+        // Spigot start
+        if (true) {
+            executeSpigotTimings(sender, args);
+            return true;
+        }
+        // Spigot end
         if (!sender.getServer().getPluginManager().useTimings()) {
             sender.sendMessage("Please enable timings by setting \"settings.plugin-profiling\" to true in bukkit.yml");
             return true;
@@ -122,4 +201,50 @@ 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(@NotNull CommandSender sender, @NotNull 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("https://timings.spigotmc.org/paste").openConnection();
+                con.setDoOutput(true);
+                con.setRequestMethod("POST");
+                con.setInstanceFollowRedirects(false);
+
+                OutputStream out = con.getOutputStream();
+                out.write(bout.toByteArray());
+                out.close();
+
+                com.google.gson.JsonObject location = new com.google.gson.Gson().fromJson(new java.io.InputStreamReader(con.getInputStream()), com.google.gson.JsonObject.class);
+                con.getInputStream().close();
+
+                String pasteID = location.get("key").getAsString();
+                sender.sendMessage(ChatColor.GREEN + "Timings results can be viewed at https://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
 }

paper-api/src/main/java/org/bukkit/plugin/SimplePluginManager.java

@@ -370,6 +370,7 @@ public final class SimplePluginManager implements PluginManager {
             }
         }
 
+        org.bukkit.command.defaults.TimingsCommand.timingStart = System.nanoTime(); // Spigot
         return result.toArray(new Plugin[result.size()]);
     }
 

paper-api/src/main/java/org/bukkit/plugin/java/JavaPluginLoader.java

@@ -43,6 +43,7 @@ import org.bukkit.plugin.TimedRegisteredListener;
 import org.bukkit.plugin.UnknownDependencyException;
 import org.jetbrains.annotations.NotNull;
 import org.jetbrains.annotations.Nullable;
+import org.spigotmc.CustomTimingsHandler; // Spigot
 import org.yaml.snakeyaml.error.YAMLException;
 
 /**
@@ -53,6 +54,7 @@ public final class JavaPluginLoader implements PluginLoader {
     private final Pattern[] fileFilters = new Pattern[]{Pattern.compile("\\.jar$")};
     private final List<PluginClassLoader> loaders = new CopyOnWriteArrayList<PluginClassLoader>();
     private final LibraryLoader libraryLoader;
+    public static final CustomTimingsHandler pluginParentTimer = new CustomTimingsHandler("** Plugins"); // Spigot
 
     /**
      * This class was not meant to be constructed explicitly
@@ -290,6 +292,7 @@ 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() {
                 @Override
                 public void execute(@NotNull Listener listener, @NotNull Event event) throws EventException {
@@ -297,7 +300,12 @@ public final class JavaPluginLoader implements PluginLoader {
                         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) {
@@ -305,7 +313,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()));

paper-api/src/main/java/org/spigotmc/CustomTimingsHandler.java

@@ -0,0 +1,137 @@
+package org.spigotmc;
+
+import java.io.PrintStream;
+import java.util.Queue;
+import java.util.concurrent.ConcurrentLinkedQueue;
+import org.bukkit.Bukkit;
+import org.bukkit.World;
+import org.bukkit.command.defaults.TimingsCommand;
+import org.jetbrains.annotations.NotNull;
+import org.jetbrains.annotations.Nullable;
+
+/**
+ * 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(@NotNull String name) {
+        this(name, null);
+    }
+
+    public CustomTimingsHandler(@NotNull String name, @Nullable CustomTimingsHandler parent) {
+        this.name = name;
+        this.parent = parent;
+        HANDLERS.add(this);
+    }
+
+    /**
+     * Prints the timings and extra data to the given stream.
+     *
+     * @param printStream output stream
+     */
+    public static void printTimings(@NotNull 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;
+    }
+}

paper-api/src/main/java/org/spigotmc/package-info.java

@@ -0,0 +1,4 @@
+/**
+ * Spigot-specific classes.
+ */
+package org.spigotmc;