Add more trace prints to indicate when each Phase starts + re-word some info logs

[Shadowrs]

• The re-wording of some statements is to maintain some consistency at the start of each sentence- making similar info more human readable
• Send some logs to MixinEnv.logger as well as system.out - this ensures info is captures in the latest.log (or a file specified by the end user by using a custom log4j.xml)

Suggested log4j.xml which splits mixin related logs to mixin.log instead of spamming latest.log and debug.log:

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="warn" packages="com.mojang.util,net.minecrell.terminalconsole.util,com.larxstar.log">
	<Appenders>
(SYSTEM OUT, SYSTEM ERR, DEBUG, LATEST REMOVED FOR DEMO)
		
		<RollingRandomAccessFile name="MixinFile" fileName="logs/mixins.log" filePattern="logs/mixin-%i.log.gz">
			<PatternLayout pattern="[%d{HH:mm:ss}] [%t/%level] (%logger) %msg{nolookups}%n" />
			<Policies>
				<TimeBasedTriggeringPolicy />
				<OnStartupTriggeringPolicy />
			</Policies>
		</RollingRandomAccessFile>
		
		<RollingRandomAccessFile name="MiscFile" fileName="logs/misc.log" filePattern="logs/misc-%i.log.gz">
			<PatternLayout pattern="[%d{HH:mm:ss}] [%t/%level] (%logger) %msg{nolookups}%n" />
			<Policies>
				<TimeBasedTriggeringPolicy />
				<OnStartupTriggeringPolicy />
			</Policies>
		</RollingRandomAccessFile>
	</Appenders>
	<Loggers>
		<Logger level="${sys:fabric.log.level:-info}" name="net.minecraft"/>
		<Logger level="TRACE" name="mixin" additivity="false" >
			<appender-ref ref="MiscFile"/>
		</Logger>
        <Logger level="TRACE" name="mixin.audit" additivity="false" >
			<appender-ref ref="MiscFile"/>
		</Logger>
        <Logger level="TRACE" name="mixin.agent" additivity="false" >
			<appender-ref ref="MiscFile"/>
		</Logger>
        <Logger level="TRACE" name="FabricLoader/Mixin/compat" additivity="false" >
			<appender-ref ref="MixinFile"/>
			<!-- <appender-ref ref="DebugFile"/> -->
		</Logger>
        <Logger level="TRACE" name="FabricLoader/Mixin/meta" additivity="false" >
			<appender-ref ref="MixinFile"/>
		</Logger>
        <Logger level="TRACE" name="FabricLoader/Mixin/all" additivity="false" >
			<appender-ref ref="MixinFile"/>
		</Logger>
        <Logger level="TRACE" name="FabricLoader/Mixin/processor" additivity="false" >
			<appender-ref ref="MixinFile"/>
		</Logger>
        <Logger level="TRACE" name="FabricLoader/Mixin/injector" additivity="false" >
			<appender-ref ref="MixinFile"/>
		</Logger>
        <Logger level="TRACE" name="FabricLoader/Mixin" additivity="false" >
			<appender-ref ref="MixinFile"/>
		</Logger>
		<!-- ctrl+q for comment np++ -->
        <Logger level="TRACE" name="org.spongepowered" additivity="false" >
			<appender-ref ref="MiscFile"/>
		</Logger>
        <Logger level="TRACE" name="org.spongepowered.asm.mixin" additivity="false" >
			<appender-ref ref="MiscFile"/>
		</Logger>
		<Logger level="ERROR" name="net.minecraft.class_3294" additivity="false" >
			<appender-ref ref="MiscFile"/>
		</Logger>
		<Logger level="warn" name="cpw.mods.modlauncher.ClassTransformer" additivity="false" />
		<Logger level="warn" name="com.tterrag.registrate.AbstractRegistrate" additivity="false" />
		<Root level="all" additivity="false" >
			<AppenderRef ref="DebugFile" level="${sys:fabric.log.debug.level:-debug}" />
			<AppenderRef ref="SysOut" level="${sys:fabric.log.level:-info}"/>
			<AppenderRef ref="LatestFile" level="${sys:fabric.log.level:-info}"/>
			<AppenderRef ref="ServerGuiConsole" level="${sys:fabric.log.level:-info}"/>
		</Root>
	</Loggers>
</Configuration>

[Shadowrs]

Send to the MixinEnv logger as well as sys.err

[Shadowrs]

The mixin profiler breakdown isn't printing to a log4j file yet and I'm not sure why

[Player3324]

Mixin in particular is a library where we don't want to diverge too much from upstream unless there's enough of a reason for it. Did you try a sampling based approach yet? It should be able to give a time usage breakdown as well, but without instrumenting the code and with deeper insight.