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

@@ -16,6 +16,7 @@ commands:
         usage: |
                Administrative commands overview:
                /<command> reload: reload NoCheatPlus configuration
+               /<command> lag: Lag related info [expect changes] 
                /<command> info (player): Display the violations of a player
                /<command> removeplayer (player) [(check type)]: Remove data
                /<command> 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:

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);
         

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);
         }

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;
+	}
+
+}

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";

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);
 	}
 
 	/**

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<PermissionUpdateEntry> permissionUpdates = new LinkedHashSet<PermissionUpdateEntry>(50);
 	
 	/** Actions to execute. */
 	private static final List<ViolationData> delayedActions = new LinkedList<ViolationData>();
 	
+	/** 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.<br>
+	 * 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;
 	}