feat: add tracing points for the NDMF preview tracing system

.github/ProjectRoot/vpm-manifest-2022.json

@@ -19,7 +19,7 @@
       "dependencies": {}
     },
     "nadena.dev.ndmf": {
-      "version": "1.5.0-rc.8"
+      "version": "1.5.0-rc.11"
     }
   }
 }

Editor/ReactiveObjects/AnimationGeneration/PropCache.cs

@@ -1,6 +1,7 @@
 using System;
 using System.Collections.Generic;
 using nadena.dev.ndmf.preview;
+using nadena.dev.ndmf.preview.trace;
 
 namespace nadena.dev.modular_avatar.core.editor
 {
@@ -13,6 +14,7 @@ namespace nadena.dev.modular_avatar.core.editor
             public Key Key;
             public Value Value;
             public string DebugName;
+            public int Generation;
         }
 
         private readonly string _debugName;
@@ -20,6 +22,8 @@ namespace nadena.dev.modular_avatar.core.editor
         private readonly Func<Value, Value, bool> _equalityComparer;
         private readonly Dictionary<Key, CacheEntry> _cache = new();
 
+        private static int _generation = 0;
+
         public PropCache(string debugName, Func<ComputeContext, Key, Value> operatorFunc,
             Func<Value, Value, bool> equalityComparer = null)
         {
@@ -30,41 +34,97 @@ namespace nadena.dev.modular_avatar.core.editor
         
         private static void InvalidateEntry(CacheEntry entry)
         {
-            var newGenContext = new ComputeContext("PropCache/" + entry.DebugName + " key " + entry.Key);
+            var newGenContext = new ComputeContext("PropCache/" + entry.DebugName + " key " + FormatKey(entry.Key) + " gen=" + _generation++);
             var newValue = entry.Owner._operator(newGenContext, entry.Key);
-            if (entry.Owner._equalityComparer != null && entry.Owner._equalityComparer(entry.Value, newValue))
+            if (!entry.ObserverContext.IsInvalidated && entry.Owner._equalityComparer != null && entry.Owner._equalityComparer(entry.Value, newValue))
             {
+                TraceBuffer.RecordTraceEvent(
+                    "PropCache.InvalidateEntry", 
+                    (ev) => $"[PropCache/{ev.Arg0}] Value did not change, retaining result (new gen={ev.Arg1})",
+                    entry.DebugName, entry.Generation
+                );
+                
                 entry.GenerateContext = newGenContext;
                 entry.GenerateContext.InvokeOnInvalidate(entry, InvalidateEntry);
                 return;
             }
             
+            var trace = TraceBuffer.RecordTraceEvent(
+                "PropCache.InvalidateEntry", 
+                (ev) => $"[PropCache/{ev.Arg0}] Value changed, invalidating",
+                entry.DebugName
+            );
+            
             entry.Owner._cache.Remove(entry.Key);
-            entry.ObserverContext.Invalidate();
+            using (trace.Scope()) entry.ObserverContext.Invalidate();
         }
         
         public Value Get(ComputeContext context, Key key)
         {
+            TraceEvent ev;
+            var formattedKey = FormatKey(key);
             if (!_cache.TryGetValue(key, out var entry) || entry.GenerateContext.IsInvalidated)
             {
-                var subContext = new ComputeContext("PropCache/" + _debugName + " key " + key);
+                var curGen = _generation++;
+                
+                var subContext = new ComputeContext("PropCache/" + _debugName + " key " + formattedKey + " gen=" + curGen);
                 entry = new CacheEntry
                 {
                     GenerateContext = subContext,
-                    ObserverContext = new ComputeContext("Observer for PropCache for key " + key),
+                    ObserverContext = new ComputeContext("Observer for PropCache/" + _debugName + " for key " +
+                                                         formattedKey + " gen=" + curGen),
                     Owner = this,
                     Key = key,
-                    Value = _operator(subContext, key),
+                    DebugName = _debugName,
-                    DebugName = _debugName
+                    Generation = curGen
                 };
+
+                ev = TraceBuffer.RecordTraceEvent(
+                    "PropCache.Get",
+                    (ev) =>
+                    {
+                        var entry_ = (CacheEntry)ev.Arg0;
+                        return
+                            $"[PropCache/{entry_.DebugName}] Cache miss for key {entry_.Key} gen={entry_.Generation} from context {ev.Arg1}";
+                    },
+                    entry, context
+                );
+
                 _cache[key] = entry;
-                
+                using (ev.Scope())
-                subContext.InvokeOnInvalidate(entry, InvalidateEntry);
+                {
+                    entry.Value = _operator(subContext, key);
+                    entry.GenerateContext.InvokeOnInvalidate(entry, InvalidateEntry);
+                }
+            }
+            else
+            {
+                ev = TraceBuffer.RecordTraceEvent(
+                    "PropCache.Get", 
+                    (ev) =>
+                    {
+                        var entry_ = (CacheEntry) ev.Arg0;
+                        return $"[PropCache/{entry_.DebugName}] Cache hit for key {entry_.Key} gen={entry_.Generation} from context {ev.Arg1}";
+                    },
+                    entry, context
+                );
             }
             
             entry.ObserverContext.Invalidates(context);
 
             return entry.Value;
         }
+
+        private static string FormatKey(object obj)
+        {
+            if (obj is UnityEngine.Object unityObj)
+            {
+                return $"{unityObj.GetHashCode()}#{unityObj}";
+            }
+            else
+            {
+                return "" + obj;
+            }
+        }
     }
 }

Editor/ReactiveObjects/Simulator/ROSimulator.cs

@@ -5,6 +5,7 @@ using System.Linq;
 using nadena.dev.modular_avatar.ui;
 using nadena.dev.ndmf.localization;
 using nadena.dev.ndmf.preview;
+using nadena.dev.ndmf.preview.trace;
 using UnityEditor;
 using UnityEditor.UIElements;
 using UnityEngine;
@@ -14,8 +15,8 @@ namespace nadena.dev.modular_avatar.core.editor.Simulator
 {
     internal class ROSimulator : EditorWindow, IHasCustomMenu
     {
-        public static PublishedValue<ImmutableDictionary<string, float>> PropertyOverrides = new(null);
+        public static PublishedValue<ImmutableDictionary<string, float>> PropertyOverrides = new(null, debugName: "ROSimulator.PropertyOverrides");
-        public static PublishedValue<ImmutableDictionary<string, ModularAvatarMenuItem>> MenuItemOverrides = new(null);
+        public static PublishedValue<ImmutableDictionary<string, ModularAvatarMenuItem>> MenuItemOverrides = new(null, debugName: "ROSimulator.MenuItemOverrides");
         
         internal static string ROOT_PATH = "Packages/nadena.dev.modular-avatar/Editor/ReactiveObjects/Simulator/";
         private static string USS = ROOT_PATH + "ROSimulator.uss";
@@ -106,6 +107,14 @@ namespace nadena.dev.modular_avatar.core.editor.Simulator
         
         private void UpdatePropertyOverride(string prop, bool? enable, float f_val)
         {
+            var trace = TraceBuffer.RecordTraceEvent(
+                "ROSimulator.UpdatePropertyOverride",
+                (ev) => $"Property {ev.Arg0} set to {ev.Arg1}",
+                arg0: prop,
+                arg1: enable == null ? "null" : enable.Value ? f_val : 0f
+            );
+            
+            using (trace.Scope())
             if (enable == null)
             {
                 PropertyOverrides.Value = PropertyOverrides.Value.Remove(prop);
@@ -123,6 +132,15 @@ namespace nadena.dev.modular_avatar.core.editor.Simulator
 
         private void UpdateMenuItemOverride(string prop, ModularAvatarMenuItem item, bool? value)
         {
+            var trace = TraceBuffer.RecordTraceEvent(
+                "ROSimulator.UpdateMenuItemOverride",
+                (ev) => $"MenuItem {ev.Arg0} for prop {ev.Arg1} set to {ev.Arg2}",
+                arg0: item.gameObject.name,
+                arg1: prop,
+                arg2: value == null ? "null" : value.Value ? "true" : "false"
+            );
+            
+            using (trace.Scope())
             if (value == null)
             {
                 MenuItemOverrides.Value = MenuItemOverrides.Value.Remove(prop);

package.json

@@ -16,6 +16,6 @@
   },
   "vpmDependencies": {
     "com.vrchat.avatars": ">=3.7.0",
-    "nadena.dev.ndmf": ">=1.5.0-rc.10 <2.0.0-a"
+    "nadena.dev.ndmf": ">=1.5.0-rc.11 <2.0.0-a"
   }
 }