From f957f742dfd372eb6c20020bbd48d575116dac24 Mon Sep 17 00:00:00 2001 From: Mihai Codoban Date: Fri, 25 Jun 2021 17:55:29 -0700 Subject: [PATCH 1/3] Print begin/end messages for cache init and shutdown Helps with debugging --- .../Components/ProjectCache/ProjectCacheService.cs | 13 +++++++++++++ 1 file changed, 13 insertions(+) diff --git a/src/Build/BackEnd/Components/ProjectCache/ProjectCacheService.cs b/src/Build/BackEnd/Components/ProjectCache/ProjectCacheService.cs index e5e25ce697e..7d7c0dc5759 100644 --- a/src/Build/BackEnd/Components/ProjectCache/ProjectCacheService.cs +++ b/src/Build/BackEnd/Components/ProjectCache/ProjectCacheService.cs @@ -4,6 +4,7 @@ #nullable enable using System; using System.Collections.Generic; +using System.Diagnostics; using System.Linq; using System.Reflection; using System.Threading; @@ -102,6 +103,9 @@ private async Task BeginBuildAsync(ProjectCacheDescriptor? vsWorkaroundOverrideD { SetState(ProjectCacheServiceState.BeginBuildStarted); + logger.LogMessage("Initializing project cache plugin", MessageImportance.Low); + var timer = Stopwatch.StartNew(); + if (_projectCacheDescriptor.VsWorkaround) { logger.LogMessage("Running project cache with Visual Studio workaround"); @@ -118,6 +122,9 @@ await _projectCachePlugin.BeginBuildAsync( logger, _cancellationToken); + timer.Stop(); + logger.LogMessage($"Finished initializing project cache plugin in {timer.Elapsed.TotalMilliseconds} ms", MessageImportance.Low); + SetState(ProjectCacheServiceState.BeginBuildFinished); } catch (Exception e) @@ -413,8 +420,14 @@ public async Task ShutDown() { SetState(ProjectCacheServiceState.ShutdownStarted); + logger.LogMessage("Shutting down project cache plugin", MessageImportance.Low); + var timer = Stopwatch.StartNew(); + await _projectCachePlugin.EndBuildAsync(logger, _cancellationToken); + timer.Stop(); + logger.LogMessage($"Finished shutting down project cache plugin in {timer.Elapsed.TotalMilliseconds} ms", MessageImportance.Low); + if (logger.HasLoggedErrors) { ProjectCacheException.ThrowForErrorLoggedInsideTheProjectCache("ProjectCacheShutdownFailed"); From 6d33a1ae5ce410a5e92c8e7621c3726cbffeb2b2 Mon Sep 17 00:00:00 2001 From: Mihai Codoban Date: Fri, 25 Jun 2021 17:54:31 -0700 Subject: [PATCH 2/3] Fix problems with inproc node confinement --- .../ProjectCache/ProjectCacheTests.cs | 108 ++++++++++++++++++ .../BackEnd/Components/Scheduler/Scheduler.cs | 8 +- .../Components/Scheduler/SchedulingData.cs | 7 +- 3 files changed, 120 insertions(+), 3 deletions(-) diff --git a/src/Build.UnitTests/ProjectCache/ProjectCacheTests.cs b/src/Build.UnitTests/ProjectCache/ProjectCacheTests.cs index 65b60c15a0c..d617ecc609b 100644 --- a/src/Build.UnitTests/ProjectCache/ProjectCacheTests.cs +++ b/src/Build.UnitTests/ProjectCache/ProjectCacheTests.cs @@ -233,6 +233,30 @@ public enum ErrorKind LoggedError } + public class ConfigurableMockCache : ProjectCachePluginBase + { + public Func>? GetCacheResultImplementation { get; set; } + public override Task BeginBuildAsync(CacheContext context, PluginLoggerBase logger, CancellationToken cancellationToken) + { + return Task.CompletedTask; + } + + public override Task GetCacheResultAsync( + BuildRequestData buildRequest, + PluginLoggerBase logger, + CancellationToken cancellationToken) + { + return GetCacheResultImplementation != null + ? GetCacheResultImplementation(buildRequest, logger, cancellationToken) + : Task.FromResult(CacheResult.IndicateNonCacheHit(CacheResultType.CacheNotApplicable)); + } + + public override Task EndBuildAsync(PluginLoggerBase logger, CancellationToken cancellationToken) + { + return Task.CompletedTask; + } + } + public class InstanceMockCache : ProjectCachePluginBase { private readonly GraphCacheResponse? _testData; @@ -1475,6 +1499,90 @@ public void ParallelStressTest(bool useSynchronousLogging, bool disableInprocNod cache.QueryStartStops.Count.ShouldBe(graph.ProjectNodes.Count * 2); } + [Fact] + public void ProxyCacheHitsOnPreviousCacheMissesShouldWork() + { + var cacheNotApplicableTarget = "NATarget"; + var cacheHitTarget = "CacheHitTarget"; + var proxyTarget = "ProxyTarget"; + + var project = +@$" + + + + + + + + + + + + + + +".Cleanup(); + + var projectPaths = Enumerable.Range(0, NativeMethodsShared.GetLogicalCoreCount()) + .Select(i => _env.CreateFile($"project{i}.proj", project).Path) + .ToArray(); + + var cacheHitCount = 0; + var nonCacheHitCount = 0; + + var buildParameters = new BuildParameters + { + ProjectCacheDescriptor = ProjectCacheDescriptor.FromInstance( + new ConfigurableMockCache + { + GetCacheResultImplementation = (request, _, _) => + { + var projectFile = request.ProjectFullPath; + + if (request.TargetNames.Contains(cacheNotApplicableTarget)) + { + Interlocked.Increment(ref nonCacheHitCount); + return Task.FromResult(CacheResult.IndicateNonCacheHit(CacheResultType.CacheNotApplicable)); + } + else + { + Interlocked.Increment(ref cacheHitCount); + return Task.FromResult( + CacheResult.IndicateCacheHit( + new ProxyTargets(new Dictionary {{proxyTarget, cacheHitTarget}}))); + } + } + }, + projectPaths.Select(p => new ProjectGraphEntryPoint(p)).ToArray(), + projectGraph: null), + MaxNodeCount = NativeMethodsShared.GetLogicalCoreCount() + }; + + using var buildSession = new Helpers.BuildManagerSession(_env, buildParameters); + + var buildRequests = new List<(string, string)>(); + buildRequests.AddRange(projectPaths.Select(r => (r, cacheNotApplicableTarget))); + buildRequests.AddRange(projectPaths.Select(r => (r, cacheHitTarget))); + + var buildTasks = new List>(); + foreach (var (projectPath, target) in buildRequests) + { + buildTasks.Add(buildSession.BuildProjectFileAsync(projectPath, new[] {target})); + } + + foreach (var buildResult in buildTasks.Select(buildTask => buildTask.Result)) + { + buildResult.Exception.ShouldBeNull(); + buildResult.OverallResult.ShouldBe(BuildResultCode.Success); + } + + buildSession.Logger.ProjectStartedEvents.Count.ShouldBe(2 * projectPaths.Length); + + cacheHitCount.ShouldBe(projectPaths.Length); + nonCacheHitCount.ShouldBe(projectPaths.Length); + } + private static void StringShouldContainSubstring(string aString, string substring, int expectedOccurrences) { aString.ShouldContain(substring); diff --git a/src/Build/BackEnd/Components/Scheduler/Scheduler.cs b/src/Build/BackEnd/Components/Scheduler/Scheduler.cs index 03fc8f8a1ab..e95847208e8 100644 --- a/src/Build/BackEnd/Components/Scheduler/Scheduler.cs +++ b/src/Build/BackEnd/Components/Scheduler/Scheduler.cs @@ -1385,7 +1385,7 @@ private void AssignUnscheduledRequestToNode(SchedulableRequest request, int node void WarnWhenProxyBuildsGetScheduledOnOutOfProcNode() { - if (request.IsProxyBuildRequest() && nodeId != InProcNodeId) + if (request.IsProxyBuildRequest() && nodeId != InProcNodeId && _schedulingData.CanScheduleRequestToNode(request, InProcNodeId)) { ErrorUtilities.VerifyThrow( _componentHost.BuildParameters.DisableInProcNode || _forceAffinityOutOfProc, @@ -2107,7 +2107,11 @@ private NodeAffinity GetNodeAffinityForRequest(BuildRequest request) return NodeAffinity.InProc; } - if (request.IsProxyBuildRequest()) + ErrorUtilities.VerifyThrow(request.ConfigurationId != BuildRequestConfiguration.InvalidConfigurationId, "Requests should have a valid configuration id at this point"); + // If this configuration has been previously built on an out of proc node, scheduling it on the inproc node can cause either an affinity mismatch error when + // there are other pending requests for the same configuration or "unscheduled requests remain in the presence of free out of proc nodes" errors if there's no pending requests. + // So only assign proxy builds to the inproc node if their config hasn't been previously assigned to an out of proc node. + if (_schedulingData.CanScheduleConfigurationToNode(request.ConfigurationId, InProcNodeId) && request.IsProxyBuildRequest()) { return NodeAffinity.InProc; } diff --git a/src/Build/BackEnd/Components/Scheduler/SchedulingData.cs b/src/Build/BackEnd/Components/Scheduler/SchedulingData.cs index 0edc83f296e..9aeb9009c80 100644 --- a/src/Build/BackEnd/Components/Scheduler/SchedulingData.cs +++ b/src/Build/BackEnd/Components/Scheduler/SchedulingData.cs @@ -647,7 +647,12 @@ public int GetAssignedNodeForRequestConfiguration(int configurationId) /// public bool CanScheduleRequestToNode(SchedulableRequest request, int nodeId) { - int requiredNodeId = GetAssignedNodeForRequestConfiguration(request.BuildRequest.ConfigurationId); + return CanScheduleConfigurationToNode(request.BuildRequest.ConfigurationId, nodeId); + } + + public bool CanScheduleConfigurationToNode(int configurationId, int nodeId) + { + int requiredNodeId = GetAssignedNodeForRequestConfiguration(configurationId); return requiredNodeId == Scheduler.InvalidNodeId || requiredNodeId == nodeId; } From 06677fbb63aabf4d66284ba5f7890f8c8230773e Mon Sep 17 00:00:00 2001 From: Mihai Codoban Date: Tue, 29 Jun 2021 16:38:04 -0700 Subject: [PATCH 3/3] Comment test --- src/Build.UnitTests/ProjectCache/ProjectCacheTests.cs | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/src/Build.UnitTests/ProjectCache/ProjectCacheTests.cs b/src/Build.UnitTests/ProjectCache/ProjectCacheTests.cs index d617ecc609b..79446a04695 100644 --- a/src/Build.UnitTests/ProjectCache/ProjectCacheTests.cs +++ b/src/Build.UnitTests/ProjectCache/ProjectCacheTests.cs @@ -1500,6 +1500,13 @@ public void ParallelStressTest(bool useSynchronousLogging, bool disableInprocNod } [Fact] + // Schedules different requests for the same BuildRequestConfiguration in parallel. + // The first batch of the requests are cache misses, the second batch are cache hits via proxy builds. + // The first batch is delayed so it starts intermingling with the second batch. + // This test ensures that scheduling proxy builds on the inproc node works nicely within the Scheduler + // if the BuildRequestConfigurations for those proxy builds have built before (or are still building) on + // the out of proc node. + // More details: https://github.com/dotnet/msbuild/pull/6635 public void ProxyCacheHitsOnPreviousCacheMissesShouldWork() { var cacheNotApplicableTarget = "NATarget";