refactor(StartupAudit): enhance measurement and reporting of startup phases

- Updated RitsuLibStartupAudit to utilize a new MeasureScope for better tracking of inclusive and exclusive timing during phase measurements.
- Improved the Record method to differentiate between inclusive and exclusive timings, enhancing the accuracy of performance reports.
- Added caching mechanisms for missing asset paths in AssetPathDiagnostics to prevent redundant warnings and improve logging efficiency.
- Introduced methods to manage a cache of missing paths, ensuring that warnings are only logged when necessary, thus reducing clutter in logs.

Author: BAKAOLC

Diagnostics/RitsuLibStartupAudit.cs

@@ -15,15 +15,18 @@ namespace STS2RitsuLib.Diagnostics
     internal static class RitsuLibStartupAudit
     {
         private static readonly Lock Gate = new();
-        private static readonly List<(string Phase, double Milliseconds)> Phases = [];
+        private static readonly List<PhaseTiming> Phases = [];
         private static int _reportedCount;
 
+        [ThreadStatic] private static MeasureScope? _currentScope;
+
         /// <summary>
         ///     Times <paramref name="action" /> and records its duration under <paramref name="phase" />.
         ///     对 <paramref name="action" /> 计时，并以 <paramref name="phase" /> 记录其耗时。
         /// </summary>
         internal static void Measure(string phase, Action action)
         {
+            var scope = PushScope(phase);
             var sw = Stopwatch.StartNew();
             try
             {
@@ -32,7 +35,7 @@ internal static void Measure(string phase, Action action)
             finally
             {
                 sw.Stop();
-                Record(phase, sw.Elapsed.TotalMilliseconds);
+                PopScope(scope, sw.Elapsed.TotalMilliseconds);
             }
         }
 
@@ -42,6 +45,7 @@ internal static void Measure(string phase, Action action)
         /// </summary>
         internal static T Measure<T>(string phase, Func<T> func)
         {
+            var scope = PushScope(phase);
             var sw = Stopwatch.StartNew();
             try
             {
@@ -50,7 +54,7 @@ internal static T Measure<T>(string phase, Func<T> func)
             finally
             {
                 sw.Stop();
-                Record(phase, sw.Elapsed.TotalMilliseconds);
+                PopScope(scope, sw.Elapsed.TotalMilliseconds);
             }
         }
 
@@ -60,9 +64,10 @@ internal static T Measure<T>(string phase, Func<T> func)
         /// </summary>
         internal static void Record(string phase, double milliseconds)
         {
+            _currentScope?.AddChild(milliseconds);
             lock (Gate)
             {
-                Phases.Add((phase, milliseconds));
+                Phases.Add(new(phase, milliseconds, milliseconds));
             }
         }
 
@@ -77,20 +82,62 @@ internal static void LogReport(string title)
                 if (Phases.Count <= _reportedCount)
                     return;
 
-                var total = Phases.Sum(static entry => entry.Milliseconds);
+                var total = Phases.Sum(static entry => entry.ExclusiveMilliseconds);
                 var text = new StringBuilder()
                     .AppendLine()
                     .AppendLine($"=== RitsuLib Startup Audit: {title} ===");
 
-                foreach (var (phase, milliseconds) in Phases)
-                    text.AppendLine($"  {phase}: {milliseconds:F1} ms");
+                foreach (var timing in Phases)
+                {
+                    text.Append($"  {timing.Phase}: {timing.ExclusiveMilliseconds:F1} ms");
+                    if (Math.Abs(timing.InclusiveMilliseconds - timing.ExclusiveMilliseconds) >= 0.05d)
+                        text.Append($" (inclusive {timing.InclusiveMilliseconds:F1} ms)");
+
+                    text.AppendLine();
+                }
 
                 text.AppendLine("  ---")
-                    .Append($"  RitsuLib self-time total: {total:F1} ms");
+                    .Append($"  RitsuLib exclusive self-time total: {total:F1} ms");
 
                 _reportedCount = Phases.Count;
                 RitsuLibFramework.Logger.Info(text.ToString());
             }
         }
+
+        private static MeasureScope PushScope(string phase)
+        {
+            var scope = new MeasureScope(phase, _currentScope);
+            _currentScope = scope;
+            return scope;
+        }
+
+        private static void PopScope(MeasureScope scope, double inclusiveMilliseconds)
+        {
+            _currentScope = scope.Parent;
+            scope.Parent?.AddChild(inclusiveMilliseconds);
+
+            var exclusiveMilliseconds = Math.Max(0d, inclusiveMilliseconds - scope.ChildMilliseconds);
+            lock (Gate)
+            {
+                Phases.Add(new(scope.Phase, inclusiveMilliseconds, exclusiveMilliseconds));
+            }
+        }
+
+        private sealed class MeasureScope(string phase, MeasureScope? parent)
+        {
+            internal string Phase { get; } = phase;
+            internal MeasureScope? Parent { get; } = parent;
+            internal double ChildMilliseconds { get; private set; }
+
+            internal void AddChild(double milliseconds)
+            {
+                ChildMilliseconds += milliseconds;
+            }
+        }
+
+        private readonly record struct PhaseTiming(
+            string Phase,
+            double InclusiveMilliseconds,
+            double ExclusiveMilliseconds);
     }
 }

Utils/AssetPathDiagnostics.cs

@@ -4,12 +4,25 @@ namespace STS2RitsuLib.Utils
 {
     internal static class AssetPathDiagnostics
     {
+        private static readonly Lock StartupMissingPathCacheGate = new();
+        private static readonly HashSet<string> StartupMissingPathCache = [];
+        private static bool _startupMissingPathCacheEnabled = true;
+        private static bool _startupMissingPathCacheShutdownRegistered;
+
         internal static bool Exists(string path, object owner, string memberName)
         {
+            var ownerLabel = DescribeOwner(owner);
+            var cacheKey = BuildMissingPathCacheKey(ownerLabel, memberName, path);
+
+            if (IsCachedStartupMissingPath(cacheKey))
+                return false;
+
             if (GodotResourcePath.ResourceExists(path))
                 return true;
 
-            WarnMissingPath(owner, memberName, path);
+            if (ShouldWarnMissingPath(cacheKey))
+                WarnMissingPath(ownerLabel, memberName, path);
+
             return false;
         }
 
@@ -22,6 +35,10 @@ internal static bool Exists(string path, object owner, string memberName)
         internal static void WarnModCharacterAssetOverrideMissing(object owner, string memberName, string path)
         {
             var ownerLabel = DescribeOwner(owner);
+            var cacheKey = BuildMissingPathCacheKey(ownerLabel, memberName, path);
+
+            if (!ShouldWarnMissingPath(cacheKey))
+                return;
 
             RitsuLibFramework.Logger.Warn(
                 $"[Assets] Mod character asset override path not found for {ownerLabel}.{memberName}: '{path}'. " +
@@ -45,14 +62,62 @@ internal static string[] CollectExistingPaths(object owner,
             return [.. results];
         }
 
-        private static void WarnMissingPath(object owner, string memberName, string path)
+        private static void WarnMissingPath(string ownerLabel, string memberName, string path)
         {
-            var ownerLabel = DescribeOwner(owner);
-
             RitsuLibFramework.Logger.Warn(
                 $"[Assets] Missing resource path for {ownerLabel}.{memberName}: '{path}'. Falling back to the base asset.");
         }
 
+        private static bool IsCachedStartupMissingPath(string cacheKey)
+        {
+            EnsureStartupMissingPathCacheShutdownRegistered();
+
+            lock (StartupMissingPathCacheGate)
+            {
+                return _startupMissingPathCacheEnabled && StartupMissingPathCache.Contains(cacheKey);
+            }
+        }
+
+        private static bool ShouldWarnMissingPath(string cacheKey)
+        {
+            EnsureStartupMissingPathCacheShutdownRegistered();
+
+            lock (StartupMissingPathCacheGate)
+            {
+                return !_startupMissingPathCacheEnabled || StartupMissingPathCache.Add(cacheKey);
+            }
+        }
+
+        private static void EnsureStartupMissingPathCacheShutdownRegistered()
+        {
+            if (_startupMissingPathCacheShutdownRegistered)
+                return;
+
+            lock (StartupMissingPathCacheGate)
+            {
+                if (_startupMissingPathCacheShutdownRegistered)
+                    return;
+
+                _startupMissingPathCacheShutdownRegistered = true;
+            }
+
+            RitsuLibFramework.SubscribeLifecycleOnce<MainMenuReadyEvent>(_ => DisableStartupMissingPathCache());
+        }
+
+        private static void DisableStartupMissingPathCache()
+        {
+            lock (StartupMissingPathCacheGate)
+            {
+                _startupMissingPathCacheEnabled = false;
+                StartupMissingPathCache.Clear();
+            }
+        }
+
+        private static string BuildMissingPathCacheKey(string ownerLabel, string memberName, string path)
+        {
+            return $"{ownerLabel}\n{memberName}\n{path}";
+        }
+
         private static string DescribeOwner(object owner)
         {
             try