diff --git a/Assets/Tests/Editor/HotReload/HotReloadCompilationAssemblyReconstructionTests.cs b/Assets/Tests/Editor/HotReload/HotReloadCompilationAssemblyReconstructionTests.cs index 3b258a9de..11a442efd 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; @@ -402,6 +403,132 @@ 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 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. + /// + [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 => 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/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 }); } } } diff --git a/docs/vibe-logs.md b/docs/vibe-logs.md index 9e1bdb384..25e7caf46 100644 --- a/docs/vibe-logs.md +++ b/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