chore: Log where the hot reload source snapshot capture spends its time

Assets/Tests/Editor/HotReload/HotReloadSnapshotAssemblyEnumerationTests.cs

@@ -366,35 +366,83 @@ public void CaptureAssemblies_ForVirtualPlayerRoot_ReadsTheMainProjectsDllAndSna
         /// <summary>
         /// 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.
         /// </summary>
         [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");
         }
 
         /// <summary>
         /// 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.
         /// </summary>
         [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");
+        }
+
+        /// <summary>
+        /// 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.
+        /// </summary>
+        [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);

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);
         }

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))));
         }
 
+        /// <summary>
+        /// 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.
+        /// </summary>
+        [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));
+        }
+
         /// <summary>
         /// 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);

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.

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";

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

@@ -0,0 +1,58 @@
+using System;
+
+namespace io.github.hatayama.UnityCliLoop.FirstPartyTools
+{
+    /// <summary>
+    /// 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.
+    /// </summary>
+    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;
+        }
+    }
+}