From 4cdb6027b5b0d2e713519aba887e9dc54408a485 Mon Sep 17 00:00:00 2001 From: asofold Date: Thu, 6 Dec 2012 01:58:57 +0100 Subject: [PATCH] Add lag measurement to TickTask + command. It allows showing average lag covering any period within the last 80 ticks, and also tracks 80 times the sum of 80 ticks, covering 270 seconds roughly. Also lag spikes over 150 ms and over 1000 ms are counted for one hour (ActionFrequency with 3x20 minutes). A judgment for the current tick freezing can be done getting the last time for running the tick task. (Needs to be put to use, yet.) --- plugin.yml | 3 + .../neatmonster/nocheatplus/NoCheatPlus.java | 3 + .../nocheatplus/command/CommandHandler.java | 14 ++- .../nocheatplus/command/admin/LagCommand.java | 42 +++++++ .../nocheatplus/permissions/Permissions.java | 5 +- .../nocheatplus/utilities/CheckUtils.java | 10 ++ .../nocheatplus/utilities/TickTask.java | 103 +++++++++++++++++- 7 files changed, 170 insertions(+), 10 deletions(-) create mode 100644 src/fr/neatmonster/nocheatplus/command/admin/LagCommand.java diff --git a/plugin.yml b/plugin.yml index 188121e3..82b2d499 100644 --- a/plugin.yml +++ b/plugin.yml @@ -16,6 +16,7 @@ commands: usage: | Administrative commands overview: / reload: reload NoCheatPlus configuration + / lag: Lag related info [expect changes] / info (player): Display the violations of a player / removeplayer (player) [(check type)]: Remove data / exemptions (player) [(check type)]: Show exemptions @@ -50,6 +51,8 @@ permissions: description: Allow use of the ncp kick command. nocheatplus.admin.kicklist: description: Allow use of the ncp kicklist command. + nocheatplus.admin.lag: + description: Allow use of the ncp lag command. nocheatplus.admin.tell: description: Allow use of the ncp tell command. nocheatplus.admin.delay: diff --git a/src/fr/neatmonster/nocheatplus/NoCheatPlus.java b/src/fr/neatmonster/nocheatplus/NoCheatPlus.java index 8190983f..4dff3e62 100644 --- a/src/fr/neatmonster/nocheatplus/NoCheatPlus.java +++ b/src/fr/neatmonster/nocheatplus/NoCheatPlus.java @@ -396,6 +396,9 @@ public class NoCheatPlus extends JavaPlugin implements NoCheatPlusAPI { * |_____|_| |_|\__,_|_.__/|_|\___| */ + // Reset TickTask (just in case). + TickTask.reset(); + // Read the configuration files. ConfigManager.init(this); diff --git a/src/fr/neatmonster/nocheatplus/command/CommandHandler.java b/src/fr/neatmonster/nocheatplus/command/CommandHandler.java index f2e323b0..b2f3f60e 100644 --- a/src/fr/neatmonster/nocheatplus/command/CommandHandler.java +++ b/src/fr/neatmonster/nocheatplus/command/CommandHandler.java @@ -29,6 +29,7 @@ import fr.neatmonster.nocheatplus.command.admin.CommandsCommand; import fr.neatmonster.nocheatplus.command.admin.ExemptCommand; import fr.neatmonster.nocheatplus.command.admin.ExemptionsCommand; import fr.neatmonster.nocheatplus.command.admin.InfoCommand; +import fr.neatmonster.nocheatplus.command.admin.LagCommand; import fr.neatmonster.nocheatplus.command.admin.ReloadCommand; import fr.neatmonster.nocheatplus.command.admin.RemovePlayerCommand; import fr.neatmonster.nocheatplus.command.admin.UnexemptCommand; @@ -101,19 +102,20 @@ public class CommandHandler implements TabExecutor { // Register sub commands: for (NCPCommand cmd : new NCPCommand[]{ new BanCommand(plugin), + new CommandsCommand(plugin), new DelayCommand(plugin), + new ExemptCommand(plugin), + new ExemptionsCommand(plugin), new InfoCommand(plugin), new KickCommand(plugin), + new KickListCommand(plugin), + new LagCommand(plugin), new ReloadCommand(plugin, notifyReload), + new RemovePlayerCommand(plugin), new TellCommand(plugin), new TempKickCommand(plugin), - new RemovePlayerCommand(plugin), - new KickListCommand(plugin), - new UnKickCommand(plugin), - new ExemptionsCommand(plugin), - new ExemptCommand(plugin), new UnexemptCommand(plugin), - new CommandsCommand(plugin), + new UnKickCommand(plugin), }){ addCommand(cmd); } diff --git a/src/fr/neatmonster/nocheatplus/command/admin/LagCommand.java b/src/fr/neatmonster/nocheatplus/command/admin/LagCommand.java new file mode 100644 index 00000000..22124d5a --- /dev/null +++ b/src/fr/neatmonster/nocheatplus/command/admin/LagCommand.java @@ -0,0 +1,42 @@ +package fr.neatmonster.nocheatplus.command.admin; + +import org.bukkit.command.Command; +import org.bukkit.command.CommandSender; + +import fr.neatmonster.nocheatplus.NoCheatPlus; +import fr.neatmonster.nocheatplus.command.NCPCommand; +import fr.neatmonster.nocheatplus.permissions.Permissions; +import fr.neatmonster.nocheatplus.utilities.CheckUtils; +import fr.neatmonster.nocheatplus.utilities.TickTask; + +public class LagCommand extends NCPCommand { + + public LagCommand(NoCheatPlus plugin) { + super(plugin, "lag", Permissions.ADMINISTRATION_LAG); + } + + @Override + public boolean onCommand(CommandSender sender, Command command, String label, String[] args) + { + long max = 50L * (1L + TickTask.lagMaxTicks) * TickTask.lagMaxTicks; + long medium = 50L * TickTask.lagMaxTicks; + long second = 1200L; + StringBuilder builder = new StringBuilder(300); + // TODO: lag spikes ! + builder.append("Lag tracking (roughly):"); + builder.append("\nAverage lag:"); + for (long ms : new long[]{second, medium, max}){ + double lag = TickTask.getLag(ms); + int p = Math.max(0, (int) ((lag - 1.0) * 100.0)); + builder.append(" " + p + "%[" + CheckUtils.fdec1.format((double) ms / 1200.0) + "s]" ); + } + builder.append("\nLast hour spikes: "); + int spikesM = TickTask.getModerateLagSpikes(); + builder.append((spikesM > 0 ? (" | " + spikesM) : " | none") + " over 150 ms"); + int spikesH = TickTask.getHeavyLagSpikes(); + builder.append((spikesH > 0 ? (" | " + spikesH) : " | none") + " of which over 1 s"); + sender.sendMessage(builder.toString()); + return true; + } + +} diff --git a/src/fr/neatmonster/nocheatplus/permissions/Permissions.java b/src/fr/neatmonster/nocheatplus/permissions/Permissions.java index 11d2a8c8..d88f7592 100644 --- a/src/fr/neatmonster/nocheatplus/permissions/Permissions.java +++ b/src/fr/neatmonster/nocheatplus/permissions/Permissions.java @@ -35,6 +35,7 @@ public class Permissions { public static final String ADMINISTRATION_COMMANDS = ADMINISTRATION + ".commands"; public static final String ADMINISTRATION_KICK = ADMINISTRATION + ".kick"; public static final String ADMINISTRATION_KICKLIST = ADMINISTRATION + ".kicklist"; + public static final String ADMINISTRATION_LAG = ADMINISTRATION + ".lag"; public static final String ADMINISTRATION_NOTIFY = ADMINISTRATION + ".notify"; public static final String ADMINISTRATION_PLUGINS = ADMINISTRATION + ".plugins"; public static final String ADMINISTRATION_RELOAD = ADMINISTRATION + ".reload"; @@ -42,9 +43,9 @@ public class Permissions { public static final String ADMINISTRATION_TELL = ADMINISTRATION + ".tell"; public static final String ADMINISTRATION_TEMPKICK = ADMINISTRATION + ".tempkick"; public static final String ADMINISTRATION_UNKICK = ADMINISTRATION + ".unkick"; + // Debug permission, for player spam (not in plugin.yml, currently). - public static final String ADMINISTRATION_DEBUG = ADMINISTRATION + ".debug"; - + public static final String ADMINISTRATION_DEBUG = ADMINISTRATION + ".debug"; // Bypasses held extra from command permissions. private final static String BYPASS = NOCHEATPLUS + ".bypass"; diff --git a/src/fr/neatmonster/nocheatplus/utilities/CheckUtils.java b/src/fr/neatmonster/nocheatplus/utilities/CheckUtils.java index 3f0e0afe..0a268234 100644 --- a/src/fr/neatmonster/nocheatplus/utilities/CheckUtils.java +++ b/src/fr/neatmonster/nocheatplus/utilities/CheckUtils.java @@ -25,13 +25,23 @@ public class CheckUtils { /** Decimal format for "#.###" */ public static final DecimalFormat fdec3 = new DecimalFormat(); + + /** Decimal format for "#.#" */ + public static final DecimalFormat fdec1 = new DecimalFormat(); static { + // 3 digits. DecimalFormatSymbols sym = fdec3.getDecimalFormatSymbols(); sym.setDecimalSeparator('.'); fdec3.setDecimalFormatSymbols(sym); fdec3.setMaximumFractionDigits(3); fdec3.setMinimumIntegerDigits(1); + // 1 digit. + sym = fdec1.getDecimalFormatSymbols(); + sym.setDecimalSeparator('.'); + fdec1.setDecimalFormatSymbols(sym); + fdec1.setMaximumFractionDigits(1); + fdec1.setMinimumIntegerDigits(1); } /** diff --git a/src/fr/neatmonster/nocheatplus/utilities/TickTask.java b/src/fr/neatmonster/nocheatplus/utilities/TickTask.java index 93da26eb..59054bc6 100644 --- a/src/fr/neatmonster/nocheatplus/utilities/TickTask.java +++ b/src/fr/neatmonster/nocheatplus/utilities/TickTask.java @@ -45,12 +45,26 @@ public class TickTask implements Runnable { } } + public static final int lagMaxTicks = 80; + /** Permissions to update: player name -> check type. */ private static final Set permissionUpdates = new LinkedHashSet(50); /** Actions to execute. */ private static final List delayedActions = new LinkedList(); + /** Last n tick durations, measured from run to run.*/ + private static final long[] tickDurations = new long[lagMaxTicks]; + + /** Tick durations summed up in packs of n (nxn time covered) */ + private static final long[] tickDurationsSq = new long[lagMaxTicks]; + + /** Lag spikes > 150 ms counting (3 x 20 minutes). */ + private static final ActionFrequency spikes150 = new ActionFrequency(3, 1000L * 60L * 20L); + + /** Lag spikes > 1000 ms counting (3 x 20 minutes). */ + private static final ActionFrequency spikes1000 = new ActionFrequency(3, 1000L * 60L * 20L); + /** Task id of the running TickTask */ protected static int taskId = -1; @@ -162,6 +176,50 @@ public class TickTask implements Runnable { return timeLast; } + /** + * Get lag percentage for the last ms milliseconds.
+ * NOTE: Will not be synchronized, still can be called from other threads. + * @return + */ + public static final float getLag(final long ms){ + // TODO: Account for freezing (i.e. check timeLast, might be an extra method)! + final int tick = TickTask.tick; + if (tick == 0) return 1f; + + final int totalTicks = Math.min(tick, 1 + (int) (ms / 50)); + final int maxTick = Math.min(lagMaxTicks, totalTicks); + long sum = tickDurations[maxTick - 1]; + long covered = maxTick * 50; + + // Only count fully covered: + if (totalTicks > lagMaxTicks){ + int maxTickSq = Math.min(lagMaxTicks, totalTicks / lagMaxTicks); + if (lagMaxTicks * maxTickSq == totalTicks) maxTickSq -= 1; + sum += tickDurationsSq[maxTickSq - 1]; + covered += lagMaxTicks * 50 * maxTickSq; + } + + return (float) sum / (float) covered; + } + + /** + * Get moderate lag spikes of the last hour (>150 ms). + * @return + */ + public static final int getModerateLagSpikes(){ + spikes150.update(System.currentTimeMillis()); + return (int) spikes150.score(1f); + } + + /** + * Get heavy lag spikes of the last hour (> 1 s). + * @return + */ + public static final int getHeavyLagSpikes(){ + spikes1000.update(System.currentTimeMillis()); + return (int) spikes1000.score(1f); + } + /** * Check if new permission update requests and actions can be added. * @return True if locked. @@ -178,6 +236,7 @@ public class TickTask implements Runnable { cancel(); taskId = Bukkit.getScheduler().scheduleSyncRepeatingTask(plugin, new TickTask(), 1, 1); if (taskId != -1) timeStart = System.currentTimeMillis(); + else timeStart = 0; return taskId; } @@ -208,6 +267,20 @@ public class TickTask implements Runnable { } } + /** + * Reset tick and tick stats to 0 (!). + */ + public static void reset(){ + tick = 0; + timeLast = 0; + for (int i = 0; i < lagMaxTicks; i++){ + tickDurations[i] = 0; + tickDurationsSq[i] = 0; + } + spikes150.clear(0); + spikes1000.clear(0); + } + ////////////////////////// // Instance methods ////////////////////////// @@ -215,20 +288,46 @@ public class TickTask implements Runnable { @Override public void run() { tick ++; - final long time = System.currentTimeMillis(); // Now sync is forced, for the ability to lock. executeActions(); updatePermissions(); + // Measure time after heavy stuff. + final long time = System.currentTimeMillis(); + final long lastDur; + // Time running backwards check (not only players can!). if (timeLast > time) { + lastDur = 50; LogUtil.logSevere("[NoCheatPlus] System time ran backwards (" + timeLast + "->" + time + "), clear all data and history..."); DataManager.clearData(CheckType.ALL); } + else{ + lastDur = time - timeLast; + } - // TODO: Lag measurement ! + // Update sums of sums of tick durations. + if (tick > 0 && (tick % lagMaxTicks) == 0){ + final long sum = tickDurations[lagMaxTicks - 1]; + for (int i = 1; i < lagMaxTicks; i++){ + tickDurationsSq[i] = tickDurationsSq[i - 1] + sum; + } + tickDurationsSq[0] = sum; + } + // Update tick duraiton sums. + for (int i = 1; i < lagMaxTicks; i++){ + tickDurations[i] = tickDurations[i - 1] + lastDur; + } + tickDurations[0] = lastDur; + + // Lag spikes150 counting. [Subject to adjustments!] + if (lastDur > 150){ + spikes150.add(time, 1f); + if (lastDur > 1000) spikes1000.add(time, 1f); + } + // Finish. timeLast = time; }