diff --git a/Assets/Tests/Editor/HotReload/HotReloadRunTimingTests.cs b/Assets/Tests/Editor/HotReload/HotReloadRunTimingTests.cs index 3e561ef3c..8d0854084 100644 --- a/Assets/Tests/Editor/HotReload/HotReloadRunTimingTests.cs +++ b/Assets/Tests/Editor/HotReload/HotReloadRunTimingTests.cs @@ -1,4 +1,5 @@ using System; +using System.Collections.Generic; using NUnit.Framework; @@ -113,5 +114,76 @@ public void Complete_TotalBelowThePhases_Throws() Assert.Throws(() => timing.Complete(329)); } + + /// + /// What: a step measured twice in one run, such as once per group, adds up under one entry, + /// and the steps keep the order they were first seen in. + /// + [Test] + public void AddDetail_SameStepTwice_SumsAndKeepsFirstSeenOrder() + { + HotReloadRunTiming timing = new HotReloadRunTiming(); + + timing.AddDetail("plan", 3); + timing.AddDetail("resolve_inputs", 5); + timing.AddDetail("plan", 4); + + Assert.That(timing.Details, Is.EqualTo(new[] + { + new KeyValuePair("plan", 7), + new KeyValuePair("resolve_inputs", 5), + })); + } + + /// + /// What: a negative step time is refused instead of shrinking the step's sum. + /// + [Test] + public void AddDetail_NegativeMilliseconds_Throws() + { + HotReloadRunTiming timing = new HotReloadRunTiming(); + + Assert.Throws(() => timing.AddDetail("plan", -1)); + } + + /// + /// What: a step without a name is refused, whether the name is empty or null. + /// + [Test] + public void AddDetail_EmptyStep_Throws() + { + HotReloadRunTiming timing = new HotReloadRunTiming(); + + Assert.Throws(() => timing.AddDetail(string.Empty, 1)); + Assert.Throws(() => timing.AddDetail(null, 1)); + } + + /// + /// What: disposing a measured scope adds its elapsed time to the step. + /// + [Test] + public void MeasureDetail_AddsTheElapsedOnDispose() + { + HotReloadRunTiming timing = new HotReloadRunTiming(); + + using (timing.MeasureDetail("plan")) + { + } + + Assert.That(timing.Details.Count, Is.EqualTo(1)); + Assert.That(timing.Details[0].Key, Is.EqualTo("plan")); + Assert.That(timing.Details[0].Value, Is.GreaterThanOrEqualTo(0)); + } + + /// + /// What: a run that measured no step reports no steps. + /// + [Test] + public void Details_WithoutAnyStep_IsEmpty() + { + HotReloadRunTiming timing = new HotReloadRunTiming(); + + Assert.That(timing.Details, Is.Empty); + } } } diff --git a/Assets/Tests/Editor/HotReload/HotReloadTimingDetailPayloadTests.cs b/Assets/Tests/Editor/HotReload/HotReloadTimingDetailPayloadTests.cs new file mode 100644 index 000000000..fc0a80c07 --- /dev/null +++ b/Assets/Tests/Editor/HotReload/HotReloadTimingDetailPayloadTests.cs @@ -0,0 +1,79 @@ +using System.Collections.Generic; + +using NUnit.Framework; + +using io.github.hatayama.UnityCliLoop.FirstPartyTools; + +namespace io.github.hatayama.UnityCliLoop.Tests.Editor.HotReload +{ + /// + /// Tests the timing detail entry that breaks down the time outside an apply run's phases. + /// + public sealed class HotReloadTimingDetailPayloadTests + { + /// + /// What: the entry carries each phase, the steps in order, and the part of the time outside + /// the phases that no step covers. + /// + [Test] + public void Build_ReportsThePhasesTheStepsAndTheUnaccountedRest() + { + HotReloadTimingBreakdown breakdown = new HotReloadTimingBreakdown(100, 50, 10, 1000); + List> details = new List> + { + new KeyValuePair("plan", 300), + new KeyValuePair("sibling_detect", 400), + }; + + HotReloadTimingDetailPayload payload = HotReloadTimingDetailPayload.Build(breakdown, details, 2); + + Assert.That(payload.TotalMs, Is.EqualTo(1000)); + Assert.That(payload.AnalysisMs, Is.EqualTo(100)); + Assert.That(payload.ShimCompileMs, Is.EqualTo(50)); + Assert.That(payload.PatchMs, Is.EqualTo(10)); + Assert.That(payload.OtherMs, Is.EqualTo(840)); + Assert.That(payload.UnaccountedMs, Is.EqualTo(140)); + Assert.That(payload.GroupCount, Is.EqualTo(2)); + Assert.That(payload.Steps.Count, Is.EqualTo(2)); + Assert.That(payload.Steps[0].Step, Is.EqualTo("plan")); + Assert.That(payload.Steps[0].Ms, Is.EqualTo(300)); + Assert.That(payload.Steps[1].Step, Is.EqualTo("sibling_detect")); + Assert.That(payload.Steps[1].Ms, Is.EqualTo(400)); + } + + /// + /// What: steps that add up to more than the time outside the phases report a negative + /// unaccounted time as it is, because that is the sign that a step overlaps a phase. + /// + [Test] + public void Build_StepsOverlappingAPhase_ReportsANegativeUnaccounted() + { + HotReloadTimingBreakdown breakdown = new HotReloadTimingBreakdown(100, 50, 10, 1000); + List> details = new List> + { + new KeyValuePair("plan", 900), + }; + + HotReloadTimingDetailPayload payload = HotReloadTimingDetailPayload.Build(breakdown, details, 1); + + Assert.That(payload.UnaccountedMs, Is.EqualTo(-60)); + } + + /// + /// What: a run that measured no step leaves all of the time outside the phases unaccounted. + /// + [Test] + public void Build_WithoutSteps_ReportsOtherAsUnaccounted() + { + HotReloadTimingBreakdown breakdown = new HotReloadTimingBreakdown(100, 50, 10, 1000); + + HotReloadTimingDetailPayload payload = HotReloadTimingDetailPayload.Build( + breakdown, + new List>(), + 0); + + Assert.That(payload.UnaccountedMs, Is.EqualTo(payload.OtherMs)); + Assert.That(payload.Steps, Is.Empty); + } + } +} diff --git a/Assets/Tests/Editor/HotReload/HotReloadTimingDetailPayloadTests.cs.meta b/Assets/Tests/Editor/HotReload/HotReloadTimingDetailPayloadTests.cs.meta new file mode 100644 index 000000000..896ed30a1 --- /dev/null +++ b/Assets/Tests/Editor/HotReload/HotReloadTimingDetailPayloadTests.cs.meta @@ -0,0 +1,11 @@ +fileFormatVersion: 2 +guid: 5501d2b14655347609732859c8dc3434 +MonoImporter: + externalObjects: {} + serializedVersion: 2 + defaultReferences: [] + executionOrder: 0 + icon: {instanceID: 0} + userData: + assetBundleName: + assetBundleVariant: diff --git a/Packages/src/Editor/FirstPartyTools/HotReload/HotReloadGroupFileLists.cs b/Packages/src/Editor/FirstPartyTools/HotReload/HotReloadGroupFileLists.cs new file mode 100644 index 000000000..ec3d694f7 --- /dev/null +++ b/Packages/src/Editor/FirstPartyTools/HotReload/HotReloadGroupFileLists.cs @@ -0,0 +1,37 @@ +using System.Collections.Generic; + +namespace io.github.hatayama.UnityCliLoop.FirstPartyTools +{ + /// + /// Lists that a group processor derives from the files of one group. + /// + internal static class HotReloadGroupFileLists + { + // Why a file that declares a new type never counts as enum-only: its artifact is prepared + // against the whole group, and leaving its owner out would drop it from the commit. + internal static List DescribeLeaveOutFiles(IReadOnlyList files) + { + List leaveOutFiles = new List(files.Count); + foreach (HotReloadGroupFile file in files) + { + leaveOutFiles.Add(new HotReloadLeaveOutFile( + file.ProjectRelativePath, + file.IsDefaultSelected, + file.DeclaresIntroducedType || file.DeclaresRefusedIntroducedType)); + } + + return leaveOutFiles; + } + + internal static List CollectProjectRelativePaths(IReadOnlyList files) + { + List projectRelativePaths = new List(files.Count); + foreach (HotReloadGroupFile file in files) + { + projectRelativePaths.Add(file.ProjectRelativePath); + } + + return projectRelativePaths; + } + } +} diff --git a/Packages/src/Editor/FirstPartyTools/HotReload/HotReloadGroupFileLists.cs.meta b/Packages/src/Editor/FirstPartyTools/HotReload/HotReloadGroupFileLists.cs.meta new file mode 100644 index 000000000..b9a69bdcb --- /dev/null +++ b/Packages/src/Editor/FirstPartyTools/HotReload/HotReloadGroupFileLists.cs.meta @@ -0,0 +1,11 @@ +fileFormatVersion: 2 +guid: c4b48e49fb28b4f4bb7e31b0b9d0e2d6 +MonoImporter: + externalObjects: {} + serializedVersion: 2 + defaultReferences: [] + executionOrder: 0 + icon: {instanceID: 0} + userData: + assetBundleName: + assetBundleVariant: diff --git a/Packages/src/Editor/FirstPartyTools/HotReload/HotReloadGroupProcessor.cs b/Packages/src/Editor/FirstPartyTools/HotReload/HotReloadGroupProcessor.cs index ff92ac41e..6919bd10b 100644 --- a/Packages/src/Editor/FirstPartyTools/HotReload/HotReloadGroupProcessor.cs +++ b/Packages/src/Editor/FirstPartyTools/HotReload/HotReloadGroupProcessor.cs @@ -57,35 +57,60 @@ internal async Task> ProcessGroupAsync HotReloadGroupFile firstFile = files[0]; // Application.dataPath and the ledgers require the Unity main thread. - await MainThreadSwitcher.SwitchToMainThread(ct); - if (!_dependencies.ValidateNewSourceMembership(files)) + using (timing.MeasureDetail(HotReloadConstants.TimingDetailStepMainThreadSwitch)) { - return _fileEntryApplier.BuildUnappliedGroupResults(files); + await MainThreadSwitcher.SwitchToMainThread(ct); + } + + using (timing.MeasureDetail(HotReloadConstants.TimingDetailStepMembershipValidate)) + { + if (!_dependencies.ValidateNewSourceMembership(files)) + { + return _fileEntryApplier.BuildUnappliedGroupResults(files); + } + } + + using (timing.MeasureDetail(HotReloadConstants.TimingDetailStepSnapshotGroupState)) + { + SnapshotGroupState(files); } - SnapshotGroupState(files); // Why here and not at the leave-out decision: the ledgers need the main thread, which // the worker await leaves, and nothing changes which files hold changes before the // decision — the domain changes only after it, and a prepared type is not active. - HashSet activePaths = new HotReloadDomainCarriedInLookup(_domain).ListActivePaths(); - - HotReloadChangedSiblingScanResult siblingScan = HotReloadChangedSiblingSourceDetector.Detect( - firstFile.ProjectRoot, - firstFile.AssemblyName, - firstFile.TargetDllPath, - firstFile.CompilationAssembly.sourceFiles, - CollectProjectRelativePaths(files)); + HashSet activePaths; + using (timing.MeasureDetail(HotReloadConstants.TimingDetailStepActivePaths)) + { + activePaths = new HotReloadDomainCarriedInLookup(_domain).ListActivePaths(); + } + + HotReloadChangedSiblingScanResult siblingScan; + using (timing.MeasureDetail(HotReloadConstants.TimingDetailStepSiblingDetect)) + { + siblingScan = HotReloadChangedSiblingSourceDetector.Detect( + firstFile.ProjectRoot, + firstFile.AssemblyName, + firstFile.TargetDllPath, + firstFile.CompilationAssembly.sourceFiles, + HotReloadGroupFileLists.CollectProjectRelativePaths(files)); + } + if (!string.IsNullOrEmpty(siblingScan.ScanLimitWarning)) { firstFile.Sinks.SiblingDerivedWarnings.Add(siblingScan.ScanLimitWarning); } - TransformWorkerInputDto workerInput = HotReloadGroupWorkerInputBuilder.BuildWorkerInput(files, siblingScan, _domain); - workerInput.introducedTypeArtifacts = HotReloadIntroducedTypeArtifactRecords.CollectActive( - _domain.IntroducedTypes, - workerInput.targetAssemblyName, - workerInput.targetAssemblyMvid, - FindFullyAppliedSourceHash).ToArray(); + TransformWorkerInputDto workerInput; + using (timing.MeasureDetail(HotReloadConstants.TimingDetailStepWorkerInput)) + { + workerInput = HotReloadGroupWorkerInputBuilder.BuildWorkerInput(files, siblingScan, _domain); + workerInput.introducedTypeArtifacts = HotReloadIntroducedTypeArtifactRecords.CollectActive( + _domain.IntroducedTypes, + workerInput.targetAssemblyName, + workerInput.targetAssemblyMvid, + FindFullyAppliedSourceHash).ToArray(); + } + Stopwatch preparationWatch = Stopwatch.StartNew(); HotReloadIntroducedTypePreparationResult preparation = await _dependencies .PrepareIntroducedTypes(files, workerInput, ct) @@ -98,36 +123,40 @@ internal async Task> ProcessGroupAsync // declaration bound from a retained artifact introduces nothing, so no artifact of // this run publishes it and a run whose only change is such a declaration never // reaches an activation at all. - HotReloadIntroducedTypeOutcomeSink.Append(files, preparation.AlreadyActiveTypes); - HotReloadIntroducedTypeOutcomeSink.AppendNotices(files, preparation.Notices); - - if (!preparation.Success) + IReadOnlyList refusedTypes; + using (timing.MeasureDetail(HotReloadConstants.TimingDetailStepPreparationOutcome)) { - // Why the two failures part ways here: a refused declaration is reported as the - // type it refused, while a preparation that could not run at all refused no - // declaration and stays a run-level failure of every file of the group. - if (preparation.Failures.Count > 0) - { - HotReloadIntroducedTypeOutcomeSink.Append(files, preparation.Failures); - // Why here: the transform run that reports these for a run that continues - // never runs, and an added enum member is a likely cause of the refusal. - HotReloadIntroducedTypeOutcomeSink.AppendDeclarationDriftWarnings( - files, - preparation.DeclarationDriftWarnings); - } - else + HotReloadIntroducedTypeOutcomeSink.Append(files, preparation.AlreadyActiveTypes); + HotReloadIntroducedTypeOutcomeSink.AppendNotices(files, preparation.Notices); + + if (!preparation.Success) { - HotReloadGroupOutcomeRouter.AppendGroupFailure( - files, - "(file)", - HotReloadFailureDescription.Declaration(preparation.ErrorMessage)); + // Why the two failures part ways here: a refused declaration is reported as the + // type it refused, while a preparation that could not run at all refused no + // declaration and stays a run-level failure of every file of the group. + if (preparation.Failures.Count > 0) + { + HotReloadIntroducedTypeOutcomeSink.Append(files, preparation.Failures); + // Why here: the transform run that reports these for a run that continues + // never runs, and an added enum member is a likely cause of the refusal. + HotReloadIntroducedTypeOutcomeSink.AppendDeclarationDriftWarnings( + files, + preparation.DeclarationDriftWarnings); + } + else + { + HotReloadGroupOutcomeRouter.AppendGroupFailure( + files, + "(file)", + HotReloadFailureDescription.Declaration(preparation.ErrorMessage)); + } + + return _fileEntryApplier.BuildUnappliedGroupResults(files); } - return _fileEntryApplier.BuildUnappliedGroupResults(files); + refusedTypes = HotReloadRefusedIntroducedType.CollectFrom(preparation.Notices); } - IReadOnlyList refusedTypes = - HotReloadRefusedIntroducedType.CollectFrom(preparation.Notices); if (preparation.Prepared == null) { return await TransformAndApplyGroupAsync(files, workerInput, null, refusedTypes, activePaths, correlationId, timing, ct) @@ -171,13 +200,16 @@ private async Task> TransformAndApplyP { HotReloadIntroducedTypeArtifact artifact = prepared.Artifact; HotReloadIntroducedTypeRegistry registry = _domain.IntroducedTypes; - List records = - new List(workerInput.introducedTypeArtifacts); - TransformWorkerIntroducedTypeArtifactDto preparedRecord = - HotReloadIntroducedTypeArtifactRecords.CreateRecord(artifact); - preparedRecord.preparedByThisRun = true; - records.Add(preparedRecord); - workerInput.introducedTypeArtifacts = records.ToArray(); + using (timing.MeasureDetail(HotReloadConstants.TimingDetailStepWorkerInput)) + { + List records = + new List(workerInput.introducedTypeArtifacts); + TransformWorkerIntroducedTypeArtifactDto preparedRecord = + HotReloadIntroducedTypeArtifactRecords.CreateRecord(artifact); + preparedRecord.preparedByThisRun = true; + records.Add(preparedRecord); + workerInput.introducedTypeArtifacts = records.ToArray(); + } // The scope answers binds for the prepared assembly while nothing has activated it, so // the shim compilation and the reflection it drives can already reach the new types. @@ -238,10 +270,15 @@ private async Task> TransformAndApplyG Debug.Assert( workerOutput.files.Length == files.Count, "A group worker run must return one per-file output per edited file."); - IReadOnlyList leftOutPaths = _leaveOut.FindLeftOutPaths( - DescribeLeaveOutFiles(files), - workerOutput, - activePaths); + IReadOnlyList leftOutPaths; + using (timing.MeasureDetail(HotReloadConstants.TimingDetailStepIsolationSplit)) + { + leftOutPaths = _leaveOut.FindLeftOutPaths( + HotReloadGroupFileLists.DescribeLeaveOutFiles(files), + workerOutput, + activePaths); + } + if (leftOutPaths.Count == 0) { return await ApplyTransformedGroupAsync(files, workerInput, workerOutput, prepared, refusedTypes, correlationId, timing, ct) @@ -250,9 +287,16 @@ private async Task> TransformAndApplyG // Why the rerun input first: it refuses a leave-out the sources do not match before // anything is written to the left-out files. - TransformWorkerInputDto retryInput = _leaveOut.BuildRetryInput(workerInput, leftOutPaths); - HotReloadGroupLeaveOutSplit split = new HotReloadGroupLeaveOutSplit(files, leftOutPaths); - List leftOutResults = BuildLeftOutResults(split, files, workerOutput); + TransformWorkerInputDto retryInput; + HotReloadGroupLeaveOutSplit split; + List leftOutResults; + using (timing.MeasureDetail(HotReloadConstants.TimingDetailStepIsolationSplit)) + { + retryInput = _leaveOut.BuildRetryInput(workerInput, leftOutPaths); + split = new HotReloadGroupLeaveOutSplit(files, leftOutPaths); + leftOutResults = BuildLeftOutResults(split, files, workerOutput); + } + TransformWorkerClientResult retryResult = await RunWorkerAsync(retryInput, correlationId, timing, ct) .ConfigureAwait(false); IReadOnlyList remainingResults = retryResult.Success @@ -293,22 +337,6 @@ private List FailGroup(IReadOnlyList DescribeLeaveOutFiles(IReadOnlyList files) - { - List leaveOutFiles = new List(files.Count); - foreach (HotReloadGroupFile file in files) - { - leaveOutFiles.Add(new HotReloadLeaveOutFile( - file.ProjectRelativePath, - file.IsDefaultSelected, - file.DeclaresIntroducedType || file.DeclaresRefusedIntroducedType)); - } - - return leaveOutFiles; - } - // Why the first run's rows: the left-out file gets the notices, hash and counts it would // have had in the run, so only the added members of the other files change. private List BuildLeftOutResults( @@ -318,7 +346,7 @@ private List BuildLeftOutResults( { HotReloadWorkerRowsByFile firstRows = HotReloadWorkerRowsByFile.Build( firstOutput, - CollectProjectRelativePaths(files)); + HotReloadGroupFileLists.CollectProjectRelativePaths(files)); HotReloadGroupNotices.AppendPerFileWorkerNotices(split.LeftOutFiles, firstRows); List results = new List(split.LeftOutFiles.Count); foreach (HotReloadGroupFile file in split.LeftOutFiles) @@ -346,15 +374,19 @@ private async Task> ApplyTransformedGr Debug.Assert( workerOutput.files.Length == files.Count, "A group worker run must return one per-file output per edited file."); - HotReloadWorkerRowsByFile rows = HotReloadWorkerRowsByFile.Build( - workerOutput, - CollectProjectRelativePaths(files)); - HotReloadGroupNotices.AppendPerFileWorkerNotices(files, rows); - // Why once for the group: the worker scans the assembly's unedited siblings for const - // drift as a whole, so flowing them per file would repeat the same texts. - if (workerOutput.siblingConstDriftWarnings != null) + HotReloadWorkerRowsByFile rows; + using (timing.MeasureDetail(HotReloadConstants.TimingDetailStepWorkerNotices)) { - firstFile.Sinks.SiblingDerivedWarnings.AddRange(workerOutput.siblingConstDriftWarnings); + rows = HotReloadWorkerRowsByFile.Build( + workerOutput, + HotReloadGroupFileLists.CollectProjectRelativePaths(files)); + HotReloadGroupNotices.AppendPerFileWorkerNotices(files, rows); + // Why once for the group: the worker scans the assembly's unedited siblings for const + // drift as a whole, so flowing them per file would repeat the same texts. + if (workerOutput.siblingConstDriftWarnings != null) + { + firstFile.Sinks.SiblingDerivedWarnings.AddRange(workerOutput.siblingConstDriftWarnings); + } } // Why before the empty-entries return: all-unchanged runs exit there, and those are @@ -366,27 +398,35 @@ private async Task> ApplyTransformedGr // marks a file unapplied runs later, so the only mark a file can carry at this point // is a parse error, and the worker drops a unit with parse errors before the transform // that reports unchanged methods, leaving such a file no row to peel either way. - if (!_collaborators.CommitPolicy.CommitsIntroducedTypes(prepared, files[0].AssemblyName) - && !await RevalidateBeforeRevertAsync( - files, - ct, - () => _entryApplier.RevertUnchangedPatchesPerFile(files, rows)).ConfigureAwait(false)) + using (timing.MeasureDetail(HotReloadConstants.TimingDetailStepRevalidateBeforeRevert)) { - return _fileEntryApplier.BuildUnappliedGroupResults(files); + if (!_collaborators.CommitPolicy.CommitsIntroducedTypes(prepared, files[0].AssemblyName) + && !await RevalidateBeforeRevertAsync( + files, + ct, + () => _entryApplier.RevertUnchangedPatchesPerFile(files, rows)).ConfigureAwait(false)) + { + return _fileEntryApplier.BuildUnappliedGroupResults(files); + } + } + + HotReloadApplyContext context; + using (timing.MeasureDetail(HotReloadConstants.TimingDetailStepApplyContext)) + { + context = new HotReloadApplyContext( + firstFile.ProjectRoot, + firstFile.AssemblyName, + correlationId, + firstFile.CompilationAssembly, + firstFile.Home, + firstFile.CompilationAssembly.defines ?? Array.Empty(), + workerInput, + workerOutput, + files, + prepared, + new HotReloadCompileFailureNoteSources(workerOutput.skipped, refusedTypes)); } - HotReloadApplyContext context = new HotReloadApplyContext( - firstFile.ProjectRoot, - firstFile.AssemblyName, - correlationId, - firstFile.CompilationAssembly, - firstFile.Home, - firstFile.CompilationAssembly.defines ?? Array.Empty(), - workerInput, - workerOutput, - files, - prepared, - new HotReloadCompileFailureNoteSources(workerOutput.skipped, refusedTypes)); Stopwatch gateWatch = Stopwatch.StartNew(); HotReloadGroupGateAndCompileResult gateAndCompile = await _dependencies .GateAndCompile(context, ct) @@ -594,17 +634,5 @@ private void SnapshotGroupState(IReadOnlyList files) : HotReloadSnapshotMissReason.None; } } - - private static List CollectProjectRelativePaths(IReadOnlyList files) - { - List projectRelativePaths = new List(files.Count); - foreach (HotReloadGroupFile file in files) - { - projectRelativePaths.Add(file.ProjectRelativePath); - } - - return projectRelativePaths; - } - } } diff --git a/Packages/src/Editor/FirstPartyTools/HotReload/HotReloadOrchestrator.cs b/Packages/src/Editor/FirstPartyTools/HotReload/HotReloadOrchestrator.cs index cb3217fa3..d4769eace 100644 --- a/Packages/src/Editor/FirstPartyTools/HotReload/HotReloadOrchestrator.cs +++ b/Packages/src/Editor/FirstPartyTools/HotReload/HotReloadOrchestrator.cs @@ -83,12 +83,20 @@ public async Task RunAsync( using IDisposable callSiteCacheHold = HotReloadCompiledCallSiteCache.Shared.HoldEntriesForRun(); HotReloadRunTiming timing = new HotReloadRunTiming(); - // CompilationPipeline / Application.dataPath require the Unity main thread, and the - // groups cannot be planned before every file knows which assembly it compiles into. - await MainThreadSwitcher.SwitchToMainThread(ct); - // Why after the switch: PackageInfo is main-thread only, and script paths are - // normalized against these roots later on the background threads this run switches to. - _packageRootCapture.CaptureCurrent(); + using (timing.MeasureDetail(HotReloadConstants.TimingDetailStepMainThreadSwitch)) + { + // CompilationPipeline / Application.dataPath require the Unity main thread, and the + // groups cannot be planned before every file knows which assembly it compiles into. + await MainThreadSwitcher.SwitchToMainThread(ct); + } + + using (timing.MeasureDetail(HotReloadConstants.TimingDetailStepPackageRoots)) + { + // Why after the switch: PackageInfo is main-thread only, and script paths are + // normalized against these roots later on the background threads this run switches to. + _packageRootCapture.CaptureCurrent(); + } + // Why after the switch: the accumulator has to read the Auto Refresh hold flag out of // SessionState, which is a main-thread API. HotReloadRunAccumulator run = @@ -97,6 +105,7 @@ public async Task RunAsync( _patcher, _unityMessageForwarding, HotReloadAutoRefreshHold.IsHeld); + HotReloadInputResolutionSlot[] slots = new HotReloadInputResolutionSlot[files.Count]; for (int index = 0; index < slots.Length; index++) { @@ -105,37 +114,45 @@ public async Task RunAsync( List<(int InputIndex, string AssemblyName, string ProjectRelativePath)> plannerInput = new List<(int InputIndex, string AssemblyName, string ProjectRelativePath)>(); - for (int index = 0; index < files.Count; index++) + using (timing.MeasureDetail(HotReloadConstants.TimingDetailStepResolveInputs)) { - ct.ThrowIfCancellationRequested(); - _inputFileResolver.ResolveInputFile( - files[index], - index, - contentPathOverride, - contentPathOverrideByFile, - correlationId, - run, - slots[index], - plannerInput); + for (int index = 0; index < files.Count; index++) + { + ct.ThrowIfCancellationRequested(); + _inputFileResolver.ResolveInputFile( + files[index], + index, + contentPathOverride, + contentPathOverrideByFile, + correlationId, + run, + slots[index], + plannerInput); + } } - MarkDefaultSelectedInputs(slots, isDefaultSelection); - IReadOnlyList plans = HotReloadFileGroupPlanner.Plan(plannerInput); + IReadOnlyList plans; HashSet pathsInRun = new HashSet( HotReloadSourcePathNormalizer.ProjectRelativePathComparer()); - for (int pathIndex = 0; pathIndex < slots.Length; pathIndex++) + IReadOnlyList classifiedPlans; + using (timing.MeasureDetail(HotReloadConstants.TimingDetailStepPlan)) { - if (!string.IsNullOrEmpty(slots[pathIndex].ResultPath)) + MarkDefaultSelectedInputs(slots, isDefaultSelection); + plans = HotReloadFileGroupPlanner.Plan(plannerInput); + for (int pathIndex = 0; pathIndex < slots.Length; pathIndex++) { - pathsInRun.Add(slots[pathIndex].ResultPath); + if (!string.IsNullOrEmpty(slots[pathIndex].ResultPath)) + { + pathsInRun.Add(slots[pathIndex].ResultPath); + } } - } - IReadOnlyList classifiedPlans = - _deferredInputClassifier.ClassifyAllDeferredPlans(plans, slots); + classifiedPlans = _deferredInputClassifier.ClassifyAllDeferredPlans(plans, slots); + } List<(string Path, HotReloadFileProcessResult Result)> extraResults = new List<(string Path, HotReloadFileProcessResult Result)>(); + int groupCount = 0; for (int planIndex = 0; planIndex < plans.Count; planIndex++) { ct.ThrowIfCancellationRequested(); @@ -145,21 +162,26 @@ public async Task RunAsync( continue; } - bool isLastChangedGroup = _siblingRebindReporter.IsLastChangedPlanForAssembly( - plans, - classifiedPlans, - planIndex); + bool isLastChangedGroup; List inputIndexes = new List(plan.InputIndexes); - if (isLastChangedGroup) + using (timing.MeasureDetail(HotReloadConstants.TimingDetailStepPlan)) { - _deferredInputClassifier.AppendUniqueDeferredInputIndexes( + isLastChangedGroup = _siblingRebindReporter.IsLastChangedPlanForAssembly( plans, classifiedPlans, - planIndex, - slots, - inputIndexes); + planIndex); + if (isLastChangedGroup) + { + _deferredInputClassifier.AppendUniqueDeferredInputIndexes( + plans, + classifiedPlans, + planIndex, + slots, + inputIndexes); + } } + groupCount++; await ProcessPlannedGroupAsync( inputIndexes, slots, @@ -176,11 +198,14 @@ await ProcessPlannedGroupAsync( // Why after every changed plan: an earlier all-deferred plan must not fill its // slots before the last changed group can absorb its unique callers. - for (int planIndex = 0; planIndex < plans.Count; planIndex++) + using (timing.MeasureDetail(HotReloadConstants.TimingDetailStepPlan)) { - if (classifiedPlans[planIndex].IsAllDeferred) + for (int planIndex = 0; planIndex < plans.Count; planIndex++) { - _deferredInputClassifier.ApplyDeferredAlreadyActive(plans[planIndex], slots); + if (classifiedPlans[planIndex].IsAllDeferred) + { + _deferredInputClassifier.ApplyDeferredAlreadyActive(plans[planIndex], slots); + } } } @@ -194,15 +219,37 @@ await ProcessPlannedGroupAsync( run.AddReappliedSibling(extraResults[extraIndex].Path, extraResults[extraIndex].Result); } - run.RecordAppliedSourceHashes(); - run.DisplayedRemovedMembers.ApplyTo(_patcher); + using (timing.MeasureDetail(HotReloadConstants.TimingDetailStepRecordSourceHashes)) + { + run.RecordAppliedSourceHashes(); + } + + using (timing.MeasureDetail(HotReloadConstants.TimingDetailStepRemovedMembers)) + { + run.DisplayedRemovedMembers.ApplyTo(_patcher); + } + + using (timing.MeasureDetail(HotReloadConstants.TimingDetailStepMainThreadSwitch)) + { + await MainThreadSwitcher.SwitchToMainThread(ct); + } + + using (timing.MeasureDetail(HotReloadConstants.TimingDetailStepCallerNotes)) + { + string projectRoot = Path.GetFullPath(Path.Combine(Application.dataPath, "..")); + run.ApplyOneShotCallerNotes(projectRoot); + } - await MainThreadSwitcher.SwitchToMainThread(ct); - string projectRoot = Path.GetFullPath(Path.Combine(Application.dataPath, "..")); - run.ApplyOneShotCallerNotes(projectRoot); + using (timing.MeasureDetail(HotReloadConstants.TimingDetailStepMainThreadSwitch)) + { + await MainThreadSwitcher.SwitchToMainThread(ct); + } - await MainThreadSwitcher.SwitchToMainThread(ct); - return run.BuildResult(correlationId, timing.Complete(total.ElapsedMilliseconds)); + HotReloadTimingBreakdown breakdown = timing.Complete(total.ElapsedMilliseconds); + HotReloadOrchestratorLog.LogHotReloadTimingDetail( + HotReloadTimingDetailPayload.Build(breakdown, timing.Details, groupCount), + correlationId); + return run.BuildResult(correlationId, breakdown); } // Why on the inputs only: a re-applied sibling joins a group later and was never selected, @@ -239,14 +286,17 @@ private async Task ProcessPlannedGroupAsync( } int inputCount = inputIndexes.Count; - if (isLastGroupOfAssembly) + using (timing.MeasureDetail(HotReloadConstants.TimingDetailStepActiveSiblings)) { - _siblingRebindReporter.AppendActiveSiblingsToGroup( - filesOfGroup, - pathsInRun, - contentPathOverrideByFile, - run, - _inputFileResolver); + if (isLastGroupOfAssembly) + { + _siblingRebindReporter.AppendActiveSiblingsToGroup( + filesOfGroup, + pathsInRun, + contentPathOverrideByFile, + run, + _inputFileResolver); + } } // Why ConfigureAwait(false): UnityCliLoopTool forbids capturing Unity's diff --git a/Packages/src/Editor/FirstPartyTools/HotReload/HotReloadOrchestratorLog.cs b/Packages/src/Editor/FirstPartyTools/HotReload/HotReloadOrchestratorLog.cs index 4ed882fad..0d59d8a04 100644 --- a/Packages/src/Editor/FirstPartyTools/HotReload/HotReloadOrchestratorLog.cs +++ b/Packages/src/Editor/FirstPartyTools/HotReload/HotReloadOrchestratorLog.cs @@ -1,5 +1,6 @@ using System; using System.Collections.Generic; +using System.Linq; using io.github.hatayama.UnityCliLoop.ToolContracts; @@ -129,5 +130,26 @@ internal static void LogHotReloadApplySummary( }, correlationId); } + + // Why an anonymous array for the steps: the entry keys stay camelCase like the rest of the + // entry, which the step type's PascalCase properties would not. + internal static void LogHotReloadTimingDetail(HotReloadTimingDetailPayload payload, string correlationId) + { + VibeLogger.LogInfo( + HotReloadConstants.VibeLogTimingDetail, + "Hot reload timing detail.", + new + { + totalMs = payload.TotalMs, + analysisMs = payload.AnalysisMs, + shimCompileMs = payload.ShimCompileMs, + patchMs = payload.PatchMs, + otherMs = payload.OtherMs, + unaccountedMs = payload.UnaccountedMs, + groupCount = payload.GroupCount, + steps = payload.Steps.Select(step => new { step = step.Step, ms = step.Ms }).ToArray() + }, + correlationId); + } } } diff --git a/Packages/src/Editor/FirstPartyTools/HotReload/HotReloadRunTiming.cs b/Packages/src/Editor/FirstPartyTools/HotReload/HotReloadRunTiming.cs index 2827b23c8..81b4ff640 100644 --- a/Packages/src/Editor/FirstPartyTools/HotReload/HotReloadRunTiming.cs +++ b/Packages/src/Editor/FirstPartyTools/HotReload/HotReloadRunTiming.cs @@ -1,7 +1,13 @@ +using System; +using System.Collections.Generic; +using System.Diagnostics; + namespace io.github.hatayama.UnityCliLoop.FirstPartyTools { /// /// Sums the milliseconds one apply run spends in each phase across all of its groups. + /// Also sums the named steps outside the phases, in the order each was first seen. The + /// response does not carry them; only the hot_reload_timing_detail vibe entry reads them. /// /// /// Why an accumulator the run hands down: group results are per file and carry no group-level @@ -10,10 +16,13 @@ namespace io.github.hatayama.UnityCliLoop.FirstPartyTools /// internal sealed class HotReloadRunTiming { + private readonly List> _details = new List>(); private long _analysisMs; private long _shimCompileMs; private long _patchMs; + public IReadOnlyList> Details => _details; + public void AddAnalysis(long milliseconds) { _analysisMs += HotReloadTimingBreakdown.RequireElapsed(milliseconds, nameof(milliseconds)); @@ -29,9 +38,62 @@ public void AddPatch(long milliseconds) _patchMs += HotReloadTimingBreakdown.RequireElapsed(milliseconds, nameof(milliseconds)); } + public void AddDetail(string step, long milliseconds) + { + if (string.IsNullOrEmpty(step)) + { + throw new ArgumentException("step must not be null or empty.", nameof(step)); + } + + long elapsed = HotReloadTimingBreakdown.RequireElapsed(milliseconds, nameof(milliseconds)); + int index = _details.FindIndex(pair => pair.Key == step); + if (index < 0) + { + _details.Add(new KeyValuePair(step, elapsed)); + return; + } + + _details[index] = new KeyValuePair(step, _details[index].Value + elapsed); + } + + /// + /// Measures the wall-clock time until the returned scope is disposed and adds it to the step. + /// + public IDisposable MeasureDetail(string step) + { + return new DetailScope(this, step); + } + public HotReloadTimingBreakdown Complete(long totalMs) { return new HotReloadTimingBreakdown(_analysisMs, _shimCompileMs, _patchMs, totalMs); } + + private sealed class DetailScope : IDisposable + { + private readonly HotReloadRunTiming _timing; + private readonly string _step; + private readonly Stopwatch _watch = Stopwatch.StartNew(); + private bool _disposed; + + public DetailScope(HotReloadRunTiming timing, string step) + { + _timing = timing; + _step = step; + } + + public void Dispose() + { + // Why only once: a second dispose would count the same span twice. + if (_disposed) + { + return; + } + + _disposed = true; + _watch.Stop(); + _timing.AddDetail(_step, _watch.ElapsedMilliseconds); + } + } } } diff --git a/Packages/src/Editor/FirstPartyTools/HotReload/HotReloadTimingDetailPayload.cs b/Packages/src/Editor/FirstPartyTools/HotReload/HotReloadTimingDetailPayload.cs new file mode 100644 index 000000000..9d5eddad8 --- /dev/null +++ b/Packages/src/Editor/FirstPartyTools/HotReload/HotReloadTimingDetailPayload.cs @@ -0,0 +1,77 @@ +using System; +using System.Collections.Generic; + +namespace io.github.hatayama.UnityCliLoop.FirstPartyTools +{ + /// + /// Values of the hot_reload_timing_detail vibe entry: the run's phases, the named steps outside + /// them, and the part of the time outside the phases that no step covers. + /// + internal sealed class HotReloadTimingDetailPayload + { + private HotReloadTimingDetailPayload( + HotReloadTimingBreakdown breakdown, + IReadOnlyList steps, + long unaccountedMs, + int groupCount) + { + TotalMs = breakdown.TotalMs; + AnalysisMs = breakdown.AnalysisMs; + ShimCompileMs = breakdown.ShimCompileMs; + PatchMs = breakdown.PatchMs; + OtherMs = breakdown.OtherMs; + Steps = steps; + UnaccountedMs = unaccountedMs; + GroupCount = groupCount; + } + + public long TotalMs { get; } + + public long AnalysisMs { get; } + + public long ShimCompileMs { get; } + + public long PatchMs { get; } + + public long OtherMs { get; } + + // Negative when the steps add up to more than OtherMs, which means a step overlaps a phase. + public long UnaccountedMs { get; } + + public int GroupCount { get; } + + public IReadOnlyList Steps { get; } + + public static HotReloadTimingDetailPayload Build( + HotReloadTimingBreakdown breakdown, + IReadOnlyList> details, + int groupCount) + { + if (breakdown == null) + { + throw new ArgumentNullException(nameof(breakdown)); + } + + if (details == null) + { + throw new ArgumentNullException(nameof(details)); + } + + if (groupCount < 0) + { + throw new ArgumentOutOfRangeException(nameof(groupCount), groupCount, "groupCount must not be negative."); + } + + List steps = new List(details.Count); + long stepsMs = 0; + foreach (KeyValuePair detail in details) + { + steps.Add(new HotReloadTimingDetailStep(detail.Key, detail.Value)); + stepsMs += detail.Value; + } + + // Why not clamped at zero: a negative rest is the only sign that a step overlaps a phase. + return new HotReloadTimingDetailPayload(breakdown, steps, breakdown.OtherMs - stepsMs, groupCount); + } + } +} diff --git a/Packages/src/Editor/FirstPartyTools/HotReload/HotReloadTimingDetailPayload.cs.meta b/Packages/src/Editor/FirstPartyTools/HotReload/HotReloadTimingDetailPayload.cs.meta new file mode 100644 index 000000000..4a33f2019 --- /dev/null +++ b/Packages/src/Editor/FirstPartyTools/HotReload/HotReloadTimingDetailPayload.cs.meta @@ -0,0 +1,11 @@ +fileFormatVersion: 2 +guid: d9064e9e9f9794d18a086bda4c06be91 +MonoImporter: + externalObjects: {} + serializedVersion: 2 + defaultReferences: [] + executionOrder: 0 + icon: {instanceID: 0} + userData: + assetBundleName: + assetBundleVariant: diff --git a/Packages/src/Editor/FirstPartyTools/HotReload/HotReloadTimingDetailStep.cs b/Packages/src/Editor/FirstPartyTools/HotReload/HotReloadTimingDetailStep.cs new file mode 100644 index 000000000..dc1ace1f6 --- /dev/null +++ b/Packages/src/Editor/FirstPartyTools/HotReload/HotReloadTimingDetailStep.cs @@ -0,0 +1,18 @@ +namespace io.github.hatayama.UnityCliLoop.FirstPartyTools +{ + /// + /// One named step outside the apply run's phases and the milliseconds the run spent in it. + /// + internal sealed class HotReloadTimingDetailStep + { + public HotReloadTimingDetailStep(string step, long ms) + { + Step = step; + Ms = ms; + } + + public string Step { get; } + + public long Ms { get; } + } +} diff --git a/Packages/src/Editor/FirstPartyTools/HotReload/HotReloadTimingDetailStep.cs.meta b/Packages/src/Editor/FirstPartyTools/HotReload/HotReloadTimingDetailStep.cs.meta new file mode 100644 index 000000000..54ccc6494 --- /dev/null +++ b/Packages/src/Editor/FirstPartyTools/HotReload/HotReloadTimingDetailStep.cs.meta @@ -0,0 +1,11 @@ +fileFormatVersion: 2 +guid: 4f0ca74b735e14073ab1da361fd23b94 +MonoImporter: + externalObjects: {} + serializedVersion: 2 + defaultReferences: [] + executionOrder: 0 + icon: {instanceID: 0} + userData: + assetBundleName: + assetBundleVariant: diff --git a/Packages/src/Editor/FirstPartyTools/HotReload/Shared/HotReloadConstants.cs b/Packages/src/Editor/FirstPartyTools/HotReload/Shared/HotReloadConstants.cs index e277cf713..ed68369eb 100644 --- a/Packages/src/Editor/FirstPartyTools/HotReload/Shared/HotReloadConstants.cs +++ b/Packages/src/Editor/FirstPartyTools/HotReload/Shared/HotReloadConstants.cs @@ -649,6 +649,28 @@ public static bool IsPublicizableProjectAssemblyFileName(string fileNameWithoutE public const string VibeLogEmptyEntriesClear = "hot_reload_empty_entries_clear"; public const string VibeLogRevertFailed = "hot_reload_revert_failed"; public const string VibeLogApplySummary = "hot_reload_apply_summary"; + public const string VibeLogTimingDetail = "hot_reload_timing_detail"; + + // Steps of an apply run outside the response's Timing phases, as named in the + // hot_reload_timing_detail vibe entry. Steps that run once per group add up. + public const string TimingDetailStepMainThreadSwitch = "main_thread_switch"; + public const string TimingDetailStepPackageRoots = "package_roots"; + public const string TimingDetailStepResolveInputs = "resolve_inputs"; + public const string TimingDetailStepPlan = "plan"; + public const string TimingDetailStepActiveSiblings = "active_siblings"; + public const string TimingDetailStepMembershipValidate = "membership_validate"; + public const string TimingDetailStepSnapshotGroupState = "snapshot_group_state"; + public const string TimingDetailStepActivePaths = "active_paths"; + public const string TimingDetailStepSiblingDetect = "sibling_detect"; + public const string TimingDetailStepWorkerInput = "worker_input"; + public const string TimingDetailStepPreparationOutcome = "preparation_outcome"; + public const string TimingDetailStepWorkerNotices = "worker_notices"; + public const string TimingDetailStepRevalidateBeforeRevert = "revalidate_before_revert"; + public const string TimingDetailStepApplyContext = "apply_context"; + public const string TimingDetailStepIsolationSplit = "isolation_split"; + public const string TimingDetailStepRecordSourceHashes = "record_source_hashes"; + public const string TimingDetailStepRemovedMembers = "removed_members"; + public const string TimingDetailStepCallerNotes = "caller_notes"; public const string VibeLogShimCompileStageFirstPass = "first_pass"; public const string VibeLogShimCompileStageRetry = "retry"; public const string VibeLogIsolationTriggerShimCompileFailure = "shim_compile_failure"; diff --git a/docs/vibe-logs.md b/docs/vibe-logs.md index 7dd248814..960dc5ad8 100644 --- a/docs/vibe-logs.md +++ b/docs/vibe-logs.md @@ -31,6 +31,10 @@ command ran against: - Unity side: only when the `ULOOP_DEBUG` scripting define symbol is set in the project. Every log method is `[Conditional("ULOOP_DEBUG")]`, so without it nothing is written — not even errors. This repository's development project defines it for the Standalone build target. + Hot reload also writes one `hot_reload_timing_detail` per apply run, with the milliseconds of + each step outside the response's `Timing` phases (`steps`), the phases themselves, and + `unaccountedMs` — the part of `otherMs` no step covers. A negative `unaccountedMs` means a + step overlaps a phase. - CLI side: only when the `ULOOP_DEBUG` environment variable is set to a value other than empty, `0`, or `false` (`cli/common/vibelog/cli_vibe.go`). - A missing line is evidence only when the define was set and the code path logs at all.