chore: Hot reload's startup log separates rebuilding the compilation list from waiting for the main thread

Assets/Tests/Editor/HotReload/HotReloadCompilationAssemblyReconstructionTests.cs

@@ -5,6 +5,7 @@
 using System.Threading.Tasks;
 
 using Newtonsoft.Json;
+using Newtonsoft.Json.Linq;
 
 using NUnit.Framework;
 
@@ -402,6 +403,132 @@ public void ReconstructAndFill_WhileCompilationFailed_KeepsAndSavesNothing()
                 Is.EqualTo(HotReloadConstants.CompilationListReasonCompilationFailed));
         }
 
+        /// <summary>
+        /// 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.
+        /// </summary>
+        [Test]
+        public void ReconstructAndFill_WhenFilled_LogsTheBackgroundAndMainThreadWaitTimes()
+        {
+            HotReloadCompilationAssemblyListStore store = SaveCleanThenEdit(saved => { });
+            HotReloadCompilationAssemblyCache cache = new HotReloadCompilationAssemblyCache(Array.Empty<UnityCompilationAssembly>);
+            VibeLogger.ClearMemoryLogs();
+
+            Task<bool> 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");
+        }
+
+        /// <summary>
+        /// 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.
+        /// </summary>
+        [Test]
+        public async Task ReconstructAndFill_CancelledBeforeTheMainThread_LogsOnlyTheBackgroundTime()
+        {
+            HotReloadCompilationAssemblyListStore store = SaveCleanThenEdit(saved => { });
+            HotReloadCompilationAssemblyCache cache = new HotReloadCompilationAssemblyCache(Array.Empty<UnityCompilationAssembly>);
+            TaskCompletionSource<HotReloadCompilationListReconstruction> held =
+                new TaskCompletionSource<HotReloadCompilationListReconstruction>();
+            Func<HotReloadCompilationListReconstruction> rebuild = null;
+            HotReloadCompilationListRefill refill = new HotReloadCompilationListRefill(
+                store,
+                cache,
+                HotReloadSnapshotCaptureInputs.ReadOnMainThread,
+                () => _isCompilationFailed,
+                work =>
+                {
+                    rebuild = work;
+                    return held.Task;
+                });
+            VibeLogger.ClearMemoryLogs();
+
+            Task<bool> 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");
+        }
+
+        /// <summary>
+        /// What: a rebuild cancelled while the background work runs logs neither time as a number,
+        /// because the work threw before its time was taken.
+        /// </summary>
+        [Test]
+        public async Task ReconstructAndFill_CancelledDuringTheRebuild_LogsNeitherTime()
+        {
+            HotReloadCompilationAssemblyListStore store = SaveCleanThenEdit(saved => { });
+            HotReloadCompilationAssemblyCache cache = new HotReloadCompilationAssemblyCache(Array.Empty<UnityCompilationAssembly>);
+            TaskCompletionSource<HotReloadCompilationListReconstruction> held =
+                new TaskCompletionSource<HotReloadCompilationListReconstruction>();
+            Func<HotReloadCompilationListReconstruction> rebuild = null;
+            HotReloadCompilationListRefill refill = new HotReloadCompilationListRefill(
+                store,
+                cache,
+                HotReloadSnapshotCaptureInputs.ReadOnMainThread,
+                () => _isCompilationFailed,
+                work =>
+                {
+                    rebuild = work;
+                    return held.Task;
+                });
+            VibeLogger.ClearMemoryLogs();
+
+            Task<bool> run = refill.RunAsync();
+            refill.Cancel();
+            OperationCanceledException thrown = Assert.Throws<OperationCanceledException>(() => 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");
+        }
+
+        /// <summary>
+        /// 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.
+        /// </summary>
+        [Test]
+        public void ReconstructAndFill_WhenTheRebuildFails_LogsNeitherTime()
+        {
+            HotReloadCompilationAssemblyListStore store = SaveCleanThenEdit(saved => { });
+            HotReloadCompilationAssemblyCache cache = new HotReloadCompilationAssemblyCache(Array.Empty<UnityCompilationAssembly>);
+            HotReloadCompilationListRefill refill = new HotReloadCompilationListRefill(
+                store,
+                cache,
+                HotReloadSnapshotCaptureInputs.ReadOnMainThread,
+                () => _isCompilationFailed,
+                work => Task.FromException<HotReloadCompilationListReconstruction>(new InvalidOperationException("test")));
+            VibeLogger.ClearMemoryLogs();
+
+            Task<bool> 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<HotReloadSavedReference> editTargetReference)
         {
             HotReloadCompilationAssemblyListStore store = SaveCleanThenEdit(saved =>

Packages/src/Editor/FirstPartyTools/HotReload/Shared/HotReloadCompilationAssemblies.cs

@@ -12,12 +12,14 @@
 namespace io.github.hatayama.UnityCliLoop.FirstPartyTools
 {
     /// <summary>
-    /// 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

Packages/src/Editor/FirstPartyTools/HotReload/Shared/HotReloadCompilationListRefill.cs

@@ -69,21 +69,31 @@ internal void Cancel()
         private async Task<bool> 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,30 +108,31 @@ private async Task<bool> 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)
             {
                 // 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 });
         }
     }
 }

docs/vibe-logs.md

@@ -155,9 +155,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`: 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
+    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`
+  (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