From d89badb9d8bb838c3405e8950fe2174e66506ee5 Mon Sep 17 00:00:00 2001 From: Roman Konecny Date: Fri, 17 Feb 2023 08:41:14 +0100 Subject: [PATCH 1/3] BuildManager instances acquire its own BuildTelemetry instance (#8444) Fixes https://devdiv.visualstudio.com/DevDiv/_workitems/edit/1708215 Context In VS there are multiple instances of BuildManager called asynchronously. For DTB and normal build and maybe other which I have not identified yet. Changes Made BuildManager instances acquire its own BuildTelemetry instance as oppose to sharing single BuildTelemetry instance in non thread safe manner. Testing Locally # Conflicts: # src/Build/BackEnd/Client/MSBuildClient.cs - resolved with minimal and safe approach --- .../BackEnd/KnownTelemetry_Tests.cs | 10 ++-- .../BackEnd/BuildManager/BuildManager.cs | 57 ++++++++++++------- src/Build/BackEnd/Client/MSBuildClient.cs | 14 ++--- src/Build/BackEnd/Node/OutOfProcServerNode.cs | 12 ++-- src/Framework/Telemetry/KnownTelemetry.cs | 9 +-- src/MSBuild/MSBuildClientApp.cs | 4 +- src/MSBuild/XMake.cs | 12 ++-- 7 files changed, 67 insertions(+), 51 deletions(-) diff --git a/src/Build.UnitTests/BackEnd/KnownTelemetry_Tests.cs b/src/Build.UnitTests/BackEnd/KnownTelemetry_Tests.cs index a0ae7a9fafd..a515a5cdc68 100644 --- a/src/Build.UnitTests/BackEnd/KnownTelemetry_Tests.cs +++ b/src/Build.UnitTests/BackEnd/KnownTelemetry_Tests.cs @@ -15,19 +15,19 @@ public class KnownTelemetry_Tests [Fact] public void BuildTelemetryCanBeSetToNull() { - KnownTelemetry.BuildTelemetry = new BuildTelemetry(); - KnownTelemetry.BuildTelemetry = null; + KnownTelemetry.PartialBuildTelemetry = new BuildTelemetry(); + KnownTelemetry.PartialBuildTelemetry = null; - KnownTelemetry.BuildTelemetry.ShouldBeNull(); + KnownTelemetry.PartialBuildTelemetry.ShouldBeNull(); } [Fact] public void BuildTelemetryCanBeSet() { BuildTelemetry buildTelemetry = new BuildTelemetry(); - KnownTelemetry.BuildTelemetry = buildTelemetry; + KnownTelemetry.PartialBuildTelemetry = buildTelemetry; - KnownTelemetry.BuildTelemetry.ShouldBeSameAs(buildTelemetry); + KnownTelemetry.PartialBuildTelemetry.ShouldBeSameAs(buildTelemetry); } [Fact] diff --git a/src/Build/BackEnd/BuildManager/BuildManager.cs b/src/Build/BackEnd/BuildManager/BuildManager.cs index a188f318b64..58bab659a17 100644 --- a/src/Build/BackEnd/BuildManager/BuildManager.cs +++ b/src/Build/BackEnd/BuildManager/BuildManager.cs @@ -253,6 +253,12 @@ public class BuildManager : INodePacketHandler, IBuildComponentHost, IDisposable private IEnumerable _deferredBuildMessages; + /// + /// Build telemetry to be send when this build ends. + /// Could be null + /// + private BuildTelemetry _buildTelemetry; + private ProjectCacheService _projectCacheService; private bool _hasProjectCacheServiceInitializedVsScenario; @@ -491,11 +497,22 @@ public void BeginBuild(BuildParameters parameters) // Initiate build telemetry data DateTime now = DateTime.UtcNow; - KnownTelemetry.BuildTelemetry ??= new() + + // Acquire it from static variable so we can apply data collected up to this moment + _buildTelemetry = KnownTelemetry.PartialBuildTelemetry; + if (_buildTelemetry != null) + { + KnownTelemetry.PartialBuildTelemetry = null; + } + else { - StartAt = now, - }; - KnownTelemetry.BuildTelemetry.InnerStartAt = now; + _buildTelemetry = new() + { + StartAt = now, + }; + } + + _buildTelemetry.InnerStartAt = now; if (BuildParameters.DumpOpportunisticInternStats) { @@ -805,10 +822,10 @@ public BuildSubmission PendBuildRequest(BuildRequestData requestData) var newSubmission = new BuildSubmission(this, GetNextSubmissionId(), requestData, _buildParameters.LegacyThreadingSemantics); - if (KnownTelemetry.BuildTelemetry != null) + if (_buildTelemetry != null) { - KnownTelemetry.BuildTelemetry.Project ??= requestData.ProjectFullPath; - KnownTelemetry.BuildTelemetry.Target ??= string.Join(",", requestData.TargetNames); + _buildTelemetry.Project ??= requestData.ProjectFullPath; + _buildTelemetry.Target ??= string.Join(",", requestData.TargetNames); } _buildSubmissions.Add(newSubmission.SubmissionId, newSubmission); @@ -833,12 +850,12 @@ public GraphBuildSubmission PendBuildRequest(GraphBuildRequestData requestData) var newSubmission = new GraphBuildSubmission(this, GetNextSubmissionId(), requestData); - if (KnownTelemetry.BuildTelemetry != null) + if (_buildTelemetry != null) { // Project graph can have multiple entry points, for purposes of identifying event for same build project, // we believe that including only one entry point will provide enough precision. - KnownTelemetry.BuildTelemetry.Project ??= requestData.ProjectGraphEntryPoints?.FirstOrDefault().ProjectFile; - KnownTelemetry.BuildTelemetry.Target ??= string.Join(",", requestData.TargetNames); + _buildTelemetry.Project ??= requestData.ProjectGraphEntryPoints?.FirstOrDefault().ProjectFile; + _buildTelemetry.Target ??= string.Join(",", requestData.TargetNames); } _graphBuildSubmissions.Add(newSubmission.SubmissionId, newSubmission); @@ -987,13 +1004,13 @@ public void EndBuild() loggingService.LogBuildFinished(_overallBuildSuccess); - if (KnownTelemetry.BuildTelemetry != null) + if (_buildTelemetry != null) { - KnownTelemetry.BuildTelemetry.FinishedAt = DateTime.UtcNow; - KnownTelemetry.BuildTelemetry.Success = _overallBuildSuccess; - KnownTelemetry.BuildTelemetry.Version = ProjectCollection.Version; - KnownTelemetry.BuildTelemetry.DisplayVersion = ProjectCollection.DisplayVersion; - KnownTelemetry.BuildTelemetry.FrameworkName = NativeMethodsShared.FrameworkName; + _buildTelemetry.FinishedAt = DateTime.UtcNow; + _buildTelemetry.Success = _overallBuildSuccess; + _buildTelemetry.Version = ProjectCollection.Version; + _buildTelemetry.DisplayVersion = ProjectCollection.DisplayVersion; + _buildTelemetry.FrameworkName = NativeMethodsShared.FrameworkName; string host = null; if (BuildEnvironmentState.s_runningInVisualStudio) @@ -1008,12 +1025,12 @@ public void EndBuild() { host = "VSCode"; } - KnownTelemetry.BuildTelemetry.Host = host; + _buildTelemetry.Host = host; - KnownTelemetry.BuildTelemetry.UpdateEventProperties(); - loggingService.LogTelemetry(buildEventContext: null, KnownTelemetry.BuildTelemetry.EventName, KnownTelemetry.BuildTelemetry.Properties); + _buildTelemetry.UpdateEventProperties(); + loggingService.LogTelemetry(buildEventContext: null, _buildTelemetry.EventName, _buildTelemetry.Properties); // Clean telemetry to make it ready for next build submission. - KnownTelemetry.BuildTelemetry = null; + _buildTelemetry = null; } } diff --git a/src/Build/BackEnd/Client/MSBuildClient.cs b/src/Build/BackEnd/Client/MSBuildClient.cs index 523cb72e62d..fcbdc8c816b 100644 --- a/src/Build/BackEnd/Client/MSBuildClient.cs +++ b/src/Build/BackEnd/Client/MSBuildClient.cs @@ -166,9 +166,9 @@ public MSBuildClientExitResult Execute(CancellationToken cancellationToken) CommunicationsUtilities.Trace("Executing build with command line '{0}'", descriptiveCommandLine); bool serverIsAlreadyRunning = ServerIsRunning(); - if (KnownTelemetry.BuildTelemetry != null) + if (KnownTelemetry.PartialBuildTelemetry != null) { - KnownTelemetry.BuildTelemetry.InitialServerState = serverIsAlreadyRunning ? "hot" : "cold"; + KnownTelemetry.PartialBuildTelemetry.InitialServerState = serverIsAlreadyRunning ? "hot" : "cold"; } if (!serverIsAlreadyRunning) { @@ -524,14 +524,14 @@ private ServerNodeBuildCommand GetServerNodeBuildCommand() // We remove env variable used to invoke MSBuild server as that might be equal to 1, so we do not get an infinite recursion here. envVars.Remove(Traits.UseMSBuildServerEnvVarName); - Debug.Assert(KnownTelemetry.BuildTelemetry == null || KnownTelemetry.BuildTelemetry.StartAt.HasValue, "BuildTelemetry.StartAt was not initialized!"); + Debug.Assert(KnownTelemetry.PartialBuildTelemetry == null || KnownTelemetry.PartialBuildTelemetry.StartAt.HasValue, "BuildTelemetry.StartAt was not initialized!"); - PartialBuildTelemetry? partialBuildTelemetry = KnownTelemetry.BuildTelemetry == null + PartialBuildTelemetry? partialBuildTelemetry = KnownTelemetry.PartialBuildTelemetry == null ? null : new PartialBuildTelemetry( - startedAt: KnownTelemetry.BuildTelemetry.StartAt.GetValueOrDefault(), - initialServerState: KnownTelemetry.BuildTelemetry.InitialServerState, - serverFallbackReason: KnownTelemetry.BuildTelemetry.ServerFallbackReason); + startedAt: KnownTelemetry.PartialBuildTelemetry.StartAt.GetValueOrDefault(), + initialServerState: KnownTelemetry.PartialBuildTelemetry.InitialServerState, + serverFallbackReason: KnownTelemetry.PartialBuildTelemetry.ServerFallbackReason); return new ServerNodeBuildCommand( _commandLine, diff --git a/src/Build/BackEnd/Node/OutOfProcServerNode.cs b/src/Build/BackEnd/Node/OutOfProcServerNode.cs index 2901298ed0a..4d6f04a2112 100644 --- a/src/Build/BackEnd/Node/OutOfProcServerNode.cs +++ b/src/Build/BackEnd/Node/OutOfProcServerNode.cs @@ -365,15 +365,13 @@ private void HandleServerNodeBuildCommand(ServerNodeBuildCommand command) ConsoleConfiguration.Provider = command.ConsoleConfiguration; // Initiate build telemetry - if (KnownTelemetry.BuildTelemetry == null) - { - KnownTelemetry.BuildTelemetry = new BuildTelemetry(); - } if (command.PartialBuildTelemetry != null) { - KnownTelemetry.BuildTelemetry.StartAt = command.PartialBuildTelemetry.StartedAt; - KnownTelemetry.BuildTelemetry.InitialServerState = command.PartialBuildTelemetry.InitialServerState; - KnownTelemetry.BuildTelemetry.ServerFallbackReason = command.PartialBuildTelemetry.ServerFallbackReason; + BuildTelemetry buildTelemetry = KnownTelemetry.PartialBuildTelemetry ??= new BuildTelemetry(); + + buildTelemetry.StartAt = command.PartialBuildTelemetry.StartedAt; + buildTelemetry.InitialServerState = command.PartialBuildTelemetry.InitialServerState; + buildTelemetry.ServerFallbackReason = command.PartialBuildTelemetry.ServerFallbackReason; } // Also try our best to increase chance custom Loggers which use Console static members will work as expected. diff --git a/src/Framework/Telemetry/KnownTelemetry.cs b/src/Framework/Telemetry/KnownTelemetry.cs index 5f32304d7e6..a86dfb63574 100644 --- a/src/Framework/Telemetry/KnownTelemetry.cs +++ b/src/Framework/Telemetry/KnownTelemetry.cs @@ -9,9 +9,10 @@ namespace Microsoft.Build.Framework.Telemetry; internal static class KnownTelemetry { /// - /// Telemetry for build. - /// If null Telemetry is not supposed to be emitted. - /// After telemetry is emitted, sender shall null it. + /// Partial Telemetry for build. + /// This could be optionally initialized with some values from early in call stack, for example in Main method. + /// After this instance is acquired by a particular build, this is set to null. + /// Null means there are no prior collected build telemetry data, new clean instance shall be created for particular build. /// - public static BuildTelemetry? BuildTelemetry { get; set; } + public static BuildTelemetry? PartialBuildTelemetry { get; set; } } diff --git a/src/MSBuild/MSBuildClientApp.cs b/src/MSBuild/MSBuildClientApp.cs index 9177f76aa19..2b371148651 100644 --- a/src/MSBuild/MSBuildClientApp.cs +++ b/src/MSBuild/MSBuildClientApp.cs @@ -78,9 +78,9 @@ public static MSBuildApp.ExitType Execute( exitResult.MSBuildClientExitType == MSBuildClientExitType.UnableToConnect || exitResult.MSBuildClientExitType == MSBuildClientExitType.LaunchError) { - if (KnownTelemetry.BuildTelemetry != null) + if (KnownTelemetry.PartialBuildTelemetry != null) { - KnownTelemetry.BuildTelemetry.ServerFallbackReason = exitResult.MSBuildClientExitType.ToString(); + KnownTelemetry.PartialBuildTelemetry.ServerFallbackReason = exitResult.MSBuildClientExitType.ToString(); } // Server is busy, fallback to old behavior. diff --git a/src/MSBuild/XMake.cs b/src/MSBuild/XMake.cs index f70e92bb9a0..a5a18b6dc3a 100644 --- a/src/MSBuild/XMake.cs +++ b/src/MSBuild/XMake.cs @@ -220,7 +220,7 @@ string[] args DebuggerLaunchCheck(); // Initialize new build telemetry and record start of this build. - KnownTelemetry.BuildTelemetry = new BuildTelemetry { StartAt = DateTime.UtcNow }; + KnownTelemetry.PartialBuildTelemetry = new BuildTelemetry { StartAt = DateTime.UtcNow }; using PerformanceLogEventListener eventListener = PerformanceLogEventListener.Create(); @@ -308,18 +308,18 @@ string[] commandLine IsInteractiveBuild(commandLineSwitches)) { canRunServer = false; - if (KnownTelemetry.BuildTelemetry != null) + if (KnownTelemetry.PartialBuildTelemetry != null) { - KnownTelemetry.BuildTelemetry.ServerFallbackReason = "Arguments"; + KnownTelemetry.PartialBuildTelemetry.ServerFallbackReason = "Arguments"; } } } catch (Exception ex) { CommunicationsUtilities.Trace("Unexpected exception during command line parsing. Can not determine if it is allowed to use Server. Fall back to old behavior. Exception: {0}", ex); - if (KnownTelemetry.BuildTelemetry != null) + if (KnownTelemetry.PartialBuildTelemetry != null) { - KnownTelemetry.BuildTelemetry.ServerFallbackReason = "ErrorParsingCommandLine"; + KnownTelemetry.PartialBuildTelemetry.ServerFallbackReason = "ErrorParsingCommandLine"; } canRunServer = false; } @@ -631,7 +631,7 @@ string[] commandLine DebuggerLaunchCheck(); // Initialize new build telemetry and record start of this build, if not initialized already - KnownTelemetry.BuildTelemetry ??= new BuildTelemetry { StartAt = DateTime.UtcNow }; + KnownTelemetry.PartialBuildTelemetry ??= new BuildTelemetry { StartAt = DateTime.UtcNow }; // Indicate to the engine that it can toss extraneous file content // when it loads microsoft.*.targets. We can't do this in the general case, From aa371ab124f64394e9387675511c65186443d6f7 Mon Sep 17 00:00:00 2001 From: Roman Konecny Date: Tue, 14 Mar 2023 16:11:41 +0100 Subject: [PATCH 2/3] Bumping version --- eng/Versions.props | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/eng/Versions.props b/eng/Versions.props index 0d75b66612a..26a7381e2ae 100644 --- a/eng/Versions.props +++ b/eng/Versions.props @@ -2,7 +2,7 @@ - 17.4.1release + 17.4.2release 15.1.0.0 preview true From f0f039c97aca419daf78c46f99e408d9f7b1203e Mon Sep 17 00:00:00 2001 From: AR-May <67507805+AR-May@users.noreply.github.com> Date: Fri, 24 Feb 2023 17:12:48 +0100 Subject: [PATCH 3/3] Turn off static graph restore. (#8498) Our CI builds fails because of bug https://github.com/NuGet/Home/issues/12373. It is fixed in https://github.com/NuGet/NuGet.Client/pull/5010. We are waiting for it to flow to CI machines. Meanwhile this PR applies a workaround. Note: This PR needs to be reverted once it happens. --- eng/Build.props | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/eng/Build.props b/eng/Build.props index f2afe806410..92315cd00ab 100644 --- a/eng/Build.props +++ b/eng/Build.props @@ -2,9 +2,13 @@ + +