diff --git a/minecraft/src/main/java/net/fabricmc/loader/impl/game/minecraft/Hooks.java b/minecraft/src/main/java/net/fabricmc/loader/impl/game/minecraft/Hooks.java index 867373861..205d4f4a1 100644 --- a/minecraft/src/main/java/net/fabricmc/loader/impl/game/minecraft/Hooks.java +++ b/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) { diff --git a/minecraft/src/main/java/net/fabricmc/loader/impl/game/minecraft/launchwrapper/FabricTweaker.java b/minecraft/src/main/java/net/fabricmc/loader/impl/game/minecraft/launchwrapper/FabricTweaker.java index 44ca87194..59dcfc547 100644 --- a/minecraft/src/main/java/net/fabricmc/loader/impl/game/minecraft/launchwrapper/FabricTweaker.java +++ b/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 times = new HashMap(); + /** + * 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); } } diff --git a/src/main/java/net/fabricmc/loader/impl/FabricLoaderImpl.java b/src/main/java/net/fabricmc/loader/impl/FabricLoaderImpl.java index e633fd55d..c864cf2b4 100644 --- a/src/main/java/net/fabricmc/loader/impl/FabricLoaderImpl.java +++ b/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!"); } diff --git a/src/main/java/net/fabricmc/loader/impl/discovery/RuntimeModRemapper.java b/src/main/java/net/fabricmc/loader/impl/discovery/RuntimeModRemapper.java index 58744fdd5..cc2b5be7c 100644 --- a/src/main/java/net/fabricmc/loader/impl/discovery/RuntimeModRemapper.java +++ b/src/main/java/net/fabricmc/loader/impl/discovery/RuntimeModRemapper.java @@ -52,6 +52,7 @@ public final class RuntimeModRemapper { public static void remap(Collection modCandidates, Path tmpDir, Path outputDir) { + Log.info(LogCategory.MOD_REMAP, "Starting remapping"); List modsToRemap = new ArrayList<>(); for (ModCandidate mod : modCandidates) { @@ -119,7 +120,7 @@ public static void remap(Collection 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 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); diff --git a/src/main/java/net/fabricmc/loader/impl/entrypoint/EntrypointUtils.java b/src/main/java/net/fabricmc/loader/impl/entrypoint/EntrypointUtils.java index e9b5ef50d..af9e11264 100644 --- a/src/main/java/net/fabricmc/loader/impl/entrypoint/EntrypointUtils.java +++ b/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,12 +46,25 @@ private static void invoke0(String name, Class type, Consumer RuntimeException exception = null; Collection> 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 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'!", @@ -53,6 +72,20 @@ private static void invoke0(String name, Class type, Consumer 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; diff --git a/src/main/java/net/fabricmc/loader/impl/launch/FabricLauncherBase.java b/src/main/java/net/fabricmc/loader/impl/launch/FabricLauncherBase.java index 856595331..9fcc801ec 100644 --- a/src/main/java/net/fabricmc/loader/impl/launch/FabricLauncherBase.java +++ b/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() { diff --git a/src/main/java/net/fabricmc/loader/impl/launch/FabricMixinBootstrap.java b/src/main/java/net/fabricmc/loader/impl/launch/FabricMixinBootstrap.java index a9cc9c4c9..b995df795 100644 --- a/src/main/java/net/fabricmc/loader/impl/launch/FabricMixinBootstrap.java +++ b/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 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); diff --git a/src/main/java/net/fabricmc/loader/impl/launch/knot/Knot.java b/src/main/java/net/fabricmc/loader/impl/launch/knot/Knot.java index c162461a1..abd868174 100644 --- a/src/main/java/net/fabricmc/loader/impl/launch/knot/Knot.java +++ b/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; diff --git a/src/main/java/net/fabricmc/loader/impl/launch/knot/MixinServiceKnot.java b/src/main/java/net/fabricmc/loader/impl/launch/knot/MixinServiceKnot.java index 8f230d9ae..c67cc5f6f 100644 --- a/src/main/java/net/fabricmc/loader/impl/launch/knot/MixinServiceKnot.java +++ b/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 times = new HashMap(); + /** + * 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 getTimes() { + Map times = new TreeMap(); + for (Map.Entry 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;