From a5a929cfee543a7e70b46c81e2ff3a18447012c1 Mon Sep 17 00:00:00 2001 From: md_5 Date: Sun, 2 Jun 2013 11:17:05 +1000 Subject: [PATCH] Enchanced Timings diff --git a/src/main/java/org/bukkit/command/defaults/ReloadCommand.java b/src/main/java/org/bukkit/command/defaults/ReloadCommand.java index fb3c90f..ffbcac1 100644 --- a/src/main/java/org/bukkit/command/defaults/ReloadCommand.java +++ b/src/main/java/org/bukkit/command/defaults/ReloadCommand.java @@ -20,6 +20,7 @@ public class ReloadCommand extends BukkitCommand { public boolean execute(CommandSender sender, String currentAlias, String[] args) { if (!testPermission(sender)) return true; + org.spigotmc.CustomTimingsHandler.reload(); // Spigot: TODO: Why is this here? 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 7c28b75..ec1320f 100644 --- a/src/main/java/org/bukkit/command/defaults/TimingsCommand.java +++ b/src/main/java/org/bukkit/command/defaults/TimingsCommand.java @@ -35,7 +35,7 @@ public class TimingsCommand extends BukkitCommand { public TimingsCommand(String name) { super(name); this.description = "Records timings for all plugin events"; - this.usageMessage = "/timings [paste]"; // Spigot + this.usageMessage = "/timings [paste]"; // Spigot this.setPermission("bukkit.command.timings"); } @@ -46,14 +46,33 @@ public class TimingsCommand extends BukkitCommand { sender.sendMessage(ChatColor.RED + "Usage: " + usageMessage); return false; } - if (!sender.getServer().getPluginManager().useTimings()) { + /*if (!sender.getServer().getPluginManager().useTimings()) { sender.sendMessage("Please enable timings by setting \"settings.plugin-profiling\" to true in bukkit.yml"); return true; + }*/ + + // Spigot start - dynamic enable + if ( "on".equals( args[0] ) ) + { + ( (org.bukkit.plugin.SimplePluginManager) Bukkit.getPluginManager() ).useTimings( true ); + sender.sendMessage( "Enabled Timings" ); + } else if ( "off".equals( args[0] ) ) + { + ( (org.bukkit.plugin.SimplePluginManager) Bukkit.getPluginManager() ).useTimings( false ); + sender.sendMessage( "Disabled Timings" ); } + // Spigot end boolean separate = "separate".equals(args[0]); boolean paste = "paste".equals( args[0] ); // Spigot - if ("reset".equals(args[0])) { + if ("on".equals(args[0]) || "reset".equals(args[0])) { // Spigot + // Spigot start + if ( !"on".equals( args[0] ) && !Bukkit.getPluginManager().useTimings() ) + { + sender.sendMessage( "Please enable timings by typing /timings on" ); + return true; + } + // Spigot end for (HandlerList handlerList : HandlerList.getHandlerLists()) { for (RegisteredListener listener : handlerList.getRegisteredListeners()) { if (listener instanceof TimedRegisteredListener) { @@ -61,10 +80,18 @@ public class TimingsCommand extends BukkitCommand { } } } - timingStart = System.nanoTime(); // Spigot + // Spigot start + org.spigotmc.CustomTimingsHandler.reload(); + timingStart = System.nanoTime(); sender.sendMessage("Timings reset"); - } else if ("merged".equals(args[0]) || separate || paste) { // Spigot - long sampleTime = System.nanoTime() - timingStart; // Spigot + } else if ("merged".equals(args[0]) || separate || paste) { + if ( !Bukkit.getPluginManager().useTimings() ) + { + sender.sendMessage( "Please enable timings by typing /timings on" ); + return true; + } + long sampleTime = System.nanoTime() - timingStart; + // Spigot end int index = 0; int pluginIdx = 0; File timingFolder = new File("timings"); @@ -99,12 +126,15 @@ public class TimingsCommand extends BukkitCommand { totalTime += time; Class eventClass = trl.getEventClass(); if (count > 0 && eventClass != null) { - fileTimings.println(" " + eventClass.getSimpleName() + (trl.hasMultiple() ? " (and sub-classes)" : "") + " Time: " + time + " Count: " + count + " Avg: " + avg); + fileTimings.println(" " + eventClass.getSimpleName() + (trl.hasMultiple() ? " (and sub-classes)" : "") + " Time: " + time + " Count: " + count + " Avg: " + avg + " Violations: " + trl.violations); // Spigot } } } fileTimings.println(" Total time " + totalTime + " (" + totalTime / 1000000000 + "s)"); } + + // Spigot start + org.spigotmc.CustomTimingsHandler.printTimings(fileTimings); fileTimings.println( "Sample time " + sampleTime + " (" + sampleTime / 1E9 + "s)" ); // Spigot // Spigot start if ( paste ) @@ -114,6 +144,7 @@ public class TimingsCommand extends BukkitCommand { } // Spigot end sender.sendMessage("Timings written to " + timings.getPath()); + sender.sendMessage( "Paste contents of file into form at http://aikar.co/timings.php to read results." ); if (separate) sender.sendMessage("Names written to " + names.getPath()); } catch (IOException e) { } finally { diff --git a/src/main/java/org/bukkit/plugin/TimedRegisteredListener.java b/src/main/java/org/bukkit/plugin/TimedRegisteredListener.java index e09234c..ab2c65e 100644 --- a/src/main/java/org/bukkit/plugin/TimedRegisteredListener.java +++ b/src/main/java/org/bukkit/plugin/TimedRegisteredListener.java @@ -11,6 +11,10 @@ import org.bukkit.event.Listener; public class TimedRegisteredListener extends RegisteredListener { private int count; private long totalTime; + // Spigot start + public long curTickTotal = 0; + public long violations = 0; + // Spigot end private Class eventClass; private boolean multiple = false; @@ -20,6 +24,13 @@ public class TimedRegisteredListener extends RegisteredListener { @Override public void callEvent(Event event) throws EventException { + // Spigot start + if ( org.bukkit.Bukkit.getServer() != null && !org.bukkit.Bukkit.getServer().getPluginManager().useTimings() ) + { + super.callEvent( event ); + return; + } + // Spigot end if (event.isAsynchronous()) { super.callEvent(event); return; @@ -34,7 +45,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 } private static Class getCommonSuperclass(Class class1, Class class2) { @@ -50,6 +65,10 @@ public class TimedRegisteredListener extends RegisteredListener { public void reset() { count = 0; totalTime = 0; + // Spigot start + curTickTotal = 0; + violations = 0; + // Spigot end } /** diff --git a/src/main/java/org/bukkit/plugin/java/JavaPluginLoader.java b/src/main/java/org/bukkit/plugin/java/JavaPluginLoader.java index 57681dc..075695c 100644 --- a/src/main/java/org/bukkit/plugin/java/JavaPluginLoader.java +++ b/src/main/java/org/bukkit/plugin/java/JavaPluginLoader.java @@ -323,7 +323,7 @@ public final 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())); diff --git a/src/main/java/org/spigotmc/CustomTimingsHandler.java b/src/main/java/org/spigotmc/CustomTimingsHandler.java new file mode 100644 index 0000000..9fca481 --- /dev/null +++ b/src/main/java/org/spigotmc/CustomTimingsHandler.java @@ -0,0 +1,175 @@ +package org.spigotmc; + +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 org.bukkit.Bukkit; +import org.bukkit.World; + +/** + * Provides custom timing sections for /timings merged. + */ +public class CustomTimingsHandler +{ + + private static final Collection ALL_HANDLERS = new HashSet(); + private static CustomTimingsHandler[] BAKED_HANDLERS; + /*========================================================================*/ + 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; + ALL_HANDLERS.add( this ); + BAKED_HANDLERS = ALL_HANDLERS.toArray( new CustomTimingsHandler[ ALL_HANDLERS.size() ] ); + } + + /** + * Prints the timings and extra data to the given stream. + * + * @param printStream + */ + public static void printTimings(PrintStream printStream) + { + printStream.println( "Minecraft" ); + for ( CustomTimingsHandler timings : BAKED_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 : BAKED_HANDLERS ) + { + timings.reset(); + } + } + } + + /** + * 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 : BAKED_HANDLERS ) + { + if ( timings.curTickTotal > 50000000 ) + { + timings.violations += Math.ceil( timings.curTickTotal / 50000000 ); + } + timings.curTickTotal = 0; + timings.timingDepth = 0; // incase reset messes this up + } + + 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 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; + } +} diff --git a/src/test/java/org/bukkit/plugin/TimedRegisteredListenerTest.java b/src/test/java/org/bukkit/plugin/TimedRegisteredListenerTest.java index b206b1f..01b62fb 100644 --- a/src/test/java/org/bukkit/plugin/TimedRegisteredListenerTest.java +++ b/src/test/java/org/bukkit/plugin/TimedRegisteredListenerTest.java @@ -15,7 +15,6 @@ import org.junit.Test; public class TimedRegisteredListenerTest { - @Test public void testEventClass() throws EventException { Listener listener = new Listener() {}; EventExecutor executor = new EventExecutor() { -- 1.8.3.2