Add trace log messages to indicate how long each loading phase takes

minecraft/src/main/java/net/fabricmc/loader/impl/game/minecraft/Hooks.java

@@ -26,6 +26,8 @@
 import net.fabricmc.loader.impl.util.log.Log;
 import net.fabricmc.loader.impl.util.log.LogCategory;
 
+import org.spongepowered.asm.util.perf.Profiler;
+
 public final class Hooks {
 	public static final String INTERNAL_NAME = Hooks.class.getName().replace('.', '/');
 
@@ -51,6 +53,7 @@ public static void startClient(File runDir, Object gameInstance) {
 		FabricLoaderImpl.INSTANCE.prepareModInit(runDir.toPath(), gameInstance);
 		EntrypointUtils.invoke("main", ModInitializer.class, ModInitializer::onInitialize);
 		EntrypointUtils.invoke("client", ClientModInitializer.class, ClientModInitializer::onInitializeClient);
+		Profiler.printAuditSummary();
 	}
 
 	public static void startServer(File runDir, Object gameInstance) {

minecraft/src/main/java/net/fabricmc/loader/impl/game/minecraft/launchwrapper/FabricTweaker.java

@@ -28,6 +28,7 @@
 import java.nio.file.Path;
 import java.util.ArrayList;
 import java.util.Collection;
+import java.util.HashMap;
 import java.util.List;
 import java.util.Map;
 import java.util.jar.JarEntry;
@@ -217,6 +218,50 @@ public ClassLoader getTargetClassLoader() {
 		return launchClassLoader;
 	}
 
+
+	/**
+	 * Current benchmark start time
+	 */
+	private static long start;
+	/**
+	 * All recorded times
+	 */
+	private static Map<String, Time> times = new HashMap<String, Time>();
+	/**
+	 * Mutable long, so we can easily store the times in a Map
+	 */
+	static final class Time {
+		long value;
+
+		public Long asLong() {
+			return Long.valueOf(this.value);
+		}
+	}
+
+	/**
+	 * Callback from injected code, begin benchmarking a specific transformer
+	 *
+	 * @param name transformer name
+	 */
+	public static void before(String name) {
+		start = System.currentTimeMillis();
+	}
+
+	/**
+	 * Callback from injected code, end benchmarking a transformer
+	 *
+	 * @param name transformer name
+	 */
+	public static void after(String name) {
+		long elapsed = System.currentTimeMillis() - start;
+		Time time = times.get(name);
+		if (time == null) {
+			time = new Time();
+			times.put(name, time);
+		}
+		time.value += elapsed;
+	}
+
 	@Override
 	public byte[] getClassByteArray(String name, boolean runTransformers) throws IOException {
 		String transformedName = name.replace('/', '.');
@@ -228,7 +273,9 @@ public byte[] getClassByteArray(String name, boolean runTransformers) throws IOE
 					continue; // skip mixin as per method contract
 				}
 
+				before(name);
 				classBytes = transformer.transform(name, transformedName, classBytes);
+				after(name);
 			}
 		}
 

src/main/java/net/fabricmc/loader/impl/FabricLoaderImpl.java

@@ -280,7 +280,7 @@ private void setup() throws ModResolutionException {
 		}
 
 		// add mods
-
+		Log.info(LogCategory.GENERAL, "Adding %s mods", modCandidates.size());
 		for (ModCandidate mod : modCandidates) {
 			if (!mod.hasPath() && !mod.isBuiltin()) {
 				try {
@@ -299,6 +299,7 @@ private void setup() throws ModResolutionException {
 	private void finishModLoading() {
 		// add mods to classpath
 		// TODO: This can probably be made safer, but that's a long-term goal
+		Log.info(LogCategory.GENERAL, "Adding classpaths of codesources for %s mods", mods.size());
 		for (ModContainerImpl mod : mods) {
 			if (!mod.getMetadata().getId().equals(MOD_ID) && !mod.getMetadata().getType().equals("builtin")) {
 				for (Path path : mod.getCodeSourcePaths()) {
@@ -387,6 +388,7 @@ private void addMod(ModCandidate candidate) throws ModResolutionException {
 	}
 
 	private void setupLanguageAdapters() {
+		Log.info(LogCategory.KNOT, "Setting up languages.");
 		adapterMap.put("default", DefaultLanguageAdapter.INSTANCE);
 
 		for (ModContainerImpl mod : mods) {
@@ -406,6 +408,7 @@ private void setupLanguageAdapters() {
 	}
 
 	private void setupMods() {
+		Log.info(LogCategory.KNOT, "Setting up mods.");
 		for (ModContainerImpl mod : mods) {
 			try {
 				for (String in : mod.getInfo().getOldInitializers()) {
@@ -425,6 +428,7 @@ private void setupMods() {
 	}
 
 	public void loadAccessWideners() {
+		Log.info(LogCategory.KNOT, "Loading access wideners.");
 		AccessWidenerReader accessWidenerReader = new AccessWidenerReader(accessWidener);
 
 		for (net.fabricmc.loader.api.ModContainer modContainer : getAllMods()) {
@@ -444,6 +448,7 @@ public void loadAccessWideners() {
 	}
 
 	public void prepareModInit(Path newRunDir, Object gameInstance) {
+		Log.info(LogCategory.KNOT, "prepareModInit on %s dir %s.", gameInstance, newRunDir);
 		if (!frozen) {
 			throw new RuntimeException("Cannot instantiate mods when not frozen!");
 		}

src/main/java/net/fabricmc/loader/impl/discovery/RuntimeModRemapper.java

@@ -52,6 +52,7 @@
 
 public final class RuntimeModRemapper {
 	public static void remap(Collection<ModCandidate> modCandidates, Path tmpDir, Path outputDir) {
+		Log.info(LogCategory.MOD_REMAP, "Starting remapping");
 		List<ModCandidate> modsToRemap = new ArrayList<>();
 
 		for (ModCandidate mod : modCandidates) {
@@ -119,7 +120,7 @@ public static void remap(Collection<ModCandidate> modCandidates, Path tmpDir, Pa
 
 				remapper.apply(outputConsumer, info.tag);
 			}
-
+			Log.info(LogCategory.MOD_REMAP, "Performing remapping of %s mods", modsToRemap.size());
 			//Done in a 3rd loop as this can happen when the remapper is doing its thing.
 			for (ModCandidate mod : modsToRemap) {
 				RemapInfo info = infoMap.get(mod);
@@ -173,6 +174,7 @@ public static void remap(Collection<ModCandidate> modCandidates, Path tmpDir, Pa
 
 			throw new FormattedException("Failed to remap mods!", t);
 		} finally {
+			Log.info(LogCategory.MOD_REMAP, "Deleting temp inputs");
 			for (RemapInfo info : infoMap.values()) {
 				try {
 					if (info.inputIsTemp) Files.deleteIfExists(info.inputPath);

src/main/java/net/fabricmc/loader/impl/entrypoint/EntrypointUtils.java

@@ -16,9 +16,15 @@
 
 package net.fabricmc.loader.impl.entrypoint;
 
+import java.nio.file.Path;
+import java.text.DecimalFormat;
 import java.util.Collection;
 import java.util.function.Consumer;
 
+import net.fabricmc.loader.api.EntrypointException;
+
+import org.spongepowered.asm.util.perf.Profiler;
+
 import net.fabricmc.loader.api.entrypoint.EntrypointContainer;
 import net.fabricmc.loader.impl.FabricLoaderImpl;
 import net.fabricmc.loader.impl.util.ExceptionUtil;
@@ -40,19 +46,46 @@ private static <T> void invoke0(String name, Class<T> type, Consumer<? super T>
 		RuntimeException exception = null;
 		Collection<EntrypointContainer<T>> entrypoints = FabricLoaderImpl.INSTANCE.getEntrypointContainers(name, type);
 
-		Log.debug(LogCategory.ENTRYPOINT, "Iterating over entrypoint '%s'", name);
+		Profiler profiler = new Profiler("entrypoints");
+		Log.info(LogCategory.ENTRYPOINT, "Iterating over entrypoint '%s' with %s entrypoints", name, entrypoints.size());
+		profiler.mark("entrypoinscan");
+		Profiler.Section timer = profiler.begin("entrypoint");
 
 		for (EntrypointContainer<T> container : entrypoints) {
+
+			boolean hasLink = container.getProvider().getMetadata().getContact().get("sources").isPresent() && container.getProvider().getMetadata().getContact().get("sources").get().length() > 0;
+			String sourcesUrl = !hasLink ? "" : " at "+container.getProvider().getMetadata().getContact().get("sources").get();
+
+			Log.trace(LogCategory.ENTRYPOINT, "invoke %s on '%s'%s", name, container.getProvider().getMetadata().getName(), sourcesUrl);
 			try {
 				invoker.accept(container.getEntrypoint());
 			} catch (Throwable t) {
+				Throwable root = t;
+				if (root instanceof EntrypointException) {
+					root = t.getCause();
+				}
+				Log.error(LogCategory.ENTRYPOINT, "Exception during %s : '%s' : %s", name, container.getProvider().getMetadata().getName(), root);
 				exception = ExceptionUtil.gatherExceptions(t,
 						exception,
 						exc -> new RuntimeException(String.format("Could not execute entrypoint stage '%s' due to errors, provided by '%s'!",
 								name, container.getProvider().getMetadata().getId()),
 								exc));
 			}
 		}
+		timer.end();
+		long elapsedMs = timer.getTime();
+		double elapsedTime = timer.getSeconds();
+		String elapsed = new DecimalFormat("###0.000").format(elapsedTime);
+		final int total = entrypoints.size();
+		String perMixinTime = new DecimalFormat("###0.0").format(((double)elapsedMs) / total);
+		Log.info(LogCategory.ENTRYPOINT, "Entrypoint scan %s with %s points %s sec (%sms avg)", name, total, elapsed, perMixinTime);
+		/**
+		  NOTE: this scan isn't a true representation of how long the Mixing takes for the preLaunch phase!!
+		 WHY? I DON'T KNOW.
+		  the "Entrypoint scan" messages appears after 1-3s, and then there is 13s of Sponge Mixing.
+		 "Entrypoint scan" messages for "main" and "client" appear AFTER Sponge is done Mixing, showing grouped duration of 10-30s for entrypoint loop (above) and Sponge Mixing.
+		 * the next phase after this is {@linkplain FabricLoaderImpl#prepareModInit(Path, Object)}
+		 */
 
 		if (exception != null) {
 			throw exception;

src/main/java/net/fabricmc/loader/impl/launch/FabricLauncherBase.java

@@ -138,6 +138,7 @@ protected static void finishMixinBootstrapping() {
 		}
 
 		mixinReady = true;
+		Log.info(LogCategory.MIXIN, "FabricMixin bootstrap complete.");
 	}
 
 	public static boolean isMixinReady() {

src/main/java/net/fabricmc/loader/impl/launch/FabricMixinBootstrap.java

@@ -51,6 +51,7 @@ private FabricMixinBootstrap() { }
 	private static boolean initialized = false;
 
 	public static void init(EnvType side, FabricLoaderImpl loader) {
+		Log.info(LogCategory.MIXIN, "FabricMixin bootstrap init.");
 		if (initialized) {
 			throw new RuntimeException("FabricMixinBootstrap has already been initialized!");
 		}
@@ -61,6 +62,7 @@ public static void init(EnvType side, FabricLoaderImpl loader) {
 		MixinBootstrap.init();
 
 		if (FabricLauncherBase.getLauncher().isDevelopment()) {
+			Log.info(LogCategory.MIXIN, "Dev: mixin mappings scanning.");
 			MappingConfiguration mappingConfiguration = FabricLauncherBase.getLauncher().getMappingConfiguration();
 			TinyTree mappings = mappingConfiguration.getMappings();
 
@@ -83,6 +85,7 @@ public static void init(EnvType side, FabricLoaderImpl loader) {
 		}
 
 		Map<String, ModContainerImpl> configToModMap = new HashMap<>();
+		Log.info(LogCategory.MIXIN, "Computing mixin configs.");
 
 		for (ModContainerImpl mod : loader.getModsInternal()) {
 			for (String config : mod.getMetadata().getMixinConfigs(side)) {
@@ -102,6 +105,7 @@ public static void init(EnvType side, FabricLoaderImpl loader) {
 			if (mod == null) continue;
 		}
 
+		Log.info(LogCategory.MIXIN, "Applying mixin decorators.");
 		try {
 			IMixinConfig.class.getMethod("decorate", String.class, Object.class);
 			MixinConfigDecorator.apply(configToModMap);

src/main/java/net/fabricmc/loader/impl/launch/knot/Knot.java

@@ -153,8 +153,10 @@ protected ClassLoader init(String[] args) {
 		FabricMixinBootstrap.init(getEnvironmentType(), loader);
 		FabricLauncherBase.finishMixinBootstrapping();
 
+		Log.info(LogCategory.KNOT, "Init transformers.");
 		classLoader.initializeTransformers();
 
+		Log.info(LogCategory.KNOT, "Unlock classpath.");
 		provider.unlockClassPath(this);
 		unlocked = true;
 

src/main/java/net/fabricmc/loader/impl/launch/knot/MixinServiceKnot.java

@@ -21,6 +21,9 @@
 import java.net.URL;
 import java.util.Collection;
 import java.util.Collections;
+import java.util.HashMap;
+import java.util.Map;
+import java.util.TreeMap;
 
 import org.objectweb.asm.ClassReader;
 import org.objectweb.asm.tree.ClassNode;
@@ -52,12 +55,75 @@ public MixinServiceKnot() {
 		lock = new ReEntranceLock(1);
 	}
 
+	/**
+	 * Current benchmark start time
+	 */
+	private static long start;
+	/**
+	 * All recorded times
+	 */
+	private static Map<String, Time> times = new HashMap<String, Time>();
+	/**
+	 * Mutable long, so we can easily store the times in a Map
+	 */
+	static final class Time {
+		long value;
+
+		public Long asLong() {
+			return Long.valueOf(this.value);
+		}
+	}
+
+	/**
+	 * Callback from injected code, begin benchmarking a specific transformer
+	 *
+	 * @param name transformer name
+	 */
+	public static void before(String name) {
+		start = System.currentTimeMillis();
+	}
+
+	/**
+	 * Callback from injected code, end benchmarking a transformer
+	 *
+	 * @param name transformer name
+	 */
+	public static void after(String name) {
+		long elapsed = System.currentTimeMillis() - start;
+		Time time = times.get(name);
+		if (time == null) {
+			time = new Time();
+			times.put(name, time);
+		}
+		time.value += elapsed;
+	}
+
+	/**
+	 * Method to obtain current time information
+	 *
+	 * @return Times as key/value pairs with transformer class name as key and
+	 *      total time as value
+	 */
+	public static Map<String, Long> getTimes() {
+		Map<String, Long> times = new TreeMap<String, Long>();
+		for (Map.Entry<String, Time> entry : MixinServiceKnot.times.entrySet()) {
+			times.put(entry.getKey(), entry.getValue().asLong());
+		}
+		return times;
+	}
+
 	public byte[] getClassBytes(String name, String transformedName) throws IOException {
 		return FabricLauncherBase.getLauncher().getClassByteArray(name, true);
 	}
 
 	public byte[] getClassBytes(String name, boolean runTransformers) throws ClassNotFoundException, IOException {
+		if (runTransformers) {
+			before(name);
+		}
 		byte[] classBytes = FabricLauncherBase.getLauncher().getClassByteArray(name, runTransformers);
+		if (runTransformers) {
+			after(name);
+		}
 
 		if (classBytes != null) {
 			return classBytes;