added code execution time measuring and logging

Eddio0141 · Aug 8, 2024 · bc3c671 · bc3c671
1 parent d042932
commit bc3c671
Show file tree

Hide file tree

Showing 3 changed files with 68 additions and 1 deletion.
diff --git a/UniTAS/Patcher/Entry.cs b/UniTAS/Patcher/Entry.cs
@@ -8,6 +8,9 @@
 using UniTAS.Patcher.ManualServices;
 using UniTAS.Patcher.Models.DependencyInjection;
 using UniTAS.Patcher.Utils;
+#if TRACE
+using System.Diagnostics;
+#endif
 
 namespace UniTAS.Patcher;
 
@@ -51,10 +54,19 @@ public static void Patch(ref AssemblyDefinition assembly)
         var assemblyNameWithDll = $"{assembly.Name.Name}.dll";
         StaticLogger.Log.LogDebug($"Received assembly {assemblyNameWithDll} for patching");
 
+#if TRACE
+        var sw = new Stopwatch();
+        sw.Start();
+#endif
+
         // check cache validity and patch if needed
         if (TargetAssemblyCacheIsValid(ref assembly))
         {
             StaticLogger.Log.LogDebug("Skipping patching as it is cached");
+#if TRACE
+            sw.Stop();
+            StaticLogger.Trace($"time elapsed modifying assembly: {sw.Elapsed.Milliseconds}ms");
+#endif
             return;
         }
 
@@ -63,9 +75,22 @@ public static void Patch(ref AssemblyDefinition assembly)
             // only patch the assembly if it's in the list of target assemblies
             if (!patcher.TargetDLLs.Contains(assemblyNameWithDll)) continue;
             StaticLogger.Log.LogInfo($"Patching {assemblyNameWithDll} with {patcher.GetType().Name}");
+#if TRACE
+            var swPatch = new Stopwatch();
+            swPatch.Start();
+#endif
             patcher.Patch(ref assembly);
+#if TRACE
+            swPatch.Stop();
+            StaticLogger.Trace($"time elapsed processing patch: {swPatch.Elapsed.TotalMilliseconds}ms");
+#endif
         }
 
+#if TRACE
+        sw.Stop();
+        StaticLogger.Trace($"time elapsed modifying assembly: {sw.Elapsed.Milliseconds}ms");
+#endif
+
         // save patched assembly to cache
         SavePatchedAssemblyToCache(assembly);
     }

diff --git a/UniTAS/Patcher/Implementations/GameRestart/GameRestart.cs b/UniTAS/Patcher/Implementations/GameRestart/GameRestart.cs
@@ -12,6 +12,10 @@
 using UniTAS.Patcher.Services.UnitySafeWrappers.Wrappers;
 using UniTAS.Patcher.Services.VirtualEnvironment;
 using Object = UnityEngine.Object;
+#if TRACE
+using System.Diagnostics;
+using UniTAS.Patcher.Utils;
+#endif
 
 namespace UniTAS.Patcher.Implementations.GameRestart;
 
@@ -98,6 +102,10 @@ public void SoftRestart(DateTime time)
 
         _logger.LogInfo("Starting soft restart");
 
+#if TRACE
+        var sw = new Stopwatch();
+        sw.Start();
+#endif
         InvokeOnPreGameRestart();
 
         _pendingRestart = true;
@@ -117,6 +125,11 @@ public void SoftRestart(DateTime time)
         _logger.LogDebug("Enabling finalize invoke");
         _finalizeSuppressor.DisableFinalizeInvoke = false;
 
+#if TRACE
+        sw.Stop();
+        StaticLogger.Trace($"time elapsed for soft restart first phase: {sw.Elapsed.Milliseconds}ms");
+#endif
+
         _syncFixedUpdate.OnSync(SoftRestartOperation, -_timeEnv.FrameTime);
     }
 
@@ -138,10 +151,20 @@ private void SoftRestartOperation()
     {
         _logger.LogInfo("Soft restarting");
 
+#if TRACE
+        var sw = new Stopwatch();
+        sw.Start();
+#endif
+
         OnGameRestart?.Invoke(_softRestartTime, true);
         _sceneWrapper.LoadScene(0);
         OnGameRestart?.Invoke(_softRestartTime, false);
 
+#if TRACE
+        sw.Stop();
+        StaticLogger.Trace($"time elapsed for soft restart scene reload: {sw.Elapsed.Milliseconds}ms");
+#endif
+
         _pendingRestart = false;
         _pendingResumePausedExecution = true;
     }
@@ -181,4 +204,4 @@ private void PendingResumePausedExecution(string timing)
         _logger.LogDebug($"Resuming MonoBehaviour execution at {timing}, {_updateInvokeOffset.Offset}");
         InvokeOnGameRestartResume(false);
     }
-}
+}
diff --git a/UniTAS/Patcher/Implementations/StaticFieldStorage.cs b/UniTAS/Patcher/Implementations/StaticFieldStorage.cs
@@ -5,6 +5,9 @@
 using UniTAS.Patcher.Services.Logging;
 using UniTAS.Patcher.Services.Trackers.TrackInfo;
 using UniTAS.Patcher.Utils;
+#if TRACE
+using System.Diagnostics;
+#endif
 
 namespace UniTAS.Patcher.Implementations;
 
@@ -23,6 +26,10 @@ public void ResetStaticFields()
 
         UnityEngine.Resources.UnloadUnusedAssets();
 
+#if TRACE
+        var sw = new Stopwatch();
+        sw.Start();
+#endif
         foreach (var field in classStaticInfoTracker.StaticFields)
         {
             var typeName = field.DeclaringType?.FullName ?? "unknown_type";
@@ -40,13 +47,21 @@ public void ResetStaticFields()
             freeMalloc?.TryFree(null, field);
             field.SetValue(null, null);
         }
+#if TRACE
+        sw.Stop();
+        StaticLogger.Trace($"Time elapsed for static fields resetting: {sw.Elapsed.Milliseconds}ms");
+#endif
 
         // idk if this even works
         GC.Collect();
         GC.WaitForPendingFinalizers();
 
         var count = classStaticInfoTracker.StaticCtorInvokeOrder.Count;
         logger.LogDebug($"calling {count} static constructors");
+#if TRACE
+        sw.Reset();
+        sw.Start();
+#endif
         for (var i = 0; i < count; i++)
         {
             var staticCtorType = classStaticInfoTracker.StaticCtorInvokeOrder[i];
@@ -64,5 +79,9 @@ public void ResetStaticFields()
                 logger.LogDebug($"Exception thrown while calling static constructor: {e}");
             }
         }
+#if TRACE
+        sw.Stop();
+        StaticLogger.Trace($"Time elapsed for static constructor invokes: {sw.Elapsed.Milliseconds}ms");
+#endif
     }
 }