Re-enable the vanilla debug MethodProfiler and /debug command

This is highly useful for profiling vanilla code, and in some cases plugin code.  It is somewhat expensive, though, which is why it was initially disabled.

I chose to use a system property instead of a configuration setting because 1) the MethodProfiler is exclusive to CraftBukkit and not part of the general API (the timings system is the general API equivalent), and 2) using a static final boolean property _may_ allow the JITter to optimize out the methods when disabled (though I'm not sure of it).

There are several changes to fix cases where the profiler code was broken slightly by other craftbukkit changes.  All of cases have been fixed, except for the block entity ticking one, due to the cost of the getSimpleName call.  For that, a ticking entry is used instead, so that time spent actually ticking the block entities can be compared with time processing the list.

This (effectively) reverts 7dde6cc566.

nms-patches/CommandDebug.patch

@@ -0,0 +1,32 @@
+--- a/net/minecraft/server/CommandDebug.java
++++ b/net/minecraft/server/CommandDebug.java
+@@ -32,6 +32,14 @@
+     }
+ 
+     public void execute(MinecraftServer minecraftserver, ICommandListener icommandlistener, String[] astring) throws CommandException {
++        // CraftBukkit start - only allow use when enabled (so that no blank profile results occur)
++        if (!minecraftserver.methodProfiler.ENABLED) {
++            icommandlistener.sendMessage(new ChatComponentText("Vanilla debug profiling is disabled."));
++            icommandlistener.sendMessage(new ChatComponentText("To enable, restart the server with `-DenableDebugMethodProfiler=true' before `-jar'."));
++            icommandlistener.sendMessage(new ChatComponentText("Use `/timings' for plugin timings."));
++            return;
++        }
++        // CraftBukkit end
+         if (astring.length < 1) {
+             throw new ExceptionUsage("commands.debug.usage", new Object[0]);
+         } else {
+@@ -140,6 +148,13 @@
+     }
+ 
+     public List<String> tabComplete(MinecraftServer minecraftserver, ICommandListener icommandlistener, String[] astring, @Nullable BlockPosition blockposition) {
+-        return astring.length == 1 ? a(astring, new String[] { "start", "stop"}) : Collections.emptyList();
++        return astring.length == 1 ? a(astring, new String[] { "start", "stop"}) : Collections.<String>emptyList(); // CraftBukkit - decompile error
++    }
++
++    // CraftBukkit start - fix decompile error
++    @Override
++    public int compareTo(ICommand o) {
++        return a((ICommand) o);
+     }
++    // CraftBukkit end
+ }

nms-patches/Entity.patch

@@ -478,7 +478,7 @@
          }
  
      }
-@@ -1867,19 +2161,67 @@
+@@ -1867,19 +2161,70 @@
          if (!this.world.isClientSide && !this.dead) {
              this.world.methodProfiler.a("changeDimension");
              MinecraftServer minecraftserver = this.B_();
@@ -522,7 +522,10 @@
 +                return null;
 +            }
 +            exit = event.useTravelAgent() ? event.getPortalTravelAgent().findOrCreate(event.getTo()) : event.getTo();
-+            return this.teleportTo(exit, true);
++            // Need to make sure the profiler state is reset afterwards (but we still want to time the call)
++            Entity entity = this.teleportTo(exit, true);
++            this.world.methodProfiler.b();
++            return entity;
 +        }
 +        return null;
 +    }
@@ -549,7 +552,7 @@
              BlockPosition blockposition;
  
              if (i == 1) {
-@@ -1908,12 +2250,18 @@
+@@ -1908,12 +2253,18 @@
                  blockposition = new BlockPosition(this);
              }
  
@@ -569,7 +572,7 @@
                  if (j == 1 && i == 1) {
                      BlockPosition blockposition1 = worldserver1.q(worldserver1.getSpawn());
  
-@@ -1921,6 +2269,7 @@
+@@ -1921,6 +2272,7 @@
                  } else {
                      entity.setPositionRotation(blockposition, entity.yaw, entity.pitch);
                  }
@@ -577,7 +580,7 @@
  
                  boolean flag = entity.attachedToPlayer;
  
-@@ -1928,6 +2277,14 @@
+@@ -1928,13 +2280,21 @@
                  worldserver1.addEntity(entity);
                  entity.attachedToPlayer = flag;
                  worldserver1.entityJoinedWorld(entity, false);
@@ -592,7 +595,15 @@
              }
  
              this.dead = true;
-@@ -2038,6 +2395,11 @@
+             this.world.methodProfiler.b();
+             worldserver.m();
+             worldserver1.m();
+-            this.world.methodProfiler.b();
++            // this.world.methodProfiler.b(); // CraftBukkit: Moved up to keep balanced
+             return entity;
+         } else {
+             return null;
+@@ -2038,6 +2398,11 @@
      }
  
      public void setCustomName(String s) {
@@ -604,7 +615,7 @@
          this.datawatcher.set(Entity.aA, s);
      }
  
-@@ -2095,7 +2457,26 @@
+@@ -2095,7 +2460,26 @@
      }
  
      public void a(AxisAlignedBB axisalignedbb) {
@@ -632,7 +643,7 @@
      }
  
      public float getHeadHeight() {
-@@ -2269,7 +2650,7 @@
+@@ -2269,7 +2653,7 @@
          for (Iterator iterator = this.bx().iterator(); iterator.hasNext(); entity.a(oclass, set)) {
              entity = (Entity) iterator.next();
              if (oclass.isAssignableFrom(entity.getClass())) {

nms-patches/MethodProfiler.patch

@@ -1,140 +1,60 @@
 --- a/net/minecraft/server/MethodProfiler.java
 +++ b/net/minecraft/server/MethodProfiler.java
-@@ -10,130 +10,30 @@
+@@ -12,6 +12,7 @@
- import org.apache.logging.log4j.LogManager;
- import org.apache.logging.log4j.Logger;
  
-+// CraftBukkit start - Strip down to empty methods, performance cost
  public class MethodProfiler {
  
--    private static final Logger b = LogManager.getLogger();
++    public static final boolean ENABLED = Boolean.getBoolean("enableDebugMethodProfiler"); // CraftBukkit - disable unless specified in JVM arguments
--    private final List<String> c = Lists.newArrayList();
+     private static final Logger b = LogManager.getLogger();
--    private final List<Long> d = Lists.newArrayList();
+     private final List<String> c = Lists.newArrayList();
-     public boolean a;
+     private final List<Long> d = Lists.newArrayList();
--    private String e = "";
+@@ -22,12 +23,14 @@
--    private final Map<String, Long> f = Maps.newHashMap();
--
      public MethodProfiler() {}
  
      public void a() {
--        this.f.clear();
++        if (!ENABLED) return;  // CraftBukkit
--        this.e = "";
+         this.f.clear();
--        this.c.clear();
+         this.e = "";
+         this.c.clear();
      }
  
      public void a(String s) {
--        if (this.a) {
++        if (!ENABLED) return;  // CraftBukkit
--            if (this.e.length() > 0) {
+         if (this.a) {
--                this.e = this.e + ".";
+             if (this.e.length() > 0) {
--            }
+                 this.e = this.e + ".";
--
+@@ -40,6 +43,7 @@
--            this.e = this.e + s;
--            this.c.add(this.e);
--            this.d.add(Long.valueOf(System.nanoTime()));
--        }
      }
  
      public void b() {
--        if (this.a) {
++        if (!ENABLED) return;  // CraftBukkit
--            long i = System.nanoTime();
+         if (this.a) {
--            long j = ((Long) this.d.remove(this.d.size() - 1)).longValue();
+             long i = System.nanoTime();
--
+             long j = ((Long) this.d.remove(this.d.size() - 1)).longValue();
--            this.c.remove(this.c.size() - 1);
+@@ -62,7 +66,7 @@
--            long k = i - j;
--
--            if (this.f.containsKey(this.e)) {
--                this.f.put(this.e, Long.valueOf(((Long) this.f.get(this.e)).longValue() + k));
--            } else {
--                this.f.put(this.e, Long.valueOf(k));
--            }
--
--            if (k > 100000000L) {
--                MethodProfiler.b.warn("Something\'s taking too long! \'{}\' took aprox {} ms", new Object[] { this.e, Double.valueOf((double) k / 1000000.0D)});
--            }
--
--            this.e = this.c.isEmpty() ? "" : (String) this.c.get(this.c.size() - 1);
--        }
      }
  
      public List<MethodProfiler.ProfilerInfo> b(String s) {
 -        if (!this.a) {
--            return Collections.emptyList();
++        if (!ENABLED || !this.a) {  // CraftBukkit
--        } else {
+             return Collections.emptyList();
--            long i = this.f.containsKey("root") ? ((Long) this.f.get("root")).longValue() : 0L;
+         } else {
--            long j = this.f.containsKey(s) ? ((Long) this.f.get(s)).longValue() : -1L;
+             long i = this.f.containsKey("root") ? ((Long) this.f.get("root")).longValue() : 0L;
--            ArrayList arraylist = Lists.newArrayList();
+@@ -128,11 +132,13 @@
--
--            if (s.length() > 0) {
--                s = s + ".";
--            }
--
--            long k = 0L;
--            Iterator iterator = this.f.keySet().iterator();
--
--            while (iterator.hasNext()) {
--                String s1 = (String) iterator.next();
--
--                if (s1.length() > s.length() && s1.startsWith(s) && s1.indexOf(".", s.length() + 1) < 0) {
--                    k += ((Long) this.f.get(s1)).longValue();
--                }
--            }
--
--            float f = (float) k;
--
--            if (k < j) {
--                k = j;
--            }
--
--            if (i < k) {
--                i = k;
--            }
--
--            Iterator iterator1 = this.f.keySet().iterator();
--
--            String s2;
--
--            while (iterator1.hasNext()) {
--                s2 = (String) iterator1.next();
--                if (s2.length() > s.length() && s2.startsWith(s) && s2.indexOf(".", s.length() + 1) < 0) {
--                    long l = ((Long) this.f.get(s2)).longValue();
--                    double d0 = (double) l * 100.0D / (double) k;
--                    double d1 = (double) l * 100.0D / (double) i;
--                    String s3 = s2.substring(s.length());
--
--                    arraylist.add(new MethodProfiler.ProfilerInfo(s3, d0, d1));
--                }
--            }
--
--            iterator1 = this.f.keySet().iterator();
--
--            while (iterator1.hasNext()) {
--                s2 = (String) iterator1.next();
--                this.f.put(s2, Long.valueOf(((Long) this.f.get(s2)).longValue() * 999L / 1000L));
--            }
--
--            if ((float) k > f) {
--                arraylist.add(new MethodProfiler.ProfilerInfo("unspecified", (double) ((float) k - f) * 100.0D / (double) k, (double) ((float) k - f) * 100.0D / (double) i));
--            }
--
--            Collections.sort(arraylist);
--            arraylist.add(0, new MethodProfiler.ProfilerInfo(s, 100.0D, (double) k * 100.0D / (double) i));
--            return arraylist;
--        }
-+        return null;
      }
  
      public void c(String s) {
--        this.b();
++        if (!ENABLED) return;  // CraftBukkit
--        this.a(s);
+         this.b();
+         this.a(s);
      }
  
      public String c() {
--        return this.c.size() == 0 ? "[UNKNOWN]" : (String) this.c.get(this.c.size() - 1);
++        if (!ENABLED) return "[DISABLED]";  // CraftBukkit
-+        return "";
+         return this.c.size() == 0 ? "[UNKNOWN]" : (String) this.c.get(this.c.size() - 1);
      }
  
-     public static final class ProfilerInfo implements Comparable<MethodProfiler.ProfilerInfo> {
+@@ -152,7 +158,7 @@
-@@ -152,7 +52,7 @@
              return methodprofiler_profilerinfo.a < this.a ? -1 : (methodprofiler_profilerinfo.a > this.a ? 1 : methodprofiler_profilerinfo.c.compareTo(this.c));
          }
  

nms-patches/PlayerList.patch

@@ -340,13 +340,13 @@
 +            if (this.players.size() >= this.maxPlayers && !this.f(gameprofile)) {
 +                event.disallow(PlayerLoginEvent.Result.KICK_FULL, "The server is full");
 +            }
-         }
++        }
 +
 +        cserver.getPluginManager().callEvent(event);
 +        if (event.getResult() != PlayerLoginEvent.Result.ALLOWED) {
 +            loginlistener.disconnect(event.getKickMessage());
 +            return null;
-+        }
+         }
 +        return entity;
      }
  
@@ -427,13 +427,13 @@
 +                    entityplayer1.setRespawnPosition(null, true);
 +                    entityplayer1.playerConnection.sendPacket(new PacketPlayOutGameStateChange(0, 0.0F));
 +                }
-+            }
+             }
 +
 +            if (location == null) {
 +                cworld = (CraftWorld) this.server.server.getWorlds().get(0);
 +                blockposition = cworld.getHandle().getSpawn();
 +                location = new Location(cworld, (double) ((float) blockposition.getX() + 0.5F), (double) ((float) blockposition.getY() + 0.1F), (double) ((float) blockposition.getZ() + 0.5F));
-             }
++            }
 +
 +            Player respawnPlayer = cserver.getPlayer(entityplayer1);
 +            PlayerRespawnEvent respawnEvent = new PlayerRespawnEvent(respawnPlayer, location, isBedSpawn);
@@ -597,9 +597,9 @@
 +        double d1 = entity.locZ;
 +        double d2 = 8.0D;
 +        float f = entity.yaw;
++        */
 +
 +        worldserver.methodProfiler.a("moving");
-+        */
 +        if (worldserver1.dimension == -1) {
 +            d0 = MathHelper.a(d0 / d2, worldserver1.getWorldBorder().b()+ 16.0D, worldserver1.getWorldBorder().d() - 16.0D);
 +            d1 = MathHelper.a(d1 / d2, worldserver1.getWorldBorder().c() + 16.0D, worldserver1.getWorldBorder().e() - 16.0D);
@@ -640,7 +640,7 @@
 +            */
 +        }
 +
-+        // worldserver.methodProfiler.b();
++        worldserver.methodProfiler.b();
 +        if (i != 1) {
 +            worldserver.methodProfiler.a("placing");
 +            d0 = (double) MathHelper.clamp((int) d0, -29999872, 29999872);
@@ -652,9 +652,9 @@
 +                worldserver1.addEntity(entity);
 +                worldserver1.entityJoinedWorld(entity, false);
 +            }
++            */
 +
 +            worldserver.methodProfiler.b();
-+            */
 +        }
 +
 +        // entity.spawnIn(worldserver1);
@@ -672,9 +672,9 @@
          double d1 = entity.locZ;
          double d2 = 8.0D;
          float f = entity.yaw;
++        */
  
          worldserver.methodProfiler.a("moving");
-+        */
 +        entity.setPositionRotation(exit.getX(), exit.getY(), exit.getZ(), exit.getYaw(), exit.getPitch());
 +        if (entity.isAlive()) {
 +            worldserver.entityJoinedWorld(entity, false);

nms-patches/World.patch

@@ -403,7 +403,7 @@
                  if (this.isLoaded(blockposition) && this.N.a(blockposition)) {
                      try {
 -                        this.methodProfiler.a(tileentity.getClass().getSimpleName());
-+                        this.methodProfiler.a(""/*tileentity.getClass().getSimpleName()*/); // CraftBukkit: SPIGOT-1900
++                        this.methodProfiler.a("ticking"/*tileentity.getClass().getSimpleName()*/); // CraftBukkit: SPIGOT-1900
                          ((ITickable) tileentity).F_();
                          this.methodProfiler.b();
                      } catch (Throwable throwable2) {

nms-patches/WorldServer.patch

@@ -174,11 +174,10 @@
      public void doTick() {
          super.doTick();
          if (this.getWorldData().isHardcore() && this.getDifficulty() != EnumDifficulty.HARD) {
-@@ -106,9 +221,11 @@
+@@ -107,8 +222,11 @@
-             this.f();
          }
  
--        this.methodProfiler.a("mobSpawner");
+         this.methodProfiler.a("mobSpawner");
 -        if (this.getGameRules().getBoolean("doMobSpawning") && this.worldData.getType() != WorldType.DEBUG_ALL_BLOCK_STATES) {
 -            this.spawnerCreature.a(this, this.allowMonsters, this.allowAnimals, this.worldData.getTime() % 400L == 0L);
 +        // CraftBukkit start - Only call spawner if we have players online and the world allows for mobs or animals
@@ -189,7 +188,7 @@
          }
  
          this.methodProfiler.c("chunkSource");
-@@ -137,6 +254,8 @@
+@@ -137,6 +255,8 @@
          this.portalTravelAgent.a(this.getTime());
          this.methodProfiler.b();
          this.ao();
@@ -198,7 +197,7 @@
      }
  
      @Nullable
-@@ -164,7 +283,7 @@
+@@ -164,7 +284,7 @@
  
                  if (entityhuman.isSpectator()) {
                      ++i;
@@ -207,7 +206,7 @@
                      ++j;
                  }
              }
-@@ -193,25 +312,46 @@
+@@ -193,25 +313,46 @@
      }
  
      private void c() {
@@ -258,7 +257,7 @@
  
              return false;
          } else {
-@@ -281,7 +421,7 @@
+@@ -281,7 +422,7 @@
                              entityhorseskeleton.p(true);
                              entityhorseskeleton.setAgeRaw(0);
                              entityhorseskeleton.setPosition((double) blockposition.getX(), (double) blockposition.getY(), (double) blockposition.getZ());
@@ -267,7 +266,7 @@
                              this.strikeLightning(new EntityLightning(this, (double) blockposition.getX(), (double) blockposition.getY(), (double) blockposition.getZ(), true));
                          } else {
                              this.strikeLightning(new EntityLightning(this, (double) blockposition.getX(), (double) blockposition.getY(), (double) blockposition.getZ(), false));
-@@ -297,11 +437,11 @@
+@@ -297,11 +438,11 @@
                      BlockPosition blockposition1 = blockposition.down();
  
                      if (this.v(blockposition1)) {
@@ -281,7 +280,7 @@
                      }
  
                      if (flag && this.getBiome(blockposition1).d()) {
-@@ -376,7 +516,7 @@
+@@ -376,7 +517,7 @@
      public boolean b(BlockPosition blockposition, Block block) {
          NextTickListEntry nextticklistentry = new NextTickListEntry(blockposition, block);
  
@@ -290,7 +289,7 @@
      }
  
      public void a(BlockPosition blockposition, Block block, int i) {
-@@ -415,8 +555,8 @@
+@@ -415,8 +556,8 @@
                  nextticklistentry.a(j);
              }
  
@@ -301,7 +300,7 @@
                  this.nextTickList.add(nextticklistentry);
              }
          }
-@@ -438,15 +578,15 @@
+@@ -438,15 +579,15 @@
              nextticklistentry.a((long) i + this.worldData.getTime());
          }
  
@@ -320,7 +319,7 @@
              if (this.emptyTime++ >= 300) {
                  return;
              }
-@@ -516,11 +656,17 @@
+@@ -516,11 +657,17 @@
          } else {
              int i = this.nextTickList.size();
  
@@ -340,7 +339,7 @@
                  }
  
                  this.methodProfiler.a("cleaning");
-@@ -533,8 +679,9 @@
+@@ -533,8 +680,9 @@
                          break;
                      }
  
@@ -351,7 +350,7 @@
                      this.U.add(nextticklistentry);
                  }
  
-@@ -604,7 +751,7 @@
+@@ -604,7 +752,7 @@
                  if (blockposition.getX() >= structureboundingbox.a && blockposition.getX() < structureboundingbox.d && blockposition.getZ() >= structureboundingbox.c && blockposition.getZ() < structureboundingbox.f) {
                      if (flag) {
                          if (i == 0) {
@@ -360,7 +359,7 @@
                          }
  
                          iterator.remove();
-@@ -622,6 +769,7 @@
+@@ -622,6 +770,7 @@
          return arraylist;
      }
  
@@ -368,7 +367,7 @@
      public void entityJoinedWorld(Entity entity, boolean flag) {
          if (!this.getSpawnAnimals() && (entity instanceof EntityAnimal || entity instanceof EntityWaterAnimal)) {
              entity.die();
-@@ -633,6 +781,7 @@
+@@ -633,6 +782,7 @@
  
          super.entityJoinedWorld(entity, flag);
      }
@@ -376,7 +375,7 @@
  
      private boolean getSpawnNPCs() {
          return this.server.getSpawnNPCs();
-@@ -645,7 +794,54 @@
+@@ -645,7 +795,54 @@
      protected IChunkProvider n() {
          IChunkLoader ichunkloader = this.dataManager.createChunkLoader(this.worldProvider);
  
@@ -432,7 +431,7 @@
      }
  
      public boolean a(EntityHuman entityhuman, BlockPosition blockposition) {
-@@ -707,6 +903,23 @@
+@@ -707,6 +904,23 @@
              int j = this.worldProvider.getSeaLevel();
              int k = 8;
  
@@ -456,7 +455,7 @@
              if (blockposition != null) {
                  i = blockposition.getX();
                  k = blockposition.getZ();
-@@ -716,7 +929,7 @@
+@@ -716,7 +930,7 @@
  
              int l = 0;
  
@@ -465,7 +464,7 @@
                  i += random.nextInt(64) - random.nextInt(64);
                  k += random.nextInt(64) - random.nextInt(64);
                  ++l;
-@@ -758,6 +971,7 @@
+@@ -758,6 +972,7 @@
          ChunkProviderServer chunkproviderserver = this.getChunkProviderServer();
  
          if (chunkproviderserver.e()) {
@@ -473,7 +472,7 @@
              if (iprogressupdate != null) {
                  iprogressupdate.a("Saving level");
              }
-@@ -768,7 +982,8 @@
+@@ -768,7 +983,8 @@
              }
  
              chunkproviderserver.a(flag);
@@ -483,7 +482,7 @@
              Iterator iterator = arraylist.iterator();
  
              while (iterator.hasNext()) {
-@@ -803,6 +1018,12 @@
+@@ -803,6 +1019,12 @@
              }
          }
  
@@ -496,7 +495,7 @@
          this.worldData.a(this.getWorldBorder().getSize());
          this.worldData.d(this.getWorldBorder().getCenterX());
          this.worldData.c(this.getWorldBorder().getCenterZ());
-@@ -816,9 +1037,13 @@
+@@ -816,9 +1038,13 @@
          this.worldMaps.a();
      }
  
@@ -512,7 +511,7 @@
  
      public void a(Collection<Entity> collection) {
          ArrayList arraylist = Lists.newArrayList(collection);
-@@ -837,7 +1062,7 @@
+@@ -837,7 +1063,7 @@
  
      private boolean j(Entity entity) {
          if (entity.dead) {
@@ -521,7 +520,7 @@
              return false;
          } else {
              UUID uuid = entity.getUniqueID();
-@@ -849,7 +1074,7 @@
+@@ -849,7 +1075,7 @@
                      this.f.remove(entity1);
                  } else {
                      if (!(entity instanceof EntityHuman)) {
@@ -530,7 +529,7 @@
                          return false;
                      }
  
-@@ -902,8 +1127,16 @@
+@@ -902,8 +1128,16 @@
      }
  
      public boolean strikeLightning(Entity entity) {
@@ -548,7 +547,7 @@
              return true;
          } else {
              return false;
-@@ -919,10 +1152,20 @@
+@@ -919,10 +1153,20 @@
      }
  
      public Explosion createExplosion(@Nullable Entity entity, double d0, double d1, double d2, float f, boolean flag, boolean flag1) {
@@ -569,7 +568,7 @@
          if (!flag1) {
              explosion.clearBlocks();
          }
-@@ -968,7 +1211,8 @@
+@@ -968,7 +1212,8 @@
                  BlockActionData blockactiondata = (BlockActionData) iterator.next();
  
                  if (this.a(blockactiondata)) {
@@ -579,7 +578,7 @@
                  }
              }
  
-@@ -991,6 +1235,7 @@
+@@ -991,6 +1236,7 @@
          boolean flag = this.W();
  
          super.t();
@@ -587,7 +586,7 @@
          if (this.n != this.o) {
              this.server.getPlayerList().a((Packet) (new PacketPlayOutGameStateChange(7, this.o)), this.worldProvider.getDimensionManager().getDimensionID());
          }
-@@ -1009,6 +1254,21 @@
+@@ -1009,6 +1255,21 @@
              this.server.getPlayerList().sendAll(new PacketPlayOutGameStateChange(7, this.o));
              this.server.getPlayerList().sendAll(new PacketPlayOutGameStateChange(8, this.q));
          }
@@ -609,7 +608,7 @@
  
      }
  
-@@ -1038,10 +1298,20 @@
+@@ -1038,10 +1299,20 @@
      }
  
      public void a(EnumParticle enumparticle, boolean flag, double d0, double d1, double d2, int i, double d3, double d4, double d5, double d6, int... aint) {