Added Heartbeat debug logging.

src/sig/plugin/TwosideKeeper/Boss/EliteZombie.java

@@ -549,6 +549,7 @@ public class EliteZombie extends EliteMonster{
 						b.setType(Material.AIR);
 					} else {
 						b.setType(storedblocks.get(b));
+						b.setData(storedblockdata.get(b));
 					}
 					SoundUtils.playGlobalSound(b.getLocation(), Sound.ENTITY_GENERIC_EXPLODE, 0.7f, 1.2f);
 				}

src/sig/plugin/TwosideKeeper/HelperStructures/Common/GenericFunctions.java

@@ -20,8 +20,11 @@ import org.bukkit.attribute.Attribute;
 import org.bukkit.block.Block;
 import org.bukkit.block.BlockFace;
 import org.bukkit.block.Dropper;
+import org.bukkit.block.Hopper;
 import org.bukkit.block.Sign;
 import org.bukkit.command.CommandSender;
+import org.bukkit.craftbukkit.v1_9_R1.block.CraftDropper;
+import org.bukkit.craftbukkit.v1_9_R1.block.CraftHopper;
 import org.bukkit.enchantments.Enchantment;
 import org.bukkit.entity.CaveSpider;
 import org.bukkit.entity.Entity;
@@ -59,6 +62,8 @@ import net.md_5.bungee.api.chat.ClickEvent;
 import net.md_5.bungee.api.chat.ComponentBuilder;
 import net.md_5.bungee.api.chat.HoverEvent;
 import net.md_5.bungee.api.chat.TextComponent;
+import net.minecraft.server.v1_9_R1.TileEntityDropper;
+import net.minecraft.server.v1_9_R1.TileEntityHopper;
 import sig.plugin.TwosideKeeper.ActionBarBuffUpdater;
 import sig.plugin.TwosideKeeper.Artifact;
 import sig.plugin.TwosideKeeper.AwakenedArtifact;
@@ -4971,4 +4976,15 @@ public class GenericFunctions {
 		return true;
 	}
 	
+	public static void renameDropper(Dropper dropper, String title) {
+		CraftDropper BukkitDropper = (CraftDropper) dropper;
+		TileEntityDropper NMSDropper = (TileEntityDropper) BukkitDropper.getTileEntity();
+		NMSDropper.a(title);
+	}
+	
+	public static void renameHopper(Hopper hopper, String title) {
+		CraftHopper BukkitHopper = (CraftHopper) hopper;
+		TileEntityHopper NMSHopper = (TileEntityHopper) BukkitHopper.getTileEntity();
+		NMSHopper.a(title);
+	}
 }

src/sig/plugin/TwosideKeeper/Logging/Average.java

@@ -0,0 +1,34 @@
+package sig.plugin.TwosideKeeper.Logging;
+
+public class Average {
+	int avg;
+	int count;
+	int high;
+	int low;
+	int trend;
+	int last;
+	public Average() {
+		this.avg=0;
+		this.count=0;
+		this.high=0;
+		this.low=Integer.MAX_VALUE;
+		this.trend=0;
+		this.last=0;
+	}
+	
+	public void add(int value) {
+		if (value>high) {
+			high=value;
+		} else
+		if (value<low) {
+			low=value;
+		}
+		last=value;
+		int curravg = avg;
+		avg = (((count<60?count:60) * avg) + value) / ((count<60?count:60) + 1);
+		trend += Math.signum(avg-curravg);
+		if (trend>60) {trend=60;}
+		if (trend<-60) {trend=-60;}
+		count++;
+	}
+}

src/sig/plugin/TwosideKeeper/Logging/HeartbeatLogger.java

@@ -0,0 +1,38 @@
+package sig.plugin.TwosideKeeper.Logging;
+
+import java.text.DecimalFormat;
+import java.util.HashMap;
+import java.util.LinkedHashMap;
+import java.util.Map.Entry;
+
+import org.bukkit.ChatColor;
+
+public class HeartbeatLogger {
+	LinkedHashMap<String,Average> values = new LinkedHashMap<String,Average>();
+	
+	public HeartbeatLogger() {
+		
+	}
+	
+	public void AddEntry(String name, int value) {
+		if (values.containsKey(name)) {
+			Average avg = values.get(name);
+			avg.add(value);
+		} else {
+			Average avg = new Average();
+			avg.add(value);
+			values.put(name, avg);
+		}
+	}
+	
+	public String outputReport() {
+		StringBuilder stringy = new StringBuilder("");
+		for (Entry<String,Average> ent : values.entrySet()) {
+			Average avg = ent.getValue();
+			String str = ent.getKey();
+			DecimalFormat df = new DecimalFormat("0.00");
+			stringy.append(ChatColor.AQUA+str+": ["+(avg.trend>0?"^":avg.trend==0?"-":"v")+"]"+ChatColor.YELLOW+df.format(avg.avg/1000000d)+"ms ["+avg.count+"]"+ChatColor.RED+"H:"+df.format(avg.high/1000000d)+"ms"+ChatColor.GREEN+" L:"+df.format(avg.low/1000000d)+"ms "+ChatColor.LIGHT_PURPLE+"(Last: "+df.format(avg.last/1000000d)+"ms)\n"+ChatColor.RESET);
+		}
+		return stringy.toString();
+	}
+}

src/sig/plugin/TwosideKeeper/TwosideKeeper.java

@@ -451,6 +451,7 @@ public class TwosideKeeper extends JavaPlugin implements Listener {
 	public static MysteriousEssenceLogger EssenceLogger; //The logger for Essences.
 	public static BowModeLogger BowLogger; //The logger for Bow Modes.
 	public static LootLogger Loot_Logger; //The logger for Loot.
+	public static sig.plugin.TwosideKeeper.Logging.HeartbeatLogger HeartbeatLogger; //Diagnostics for heartbeat speed.
 	//public static AutoUpdatePlugin pluginupdater;
 	public static boolean restarting_server=false;
 	public static List<String> log_messages=new ArrayList<String>();
@@ -913,6 +914,7 @@ public class TwosideKeeper extends JavaPlugin implements Listener {
 		EssenceLogger = new MysteriousEssenceLogger();
 		BowLogger = new BowModeLogger();
 		Loot_Logger = new LootLogger();
+		HeartbeatLogger = new sig.plugin.TwosideKeeper.Logging.HeartbeatLogger();
 		habitat_data = new Habitation();
 		habitat_data.loadLocationHashesFromConfig();
 		
@@ -1172,7 +1174,12 @@ public class TwosideKeeper extends JavaPlugin implements Listener {
 	    		sender.sendMessage(ChatColor.WHITE+DisplayPlayerBar());
 	    		sender.sendMessage(ChatColor.WHITE+"To view a specific player's usage, use "+ChatColor.GREEN+"\"/debugreport <name>\"");
 	    		sender.sendMessage(ChatColor.WHITE+"To view specific entities' usage, use "+ChatColor.GREEN+"\"/debugreport ALLENTS\"");
+	    		sender.sendMessage(ChatColor.WHITE+"To view heartbeat timings, use "+ChatColor.GREEN+"\"/debugreport heartbeat\"");
     		} else {
+    			if (args[0].equalsIgnoreCase("heartbeat")) {
+    				sender.sendMessage("Heartbeat Timings:");
+    				sender.sendMessage(HeartbeatLogger.outputReport());
+    			} else 
     			if (args[0].equalsIgnoreCase("ALLENTS")) {
     				sender.sendMessage("Individual Structures for all Living Entities:");
     				int count=0;

src/sig/plugin/TwosideKeeper/runServerHeartbeat.java

@@ -77,6 +77,7 @@ final class runServerHeartbeat implements Runnable {
 		
 		//SAVE SERVER SETTINGS.
 		final long serverTickTime = TwosideKeeper.getServerTickTime();
+		long time = System.nanoTime();
 		if (serverTickTime-TwosideKeeper.LASTSERVERCHECK>=TwosideKeeper.SERVERCHECKERTICKS) { //15 MINUTES (DEFAULT)
 			if (TwosideKeeper.LAST_DEAL!=Calendar.getInstance().get(Calendar.DAY_OF_WEEK)) {
 				//This means the deal of the day has to be updated!
@@ -116,6 +117,7 @@ final class runServerHeartbeat implements Runnable {
 			//End Advertisements.
 			TwosideKeeper.LASTSERVERCHECK=serverTickTime;
 		}
+		TwosideKeeper.HeartbeatLogger.AddEntry("MOTD", (int)(System.nanoTime()-time));time=System.nanoTime();
 		
 		if (Bukkit.getWorld("world").getTime()>=12000 || Bukkit.getWorld("world").isThundering()) {
 			Collection<? extends Player> players = ServerHeartbeat.getServer().getOnlinePlayers();
@@ -158,8 +160,9 @@ final class runServerHeartbeat implements Runnable {
 				ServerHeartbeat.sleepingPlayers=0;
 			}
 		}
-		
+		TwosideKeeper.HeartbeatLogger.AddEntry("Sleep Check", (int)(System.nanoTime()-time));time=System.nanoTime();
 		//See if each player needs to regenerate their health.
+		long playerchecktime = System.nanoTime();
 		for (Player p : Bukkit.getOnlinePlayers()) {
 	    	//TwosideKeeper.outputArmorDurability(p);
 			if (!p.isDead()) { 
@@ -169,11 +172,12 @@ final class runServerHeartbeat implements Runnable {
 					CustomDamage.ApplyDamage(10, null, p, null, "Orni",CustomDamage.TRUEDMG|CustomDamage.IGNORE_DAMAGE_TICK|CustomDamage.IGNOREDODGE);
 				}
 
+				TwosideKeeper.HeartbeatLogger.AddEntry("Orni", (int)(System.nanoTime()-time));time=System.nanoTime();
 				if (p.isSprinting() && pd.lastsprintcheck+(20*5)<serverTickTime) {
 					pd.lastsprintcheck=serverTickTime;
 					GenericFunctions.ApplySwiftAegis(p);
 				}
-				
+				TwosideKeeper.HeartbeatLogger.AddEntry("Swift Aegis Application", (int)(System.nanoTime()-time));time=System.nanoTime();
 				if (TwosideKeeper.banksessions.containsKey(p.getUniqueId())) {
 					//See if it expired.
 					BankSession bs = (BankSession)TwosideKeeper.banksessions.get(p.getUniqueId());
@@ -181,6 +185,7 @@ final class runServerHeartbeat implements Runnable {
 						TwosideKeeper.banksessions.remove(p.getUniqueId());
 					}
 				}
+				TwosideKeeper.HeartbeatLogger.AddEntry("Bank Session Removal", (int)(System.nanoTime()-time));time=System.nanoTime();
 				
 				/*
 				if (GenericFunctions.isRanger(p) &&
@@ -192,88 +197,125 @@ final class runServerHeartbeat implements Runnable {
 				if (TwosideKeeper.TwosideShops.PlayerHasPurchases(p)) {
 					TwosideKeeper.TwosideShops.PlayerSendPurchases(p);
 				}
+				TwosideKeeper.HeartbeatLogger.AddEntry("Purchase Notification Sending", (int)(System.nanoTime()-time));time=System.nanoTime();
 				
+				long notafktime = System.nanoTime();
 				if (!aPlugin.API.isAFK(p)) {
 					EndShopSession(p);
+					TwosideKeeper.HeartbeatLogger.AddEntry("End Shop Session", (int)(System.nanoTime()-time));time=System.nanoTime();
 					
 					GenericFunctions.RemoveNewDebuffs(p);
+					TwosideKeeper.HeartbeatLogger.AddEntry("Remove New Debuffs", (int)(System.nanoTime()-time));time=System.nanoTime();
 					
 					ModifyDasherSetSpeedMultiplier(p);
+					TwosideKeeper.HeartbeatLogger.AddEntry("Dasher Speed Multiplier", (int)(System.nanoTime()-time));time=System.nanoTime();
 					
 					ManageHighwinder(p, pd);
+					TwosideKeeper.HeartbeatLogger.AddEntry("Highwinder", (int)(System.nanoTime()-time));time=System.nanoTime();
 					RemoveInvalidTarget(p, pd);
+					TwosideKeeper.HeartbeatLogger.AddEntry("Remove Bad Target", (int)(System.nanoTime()-time));time=System.nanoTime();
 					
 					GiveArtifactBowXP(serverTickTime, p, pd);
+					TwosideKeeper.HeartbeatLogger.AddEntry("Artifact Bow XP", (int)(System.nanoTime()-time));time=System.nanoTime();
 					
 					ReduceFireResistanceDuration(p);
+					TwosideKeeper.HeartbeatLogger.AddEntry("Reduce Fire Resist", (int)(System.nanoTime()-time));time=System.nanoTime();
 					
 					ControlTheEnd(p, pd);
+					TwosideKeeper.HeartbeatLogger.AddEntry("The End", (int)(System.nanoTime()-time));time=System.nanoTime();
 
 					ItemStack[] equips = p.getEquipment().getArmorContents();
 
 					ShadowWalkerApplication(p, equips);
+					TwosideKeeper.HeartbeatLogger.AddEntry("Shadow Walker", (int)(System.nanoTime()-time));time=System.nanoTime();
 					
 					
 					//PopulatePlayerBlockList(p,15,15,2,5,false);
 					PopRandomLavaBlock(p);
+					TwosideKeeper.HeartbeatLogger.AddEntry("Pop Lava", (int)(System.nanoTime()-time));time=System.nanoTime();
 					GenericFunctions.sendActionBarMessage(p, "");
 					GenericFunctions.AutoRepairItems(p);
+					TwosideKeeper.HeartbeatLogger.AddEntry("Auto Repair", (int)(System.nanoTime()-time));time=System.nanoTime();
 					
-					if (GenericFunctions.hasStealth(p)) {GenericFunctions.DamageRandomTool(p);}
+					if (GenericFunctions.hasStealth(p)) {GenericFunctions.DamageRandomTool(p);
+					TwosideKeeper.HeartbeatLogger.AddEntry("Damage Random Tool", (int)(System.nanoTime()-time));time=System.nanoTime();}
 					
 					//See if this player is sleeping.
 					HealForSleeping(p, pd);
+					TwosideKeeper.HeartbeatLogger.AddEntry("Heal for Sleeping", (int)(System.nanoTime()-time));time=System.nanoTime();
 					
 					//We need to see if this player's damage reduction has changed recently. If so, notify them.
 					//Check damage reduction by sending an artifical "1" damage to the player.
 					ManagePlayerScoreboardAndHealth(p);
+					TwosideKeeper.HeartbeatLogger.AddEntry("Scoreboard/Health Management", (int)(System.nanoTime()-time));time=System.nanoTime();
 					
 					if (PlayerMode.isBarbarian(p)) {
 						AutoConsumeFoods(p);
+						TwosideKeeper.HeartbeatLogger.AddEntry("Auto Consume Food", (int)(System.nanoTime()-time));time=System.nanoTime();
 					}
 				}
+				TwosideKeeper.HeartbeatLogger.AddEntry(ChatColor.BOLD+"->Not AFK Functions"+ChatColor.RESET, (int)(System.nanoTime()-notafktime));
 
 				ModifyArmorBar(p);
+				TwosideKeeper.HeartbeatLogger.AddEntry("Modify Armor Bar", (int)(System.nanoTime()-time));time=System.nanoTime();
 
 				ItemStack[] equips = p.getEquipment().getArmorContents();
 				
 				ResetVendetta(serverTickTime, pd);
+				TwosideKeeper.HeartbeatLogger.AddEntry("Vendetta Reset", (int)(System.nanoTime()-time));time=System.nanoTime();
 				ResetLifestealStacks(serverTickTime, pd);	
+				TwosideKeeper.HeartbeatLogger.AddEntry("Lifesteal Reset", (int)(System.nanoTime()-time));time=System.nanoTime();
 				
 				ManagePlayerLink(p, pd);
+				TwosideKeeper.HeartbeatLogger.AddEntry("Player Link", (int)(System.nanoTime()-time));time=System.nanoTime();
 				
 				DepleteDamagePool(serverTickTime, p, pd);
+				TwosideKeeper.HeartbeatLogger.AddEntry("Damage Pool", (int)(System.nanoTime()-time));time=System.nanoTime();
 				
 				AdventurerModeSetExhaustion(p);
+				TwosideKeeper.HeartbeatLogger.AddEntry("Adventurer Mode Exhaustion", (int)(System.nanoTime()-time));time=System.nanoTime();
 				
 				//CalculateHealthRegeneration(serverTickTime, p, pd, equips);
 				
 				ResetSwordCombo(serverTickTime, p, pd); 
+				TwosideKeeper.HeartbeatLogger.AddEntry("Reset Sword Combo", (int)(System.nanoTime()-time));time=System.nanoTime();
 				
 				ResetSlayerAggro(serverTickTime, p, pd);
+				TwosideKeeper.HeartbeatLogger.AddEntry("Reset Slayer Aggro", (int)(System.nanoTime()-time));time=System.nanoTime();
 				
 				ApplyCometRegenBonus(p);
+				TwosideKeeper.HeartbeatLogger.AddEntry("Comet Regen Application", (int)(System.nanoTime()-time));time=System.nanoTime();
 				
 				DasherFoodRegenPerk(p);
+				TwosideKeeper.HeartbeatLogger.AddEntry("Dasher Food Regen", (int)(System.nanoTime()-time));time=System.nanoTime();
 				
 				GivePartyNightVision(p);
+				TwosideKeeper.HeartbeatLogger.AddEntry("Party Night Vision", (int)(System.nanoTime()-time));time=System.nanoTime();
 			}
 	    	//TwosideKeeper.outputArmorDurability(p,">");
 		}
+		TwosideKeeper.HeartbeatLogger.AddEntry(ChatColor.BOLD+"->Full Player Checks"+ChatColor.RESET, (int)(System.nanoTime()-playerchecktime));
 		
 		ManageSnowmanHunt();
+		TwosideKeeper.HeartbeatLogger.AddEntry("Snowman Hunt", (int)(System.nanoTime()-time));time=System.nanoTime();
 		
 		CheckAndAnnounceWeather();
+		TwosideKeeper.HeartbeatLogger.AddEntry("Check/Announce Weather", (int)(System.nanoTime()-time));time=System.nanoTime();
 		
 		Christmas.ChristmasHeartbeat();
+		TwosideKeeper.HeartbeatLogger.AddEntry("Christmas Heartbeat", (int)(System.nanoTime()-time));time=System.nanoTime();
 		
 		MaintainMonsterData();
+		TwosideKeeper.HeartbeatLogger.AddEntry("Monster Management", (int)(System.nanoTime()-time));time=System.nanoTime();
 		
 		PartyManager.SetupParties();
+		TwosideKeeper.HeartbeatLogger.AddEntry("Setup Parties", (int)(System.nanoTime()-time));time=System.nanoTime();
 		
 		TwosideKeeper.TwosideSpleefGames.TickEvent();
+		TwosideKeeper.HeartbeatLogger.AddEntry("Spleef Tick", (int)(System.nanoTime()-time));time=System.nanoTime();
 		
 		performTimingsReport();
+		TwosideKeeper.HeartbeatLogger.AddEntry("Server Lag Activation", (int)(System.nanoTime()-time));time=System.nanoTime();
 	}
 
 	private void ManagePlayerScoreboardAndHealth(Player p) {
@@ -540,7 +582,7 @@ final class runServerHeartbeat implements Runnable {
 		double tps = MinecraftServer.getServer().recentTps[0];
 		if (tps<18 && TwosideKeeper.lastTimingReport+36000<TwosideKeeper.getServerTickTime()) {
 			DecimalFormat df = new DecimalFormat("0.00");
-			aPlugin.API.discordSendRawItalicized("**Server is lagging.**\nCurrent TPS: **"+df.format(tps)+"**");
+			aPlugin.API.discordSendRawItalicized("**Server is lagging.**\nCurrent TPS: **"+df.format(tps)+"** (Also writing debug timings to log file)");
 			if (TwosideKeeper.getServerTickTime()-TwosideKeeper.lastTimingReport>72000) {
 				aPlugin.API.takeTimings(1200);
 			} else {
@@ -548,6 +590,9 @@ final class runServerHeartbeat implements Runnable {
 			}
 			TwosideKeeper.lastTimingReport=TwosideKeeper.getServerTickTime();
 		}
+		if (tps<18) {
+			GenericFunctions.logToFile("["+TwosideKeeper.getServerTickTime()+"] TPS: "+tps+"\n------------------\n"+TwosideKeeper.HeartbeatLogger.outputReport());
+		}
 	}
 
 	private void CheckAndAnnounceWeather() {