From d6c29b23a5e3751a4333c3ffe4e3d243702e6837 Mon Sep 17 00:00:00 2001 From: hatayama Date: Sun, 11 Oct 2026 13:08:08 +0900 Subject: [PATCH 1/5] Log how long each phase of the source snapshot capture takes A compile on a large project spends one to several seconds of the main thread in the source snapshot capture, and the single captureMs figure does not say which phase to attack. The capture now sums the time of each phase and its counts, returns them from CaptureAssemblies, and writes one hot_reload_source_snapshot_breakdown entry per capture. Behavior is unchanged. --- ...tReloadSnapshotAssemblyEnumerationTests.cs | 46 +++++++++++++++ ...tReloadSnapshotEditedDuringCompileTests.cs | 3 +- .../HotReload/HotReloadSourceSnapshotTests.cs | 37 +++++++++++- .../HotReloadSourceSnapshotterTests.cs | 9 ++- .../HotReload/Shared/HotReloadConstants.cs | 1 + .../Shared/HotReloadSnapshotCaptureStats.cs | 58 +++++++++++++++++++ .../HotReloadSnapshotCaptureStats.cs.meta | 11 ++++ .../Shared/HotReloadSourceSnapshotCopier.cs | 36 ++++++++++-- .../Shared/HotReloadSourceSnapshotter.cs | 47 ++++++++++++--- 9 files changed, 229 insertions(+), 19 deletions(-) create mode 100644 Packages/src/Editor/FirstPartyTools/HotReload/Shared/HotReloadSnapshotCaptureStats.cs create mode 100644 Packages/src/Editor/FirstPartyTools/HotReload/Shared/HotReloadSnapshotCaptureStats.cs.meta diff --git a/Assets/Tests/Editor/HotReload/HotReloadSnapshotAssemblyEnumerationTests.cs b/Assets/Tests/Editor/HotReload/HotReloadSnapshotAssemblyEnumerationTests.cs index c6f162161..1e438266c 100644 --- a/Assets/Tests/Editor/HotReload/HotReloadSnapshotAssemblyEnumerationTests.cs +++ b/Assets/Tests/Editor/HotReload/HotReloadSnapshotAssemblyEnumerationTests.cs @@ -392,6 +392,43 @@ public void CaptureAssemblies_WithoutARecordedStart_LeavesASourceSavedBeforeTheD Assert.That(manifest.TryGetStamp(SnapshotFileName(), out long _, out long _), Is.True); } + /// + /// Verifies a capture reports how many assemblies it captured or found unchanged and how many + /// files and bytes it copied: the first capture copies the two sources that exist and skips the + /// missing one, and a second capture of the same build copies nothing. + /// + [Test] + public void CaptureAssemblies_ReturnsWhatItCopiedAndWhatItSkipped() + { + PlantCompiledAssembly("Fixture"); + WriteSourceWrittenBeforeTheCompile("Assets/Three.cs", "abc"); + WriteSourceWrittenBeforeTheCompile("Assets/Five.cs", "abcde"); + UnityCompilationAssembly[] assemblies = + { + CreateAssemblyWithSources("Fixture", new[] { "Assets/Three.cs", "Assets/Five.cs", "Assets/Missing.cs" }) + }; + + HotReloadSnapshotCaptureStats first = HotReloadSourceSnapshotter.CaptureAssemblies( + _projectRoot, + assemblies, + HotReloadCompileStart.Unknown, + CreateDocumentIndex()); + HotReloadSnapshotCaptureStats second = HotReloadSourceSnapshotter.CaptureAssemblies( + _projectRoot, + assemblies, + HotReloadCompileStart.Unknown, + CreateDocumentIndex()); + + Assert.That(first.Assemblies, Is.EqualTo(1), "first: assemblies"); + Assert.That(first.AssembliesCaptured, Is.EqualTo(1), "first: captured"); + Assert.That(first.AssembliesUnchanged, Is.EqualTo(0), "first: unchanged"); + Assert.That(first.FilesCopied, Is.EqualTo(2), "first: files copied"); + Assert.That(first.BytesCopied, Is.EqualTo(8), "first: bytes copied"); + Assert.That(second.AssembliesCaptured, Is.EqualTo(0), "second: captured"); + Assert.That(second.AssembliesUnchanged, Is.EqualTo(1), "second: unchanged"); + Assert.That(second.FilesCopied, Is.EqualTo(0), "second: files copied"); + } + // Plants the compiled assembly and orders the write times as compile start < source < DLL. // The fixture source has no document in the planted PDB, so a check cannot confirm it. private string CaptureWithSourceSavedBetweenStartAndDll(HotReloadCompileStart compileStart) @@ -412,6 +449,15 @@ private string CaptureWithSourceSavedBetweenStartAndDll(HotReloadCompileStart co return Path.Combine(_snapshotRoot, "Fixture-" + mvid); } + // Writes the source as ASCII with a write time before the planted compile, so the capture + // copies it without a PDB check. + private void WriteSourceWrittenBeforeTheCompile(string projectRelativePath, string text) + { + string path = Path.Combine(_projectRoot, projectRelativePath.Replace('/', Path.DirectorySeparatorChar)); + File.WriteAllBytes(path, System.Text.Encoding.ASCII.GetBytes(text)); + File.SetLastWriteTimeUtc(path, new DateTime(2020, 1, 1, 0, 0, 0, DateTimeKind.Utc)); + } + private static string SnapshotFileName() { return HotReloadSourceSnapshotLayout.SourceFileName(SourceRelativePath); diff --git a/Assets/Tests/Editor/HotReload/HotReloadSnapshotEditedDuringCompileTests.cs b/Assets/Tests/Editor/HotReload/HotReloadSnapshotEditedDuringCompileTests.cs index 290c33f9c..e0699649e 100644 --- a/Assets/Tests/Editor/HotReload/HotReloadSnapshotEditedDuringCompileTests.cs +++ b/Assets/Tests/Editor/HotReload/HotReloadSnapshotEditedDuringCompileTests.cs @@ -134,7 +134,8 @@ private HotReloadSourceStampManifest Capture(string projectRelativePath) _snapshotDirectory, new[] { projectRelativePath }, TestAssemblyName, - check); + check, + new HotReloadSnapshotCaptureStats()); return HotReloadSourceStampManifest.Load(_snapshotDirectory); } diff --git a/Assets/Tests/Editor/HotReload/HotReloadSourceSnapshotTests.cs b/Assets/Tests/Editor/HotReload/HotReloadSourceSnapshotTests.cs index e33fbb089..860c5ccd7 100644 --- a/Assets/Tests/Editor/HotReload/HotReloadSourceSnapshotTests.cs +++ b/Assets/Tests/Editor/HotReload/HotReloadSourceSnapshotTests.cs @@ -9,6 +9,8 @@ using Mono.Cecil.Cil; using Mono.Cecil.Pdb; +using Newtonsoft.Json.Linq; + using NUnit.Framework; using UnityEditor.Compilation; @@ -17,6 +19,7 @@ using UnityEngine.TestTools; using io.github.hatayama.UnityCliLoop.FirstPartyTools; +using io.github.hatayama.UnityCliLoop.ToolContracts; using UnityCompilationAssembly = UnityEditor.Compilation.Assembly; @@ -191,6 +194,34 @@ public void LoadVerifiedSnapshotSource_PackageSourceGivenByItsAssetPath_ReturnsT Assert.That(loaded, Is.EqualTo(File.ReadAllText(Path.Combine(projectRoot, PackageSourcePhysicalPath)))); } + /// + /// What: a capture after a domain reload writes one breakdown entry over a non-empty assembly + /// list, carrying every phase time and count, none of them negative. + /// + [Test] + public void CaptureAfterDomainReload_LogsOneBreakdownWithEveryPhase() + { + VibeLogger.ClearMemoryLogs(); + + HotReloadSourceSnapshotter.CaptureAfterDomainReload(); + + JObject context = HotReloadWarmUpTestDoubles.ReadSingleVibeContext(HotReloadConstants.VibeLogSourceSnapshotBreakdown); + string[] fields = + { + "getAssembliesMs", "packageLookupMs", "stampMs", "mvidMs", "statMs", "readWriteMs", + "pdbCheckMs", "publishMs", "cleanupMs", "totalMs", "assemblies", "assembliesImmutable", + "assembliesUnchanged", "assembliesCaptured", "filesCopied", "bytesCopied", "filesChecked" + }; + foreach (string field in fields) + { + Assert.That(context[field], Is.Not.Null, field); + Assert.That(context[field].Type, Is.EqualTo(JTokenType.Integer), field + " type"); + Assert.That((long)context[field], Is.GreaterThanOrEqualTo(0), field); + } + + Assert.That((long)context["assemblies"], Is.GreaterThan(0)); + } + /// /// What: in a Multiplayer Play Mode Virtual Player, whose root lies under the main project's /// Library, a package source's PDB document is found by the path the main project's compile @@ -598,7 +629,8 @@ public void CaptureAtomically_LongWindowsSource_CapturesByteExactSnapshot() snapshotDirectory, new[] { sourceRelativePath }, "LongPathAssembly", - SuspectsNothing(root)); + SuspectsNothing(root), + new HotReloadSnapshotCaptureStats()); string normalizedRelativePath = sourceRelativePath.Replace('\\', '/'); string snapshotPath = Path.Combine( @@ -672,7 +704,8 @@ public void CaptureAtomically_OneLockedSource_CompletesWithReadableSnapshots() snapshotDirectory, sourceRelativePaths, "LockedSourceAssembly", - SuspectsNothing(root)); + SuspectsNothing(root), + new HotReloadSnapshotCaptureStats()); } Assert.That(Directory.Exists(snapshotDirectory), Is.True); diff --git a/Assets/Tests/Editor/HotReload/HotReloadSourceSnapshotterTests.cs b/Assets/Tests/Editor/HotReload/HotReloadSourceSnapshotterTests.cs index 365c5fd24..49203054f 100644 --- a/Assets/Tests/Editor/HotReload/HotReloadSourceSnapshotterTests.cs +++ b/Assets/Tests/Editor/HotReload/HotReloadSourceSnapshotterTests.cs @@ -53,7 +53,8 @@ public void CaptureAtomically_ExistingAndMissingSources_CopiesExistingByteExactU snapshotDirectory, sourceFiles, "Fixture", - SuspectsNothing(_tempRoot)); + SuspectsNothing(_tempRoot), + new HotReloadSnapshotCaptureStats()); string firstSnapshot = Path.Combine( snapshotDirectory, @@ -89,7 +90,8 @@ public void CaptureAtomically_RecordsTheLengthAndWriteTimeOfEachCopiedSource() snapshotDirectory, sourceFiles, "Fixture", - SuspectsNothing(_tempRoot)); + SuspectsNothing(_tempRoot), + new HotReloadSnapshotCaptureStats()); string expected = HotReloadConstants.SourceStampManifestHeader + "\n" + HotReloadSourceSnapshotLayout.SourceFileName("Sources/First.cs") + "\t7\t" @@ -121,7 +123,8 @@ public void CaptureAtomically_WhenTemporaryDirectoryIsLeftOver_PublishesOnlyFres snapshotDirectory, new[] { "Sources/Fresh.cs" }, "Fixture", - SuspectsNothing(_tempRoot)); + SuspectsNothing(_tempRoot), + new HotReloadSnapshotCaptureStats()); string[] publishedNames = Directory.GetFiles(snapshotDirectory).Select(Path.GetFileName).ToArray(); // Why EquivalentTo: the order GetFiles lists files in depends on the file system. diff --git a/Packages/src/Editor/FirstPartyTools/HotReload/Shared/HotReloadConstants.cs b/Packages/src/Editor/FirstPartyTools/HotReload/Shared/HotReloadConstants.cs index 1d552fa21..da47c35f5 100644 --- a/Packages/src/Editor/FirstPartyTools/HotReload/Shared/HotReloadConstants.cs +++ b/Packages/src/Editor/FirstPartyTools/HotReload/Shared/HotReloadConstants.cs @@ -676,6 +676,7 @@ public static bool IsPublicizableProjectAssemblyFileName(string fileNameWithoutE public const string VibeLogShimReferencesTiming = "hot_reload_shim_references_timing"; public const string VibeLogPublicizedCopyWritten = "hot_reload_publicized_copy_written"; public const string VibeLogSourceSnapshotChecked = "hot_reload_source_snapshot_checked"; + public const string VibeLogSourceSnapshotBreakdown = "hot_reload_source_snapshot_breakdown"; public const string VibeLogShimCompilerTiming = "hot_reload_shim_compiler_timing"; public const string VibeLogShimCompileFailed = "hot_reload_shim_compile_failed"; public const string VibeLogIsolationRetry = "hot_reload_isolation_retry"; diff --git a/Packages/src/Editor/FirstPartyTools/HotReload/Shared/HotReloadSnapshotCaptureStats.cs b/Packages/src/Editor/FirstPartyTools/HotReload/Shared/HotReloadSnapshotCaptureStats.cs new file mode 100644 index 000000000..1097c0cd4 --- /dev/null +++ b/Packages/src/Editor/FirstPartyTools/HotReload/Shared/HotReloadSnapshotCaptureStats.cs @@ -0,0 +1,58 @@ +using System; + +namespace io.github.hatayama.UnityCliLoop.FirstPartyTools +{ + /// + /// The time one source snapshot capture spent in each of its phases and how much it did, so the + /// breakdown log shows where a slow capture went. + /// + internal sealed class HotReloadSnapshotCaptureStats + { + // Times are TimeSpan ticks, summed over every assembly and source of the capture. + internal long PackageLookupTicks; + internal long StampTicks; + internal long MvidTicks; + internal long StatTicks; + internal long ReadWriteTicks; + internal long PdbCheckTicks; + internal long PublishTicks; + internal long CleanupTicks; + + internal int Assemblies; + internal int AssembliesImmutable; + internal int AssembliesUnchanged; + internal int AssembliesCaptured; + internal int FilesCopied; + internal long BytesCopied; + internal int FilesChecked; + + internal object ToVibeLogContext(long getAssembliesMs, long totalMs) + { + return new + { + getAssembliesMs, + packageLookupMs = ToMilliseconds(PackageLookupTicks), + stampMs = ToMilliseconds(StampTicks), + mvidMs = ToMilliseconds(MvidTicks), + statMs = ToMilliseconds(StatTicks), + readWriteMs = ToMilliseconds(ReadWriteTicks), + pdbCheckMs = ToMilliseconds(PdbCheckTicks), + publishMs = ToMilliseconds(PublishTicks), + cleanupMs = ToMilliseconds(CleanupTicks), + totalMs, + assemblies = Assemblies, + assembliesImmutable = AssembliesImmutable, + assembliesUnchanged = AssembliesUnchanged, + assembliesCaptured = AssembliesCaptured, + filesCopied = FilesCopied, + bytesCopied = BytesCopied, + filesChecked = FilesChecked + }; + } + + private static long ToMilliseconds(long ticks) + { + return (long)TimeSpan.FromTicks(ticks).TotalMilliseconds; + } + } +} diff --git a/Packages/src/Editor/FirstPartyTools/HotReload/Shared/HotReloadSnapshotCaptureStats.cs.meta b/Packages/src/Editor/FirstPartyTools/HotReload/Shared/HotReloadSnapshotCaptureStats.cs.meta new file mode 100644 index 000000000..f0b624a61 --- /dev/null +++ b/Packages/src/Editor/FirstPartyTools/HotReload/Shared/HotReloadSnapshotCaptureStats.cs.meta @@ -0,0 +1,11 @@ +fileFormatVersion: 2 +guid: 9d7b4040037434c64a08d61389d35e3f +MonoImporter: + externalObjects: {} + serializedVersion: 2 + defaultReferences: [] + executionOrder: 0 + icon: {instanceID: 0} + userData: + assetBundleName: + assetBundleVariant: diff --git a/Packages/src/Editor/FirstPartyTools/HotReload/Shared/HotReloadSourceSnapshotCopier.cs b/Packages/src/Editor/FirstPartyTools/HotReload/Shared/HotReloadSourceSnapshotCopier.cs index 8188dd526..7b5c140d2 100644 --- a/Packages/src/Editor/FirstPartyTools/HotReload/Shared/HotReloadSourceSnapshotCopier.cs +++ b/Packages/src/Editor/FirstPartyTools/HotReload/Shared/HotReloadSourceSnapshotCopier.cs @@ -20,19 +20,24 @@ internal static void CaptureAtomically( string assemblySnapshotDirectory, string[] sourceFiles, string assemblyName, - HotReloadSnapshotSourceCheck check) + HotReloadSnapshotSourceCheck check, + HotReloadSnapshotCaptureStats stats) { + Debug.Assert(stats != null, "stats must not be null."); + // Why temp + Move: Directory.Exists is the "complete" signal. Copying into the final // directory first would leave a partial tree on interrupt that later reloads treat as // done and stamp-short-circuit forever. A sibling .tmp only becomes visible as complete // after Move succeeds. string temporaryDirectory = assemblySnapshotDirectory + HotReloadSourceSnapshotLayout.IncompleteDirectorySuffix; + System.Diagnostics.Stopwatch prepareWatch = System.Diagnostics.Stopwatch.StartNew(); if (Directory.Exists(temporaryDirectory)) { Directory.Delete(temporaryDirectory, recursive: true); } Directory.CreateDirectory(temporaryDirectory); + stats.PublishTicks += prepareWatch.Elapsed.Ticks; int skippedSourceCount = 0; string firstSkippedSourcePath = null; int suspectSourceCount = 0; @@ -46,7 +51,8 @@ internal static void CaptureAtomically( temporaryDirectory, projectRelativeSourcePath, check, - manifestLines); + manifestLines, + stats); if (outcome.Kind == SourceCopyKind.Unreadable) { skippedSourceCount++; @@ -66,8 +72,10 @@ internal static void CaptureAtomically( } } + System.Diagnostics.Stopwatch publishWatch = System.Diagnostics.Stopwatch.StartNew(); HotReloadSourceStampManifest.Write(temporaryDirectory, manifestLines); Directory.Move(temporaryDirectory, assemblySnapshotDirectory); + stats.PublishTicks += publishWatch.Elapsed.Ticks; if (suspectSourceCount > 0) { VibeLogger.LogInfo( @@ -95,25 +103,30 @@ private static SourceCopyOutcome CopySourceFileByteExact( string assemblySnapshotDirectory, string projectRelativeSourcePath, HotReloadSnapshotSourceCheck check, - List manifestLines) + List manifestLines, + HotReloadSnapshotCaptureStats stats) { string normalizedRelativePath = projectRelativeSourcePath.Replace('\\', '/'); string absoluteSourcePath = Path.Combine(projectRoot, normalizedRelativePath.Replace('/', Path.DirectorySeparatorChar)); string fileSystemSourcePath = HotReloadFileSystemPath.GetFileSystemPath(absoluteSourcePath); + System.Diagnostics.Stopwatch statWatch = System.Diagnostics.Stopwatch.StartNew(); FileInfo sourceBefore = new FileInfo(fileSystemSourcePath); - if (!sourceBefore.Exists) + bool sourceExists = sourceBefore.Exists; + long length = sourceExists ? sourceBefore.Length : 0; + long lastWriteTimeUtcTicks = sourceExists ? sourceBefore.LastWriteTimeUtc.Ticks : 0; + stats.StatTicks += statWatch.Elapsed.Ticks; + if (!sourceExists) { return new SourceCopyOutcome(SourceCopyKind.NotFound, 0); } - long length = sourceBefore.Length; - long lastWriteTimeUtcTicks = sourceBefore.LastWriteTimeUtc.Ticks; string snapshotFileName = HotReloadSourceSnapshotLayout.SourceFileName(normalizedRelativePath); if (!TryCopySource( fileSystemSourcePath, Path.Combine(assemblySnapshotDirectory, snapshotFileName), length, lastWriteTimeUtcTicks, + stats, out byte[] bytes, out bool stampHeldDuringRead)) { @@ -149,6 +162,9 @@ private static SourceCopyOutcome CopySourceFileByteExact( return new SourceCopyOutcome(SourceCopyKind.Trusted, 0); } + stats.PdbCheckTicks += checkWatch.Elapsed.Ticks; + stats.FilesChecked++; + SourceCopyKind checkedKind = verdict == HotReloadSnapshotCopyVerdict.EditedAfterCompile ? SourceCopyKind.CheckedEditedAfterCompile : SourceCopyKind.Checked; @@ -162,21 +178,28 @@ private static bool TryCopySource( string destinationPath, long length, long lastWriteTimeUtcTicks, + HotReloadSnapshotCaptureStats stats, out byte[] bytes, out bool stampHeldDuringRead) { + System.Diagnostics.Stopwatch readWriteWatch = System.Diagnostics.Stopwatch.StartNew(); try { bytes = File.ReadAllBytes(fileSystemSourcePath); File.WriteAllBytes(destinationPath, bytes); + stats.ReadWriteTicks += readWriteWatch.Elapsed.Ticks; + stats.FilesCopied++; + stats.BytesCopied += bytes.Length; // Why the stamp is taken before the read and checked again after it: a write during the // read moves the stamp on, and a stamp recorded then could vouch for bytes the copy does // not hold. Such a source is checked against the PDB: it gets no line when it matches, // so readers compare it by bytes until the next capture, and a marked line when it does not. + System.Diagnostics.Stopwatch statWatch = System.Diagnostics.Stopwatch.StartNew(); FileInfo sourceAfter = new FileInfo(fileSystemSourcePath); stampHeldDuringRead = sourceAfter.Exists && sourceAfter.Length == length && sourceAfter.LastWriteTimeUtc.Ticks == lastWriteTimeUtcTicks; + stats.StatTicks += statWatch.Elapsed.Ticks; return true; } catch (Exception ex) when (IsSkippableSourceReadException(ex)) @@ -185,6 +208,7 @@ private static bool TryCopySource( // while an assembly is being snapshotted. Skipping preserves the fail-closed // invariant because the method-diff baseline rejects any missing snapshot by PDB // checksum at use time. + stats.ReadWriteTicks += readWriteWatch.Elapsed.Ticks; bytes = null; stampHeldDuringRead = false; return false; diff --git a/Packages/src/Editor/FirstPartyTools/HotReload/Shared/HotReloadSourceSnapshotter.cs b/Packages/src/Editor/FirstPartyTools/HotReload/Shared/HotReloadSourceSnapshotter.cs index e06eb4857..a1f874e7e 100644 --- a/Packages/src/Editor/FirstPartyTools/HotReload/Shared/HotReloadSourceSnapshotter.cs +++ b/Packages/src/Editor/FirstPartyTools/HotReload/Shared/HotReloadSourceSnapshotter.cs @@ -2,6 +2,8 @@ using System.Collections.Generic; using System.IO; +using io.github.hatayama.UnityCliLoop.ToolContracts; + using UnityEditor.PackageManager; using UnityEngine; @@ -24,23 +26,33 @@ internal static partial class HotReloadSourceSnapshotter /// when it is captured, and marked in the manifest when it does not match, so the default file /// selection, the sibling scan and the skip check treat that file as changed. The method-diff /// baseline checks every copy against the PDB when it uses one. + /// Logs how long each phase took, even when the list is empty. /// Returns false when Unity listed no compilation assembly (as while it compiles). /// internal static bool CaptureAfterDomainReload() { + System.Diagnostics.Stopwatch totalWatch = System.Diagnostics.Stopwatch.StartNew(); string projectRoot = Path.GetFullPath(Path.Combine(Application.dataPath, "..")); + System.Diagnostics.Stopwatch getAssembliesWatch = System.Diagnostics.Stopwatch.StartNew(); IReadOnlyList assemblies = HotReloadCompilationAssemblies.Current(); - CaptureAssemblies( + getAssembliesWatch.Stop(); + HotReloadSnapshotCaptureStats stats = CaptureAssemblies( projectRoot, assemblies, HotReloadCompileStartRecord.Read(), HotReloadPdbDocumentIndex.Shared); + totalWatch.Stop(); + VibeLogger.LogInfo( + HotReloadConstants.VibeLogSourceSnapshotBreakdown, + "Hot reload source snapshot capture breakdown.", + stats.ToVibeLogContext(getAssembliesWatch.ElapsedMilliseconds, totalWatch.ElapsedMilliseconds)); return assemblies.Count > 0; } // Why separate from CaptureAfterDomainReload: the project root and the compilation assemblies come // from Unity, so taking them as arguments lets tests drive the per-assembly loop in a temporary root. - internal static void CaptureAssemblies( + // Returns how long each phase took and how much the capture did. + internal static HotReloadSnapshotCaptureStats CaptureAssemblies( string projectRoot, IEnumerable assemblies, HotReloadCompileStart compileStart, @@ -53,11 +65,13 @@ internal static void CaptureAssemblies( string snapshotRoot = HotReloadSourceSnapshotLayout.Root(projectRoot); Directory.CreateDirectory(snapshotRoot); + HotReloadSnapshotCaptureStats stats = new HotReloadSnapshotCaptureStats(); foreach (UnityCompilationAssembly assembly in assemblies) { + stats.Assemblies++; try { - CaptureAssemblyIfNeeded(projectRoot, snapshotRoot, assembly, compileStart, documentIndex); + CaptureAssemblyIfNeeded(projectRoot, snapshotRoot, assembly, compileStart, documentIndex, stats); } catch (Exception ex) when (IsSkippableAssemblyCaptureException(ex)) { @@ -69,6 +83,8 @@ internal static void CaptureAssemblies( $"[UnityCliLoop] Snapshot capture failed for assembly {assembly.name}: {ex.Message}"); } } + + return stats; } private static bool IsSkippableAssemblyCaptureException(Exception ex) @@ -85,7 +101,8 @@ private static void CaptureAssemblyIfNeeded( string snapshotRoot, UnityCompilationAssembly assembly, HotReloadCompileStart compileStart, - HotReloadPdbDocumentIndex documentIndex) + HotReloadPdbDocumentIndex documentIndex, + HotReloadSnapshotCaptureStats stats) { string[] sourceFiles = assembly.sourceFiles; if (sourceFiles == null || sourceFiles.Length == 0) @@ -93,8 +110,12 @@ private static void CaptureAssemblyIfNeeded( return; } - if (ShouldSkipImmutablePackageSources(sourceFiles)) + System.Diagnostics.Stopwatch packageLookupWatch = System.Diagnostics.Stopwatch.StartNew(); + bool immutable = ShouldSkipImmutablePackageSources(sourceFiles); + stats.PackageLookupTicks += packageLookupWatch.Elapsed.Ticks; + if (immutable) { + stats.AssembliesImmutable++; return; } @@ -116,12 +137,18 @@ private static void CaptureAssemblyIfNeeded( // Why stamp short-circuits Cecil: a false stamp (identical mtime+length with different // bytes) is vanishingly rare, and even then LoadVerifiedSnapshotSource rejects via PDB // checksum — so stamp lies degrade to fallback, never to a wrong method diff. - if (HasMatchingStamp(stampPath, dllMtimeTicks, dllByteLength)) + System.Diagnostics.Stopwatch stampWatch = System.Diagnostics.Stopwatch.StartNew(); + bool stampMatches = HasMatchingStamp(stampPath, dllMtimeTicks, dllByteLength); + stats.StampTicks += stampWatch.Elapsed.Ticks; + if (stampMatches) { + stats.AssembliesUnchanged++; return; } + System.Diagnostics.Stopwatch mvidWatch = System.Diagnostics.Stopwatch.StartNew(); string mvid = HotReloadAssemblyMvid.Read(dllPath); + stats.MvidTicks += mvidWatch.Elapsed.Ticks; string assemblySnapshotDirectory = HotReloadSourceSnapshotLayout.AssemblyDirectory(projectRoot, assembly.name, mvid); if (!Directory.Exists(assemblySnapshotDirectory)) { @@ -136,15 +163,21 @@ private static void CaptureAssemblyIfNeeded( assemblySnapshotDirectory, sourceFiles, assembly.name, - check); + check, + stats); + stats.AssembliesCaptured++; + System.Diagnostics.Stopwatch cleanupWatch = System.Diagnostics.Stopwatch.StartNew(); DeleteStaleSnapshotDirectories(snapshotRoot, assembly.name, assemblySnapshotDirectory); + stats.CleanupTicks += cleanupWatch.Elapsed.Ticks; } // Write the stamp even when individual sources were skipped: retrying every domain // reload would only repeat IO and warning spam. The partial snapshot remains fail-closed // because the method-diff baseline requires a PDB checksum match, and a changed DLL // invalidates this stamp through its mtime or length before the next capture. + System.Diagnostics.Stopwatch writeStampWatch = System.Diagnostics.Stopwatch.StartNew(); WriteStamp(stampPath, mvid, dllMtimeTicks, dllByteLength); + stats.StampTicks += writeStampWatch.Elapsed.Ticks; } /// From 979e995adde27caf9dc0d571f894b02e85acb4ca Mon Sep 17 00:00:00 2001 From: hatayama Date: Sun, 11 Oct 2026 13:08:09 +0900 Subject: [PATCH 2/5] Document the source snapshot capture breakdown log entry --- docs/vibe-logs.md | 22 ++++++++++++++++++++++ 1 file changed, 22 insertions(+) diff --git a/docs/vibe-logs.md b/docs/vibe-logs.md index 60d022fed..fd043bf15 100644 --- a/docs/vibe-logs.md +++ b/docs/vibe-logs.md @@ -94,6 +94,28 @@ command ran against: capture ran to completion, with its `trigger` (`domain_load` normally; `first_update_tick` or `apply` only when the capture at domain load threw or Unity listed no compilation assembly yet) and `captureMs`. + `hot_reload_source_snapshot_breakdown` appears once each time the capture runs to the end, + just before `hot_reload_source_snapshot_captured` (also when Unity listed no compilation + assembly, but not when the capture threw). It says where the capture spent its time: + - `getAssembliesMs`: listing the compilation assemblies from Unity. + - `packageLookupMs`: asking Package Manager whether each assembly's sources are immutable. + - `stampMs`: reading and writing the stamps beside the snapshots. + - `mvidMs`: reading the MVID of each compiled dll whose stamp did not match. + - `statMs`: reading each source's length and write time before and after it is copied. + - `readWriteMs`: reading each source and writing its copy. + - `pdbCheckMs`: checking the sources written since the compile started against the PDB. + - `publishMs`: deleting a leftover temporary directory and creating a new one, writing the + manifest, and moving the directory into place. + - `cleanupMs`: deleting the snapshot directories of earlier builds. + - `totalMs`: the whole capture. + - `assemblies`: the compilation assemblies listed. + - `assembliesImmutable`: those skipped because their sources belong to an immutable package. + - `assembliesUnchanged`: those skipped because their stamp matched the compiled dll. + - `assembliesCaptured`: those whose sources were copied into a new snapshot directory. + - `filesCopied` and `bytesCopied`: the sources copied and their total size. + - `filesChecked`: the sources checked against the PDB. + The phases add up to `totalMs` except for the loop overhead; `captureMs` in the captured entry + also includes the gate. 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 84f0d7adf6d7d9667747aa0f7e00b527b2b3a2de Mon Sep 17 00:00:00 2001 From: hatayama Date: Sun, 11 Oct 2026 13:15:07 +0900 Subject: [PATCH 3/5] Say that no captured entry follows a breakdown of an empty assembly list --- docs/vibe-logs.md | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/docs/vibe-logs.md b/docs/vibe-logs.md index fd043bf15..c457f368e 100644 --- a/docs/vibe-logs.md +++ b/docs/vibe-logs.md @@ -95,8 +95,9 @@ command ran against: `apply` only when the capture at domain load threw or Unity listed no compilation assembly yet) and `captureMs`. `hot_reload_source_snapshot_breakdown` appears once each time the capture runs to the end, - just before `hot_reload_source_snapshot_captured` (also when Unity listed no compilation - assembly, but not when the capture threw). It says where the capture spent its time: + just before `hot_reload_source_snapshot_captured`. It also appears when Unity listed no + compilation assembly, in which case no captured entry follows, and it does not appear when the + capture threw. It says where the capture spent its time: - `getAssembliesMs`: listing the compilation assemblies from Unity. - `packageLookupMs`: asking Package Manager whether each assembly's sources are immutable. - `stampMs`: reading and writing the stamps beside the snapshots. From c3df7f3bf17416a2df772854594d5d9975c0d274 Mon Sep 17 00:00:00 2001 From: hatayama Date: Sun, 11 Oct 2026 13:34:26 +0900 Subject: [PATCH 4/5] Pin how many sources the capture counts as checked against the PDB No test told a capture that counts every copy as checked from one that counts none. The two tests around the recorded compile start now also assert one checked file when the source falls inside the window and none, of one copied, when it does not. --- ...tReloadSnapshotAssemblyEnumerationTests.cs | 21 ++++++++++++++----- 1 file changed, 16 insertions(+), 5 deletions(-) diff --git a/Assets/Tests/Editor/HotReload/HotReloadSnapshotAssemblyEnumerationTests.cs b/Assets/Tests/Editor/HotReload/HotReloadSnapshotAssemblyEnumerationTests.cs index 1e438266c..035bb8f09 100644 --- a/Assets/Tests/Editor/HotReload/HotReloadSnapshotAssemblyEnumerationTests.cs +++ b/Assets/Tests/Editor/HotReload/HotReloadSnapshotAssemblyEnumerationTests.cs @@ -366,30 +366,38 @@ public void CaptureAssemblies_ForVirtualPlayerRoot_ReadsTheMainProjectsDllAndSna /// /// Verifies that the capture takes the recorded compile start as the start of the PDB check, so /// a source saved after the compile started but before the DLL was written is checked and, with - /// no PDB document to confirm it, marked as edited after the compile. + /// no PDB document to confirm it, marked as edited after the compile. The capture counts that + /// one file as checked. /// [Test] public void CaptureAssemblies_ASourceSavedAfterTheCompileStartedButBeforeTheDll_IsMarked() { string snapshotDirectory = CaptureWithSourceSavedBetweenStartAndDll( - HotReloadCompileStart.At(CompileStartUtc.Ticks)); + HotReloadCompileStart.At(CompileStartUtc.Ticks), + out HotReloadSnapshotCaptureStats stats); HotReloadSourceStampManifest manifest = HotReloadSourceStampManifest.Load(snapshotDirectory); Assert.That(manifest.IsEditedAfterCompile(SnapshotFileName()), Is.True); + Assert.That(stats.FilesChecked, Is.EqualTo(1), "files checked"); } /// /// Verifies that without a recorded compile start the same source is not checked, because the /// check then starts at the DLL write; the mark in the case above comes from the compile start. + /// The capture counts no file as checked, though it copied one. /// [Test] public void CaptureAssemblies_WithoutARecordedStart_LeavesASourceSavedBeforeTheDllUnmarked() { - string snapshotDirectory = CaptureWithSourceSavedBetweenStartAndDll(HotReloadCompileStart.Unknown); + string snapshotDirectory = CaptureWithSourceSavedBetweenStartAndDll( + HotReloadCompileStart.Unknown, + out HotReloadSnapshotCaptureStats stats); HotReloadSourceStampManifest manifest = HotReloadSourceStampManifest.Load(snapshotDirectory); Assert.That(manifest.IsEditedAfterCompile(SnapshotFileName()), Is.False); Assert.That(manifest.TryGetStamp(SnapshotFileName(), out long _, out long _), Is.True); + Assert.That(stats.FilesCopied, Is.EqualTo(1), "files copied"); + Assert.That(stats.FilesChecked, Is.EqualTo(0), "files checked"); } /// @@ -431,7 +439,10 @@ public void CaptureAssemblies_ReturnsWhatItCopiedAndWhatItSkipped() // Plants the compiled assembly and orders the write times as compile start < source < DLL. // The fixture source has no document in the planted PDB, so a check cannot confirm it. - private string CaptureWithSourceSavedBetweenStartAndDll(HotReloadCompileStart compileStart) + // Returns the snapshot directory and hands out what the capture reported. + private string CaptureWithSourceSavedBetweenStartAndDll( + HotReloadCompileStart compileStart, + out HotReloadSnapshotCaptureStats stats) { string dllPath = PlantCompiledAssembly("Fixture"); File.SetLastWriteTimeUtc(dllPath, new DateTime(2025, 6, 1, 0, 0, 0, DateTimeKind.Utc)); @@ -440,7 +451,7 @@ private string CaptureWithSourceSavedBetweenStartAndDll(HotReloadCompileStart co new DateTime(2025, 1, 1, 0, 0, 0, DateTimeKind.Utc)); string mvid = HotReloadAssemblyMvid.Read(dllPath); - HotReloadSourceSnapshotter.CaptureAssemblies( + stats = HotReloadSourceSnapshotter.CaptureAssemblies( _projectRoot, new[] { CreateAssembly("Fixture") }, compileStart, From 225f3517aee5f13257b03f6e19d4668ed17e5bad Mon Sep 17 00:00:00 2001 From: hatayama Date: Sun, 11 Oct 2026 13:34:26 +0900 Subject: [PATCH 5/5] Say that captureMs exceeds totalMs by writing the breakdown entry The gate's done check runs before its stopwatch starts, so the gap is the breakdown entry's own synchronous write, not the gate. --- docs/vibe-logs.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/docs/vibe-logs.md b/docs/vibe-logs.md index c457f368e..9a799638e 100644 --- a/docs/vibe-logs.md +++ b/docs/vibe-logs.md @@ -116,7 +116,7 @@ command ran against: - `filesCopied` and `bytesCopied`: the sources copied and their total size. - `filesChecked`: the sources checked against the PDB. The phases add up to `totalMs` except for the loop overhead; `captureMs` in the captured entry - also includes the gate. + also includes writing this breakdown entry. 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