Upstream/Paper
1
0
Fork 0
mirror of https://github.com/PaperMC/Paper.git synced 2024-11-22 10:35:38 +01:00
Code Issues Projects Releases Wiki Activity
44927fdaa6
Paper/Bukkit-Patches/0003-Improved-Timings-System.patch
Aikar e9950b70d3 Overhaul to Timings and Entity Activation Range 
This greatly extends the timings improvements I've done in recent commits, and brings timings to fully cover the entire tick.
The timings system also now tracks when specific timings causes the server to lose TPS.
The timings are also able to be turned on "on demand", meaning you do not need to restart the server to enable them.

This commit also overhauls the Entity Activation Range feature, fixing bugs, adding more immunities, and improving the performance of it.
It also fixes a regression with a recent Spigot commit that broke the entire Entity Activation Range feature.

This commit had to move the Tick Loop patch before timings because there was a change done there to time the entire tick, so lots of renames.

These 2 commits had to be bundled together to simplify applying them and reduce redundant conflict resolution.
2013-02-27 07:29:33 +11:00

412 lines
18 KiB
Diff
Raw Blame History

From 1d2352eb83a0e0cd6ff7cd592999430d37a8513a 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 10fc26a..9c7288e 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.1.1
Reference in New Issue View Git Blame Copy Permalink