Skip to content

Commit

Permalink
Concurrency bug fix - BuildManager instances acquire its own BuildTel…
Browse files Browse the repository at this point in the history 
…emetry instance (#8561)

* 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

* Bumping version

* Turn off static graph restore. (#8498)

Our CI builds fails because of bug NuGet/Home#12373. 
It is fixed in NuGet/NuGet.Client#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.

---------

Co-authored-by: AR-May <[email protected]>
  • Loading branch information
@rokonec @AR-May
rokonec and AR-May authored Mar 14, 2023
1 parent 2eac915 commit f08e881
Show file tree
Hide file tree
Showing 9 changed files with 72 additions and 52 deletions.
4 changes: 4 additions & 0 deletions eng/Build.props
View file
Original file line number Diff line number Diff line change
Expand Up @@ -2,9 +2,13 @@
<!-- Copyright (c) .NET Foundation and contributors. All rights reserved. Licensed under the MIT license. See License.txt in the project root for full license information. -->
<Project>

<!-- Commented out as a temporary fix for the msbuild CI.
Waiting for https://github.com/NuGet/NuGet.Client/pull/5010 fix to flow to CI machines. -->
<!--
<PropertyGroup>
<RestoreUseStaticGraphEvaluation Condition="'$(DotNetBuildFromSource)' != 'true'">true</RestoreUseStaticGraphEvaluation>
</PropertyGroup>
-->

<ItemGroup>
<!-- Remove all sln files globbed by arcade so far and add only MSBuild.sln to the build.
Expand Down
2 changes: 1 addition & 1 deletion eng/Versions.props
View file
Original file line number Diff line number Diff line change
Expand Up @@ -2,7 +2,7 @@
<!-- Copyright (c) .NET Foundation and contributors. All rights reserved. Licensed under the MIT license. See License.txt in the project root for full license information. -->
<Project>
<PropertyGroup>
<VersionPrefix>17.4.1</VersionPrefix><DotNetFinalVersionKind>release</DotNetFinalVersionKind>
<VersionPrefix>17.4.2</VersionPrefix><DotNetFinalVersionKind>release</DotNetFinalVersionKind>
<AssemblyVersion>15.1.0.0</AssemblyVersion>
<PreReleaseVersionLabel>preview</PreReleaseVersionLabel>
<DotNetUseShippingVersions>true</DotNetUseShippingVersions>
Expand Down
10 changes: 5 additions & 5 deletions src/Build.UnitTests/BackEnd/KnownTelemetry_Tests.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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]
Expand Down
57 changes: 37 additions & 20 deletions src/Build/BackEnd/BuildManager/BuildManager.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -253,6 +253,12 @@ public class BuildManager : INodePacketHandler, IBuildComponentHost, IDisposable

private IEnumerable<DeferredBuildMessage> _deferredBuildMessages;

/// <summary>
/// Build telemetry to be send when this build ends.
/// <remarks>Could be null</remarks>
/// </summary>
private BuildTelemetry _buildTelemetry;

private ProjectCacheService _projectCacheService;

private bool _hasProjectCacheServiceInitializedVsScenario;
Expand Down Expand Up @@ -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)
{
Expand Down Expand Up @@ -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);
Expand All @@ -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);
Expand Down Expand Up @@ -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)
Expand All @@ -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;
}
}

Expand Down
14 changes: 7 additions & 7 deletions src/Build/BackEnd/Client/MSBuildClient.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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)
{
Expand Down Expand Up @@ -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,
Expand Down
12 changes: 5 additions & 7 deletions src/Build/BackEnd/Node/OutOfProcServerNode.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down
9 changes: 5 additions & 4 deletions src/Framework/Telemetry/KnownTelemetry.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -9,9 +9,10 @@ namespace Microsoft.Build.Framework.Telemetry;
internal static class KnownTelemetry
{
/// <summary>
/// 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.
/// </summary>
public static BuildTelemetry? BuildTelemetry { get; set; }
public static BuildTelemetry? PartialBuildTelemetry { get; set; }
}
4 changes: 2 additions & 2 deletions src/MSBuild/MSBuildClientApp.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down
12 changes: 6 additions & 6 deletions src/MSBuild/XMake.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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();

Expand Down Expand Up @@ -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;
}
Expand Down Expand Up @@ -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,
Expand Down

0 comments on commit f08e881

Please sign in to comment.