From 0000000000000000000000000000000000000000 Mon Sep 17 00:00:00 2001
From: Aikar <aikar@aikar.co>
Date: Sun, 2 Jun 2013 10:42:57 +1000
Subject: [PATCH] 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
diff --git a/src/main/java/org/bukkit/Bukkit.java b/src/main/java/org/bukkit/Bukkit.java
index 0000000000000000000000000000000000000000..0000000000000000000000000000000000000000 100644
--- a/src/main/java/org/bukkit/Bukkit.java
+++ b/src/main/java/org/bukkit/Bukkit.java
@@ -0,0 +0,0 @@ public final class Bukkit {
*/
public static void reload() {
server.reload();
+ org.spigotmc.CustomTimingsHandler.reload(); // Spigot
}
/**
@@ -0,0 +0,0 @@ public final class Bukkit {
public static UnsafeValues getUnsafe() {
return server.getUnsafe();
}
+
+ public static Server.Spigot spigot()
+ {
+ return server.spigot();
+ }
}
diff --git a/src/main/java/org/bukkit/Server.java b/src/main/java/org/bukkit/Server.java
index 0000000000000000000000000000000000000000..0000000000000000000000000000000000000000 100644
--- a/src/main/java/org/bukkit/Server.java
+++ b/src/main/java/org/bukkit/Server.java
@@ -0,0 +0,0 @@ public interface Server extends PluginMessageRecipient {
*/
@Deprecated
UnsafeValues getUnsafe();
+
+ public class Spigot
+ {
+
+ public org.bukkit.configuration.file.YamlConfiguration getConfig()
+ {
+ throw new UnsupportedOperationException( "Not supported yet." );
+ }
+ }
+
+ Spigot spigot();
}
diff --git a/src/main/java/org/bukkit/command/Command.java b/src/main/java/org/bukkit/command/Command.java
index 0000000000000000000000000000000000000000..0000000000000000000000000000000000000000 100644
--- a/src/main/java/org/bukkit/command/Command.java
+++ b/src/main/java/org/bukkit/command/Command.java
@@ -0,0 +0,0 @@ public abstract class Command {
protected String usageMessage;
private String permission;
private String permissionMessage;
+ public org.spigotmc.CustomTimingsHandler timings; // Spigot
protected Command(String name) {
this(name, "", "/" + name, new ArrayList<String>());
@@ -0,0 +0,0 @@ public abstract class Command {
this.usageMessage = usageMessage;
this.aliases = aliases;
this.activeAliases = new ArrayList<String>(aliases);
+ this.timings = new org.spigotmc.CustomTimingsHandler("** Command: " + name); // Spigot
}
/**
@@ -0,0 +0,0 @@ public abstract class Command {
public boolean setLabel(String name) {
this.nextLabel = name;
if (!isRegistered()) {
+ this.timings = new org.spigotmc.CustomTimingsHandler("** Command: " + name); // Spigot
this.label = name;
return true;
}
diff --git a/src/main/java/org/bukkit/command/SimpleCommandMap.java b/src/main/java/org/bukkit/command/SimpleCommandMap.java
index 0000000000000000000000000000000000000000..0000000000000000000000000000000000000000 100644
--- a/src/main/java/org/bukkit/command/SimpleCommandMap.java
+++ b/src/main/java/org/bukkit/command/SimpleCommandMap.java
@@ -0,0 +0,0 @@ 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);
}
diff --git a/src/main/java/org/bukkit/command/defaults/TimingsCommand.java b/src/main/java/org/bukkit/command/defaults/TimingsCommand.java
index 0000000000000000000000000000000000000000..0000000000000000000000000000000000000000 100644
--- a/src/main/java/org/bukkit/command/defaults/TimingsCommand.java
+++ b/src/main/java/org/bukkit/command/defaults/TimingsCommand.java
@@ -0,0 +0,0 @@ import org.bukkit.util.StringUtil;
import com.google.common.collect.ImmutableList;
+// Spigot start
+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;
+
+import org.bukkit.command.RemoteConsoleCommandSender;
+import org.bukkit.plugin.SimplePluginManager;
+import org.spigotmc.CustomTimingsHandler;
+// 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(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(CommandSender sender, 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(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 (true) { executeSpigotTimings(sender, args); return true; } // Spigot
if (!sender.getServer().getPluginManager().useTimings()) {
sender.sendMessage("Please enable timings by setting \"settings.plugin-profiling\" to true in bukkit.yml");
return true;
@@ -0,0 +0,0 @@ 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 synchronized void start() {
+ if (sender instanceof RemoteConsoleCommandSender) {
+ run();
+ } else {
+ super.start();
+ }
+ }
+
+ @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 + "Timings results can be viewed at http://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
}
diff --git a/src/main/java/org/bukkit/plugin/SimplePluginManager.java b/src/main/java/org/bukkit/plugin/SimplePluginManager.java
index 0000000000000000000000000000000000000000..0000000000000000000000000000000000000000 100644
--- a/src/main/java/org/bukkit/plugin/SimplePluginManager.java
+++ b/src/main/java/org/bukkit/plugin/SimplePluginManager.java
@@ -0,0 +0,0 @@ public final class SimplePluginManager implements PluginManager {
}
}
+ org.bukkit.command.defaults.TimingsCommand.timingStart = System.nanoTime(); // Spigot
return result.toArray(new Plugin[result.size()]);
}
diff --git a/src/main/java/org/bukkit/plugin/java/JavaPluginLoader.java b/src/main/java/org/bukkit/plugin/java/JavaPluginLoader.java
index 0000000000000000000000000000000000000000..0000000000000000000000000000000000000000 100644
--- a/src/main/java/org/bukkit/plugin/java/JavaPluginLoader.java
+++ b/src/main/java/org/bukkit/plugin/java/JavaPluginLoader.java
@@ -0,0 +0,0 @@ import org.bukkit.plugin.PluginLoader;
import org.bukkit.plugin.RegisteredListener;
import org.bukkit.plugin.TimedRegisteredListener;
import org.bukkit.plugin.UnknownDependencyException;
+import org.spigotmc.CustomTimingsHandler; // Spigot
import org.yaml.snakeyaml.error.YAMLException;
/**
@@ -0,0 +0,0 @@ public final class JavaPluginLoader implements PluginLoader {
private final Pattern[] fileFilters = new Pattern[] { Pattern.compile("\\.jar$"), };
private final Map<String, Class<?>> classes = new HashMap<String, Class<?>>();
private final Map<String, PluginClassLoader> loaders = new LinkedHashMap<String, PluginClassLoader>();
+ public static final CustomTimingsHandler pluginParentTimer = new CustomTimingsHandler("** Plugins"); // Spigot
/**
* This class was not meant to be constructed explicitly
@@ -0,0 +0,0 @@ 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() {
public void execute(Listener listener, Event event) throws EventException {
try {
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) {
@@ -0,0 +0,0 @@ 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()));
diff --git a/src/main/java/org/spigotmc/CustomTimingsHandler.java b/src/main/java/org/spigotmc/CustomTimingsHandler.java
new file mode 100644
index 0000000000000000000000000000000000000000..0000000000000000000000000000000000000000
--- /dev/null
+++ b/src/main/java/org/spigotmc/CustomTimingsHandler.java
@@ -0,0 +0,0 @@
+package org.spigotmc;
+
+import org.bukkit.command.defaults.TimingsCommand;
+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 java.util.List;
+import java.util.Queue;
+import java.util.concurrent.ConcurrentLinkedQueue;
+
+import org.bukkit.Bukkit;
+import org.bukkit.World;
+
+/**
+ * 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(String name)
+ {
+ this( name, null );
+ }
+
+ public CustomTimingsHandler(String name, CustomTimingsHandler parent)
+ {
+ this.name = name;
+ this.parent = parent;
+ HANDLERS.add( this );
+ }
+
+ /**
+ * Prints the timings and extra data to the given stream.
+ *
+ * @param printStream
+ */
+ public static void printTimings(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;
+ }
+}
--