From e2d5dab219cb4764877c9999b57f8b2d4ad35d16 Mon Sep 17 00:00:00 2001 From: bd_ Date: Tue, 27 Aug 2024 19:28:21 -0700 Subject: [PATCH] chore: debugging improvements --- Editor/API/ObjectRegistry.cs | 39 ++++++++++++++++++ Editor/PreviewSystem/ComputeContext.cs | 3 +- Editor/PreviewSystem/IRenderFilter.cs | 6 ++- .../PreviewSystem/Rendering/NodeController.cs | 41 +++++++++++++++---- .../PreviewSystem/Rendering/ProxyPipeline.cs | 25 ++++++++--- UnitTests~/NodeControllerTest.cs | 3 +- 6 files changed, 101 insertions(+), 16 deletions(-) diff --git a/Editor/API/ObjectRegistry.cs b/Editor/API/ObjectRegistry.cs index 5337f08..d8eb307 100644 --- a/Editor/API/ObjectRegistry.cs +++ b/Editor/API/ObjectRegistry.cs @@ -3,6 +3,7 @@ using System; using System.Collections.Generic; using System.Linq; +using System.Text; using System.Threading; using nadena.dev.ndmf.runtime; using UnityEngine; @@ -117,6 +118,22 @@ public ObjectRegistry(Transform avatarRoot, ObjectRegistry parent = null) _parent = parent; } + internal string RegistryDump() + { + var sb = new StringBuilder(); + + foreach (var group in _obj2ref.GroupBy(kvp => kvp.Value)) + { + var source = group.Key.Object == null ? "" : group.Key.Object.name; + var instances = group.Select(kvp => kvp.Key.GetInstanceID() + " [" + kvp.Key.name + "]").ToArray(); + + sb.Append("\tGroup source ").Append(source).Append(": ").Append(string.Join(", ", instances)) + .Append("\n"); + } + + return sb.ToString(); + } + /// /// Returns the ObjectReference for the given object, using the ambient ObjectRegistry. /// @@ -135,6 +152,17 @@ ObjectReference IObjectRegistry.GetReference(UnityObject obj, bool create) if (objref != null || !create) { +#if NDMF_TRACE_OBJREG + if (objref != null) + { + Debug.Log("[ObjectRegistry] Returning reference for " + obj.GetInstanceID() + " [" + obj.name + + "]: " + objref.GetHashCode()); + } + else + { + Debug.Log("[ObjectRegistry] No reference for " + obj.GetInstanceID() + " [" + obj.name + "]"); + } +#endif return objref; } @@ -148,6 +176,9 @@ ObjectReference IObjectRegistry.GetReference(UnityObject obj, bool create) objref = new ObjectReference(obj, path); _obj2ref[obj] = objref; +#if NDMF_TRACE_OBJREG + Debug.Log("[ObjectRegistry] Created reference for " + obj.GetInstanceID() + " [" + obj.name + "]: " + objref.GetHashCode()); +#endif return objref; } @@ -193,6 +224,14 @@ ObjectReference IObjectRegistry.RegisterReplacedObject(ObjectReference oldObject throw new ArgumentException( "RegisterReplacedObject must be called before GetReference is called on the new object"); + var oldObj = "<" + oldObject.GetHashCode() + ">"; + if (oldObject.Object != null) + oldObj = oldObject.Object.GetInstanceID() + " [" + oldObject.Object.name + "]"; + +#if NDMF_TRACE_OBJREG + Debug.Log("[ObjectRegistry] Registering replacement for " + oldObj + " -> " + newObject.GetInstanceID() + " [" + newObject.name + "]"); +#endif + _obj2ref[newObject] = oldObject; return oldObject; diff --git a/Editor/PreviewSystem/ComputeContext.cs b/Editor/PreviewSystem/ComputeContext.cs index 760c7fd..cc99f03 100644 --- a/Editor/PreviewSystem/ComputeContext.cs +++ b/Editor/PreviewSystem/ComputeContext.cs @@ -4,6 +4,7 @@ using System.Threading.Tasks; using JetBrains.Annotations; using nadena.dev.ndmf.cs; +using UnityEngine; #endregion @@ -28,7 +29,7 @@ static ComputeContext() ~ComputeContext() { if (!IsInvalidated) - UnityEngine.Debug.LogError("ComputeContext " + Description + " was GCed without being invalidated!"); + Debug.LogError("ComputeContext " + Description + " was GCed without being invalidated!"); } #endif diff --git a/Editor/PreviewSystem/IRenderFilter.cs b/Editor/PreviewSystem/IRenderFilter.cs index edd0a62..daffd1a 100644 --- a/Editor/PreviewSystem/IRenderFilter.cs +++ b/Editor/PreviewSystem/IRenderFilter.cs @@ -7,7 +7,6 @@ using System.Linq; using System.Threading.Tasks; using JetBrains.Annotations; -using NUnit.Framework; using UnityEngine; #endregion @@ -82,6 +81,11 @@ public override int GetHashCode() return hashCode; } + + public string ToString() + { + return "RenderGroup(" + string.Join(", ", Renderers.Select(r => r.name)) + ")"; + } } internal sealed class RenderGroup : RenderGroup diff --git a/Editor/PreviewSystem/Rendering/NodeController.cs b/Editor/PreviewSystem/Rendering/NodeController.cs index 7d860f7..b8438a4 100644 --- a/Editor/PreviewSystem/Rendering/NodeController.cs +++ b/Editor/PreviewSystem/Rendering/NodeController.cs @@ -85,37 +85,64 @@ internal void OnFrame() public static Task Create( IRenderFilter filter, RenderGroup group, - List<(Renderer, ProxyObjectController, ObjectRegistry)> proxies) + List<(Renderer, ProxyObjectController, ObjectRegistry)> proxies, + string trace + ) { - return Create(filter, group, ObjectRegistry.Merge(null, proxies.Select(p => p.Item3)), proxies); + return Create(filter, group, ObjectRegistry.Merge(null, proxies.Select(p => p.Item3)), proxies, trace); } public static async Task Create( IRenderFilter filter, RenderGroup group, ObjectRegistry registry, - List<(Renderer, ProxyObjectController, ObjectRegistry)> proxies + List<(Renderer, ProxyObjectController, ObjectRegistry)> proxies, + string trace ) { var context = - new ComputeContext("NodeController for " + filter + " on " + group.Renderers[0].gameObject.name); - + new ComputeContext("NodeController " + trace + " for " + filter + " on " + + group.Renderers[0].gameObject.name); +#if NDMF_TRACE_FILTERS + UnityEngine.Debug.Log("[NodeController Create] " + trace + " Filter=" + filter + " Group=" + + group.Renderers[0].gameObject.name + + " Registry dump:\n" + registry.RegistryDump()); +#endif IRenderFilterNode node; using (var scope = new ObjectRegistryScope(registry)) { + var savedMaterials = group.Renderers.Select(r => r.sharedMaterials).ToArray(); + node = await filter.Instantiate( group, proxies.Select(p => (p.Item1, p.Item2.Renderer)), context ); + + for (var i = 0; i < group.Renderers.Count; i++) + { + if (group.Renderers[i].sharedMaterials.SequenceEqual(savedMaterials[i])) continue; + + Debug.LogWarning("[NodeController Create] Renderer " + group.Renderers[i].gameObject.name + + " sharedMaterials changed during instantiation of " + filter + " in " + + " group " + group + ". Restoring original materials."); + group.Renderers[i].sharedMaterials = savedMaterials[i]; + } } +#if NDMF_TRACE_FILTERS + Debug.Log("[NodeController Post-Create] " + trace + " Filter=" + filter + " Group=" + + group.Renderers[0].gameObject.name + + " Registry dump:\n" + registry.RegistryDump()); +#endif + return new NodeController(filter, group, node, proxies, new RefCount(), context, registry); } public async Task Refresh( List<(Renderer, ProxyObjectController, ObjectRegistry)> proxies, - RenderAspects changes + RenderAspects changes, + string trace ) { var registry = ObjectRegistry.Merge(null, proxies.Select(p => p.Item3) @@ -151,7 +178,7 @@ RenderAspects changes } else if (node == null) { - return await Create(_filter, _group, registry, proxies); + return await Create(_filter, _group, registry, proxies, trace); } else { diff --git a/Editor/PreviewSystem/Rendering/ProxyPipeline.cs b/Editor/PreviewSystem/Rendering/ProxyPipeline.cs index 289fe37..6e6ffee 100644 --- a/Editor/PreviewSystem/Rendering/ProxyPipeline.cs +++ b/Editor/PreviewSystem/Rendering/ProxyPipeline.cs @@ -112,7 +112,7 @@ private async Task Build(ProxyObjectCache proxyCache, IEnumerable _ctx = context; // prevent GC #if NDMF_DEBUG - System.Diagnostics.Debug.WriteLine($"Building pipeline {_generation}"); + Debug.WriteLine($"Building pipeline {_generation}"); #endif var filterList = filters.ToImmutableList(); @@ -120,6 +120,15 @@ private async Task Build(ProxyObjectCache proxyCache, IEnumerable var activeStages = _targetSet.ResolveActiveStages(context); +#if NDMF_TRACE_FILTERS + var sb = new System.Text.StringBuilder(); + foreach (var stage in activeStages) + { + sb.Append("\t").Append(stage.Filter).Append(" on ").Append(stage.Groups).Append("\n"); + } + UnityEngine.Debug.Log($"[ProxyPipeline] Active stages for pipeline {_generation}:\n{sb}"); +#endif + Dictionary> nodeTasks = new(); int total_nodes = 0; int reused = 0; @@ -148,6 +157,9 @@ private async Task Build(ProxyObjectCache proxyCache, IEnumerable total_nodes++; groupIndex++; + + var trace = $"Gen{_generation}/Stage{i}/Group{groupIndex}"; + var resolved = group.Renderers.Select(r => { if (nodeTasks.TryGetValue(r, out var task)) @@ -192,7 +204,8 @@ private async Task Build(ProxyObjectCache proxyCache, IEnumerable var proxies = items.Result.ToList(); #if NDMF_DEBUG - System.Diagnostics.Debug.WriteLine($"Creating node for {stage.Filter} on {group.Renderers[0].gameObject.name} for generation {_generation}"); + Debug.WriteLine( + $"Creating node for {stage.Filter} on {group.Renderers[0].gameObject.name} for generation {_generation}"); #endif if (priorNode != null) @@ -200,7 +213,7 @@ private async Task Build(ProxyObjectCache proxyCache, IEnumerable RenderAspects changeFlags = proxies.Select(p => p.Item2.ChangeFlags) .Aggregate((a, b) => a | b); - var node = await priorNode.Result.Refresh(proxies, changeFlags); + var node = await priorNode.Result.Refresh(proxies, changeFlags, trace); if (node != null) { reused++; @@ -209,8 +222,8 @@ private async Task Build(ProxyObjectCache proxyCache, IEnumerable refresh_failed++; } - - return await NodeController.Create(stage.Filter, group, items.Result.ToList()); + + return await NodeController.Create(stage.Filter, group, items.Result.ToList(), trace); }) .Unwrap(); @@ -235,7 +248,7 @@ await Task.WhenAll(_stages.SelectMany(s => s.NodeTasks)) //Debug.WriteLine($"Total nodes: {total_nodes}, reused: {reused}, refresh failed: {refresh_failed}"); #if NDMF_DEBUG - System.Diagnostics.Debug.WriteLine($"Pipeline {_generation} is ready"); + Debug.WriteLine($"Pipeline {_generation} is ready"); #endif foreach (var stage in _stages) diff --git a/UnitTests~/NodeControllerTest.cs b/UnitTests~/NodeControllerTest.cs index dc71164..77b286e 100644 --- a/UnitTests~/NodeControllerTest.cs +++ b/UnitTests~/NodeControllerTest.cs @@ -98,7 +98,8 @@ public void TestObjectRegistryProcessing() { (r1, poc1, or1), (r2, poc2, or2) - } + }, + "" ).Result; IObjectRegistry reg2 = nodeController.ObjectRegistry;