diff --git a/Assets/Tests/Editor/HotReload/HotReloadSnapshotAssemblyEnumerationTests.cs b/Assets/Tests/Editor/HotReload/HotReloadSnapshotAssemblyEnumerationTests.cs index c6f162161..035bb8f09 100644 --- a/Assets/Tests/Editor/HotReload/HotReloadSnapshotAssemblyEnumerationTests.cs +++ b/Assets/Tests/Editor/HotReload/HotReloadSnapshotAssemblyEnumerationTests.cs @@ -366,35 +366,83 @@ 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"); + } + + /// + /// 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) + // 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)); @@ -403,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, @@ -412,6 +460,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; } /// diff --git a/docs/vibe-logs.md b/docs/vibe-logs.md index 60d022fed..9a799638e 100644 --- a/docs/vibe-logs.md +++ b/docs/vibe-logs.md @@ -94,6 +94,29 @@ 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`. 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. + - `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 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