From 33ffd896356f9cff9cde44e093bade06e801e39c Mon Sep 17 00:00:00 2001 From: Aikar 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 allList = new ConcurrentLinkedQueue(); + + 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 TIMINGS_SUBCOMMANDS = ImmutableList.of("merged", "reset", "separate"); + private static final List 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 "; + this.usageMessage = "/timings "; // 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