Reimplemented TileEntity and Entity Update Profiling in the /forge track command (#4521)

src/main/java/net/minecraftforge/server/ForgeTimeTracker.java

@@ -20,34 +20,54 @@
 package net.minecraftforge.server;
 
 import java.lang.ref.WeakReference;
-import java.util.Arrays;
 import java.util.Map;
-import java.util.Map.Entry;
 
 import com.google.common.collect.ImmutableMap;
-import com.google.common.collect.ImmutableMap.Builder;
 import com.google.common.collect.MapMaker;
 
 import net.minecraft.entity.Entity;
 import net.minecraft.tileentity.TileEntity;
+import net.minecraftforge.server.timings.TimeTracker;
 
+/**
+ * @deprecated To be removed in 1.13 - Implementation has been moved
+ * @see net.minecraftforge.server.timings.TimeTracker
+ */
+@Deprecated
 public class ForgeTimeTracker {
+    /**
+     * @deprecated To be removed in 1.13 - Implementation has been moved
+     * @see net.minecraftforge.server.timings.TimeTracker
+     */
+    @Deprecated
     public static boolean tileEntityTracking;
+
+    /**
+     * @deprecated To be removed in 1.13 - Implementation has been moved
+     * @see net.minecraftforge.server.timings.TimeTracker
+     */
+    @Deprecated
     public static int tileEntityTrackingDuration;
+
+    /**
+     * @deprecated To be removed in 1.13 - Implementation has been moved
+     * @see net.minecraftforge.server.timings.TimeTracker
+     */
+    @Deprecated
     public static long tileEntityTrackingTime;
-    
+
     private Map<TileEntity,int[]> tileEntityTimings;
     private WeakReference<TileEntity> tile;
-    
+
     private static final ForgeTimeTracker INSTANCE = new ForgeTimeTracker();
 
     /* not implemented
     private WeakReference<Entity> entity;
     private Map<Entity,int[]> entityTimings;
     */
-    
+
     private long timing;
-    
+
     private ForgeTimeTracker()
     {
         MapMaker mm = new MapMaker();
@@ -55,7 +75,7 @@ public class ForgeTimeTracker {
         tileEntityTimings = mm.makeMap();
         //entityTimings = mm.makeMap();
     }
-    
+
 
     private void trackTileStart(TileEntity tileEntity, long nanoTime)
     {
@@ -67,7 +87,7 @@ public class ForgeTimeTracker {
         {
             tileEntityTracking = false;
             tileEntityTrackingTime = 0;
-            
+
             return;
         }
         tile = new WeakReference<TileEntity>(tileEntity);
@@ -88,42 +108,61 @@ public class ForgeTimeTracker {
         timings[idx] = (int) (nanoTime - timing);
     }
 
+    /**
+     * @deprecated To be removed in 1.13 - Implementation has been moved
+     * @see TimeTracker#getTimingData()
+     */
+    @Deprecated
     public static ImmutableMap<TileEntity,int[]> getTileTimings()
     {
         return INSTANCE.buildImmutableTileEntityTimingMap();
     }
-    
+
     private ImmutableMap<TileEntity, int[]> buildImmutableTileEntityTimingMap()
     {
-        Builder<TileEntity, int[]> builder = ImmutableMap.builder();
-        for (Entry<TileEntity, int[]> entry : tileEntityTimings.entrySet())
-        {
-            builder.put(entry.getKey(), Arrays.copyOfRange(entry.getValue(), 0, 100));
-        }
+        ImmutableMap.Builder<TileEntity, int[]> builder = new ImmutableMap.Builder<>();
+        TimeTracker.TILE_ENTITY_UPDATE.getTimingData().stream()
+                .filter(t -> t.getObject().get() != null).forEach(e -> builder.put(e.getObject().get(), e.getRawTimingData()));
         return builder.build();
     }
 
-
+    /**
+     * @deprecated To be removed in 1.13 - Implementation has been moved
+     * @see TimeTracker#trackStart(Object)
+     */
+    @Deprecated
     public static void trackStart(TileEntity tileEntity)
     {
-        if (!tileEntityTracking) return;
-        INSTANCE.trackTileStart(tileEntity, System.nanoTime());
+        TimeTracker.TILE_ENTITY_UPDATE.trackStart(tileEntity);
     }
 
+    /**
+     * @deprecated To be removed in 1.13 - Implementation has been moved
+     * @see TimeTracker#trackEnd(Object)
+     */
+    @Deprecated
     public static void trackEnd(TileEntity tileEntity)
     {
-        if (!tileEntityTracking) return;
-        INSTANCE.trackTileEnd(tileEntity, System.nanoTime());
+        TimeTracker.TILE_ENTITY_UPDATE.trackEnd(tileEntity);
     }
 
+    /**
+     * @deprecated To be removed in 1.13 - Implementation has been moved
+     * @see TimeTracker#trackStart(Object)
+     */
+    @Deprecated
     public static void trackStart(Entity par1Entity)
     {
-        
     }
 
+    /**
+     * @deprecated To be removed in 1.13 - Implementation has been moved
+     * @see TimeTracker#trackEnd(Object)
+     */
+    @Deprecated
     public static void trackEnd(Entity par1Entity)
     {
-        
+
     }
 
 }

src/main/java/net/minecraftforge/server/command/CommandTrack.java

@@ -19,19 +19,42 @@
 package net.minecraftforge.server.command;
 
 import javax.annotation.Nullable;
+import java.text.DecimalFormat;
+import java.util.ArrayList;
+import java.util.Arrays;
 import java.util.Collections;
+import java.util.Comparator;
 import java.util.List;
 
 import net.minecraft.command.CommandBase;
 import net.minecraft.command.CommandException;
 import net.minecraft.command.ICommandSender;
 import net.minecraft.command.WrongUsageException;
+import net.minecraft.entity.Entity;
 import net.minecraft.server.MinecraftServer;
+import net.minecraft.tileentity.TileEntity;
+import net.minecraft.util.ResourceLocation;
 import net.minecraft.util.math.BlockPos;
-import net.minecraftforge.server.ForgeTimeTracker;
+import net.minecraft.util.text.ITextComponent;
+import net.minecraft.world.DimensionType;
+import net.minecraftforge.common.DimensionManager;
+import net.minecraftforge.server.timings.ForgeTimings;
+import net.minecraftforge.server.timings.TimeTracker;
 
-class CommandTrack extends CommandBase
+class CommandTrack extends CommandTreeBase
 {
+
+    private static final DecimalFormat TIME_FORMAT = new DecimalFormat("#####0.00");
+
+    public CommandTrack()
+    {
+        addSubcommand(new StartTrackingCommand());
+        addSubcommand(new ResetTrackingCommand());
+        addSubcommand(new TrackResultsTileEntity());
+        addSubcommand(new TrackResultsEntity());
+        addSubcommand(new CommandTreeHelp(this));
+    }
+
     @Override
     public String getName()
     {
@@ -47,38 +70,289 @@ class CommandTrack extends CommandBase
     @Override
     public String getUsage(ICommandSender sender)
     {
-        return "commands.forge.usage.tracking";
+        return "commands.forge.tracking.usage";
     }
 
-    @Override
-    public void execute(MinecraftServer server, ICommandSender sender, String[] args) throws CommandException
+    private static class StartTrackingCommand extends CommandBase
     {
-        if (args.length != 2)
-        {
-            throw new WrongUsageException("commands.forge.usage.tracking");
-        }
-        String type = args[0];
-        int duration = parseInt(args[1], 1, 60);
 
-        if ("te".equals(type))
+        @Override
+        public void execute(MinecraftServer server, ICommandSender sender, String[] args) throws CommandException
         {
-            ForgeTimeTracker.tileEntityTrackingDuration = duration;
-            ForgeTimeTracker.tileEntityTracking = true;
-            sender.sendMessage(TextComponentHelper.createComponentTranslation(sender, "commands.forge.tracking.te.enabled", duration));
+            if (args.length != 2)
+            {
+                throw new WrongUsageException(getUsage(sender));
+            }
+            String type = args[0];
+            int duration = parseInt(args[1], 1, 60);
+            if ("te".equals(type))
+            {
+                TimeTracker.TILE_ENTITY_UPDATE.reset();
+                TimeTracker.TILE_ENTITY_UPDATE.enable(duration);
+                sender.sendMessage(TextComponentHelper.createComponentTranslation(sender, "commands.forge.tracking.te.enabled", duration));
+            }
+            else if ("entity".equals(type))
+            {
+                TimeTracker.ENTITY_UPDATE.reset();
+                TimeTracker.ENTITY_UPDATE.enable(duration);
+                sender.sendMessage(TextComponentHelper.createComponentTranslation(sender, "commands.forge.tracking.entity.enabled", duration));
+            }
+            else
+            {
+                throw new WrongUsageException(getUsage(sender));
+            }
         }
-        else
+
+        @Override
+        public List<String> getTabCompletions(MinecraftServer server, ICommandSender sender, String[] args, @Nullable BlockPos targetPos)
         {
-            throw new WrongUsageException("commands.forge.usage.tracking");
+            return Arrays.asList("te", "entity");
+        }
+
+        @Override
+        public String getName()
+        {
+            return "start";
+        }
+
+        @Override
+        public int getRequiredPermissionLevel()
+        {
+            return 2;
+        }
+
+        @Override
+        public String getUsage(ICommandSender sender)
+        {
+            return "commands.forge.tracking.start.usage";
         }
     }
 
-    @Override
-    public List<String> getTabCompletions(MinecraftServer server, ICommandSender sender, String[] args, @Nullable BlockPos targetPos)
+    private static class ResetTrackingCommand extends CommandBase
     {
-        if (args.length == 1)
+        @Override
+        public String getName()
         {
-            return Collections.singletonList("te");
+            return "reset";
+        }
+
+        @Override
+        public String getUsage(ICommandSender sender)
+        {
+            return "commands.forge.tracking.reset.usage";
+        }
+
+        @Override
+        public int getRequiredPermissionLevel()
+        {
+            return 2;
+        }
+
+        @Override
+        public void execute(MinecraftServer server, ICommandSender sender, String[] args) throws CommandException
+        {
+            if (args.length != 1)
+            {
+                throw new WrongUsageException(getUsage(sender));
+            }
+            String type = args[0];
+            if ("te".equals(type))
+            {
+                TimeTracker.TILE_ENTITY_UPDATE.reset();
+                sender.sendMessage(TextComponentHelper.createComponentTranslation(sender, "commands.forge.tracking.reset"));
+            }
+            else if ("entity".equals(type))
+            {
+                TimeTracker.ENTITY_UPDATE.reset();
+                sender.sendMessage(TextComponentHelper.createComponentTranslation(sender, "commands.forge.tracking.reset"));
+            }
+            else
+            {
+                throw new WrongUsageException(getUsage(sender));
+            }
+        }
+
+        @Override
+        public List<String> getTabCompletions(MinecraftServer server, ICommandSender sender, String[] args, @Nullable BlockPos targetPos)
+        {
+            return Arrays.asList("te", "entity");
+        }
+    }
+
+    /**
+     * A base command for all the tracking results commands
+     *
+     * @param <T>
+     */
+    private static abstract class TrackResultsBaseCommand<T> extends CommandBase
+    {
+
+        private TimeTracker<T> tracker;
+
+        protected TrackResultsBaseCommand(TimeTracker<T> tracker)
+        {
+            this.tracker = tracker;
+        }
+
+        /**
+         * Returns the time objects recorded by the time tracker sorted by average time
+         *
+         * @return A list of time objects
+         */
+        protected List<ForgeTimings<T>> getSortedTimings()
+        {
+            ArrayList<ForgeTimings<T>> list = new ArrayList<>();
+
+            list.addAll(tracker.getTimingData());
+            list.sort(Comparator.comparingDouble(ForgeTimings::getAverageTimings));
+            Collections.reverse(list);
+
+            return list;
+        }
+
+        @Override
+        public void execute(MinecraftServer server, ICommandSender sender, String[] args) throws CommandException
+        {
+            List<ForgeTimings<T>> timingsList = getSortedTimings();
+            if (timingsList.isEmpty())
+            {
+                sender.sendMessage(TextComponentHelper.createComponentTranslation(sender, "commands.forge.tracking.noData"));
+            }
+            else
+            {
+                timingsList.stream()
+                        .filter(timings -> timings.getObject().get() != null)
+                        .limit(10)
+                        .forEach(timings -> sender.sendMessage(buildTrackString(sender, timings))
+                        );
+            }
+        }
+
+        protected abstract ITextComponent buildTrackString(ICommandSender sender, ForgeTimings<T> data);
+
+        /**
+         * Gets the time suffix for the provided time in nanoseconds
+         *
+         * @param time The time in nanoseconds
+         * @return The time suffix
+         */
+        protected String getTimeSuffix(double time)
+        {
+            if (time < 1000)
+            {
+                return "µs";
+            }
+            else
+            {
+                return "ms";
+            }
+        }
+
+        /**
+         * Translates a world dimension ID into a name
+         *
+         * @param dimId The dimension ID
+         * @return The name of the dimension
+         */
+        protected String getWorldName(int dimId)
+        {
+            DimensionType type = DimensionManager.getProviderType(dimId);
+            if (type == null)
+            {
+                return "Dim " + dimId;
+            }
+            else
+            {
+                return type.getName();
+            }
+        }
+    }
+
+    private static class TrackResultsEntity extends TrackResultsBaseCommand<Entity>
+    {
+        public TrackResultsEntity()
+        {
+            super(TimeTracker.ENTITY_UPDATE);
+        }
+
+        @Override
+        public String getName()
+        {
+            return "entity";
+        }
+
+        @Override
+        public String getUsage(ICommandSender sender)
+        {
+            return "commands.forge.tracking.entity.usage";
+        }
+
+        @Override
+        protected ITextComponent buildTrackString(ICommandSender sender, ForgeTimings<Entity> data)
+        {
+            Entity entity = data.getObject().get();
+            if (entity == null)
+                return TextComponentHelper.createComponentTranslation(sender, "commands.forge.tracking.invalid");
+
+            BlockPos currentPos = entity.getPosition();
+            String world = getWorldName(entity.world.provider.getDimension());
+            double averageTimings = data.getAverageTimings();
+            String tickTime = (averageTimings > 1000 ? TIME_FORMAT.format(averageTimings / 1000) : TIME_FORMAT.format(averageTimings)) + getTimeSuffix(
+                    averageTimings);
+
+            return TextComponentHelper.createComponentTranslation(sender, "commands.forge.tracking.timingEntry", entity.getName(),
+                    world, currentPos.getX(), currentPos.getY(), currentPos.getZ(), tickTime);
+        }
+    }
+
+    private static class TrackResultsTileEntity extends TrackResultsBaseCommand<TileEntity>
+    {
+
+        public TrackResultsTileEntity()
+        {
+            super(TimeTracker.TILE_ENTITY_UPDATE);
+        }
+
+        @Override
+        public String getName()
+        {
+            return "te";
+        }
+
+        @Override
+        public String getUsage(ICommandSender sender)
+        {
+            return "commands.forge.tracking.te.usage";
+        }
+
+        @Override
+        protected ITextComponent buildTrackString(ICommandSender sender, ForgeTimings<TileEntity> data)
+        {
+            TileEntity te = data.getObject().get();
+            if (te == null)
+                return TextComponentHelper.createComponentTranslation(sender, "commands.forge.tracking.invalid");
+
+            String name = getTileEntityName(te);
+            BlockPos pos = te.getPos();
+
+            double averageTimings = data.getAverageTimings();
+            String tickTime = (averageTimings > 1000 ? TIME_FORMAT.format(averageTimings / 1000) : TIME_FORMAT.format(averageTimings)) + getTimeSuffix(
+                    averageTimings);
+            return TextComponentHelper
+                    .createComponentTranslation(sender, "commands.forge.tracking.timingEntry", name,
+                            getWorldName(te.getWorld().provider.getDimension()),
+                            pos.getX(), pos.getY(), pos.getZ(), tickTime);
+        }
+
+        private String getTileEntityName(TileEntity tileEntity)
+        {
+            ResourceLocation registryId = TileEntity.getKey(tileEntity.getClass());
+            if (registryId == null)
+                return tileEntity.getClass().getSimpleName();
+            else
+            {
+                return registryId.toString();
+            }
         }
-        return Collections.emptyList();
     }
 }

src/main/java/net/minecraftforge/server/timings/ForgeTimings.java

@@ -0,0 +1,80 @@
+/*
+ * Minecraft Forge
+ * Copyright (c) 2016.
+ *
+ * This library is free software; you can redistribute it and/or
+ * modify it under the terms of the GNU Lesser General Public
+ * License as published by the Free Software Foundation version 2.1
+ * of the License.
+ *
+ * This library is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
+ * Lesser General Public License for more details.
+ *
+ * You should have received a copy of the GNU Lesser General Public
+ * License along with this library; if not, write to the Free Software
+ * Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA  02110-1301  USA
+ */
+
+package net.minecraftforge.server.timings;
+
+import java.lang.ref.WeakReference;
+import java.util.Arrays;
+
+/**
+ * ForgeTimings aggregates timings data collected by {@link TimeTracker} for an Object
+ * and performs operations for interpretation of the data.
+ *
+ * @param <T>
+ */
+public class ForgeTimings<T>
+{
+
+    private WeakReference<T> object;
+
+    private int[] rawTimingData;
+
+    public ForgeTimings(T object, int[] rawTimingData)
+    {
+        this.object = new WeakReference<T>(object);
+        this.rawTimingData = rawTimingData;
+    }
+
+    /**
+     * Retrieves the object that the timings are for
+     *
+     * @return The object
+     */
+    public WeakReference<T> getObject()
+    {
+        return object;
+    }
+
+
+    /**
+     * Averages the raw timings data collected
+     *
+     * @return An average of the raw timing data
+     */
+    public double getAverageTimings()
+    {
+        double sum = 0.0;
+
+        for (int data : rawTimingData)
+        {
+            sum += data;
+        }
+
+        return sum / rawTimingData.length;
+    }
+
+    /**
+     * Returns a copy of the raw timings data collected by the tracker
+     * @return The raw timing data
+     * @deprecated Added for compatibility, remove in 1.13
+     */
+    public int[] getRawTimingData(){
+        return Arrays.copyOfRange(rawTimingData, 0, rawTimingData.length);
+    }
+}

src/main/java/net/minecraftforge/server/timings/TimeTracker.java

@@ -0,0 +1,145 @@
+/*
+ * Minecraft Forge
+ * Copyright (c) 2016.
+ *
+ * This library is free software; you can redistribute it and/or
+ * modify it under the terms of the GNU Lesser General Public
+ * License as published by the Free Software Foundation version 2.1
+ * of the License.
+ *
+ * This library is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
+ * Lesser General Public License for more details.
+ *
+ * You should have received a copy of the GNU Lesser General Public
+ * License along with this library; if not, write to the Free Software
+ * Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA  02110-1301  USA
+ */
+
+package net.minecraftforge.server.timings;
+
+import java.lang.ref.WeakReference;
+import java.util.Arrays;
+import java.util.Map;
+import java.util.concurrent.TimeUnit;
+
+import com.google.common.collect.ImmutableList;
+import com.google.common.collect.MapMaker;
+
+import net.minecraft.entity.Entity;
+import net.minecraft.tileentity.TileEntity;
+
+/**
+ * A class to assist in the collection of data to measure the update times of ticking objects {currently Tile Entities and Entities}
+ *
+ * @param <T>
+ */
+public class TimeTracker<T>
+{
+
+    /**
+     * A tracker for timing tile entity update
+     */
+    public static final TimeTracker<TileEntity> TILE_ENTITY_UPDATE = new TimeTracker<>();
+    /**
+     * A tracker for timing entity updates
+     */
+    public static final TimeTracker<Entity> ENTITY_UPDATE = new TimeTracker<>();
+
+    private boolean enabled;
+    private int trackingDuration;
+    private Map<T, int[]> timings = new MapMaker().weakKeys().makeMap();
+    private WeakReference<T> currentlyTracking;
+    private long trackTime;
+    private long timing;
+
+    /**
+     * Returns the timings data recorded by the tracker
+     *
+     * @return An immutable list of timings data collected by this tracker
+     */
+    public ImmutableList<ForgeTimings<T>> getTimingData()
+    {
+        ImmutableList.Builder<ForgeTimings<T>> builder = ImmutableList.builder();
+
+        for (Map.Entry<T, int[]> entry : timings.entrySet())
+        {
+            builder.add(new ForgeTimings<>(entry.getKey(), Arrays.copyOfRange(entry.getValue(), 0, 99)));
+        }
+        return builder.build();
+    }
+
+    /**
+     * Resets the tracker (clears timings and stops any in-progress timings)
+     */
+    public void reset()
+    {
+        enabled = false;
+        trackTime = 0;
+        timings.clear();
+    }
+
+    /**
+     * Ends the timing of the currently tracking object
+     *
+     * @param tracking The object to stop timing
+     */
+    public void trackEnd(T tracking)
+    {
+        if (!enabled)
+            return;
+        this.trackEnd(tracking, System.nanoTime());
+    }
+
+    /**
+     * Starts recording tracking data for the given duration in seconds
+     *
+     * @param duration The duration for the time to track
+     */
+    public void enable(int duration)
+    {
+        this.trackingDuration = duration;
+        this.enabled = true;
+    }
+
+    /**
+     * Starts timing of the provided object
+     *
+     * @param toTrack The object to start timing
+     */
+    public void trackStart(T toTrack)
+    {
+        if (!enabled)
+            return;
+        this.trackStart(toTrack, System.nanoTime());
+    }
+
+    private void trackEnd(T object, long nanoTime)
+    {
+        if (currentlyTracking == null || currentlyTracking.get() != object)
+        {
+            currentlyTracking = null;
+            return;
+        }
+        int[] timings = this.timings.computeIfAbsent(object, k -> new int[101]);
+        int idx = timings[100] = (timings[100] + 1) % 100;
+        timings[idx] = (int) (nanoTime - timing);
+    }
+
+    private void trackStart(T toTrack, long nanoTime)
+    {
+        if (trackTime == 0)
+        {
+            trackTime = nanoTime;
+        }
+        else if (trackTime + TimeUnit.NANOSECONDS.convert(trackingDuration, TimeUnit.SECONDS) < nanoTime)
+        {
+            enabled = false;
+            trackTime = 0;
+        }
+
+        currentlyTracking = new WeakReference<>(toTrack);
+        timing = nanoTime;
+    }
+}