Add more metrics to chunk loading (for testing)

src/main/java/org/dynmap/bukkit/DynmapPlugin.java

@@ -955,7 +955,11 @@ public class DynmapPlugin extends JavaPlugin implements DynmapAPI {
         else {
             dsender = new BukkitCommandSender(sender);
         }
-        return core.processCommand(dsender, cmd.getName(), commandLabel, args);
+        boolean rslt = core.processCommand(dsender, cmd.getName(), commandLabel, args);
+        if (commandLabel.equals("dynmap") && (args.length > 0) && (args[0].equals("stats"))) {
+            NewMapChunkCache.dumpStats(sender);
+        }
+        return rslt;
     }
 
     

src/main/java/org/dynmap/bukkit/NewMapChunkCache.java

@@ -8,6 +8,7 @@ import java.util.Map;
 import org.bukkit.World;
 import org.bukkit.Chunk;
 import org.bukkit.block.Biome;
+import org.bukkit.command.CommandSender;
 import org.bukkit.ChunkSnapshot;
 import org.dynmap.DynmapChunk;
 import org.dynmap.DynmapCore;
@@ -804,9 +805,44 @@ public class NewMapChunkCache implements MapChunkCache {
         return ss;
     }
 
+    public enum TimeStep {
+        loadChunk,
+        getChunkAt,
+        getChunkSnapshot,
+        getTileEntityData,
+        unloadChunkNoSave,
+        unloadChunkRequest,
+        isChunkLoaded,
+        isInUnloadQueue,
+        getEmptyChunkSnapshot,
+        getSnapshotCache,
+        putSnapshotCache,
+        loadLoop,
+        loadCalls
+    }
+    public static long[] timetot = new long[16];
+    public static long[] cnttot = new long[16];
+    public static long[] timestart = new long[16];
+    
+    private static final void startTime(TimeStep idx) {
+        timestart[idx.ordinal()] = System.nanoTime();
+    }
+    private static final void stopTime(TimeStep idx) {
+        int ord = idx.ordinal();
+        timetot[ord] += System.nanoTime() - timestart[ord];
+        cnttot[ord]++;
+    }
+    public static void dumpStats(CommandSender sender) {
+        for (TimeStep ts : TimeStep.values()) {
+            sender.sendMessage("  " + ts + ": " + timetot[ts.ordinal()] + "ns, " + cnttot[ts.ordinal()] + " calls, " + (0.001 * timetot[ts.ordinal()] / cnttot[ts.ordinal()]) + "us/call" );
+        }
+    }
+    
     public int loadChunks(int max_to_load) {
         if(dw.isLoaded() == false)
             return 0;
+        startTime(TimeStep.loadCalls);
+
         long t0 = System.nanoTime();
         Object queue = helper.getUnloadQueue(helper.getNMSWorld(w));
         
@@ -818,6 +854,8 @@ public class NewMapChunkCache implements MapChunkCache {
         //boolean isnormral = w.getEnvironment() == Environment.NORMAL;
         // Load the required chunks.
         while((cnt < max_to_load) && iterator.hasNext()) {
+            startTime(TimeStep.loadLoop);
+            
             DynmapChunk chunk = iterator.next();
             boolean vis = true;
             if(visible_limits != null) {
@@ -841,7 +879,10 @@ public class NewMapChunkCache implements MapChunkCache {
             ChunkSnapshot ss = null;
             long inhabited_ticks = 0;
             DynIntHashMap tileData = null;
+            startTime(TimeStep.getSnapshotCache);
             SnapshotRec ssr = DynmapPlugin.plugin.sscache.getSnapshot(dw.getName(), chunk.x, chunk.z, blockdata, biome, biomeraw, highesty); 
+            stopTime(TimeStep.getSnapshotCache);
+
             if(ssr != null) {
                 ss = ssr.ss;
                 inhabited_ticks = ssr.inhabitedTicks;
@@ -857,32 +898,47 @@ public class NewMapChunkCache implements MapChunkCache {
                 snaparray[idx] = ss;
                 snaptile[idx] = ssr.tileData;
                 inhabitedTicks[idx] = inhabited_ticks;
+                stopTime(TimeStep.loadLoop);
 
                 continue;
             }
             chunks_attempted++;
+            startTime(TimeStep.isChunkLoaded);
             boolean wasLoaded = w.isChunkLoaded(chunk.x, chunk.z);
+            stopTime(TimeStep.isChunkLoaded);
             boolean didload = false;
             boolean isunloadpending = false;
             if (queue != null) {
+                startTime(TimeStep.isInUnloadQueue);
                 isunloadpending = helper.isInUnloadQueue(queue, chunk.x, chunk.z);
+                stopTime(TimeStep.isInUnloadQueue);
             }
             if (isunloadpending) {  /* Workaround: can't be pending if not loaded */
                 wasLoaded = true;
             }
+            try {
+                startTime(TimeStep.loadChunk);
                 try {
                didload = w.loadChunk(chunk.x, chunk.z, false);
+                } finally {
+                    stopTime(TimeStep.loadChunk);
+                }
             } catch (Throwable t) { /* Catch chunk error from Bukkit */
                 Log.warning("Bukkit error loading chunk " + chunk.x + "," + chunk.z + " on " + w.getName());
                 if(!wasLoaded) {    /* If wasn't loaded, we loaded it if it now is */
+                    startTime(TimeStep.isChunkLoaded);
                     didload = w.isChunkLoaded(chunk.x, chunk.z);
+                    stopTime(TimeStep.isChunkLoaded);
                 }
             }
             /* If it did load, make cache of it */
             if(didload) {
                 tileData = new DynIntHashMap();
 
+                startTime(TimeStep.getChunkAt);
                 Chunk c = w.getChunkAt(chunk.x, chunk.z);   /* Get the chunk */
+                stopTime(TimeStep.getChunkAt);
+
                 /* Get inhabited ticks count */
                 inhabited_ticks = helper.getInhabitedTicks(c);
                 if(!vis) {
@@ -895,11 +951,14 @@ public class NewMapChunkCache implements MapChunkCache {
                 }
                 else {
                     if(blockdata || highesty) {
+                        startTime(TimeStep.getChunkSnapshot);
                         ss = c.getChunkSnapshot(highesty, biome, biomeraw);
+                        stopTime(TimeStep.getChunkSnapshot);
                         if(use_spout) {
                             ss = checkSpoutData(c, ss);
                         }
                         /* Get tile entity data */
+                        startTime(TimeStep.getTileEntityData);
                         List<Object> vals = new ArrayList<Object>();
                         Map<?,?> tileents = helper.getTileEntitiesForChunk(c);
                         for(Object t : tileents.values()) {
@@ -928,15 +987,21 @@ public class NewMapChunkCache implements MapChunkCache {
                                 }
                             }
                         }
+                        stopTime(TimeStep.getTileEntityData);
                     }
-                    else
+                    else {
+                        startTime(TimeStep.getEmptyChunkSnapshot);
                         ss = w.getEmptyChunkSnapshot(chunk.x, chunk.z, biome, biomeraw);
+                        stopTime(TimeStep.getEmptyChunkSnapshot);
+                    }
                     if(ss != null) {
                         ssr = new SnapshotRec();
                         ssr.ss = ss;
                         ssr.inhabitedTicks = inhabited_ticks;
                         ssr.tileData = tileData;
+                        startTime(TimeStep.putSnapshotCache);
                         DynmapPlugin.plugin.sscache.putSnapshot(dw.getName(), chunk.x, chunk.z, ssr, blockdata, biome, biomeraw, highesty);
+                        stopTime(TimeStep.putSnapshotCache);
                     }
                 }
                 int chunkIndex = (chunk.x-x_min) + (chunk.z - z_min)*x_dim;
@@ -953,13 +1018,18 @@ public class NewMapChunkCache implements MapChunkCache {
                      * while the actual in-use chunk area for a player where the chunks are managed
                      * by the MC base server is 21x21 (or about a 160 block radius).
                      * Also, if we did generate it, need to save it */
+                    startTime(TimeStep.unloadChunkNoSave);
                     helper.unloadChunkNoSave(w, c, chunk.x, chunk.z);
+                    stopTime(TimeStep.unloadChunkNoSave);
                 }
                 else if (isunloadpending) { /* Else, if loaded and unload is pending */
+                    startTime(TimeStep.unloadChunkRequest);
                     w.unloadChunkRequest(chunk.x, chunk.z); /* Request new unload */
+                    stopTime(TimeStep.unloadChunkRequest);
                 }
             }
             cnt++;
+            stopTime(TimeStep.loadLoop);
         }
         DynmapCore.setIgnoreChunkLoads(false);
 
@@ -974,6 +1044,7 @@ public class NewMapChunkCache implements MapChunkCache {
             }
         }
         total_loadtime += System.nanoTime() - t0;
+        stopTime(TimeStep.loadCalls);
 
         return cnt;
     }