From 9fefede017b0a318fb123c975c54f85095be677c 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
---
src/main/java/org/bukkit/CustomTimingsHandler.java | 134 ++++++++++++++++++++
.../org/bukkit/command/defaults/ReloadCommand.java | 2 +
.../bukkit/command/defaults/TimingsCommand.java | 90 ++++++++++++--
.../org/bukkit/plugin/TimedRegisteredListener.java | 12 ++-
.../org/bukkit/plugin/java/JavaPluginLoader.java | 2 +-
5 files changed, 227 insertions(+), 13 deletions(-)
create mode 100644 src/main/java/org/bukkit/CustomTimingsHandler.java
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.7.0.4