From 72cea2780129f37036aa40a5dcbe24a87b01c2f3 Mon Sep 17 00:00:00 2001 From: hatayama Date: Mon, 12 Oct 2026 10:34:23 +0900 Subject: [PATCH 1/6] Pin the background and main thread wait times of a list rebuild The rebuild log gives one total that mixes the pool work with the wait for the main thread after a reload, so a slow total cannot be read as slow work. These tests pin both parts, and null for a step the run never finished. --- ...dCompilationAssemblyReconstructionTests.cs | 90 +++++++++++++++++++ 1 file changed, 90 insertions(+) diff --git a/Assets/Tests/Editor/HotReload/HotReloadCompilationAssemblyReconstructionTests.cs b/Assets/Tests/Editor/HotReload/HotReloadCompilationAssemblyReconstructionTests.cs index 6a24f3f51..22ad8ce00 100644 --- a/Assets/Tests/Editor/HotReload/HotReloadCompilationAssemblyReconstructionTests.cs +++ b/Assets/Tests/Editor/HotReload/HotReloadCompilationAssemblyReconstructionTests.cs @@ -5,6 +5,7 @@ using System.Threading.Tasks; using Newtonsoft.Json; +using Newtonsoft.Json.Linq; using NUnit.Framework; @@ -365,6 +366,95 @@ public void ReconstructAndFill_WhileCompilationFailed_KeepsAndSavesNothing() Is.EqualTo(HotReloadConstants.CompilationListReasonCompilationFailed)); } + /// + /// What: a rebuild that fills the cache logs both the background time and the main thread + /// wait, and together they fit within the whole time. + /// + [Test] + public void ReconstructAndFill_WhenFilled_LogsTheBackgroundAndMainThreadWaitTimes() + { + HotReloadCompilationAssemblyListStore store = SaveCleanThenEdit(saved => { }); + HotReloadCompilationAssemblyCache cache = new HotReloadCompilationAssemblyCache(Array.Empty); + VibeLogger.ClearMemoryLogs(); + + Task refill = CreateRefill(store, cache).RunAsync(); + + Assert.That(refill.Status, Is.EqualTo(TaskStatus.RanToCompletion), "refill status"); + JObject context = HotReloadWarmUpTestDoubles.ReadSingleVibeContext(HotReloadConstants.VibeLogCompilationListReconstructed); + Assert.That((bool)context["filled"], Is.True, "filled"); + Assert.That(context["backgroundMs"].Type, Is.EqualTo(JTokenType.Integer), "backgroundMs"); + Assert.That(context["mainThreadWaitMs"].Type, Is.EqualTo(JTokenType.Integer), "mainThreadWaitMs"); + long backgroundMs = (long)context["backgroundMs"]; + long mainThreadWaitMs = (long)context["mainThreadWaitMs"]; + Assert.That(backgroundMs, Is.GreaterThanOrEqualTo(0), "backgroundMs"); + Assert.That(mainThreadWaitMs, Is.GreaterThanOrEqualTo(0), "mainThreadWaitMs"); + Assert.That(backgroundMs + mainThreadWaitMs, Is.LessThanOrEqualTo((long)context["reconstructMs"]), "sum"); + } + + /// + /// What: a rebuild cancelled after the background work finished logs the background time and + /// leaves the main thread wait null, because the switch to the main thread never completed. + /// + [Test] + public async Task ReconstructAndFill_CancelledBeforeTheMainThread_LogsOnlyTheBackgroundTime() + { + HotReloadCompilationAssemblyListStore store = SaveCleanThenEdit(saved => { }); + HotReloadCompilationAssemblyCache cache = new HotReloadCompilationAssemblyCache(Array.Empty); + TaskCompletionSource held = + new TaskCompletionSource(); + Func rebuild = null; + HotReloadCompilationListRefill refill = new HotReloadCompilationListRefill( + store, + cache, + HotReloadSnapshotCaptureInputs.ReadOnMainThread, + () => _isCompilationFailed, + work => + { + rebuild = work; + return held.Task; + }); + VibeLogger.ClearMemoryLogs(); + + Task run = refill.RunAsync(); + HotReloadCompilationListReconstruction rebuilt = rebuild(); + refill.Cancel(); + held.SetResult(rebuilt); + // Why awaited: the rest of the run resumes off this thread after the held rebuild completes. + await run; + + JObject context = HotReloadWarmUpTestDoubles.ReadSingleVibeContext(HotReloadConstants.VibeLogCompilationListReconstructed); + Assert.That((string)context["reason"], Is.EqualTo(HotReloadConstants.CompilationListReasonCancelled), "reason"); + Assert.That(context["backgroundMs"].Type, Is.EqualTo(JTokenType.Integer), "backgroundMs"); + Assert.That(context["mainThreadWaitMs"].Type, Is.EqualTo(JTokenType.Null), "mainThreadWaitMs"); + } + + /// + /// What: a rebuild whose background work does not finish logs neither time as a number, so a + /// step that never ran is not reported as taking 0 ms. + /// + [Test] + public void ReconstructAndFill_WhenTheRebuildFails_LogsNeitherTime() + { + HotReloadCompilationAssemblyListStore store = SaveCleanThenEdit(saved => { }); + HotReloadCompilationAssemblyCache cache = new HotReloadCompilationAssemblyCache(Array.Empty); + HotReloadCompilationListRefill refill = new HotReloadCompilationListRefill( + store, + cache, + HotReloadSnapshotCaptureInputs.ReadOnMainThread, + () => _isCompilationFailed, + work => Task.FromException(new InvalidOperationException("test"))); + VibeLogger.ClearMemoryLogs(); + + Task run = refill.RunAsync(); + + Assert.That(run.Status, Is.EqualTo(TaskStatus.RanToCompletion), "refill status"); + Assert.That(run.Result, Is.False, "kept"); + JObject context = HotReloadWarmUpTestDoubles.ReadSingleVibeContext(HotReloadConstants.VibeLogCompilationListReconstructed); + Assert.That((string)context["reason"], Is.EqualTo(nameof(InvalidOperationException)), "reason"); + Assert.That(context["backgroundMs"].Type, Is.EqualTo(JTokenType.Null), "backgroundMs"); + Assert.That(context["mainThreadWaitMs"].Type, Is.EqualTo(JTokenType.Null), "mainThreadWaitMs"); + } + private void AssertRecompiledTargetGives(string reason, Action editTargetReference) { HotReloadCompilationAssemblyListStore store = SaveCleanThenEdit(saved => From 67b013ade1427432aad963d06fa2b6c31280831a Mon Sep 17 00:00:00 2001 From: hatayama Date: Mon, 12 Oct 2026 10:40:01 +0900 Subject: [PATCH 2/6] Log the pool work and the main thread wait of a list rebuild The rebuild log's total started during domain load and ended after the switch back to the main thread, so a 6-7 s total could not tell slow pool work from a main thread that had not started running yet. The time spent in the rebuild is measured inside the pool work, so waiting for a pool thread does not count; the switch is measured around its await. A step the run did not get through stays null instead of 0. --- .../Shared/HotReloadCompilationListRefill.cs | 27 +++++++++++++------ 1 file changed, 19 insertions(+), 8 deletions(-) diff --git a/Packages/src/Editor/FirstPartyTools/HotReload/Shared/HotReloadCompilationListRefill.cs b/Packages/src/Editor/FirstPartyTools/HotReload/Shared/HotReloadCompilationListRefill.cs index c792b330c..33e657c47 100644 --- a/Packages/src/Editor/FirstPartyTools/HotReload/Shared/HotReloadCompilationListRefill.cs +++ b/Packages/src/Editor/FirstPartyTools/HotReload/Shared/HotReloadCompilationListRefill.cs @@ -69,21 +69,31 @@ internal void Cancel() private async Task RunUntilCancelledAsync(CancellationToken ct) { Stopwatch watch = Stopwatch.StartNew(); + long? backgroundMs = null; + long? mainThreadWaitMs = null; try { int generation = _cache.Generation; HotReloadSnapshotCaptureInputs inputs = _readInputs(); - HotReloadCompilationListReconstruction reconstruction = await _runInBackground( - () => HotReloadCompilationAssemblyReconstruction.Reconstruct(_store, inputs, ct)).ConfigureAwait(false); + HotReloadCompilationListReconstruction reconstruction = await _runInBackground(() => + { + // Why measured inside the work: the time it waited for a pool thread is not rebuilding. + Stopwatch backgroundWatch = Stopwatch.StartNew(); + HotReloadCompilationListReconstruction rebuilt = HotReloadCompilationAssemblyReconstruction.Reconstruct(_store, inputs, ct); + backgroundMs = backgroundWatch.ElapsedMilliseconds; + return rebuilt; + }).ConfigureAwait(false); // Why the main thread: the cache has no lock and is kept on the main thread only. + Stopwatch waitWatch = Stopwatch.StartNew(); await MainThreadSwitcher.SwitchToMainThread(ct); + mainThreadWaitMs = waitWatch.ElapsedMilliseconds; // Why not kept after a failed compile: the dlls are then older than the sources, so // every stamp still matches the saved list while Unity's list already names the // added and removed files. if (reconstruction.Assemblies != null && _isCompilationFailed()) { - LogReconstructed(false, HotReloadConstants.CompilationListReasonCompilationFailed, watch.ElapsedMilliseconds); + LogReconstructed(false, HotReloadConstants.CompilationListReasonCompilationFailed, watch.ElapsedMilliseconds, backgroundMs, mainThreadWaitMs); return false; } @@ -98,12 +108,12 @@ private async Task RunUntilCancelledAsync(CancellationToken ct) string reason = filled ? null : reconstruction.FailureReason ?? HotReloadConstants.CompilationListReasonSuperseded; - LogReconstructed(filled, reason, watch.ElapsedMilliseconds); + LogReconstructed(filled, reason, watch.ElapsedMilliseconds, backgroundMs, mainThreadWaitMs); return filled; } catch (OperationCanceledException) when (ct.IsCancellationRequested) { - LogReconstructed(false, HotReloadConstants.CompilationListReasonCancelled, watch.ElapsedMilliseconds); + LogReconstructed(false, HotReloadConstants.CompilationListReasonCancelled, watch.ElapsedMilliseconds, backgroundMs, mainThreadWaitMs); return false; } catch (Exception ex) @@ -111,17 +121,18 @@ private async Task RunUntilCancelledAsync(CancellationToken ct) // Approved deviation: this is the boundary of work that started at Editor startup, // and a list that cannot be rebuilt only leaves the cache to ask Unity as before. string reason = ex.GetType().Name; - LogReconstructed(false, reason, watch.ElapsedMilliseconds); + LogReconstructed(false, reason, watch.ElapsedMilliseconds, backgroundMs, mainThreadWaitMs); return false; } } - private static void LogReconstructed(bool filled, string reason, long reconstructMs) + // backgroundMs and mainThreadWaitMs stay null when the run did not get through that step. + private static void LogReconstructed(bool filled, string reason, long reconstructMs, long? backgroundMs, long? mainThreadWaitMs) { VibeLogger.LogInfo( HotReloadConstants.VibeLogCompilationListReconstructed, "Hot reload rebuilt the compilation assembly list at startup.", - new { filled, reason, reconstructMs }); + new { filled, reason, reconstructMs, backgroundMs, mainThreadWaitMs }); } } } From fcf380295e63639add92611035ab4fe8694ab839 Mon Sep 17 00:00:00 2001 From: hatayama Date: Mon, 12 Oct 2026 10:59:17 +0900 Subject: [PATCH 3/6] Describe the compilation list rebuild and save entries in VibeLogs The doc did not cover the rebuild and save entries, and still said the list is normally asked of Unity once per domain, which stopped being true once the list is rebuilt from a saved one at startup. --- docs/vibe-logs.md | 48 ++++++++++++++++++++++++++++++++++++++++++++--- 1 file changed, 45 insertions(+), 3 deletions(-) diff --git a/docs/vibe-logs.md b/docs/vibe-logs.md index 8536dec40..78ab57b6c 100644 --- a/docs/vibe-logs.md +++ b/docs/vibe-logs.md @@ -153,9 +153,51 @@ command ran against: The phases add up to `totalMs` except for the loop overhead; `captureMs` in the captured entry also includes reading the compile start and the package roots, and writing this breakdown entry. `hot_reload_compilation_assemblies_fetched` appears each time hot reload asks Unity for the - compilation assembly list, with `fetchMs` and `assemblyCount`. The list is kept for the rest of - the domain once it is not empty, so this normally appears once per domain, from whichever of the - warm-up or the first hot reload run needs the list first. + compilation assembly list, with `fetchMs` and `assemblyCount`. After a domain reload the list is + normally rebuilt off the main thread from the list a previous domain saved + (`hot_reload_compilation_list_reconstructed` below), so this appears only when that rebuild kept + no list or the cache was invalidated in the domain, from the first hot reload run that needs the + list. The list is then kept for the rest of the domain once it is not empty. + `hot_reload_compilation_list_reconstructed` appears once per domain reload. `filled` says whether + the rebuilt list filled the cache, and `reason` says why it did not: + - `no_saved_list`: no list has been saved yet. + - `saved_list_unreadable`: the saved list is torn, of another format version, or missing a + required field. + - `assembly_set_changed`: an assembly definition was added or removed after the list was saved. + - `pdb_mismatch`: the PDB beside a compiled-again dll belongs to another build, as while a + compile replaces the files. + - `pdb_documents_incomplete`: the PDB of a compiled-again assembly does not name every source + the compile was given. + - `unresolved_reference`: a reference has a file name the saved list does not know, or a project + reference is not in the list. + - `reference_missing`: every path saved for a reference's file name is gone, as when a package + update renames its folder. + - `reference_changed`: a saved path exists, but not with the dll of the recorded MVID. + - `compilation_failed`: the last compile failed, so the dlls are older than the sources. + - `superseded`: the cache was filled or invalidated meanwhile. + - `cancelled`: a compile started or the domain is ending. + - `tool_disabled`: the hot-reload tool is disabled in the tool settings. + - Any other value is the type name of the exception that stopped the rebuild. + `reconstructMs` is the time from the start of the rebuild to the entry, including the wait for + the main thread. `backgroundMs` is the time spent rebuilding on a pool thread, without the wait + for that thread, and `mainThreadWaitMs` the time it then waited for the main thread to run again. + Either is null when the rebuild did not get through that step. A `tool_disabled` entry has only + `filled` and `reason`, because no rebuild started. + When the cache was not filled, the first hot reload run that needs the list asks Unity for it + (`hot_reload_compilation_assemblies_fetched`) and saves it when the cache was not invalidated + in the domain and the last compile did not fail, so a reason that comes from an old saved list + (`no_saved_list`, `saved_list_unreadable`, `assembly_set_changed`, `unresolved_reference`, + `reference_missing`, `reference_changed`) does not repeat after that. Without a list, the + warm-up skips `publicized_targets`, `referenced_method_sets` and `transform_worker` with + `compilation_list_unavailable`. + `hot_reload_compilation_list_saved` appears when a list was written for the next domain, with + its size in `bytes`, `saveMs`, and the counts of `assemblies` and `references`. It is written on + a pool thread after a list is asked of Unity and after a rebuilt list fills the cache, only when + the cache was not invalidated in the domain and the last compile did not fail. + `hot_reload_compilation_list_save_skipped` names why a list was not saved in `reason`: + `generation` (the cache was invalidated in the domain), `compilation_failed`, or `superseded` + (a compile started while it was written). `hot_reload_compilation_list_save_failed` is a warning + with the exception type name in `error`. After a domain reload, the warm-up writes one `hot_reload_warm_up_complete` with the target assemblies, each item's `outcome` (`done`, `cancelled` or `failed`) and time, and `cancelledBy` (`run`, `beforeAssemblyReload`, `compilationStarted`, or null), or one From ce86ef9e30fda3f5eeef39d1d4339d944c6c02f5 Mon Sep 17 00:00:00 2001 From: hatayama Date: Mon, 12 Oct 2026 11:02:08 +0900 Subject: [PATCH 4/6] Describe pdb_documents_incomplete as the rebuild now decides it The rebuild reads the compiler's own PDB when a rewrite dropped documents, so the reason means neither PDB shows every source. --- docs/vibe-logs.md | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/docs/vibe-logs.md b/docs/vibe-logs.md index 3fb888071..cbb8d1f83 100644 --- a/docs/vibe-logs.md +++ b/docs/vibe-logs.md @@ -168,8 +168,8 @@ command ran against: - `assembly_set_changed`: an assembly definition was added or removed after the list was saved. - `pdb_mismatch`: the PDB beside a compiled-again dll belongs to another build, as while a compile replaces the files. - - `pdb_documents_incomplete`: the PDB of a compiled-again assembly does not name every source - the compile was given. + - `pdb_documents_incomplete`: neither the PDB of a compiled-again assembly nor the compiler's + own PDB of the same build shows that it names every source the compile was given. - `unresolved_reference`: a reference has a file name the saved list does not know, or a project reference is not in the list. - `reference_missing`: every path saved for a reference's file name is gone, as when a package From bc444e643bd2ee6ab422d155695efb9c2c4969c9 Mon Sep 17 00:00:00 2001 From: hatayama Date: Mon, 12 Oct 2026 11:16:23 +0900 Subject: [PATCH 5/6] Describe the compilation list as rebuilt first and asked of Unity after The class comment still said the list is asked of Unity once per domain, and the superseded save reason named only a compile, while an import that changes the script set invalidates the cache too. --- .../HotReload/Shared/HotReloadCompilationAssemblies.cs | 8 +++++--- docs/vibe-logs.md | 4 ++-- 2 files changed, 7 insertions(+), 5 deletions(-) diff --git a/Packages/src/Editor/FirstPartyTools/HotReload/Shared/HotReloadCompilationAssemblies.cs b/Packages/src/Editor/FirstPartyTools/HotReload/Shared/HotReloadCompilationAssemblies.cs index cb03b5b66..b429246ca 100644 --- a/Packages/src/Editor/FirstPartyTools/HotReload/Shared/HotReloadCompilationAssemblies.cs +++ b/Packages/src/Editor/FirstPartyTools/HotReload/Shared/HotReloadCompilationAssemblies.cs @@ -12,12 +12,14 @@ namespace io.github.hatayama.UnityCliLoop.FirstPartyTools { /// - /// The compilation assembly list for hot reload, asked of Unity once per domain. + /// The compilation assembly list for hot reload, kept for the rest of the domain. /// Why: on a project with several hundred assemblies one CompilationPipeline.GetAssemblies() call /// takes 340-620 ms, while the list only changes through a compile, or through an import that /// changes the script set without compiling (see HotReloadCompilationAssemblyListPostprocessor). - /// Whichever caller first needs the list after a domain reload asks Unity for it; later callers - /// in the domain find it kept. + /// After a domain reload the list is normally rebuilt on a pool thread from the list a previous + /// domain saved (RefillInBackground). Unity is asked only when that rebuild kept nothing or the + /// list was dropped in the domain, by the first caller that then needs it; later callers in the + /// domain find it kept. /// A list rebuilt at startup from the saved list holds only the fields hot reload reads: name, /// outputPath, sourceFiles, defines, assemblyReferences and compiledAssemblyReferences. /// compilerOptions, flags and rootNamespace keep their defaults, so code that needs them reads diff --git a/docs/vibe-logs.md b/docs/vibe-logs.md index cbb8d1f83..25e7caf46 100644 --- a/docs/vibe-logs.md +++ b/docs/vibe-logs.md @@ -198,8 +198,8 @@ command ran against: the cache was not invalidated in the domain and the last compile did not fail. `hot_reload_compilation_list_save_skipped` names why a list was not saved in `reason`: `generation` (the cache was invalidated in the domain), `compilation_failed`, or `superseded` - (a compile started while it was written). `hot_reload_compilation_list_save_failed` is a warning - with the exception type name in `error`. + (the cache was invalidated while it was written, as when a compile started). + `hot_reload_compilation_list_save_failed` is a warning with the exception type name in `error`. After a domain reload, the warm-up writes one `hot_reload_warm_up_complete` with the target assemblies, each item's `outcome` (`done`, `cancelled` or `failed`) and time, and `cancelledBy` (`run`, `beforeAssemblyReload`, `compilationStarted`, or null), or one From d298c1e426de2df631a54acc8c160d71f4b781e7 Mon Sep 17 00:00:00 2001 From: hatayama Date: Mon, 12 Oct 2026 11:23:44 +0900 Subject: [PATCH 6/6] Pin that a rebuild cancelled inside the pool work logs no time No test ran the work handed to the pool through a throw, so recording the background time even when the rebuild stopped part way was not caught. --- ...dCompilationAssemblyReconstructionTests.cs | 37 +++++++++++++++++++ 1 file changed, 37 insertions(+) diff --git a/Assets/Tests/Editor/HotReload/HotReloadCompilationAssemblyReconstructionTests.cs b/Assets/Tests/Editor/HotReload/HotReloadCompilationAssemblyReconstructionTests.cs index fbe81f37e..11a442efd 100644 --- a/Assets/Tests/Editor/HotReload/HotReloadCompilationAssemblyReconstructionTests.cs +++ b/Assets/Tests/Editor/HotReload/HotReloadCompilationAssemblyReconstructionTests.cs @@ -465,6 +465,43 @@ public async Task ReconstructAndFill_CancelledBeforeTheMainThread_LogsOnlyTheBac Assert.That(context["mainThreadWaitMs"].Type, Is.EqualTo(JTokenType.Null), "mainThreadWaitMs"); } + /// + /// What: a rebuild cancelled while the background work runs logs neither time as a number, + /// because the work threw before its time was taken. + /// + [Test] + public async Task ReconstructAndFill_CancelledDuringTheRebuild_LogsNeitherTime() + { + HotReloadCompilationAssemblyListStore store = SaveCleanThenEdit(saved => { }); + HotReloadCompilationAssemblyCache cache = new HotReloadCompilationAssemblyCache(Array.Empty); + TaskCompletionSource held = + new TaskCompletionSource(); + Func rebuild = null; + HotReloadCompilationListRefill refill = new HotReloadCompilationListRefill( + store, + cache, + HotReloadSnapshotCaptureInputs.ReadOnMainThread, + () => _isCompilationFailed, + work => + { + rebuild = work; + return held.Task; + }); + VibeLogger.ClearMemoryLogs(); + + Task run = refill.RunAsync(); + refill.Cancel(); + OperationCanceledException thrown = Assert.Throws(() => rebuild()); + held.SetException(thrown); + // Why awaited: the rest of the run resumes off this thread after the held rebuild completes. + await run; + + JObject context = HotReloadWarmUpTestDoubles.ReadSingleVibeContext(HotReloadConstants.VibeLogCompilationListReconstructed); + Assert.That((string)context["reason"], Is.EqualTo(HotReloadConstants.CompilationListReasonCancelled), "reason"); + Assert.That(context["backgroundMs"].Type, Is.EqualTo(JTokenType.Null), "backgroundMs"); + Assert.That(context["mainThreadWaitMs"].Type, Is.EqualTo(JTokenType.Null), "mainThreadWaitMs"); + } + /// /// What: a rebuild whose background work does not finish logs neither time as a number, so a /// step that never ran is not reported as taking 0 ms.