From 8080b4c167af3a46db4092eac4a71e1b3545a969 Mon Sep 17 00:00:00 2001 From: Roman Konecny Date: Fri, 27 May 2022 10:44:14 +0200 Subject: [PATCH 1/7] Solving memory leak by reusing BuildManager and ProjectRoolElementCache --- src/Build/Definition/ProjectCollection.cs | 43 ++++++++++++++++++- .../PublicAPI/net/PublicAPI.Unshipped.txt | 1 + .../netstandard/PublicAPI.Unshipped.txt | 1 + src/MSBuild/XMake.cs | 12 +++++- 4 files changed, 54 insertions(+), 3 deletions(-) diff --git a/src/Build/Definition/ProjectCollection.cs b/src/Build/Definition/ProjectCollection.cs index 485b905abe0..096fcc073a4 100644 --- a/src/Build/Definition/ProjectCollection.cs +++ b/src/Build/Definition/ProjectCollection.cs @@ -145,6 +145,8 @@ public void Dispose() /// private static string s_assemblyDisplayVersion; + private static ProjectRootElementCacheBase s_projectRootElementCache = null; + /// /// The projects loaded into this collection. /// @@ -302,6 +304,26 @@ public ProjectCollection(IDictionary globalProperties, IEnumerab /// If set to true, only critical events will be logged. /// If set to true, load all projects as read-only. public ProjectCollection(IDictionary globalProperties, IEnumerable loggers, IEnumerable remoteLoggers, ToolsetDefinitionLocations toolsetDefinitionLocations, int maxNodeCount, bool onlyLogCriticalEvents, bool loadProjectsReadOnly) + : this(globalProperties, loggers, remoteLoggers, toolsetDefinitionLocations, maxNodeCount, onlyLogCriticalEvents, loadProjectsReadOnly, reuseProjectRootElementCache: false) + { + } + + /// + /// Instantiates a project collection with specified global properties and loggers and using the + /// specified toolset locations, node count, and setting of onlyLogCriticalEvents. + /// Global properties and loggers may be null. + /// Throws InvalidProjectFileException if any of the global properties are reserved. + /// May throw InvalidToolsetDefinitionException. + /// + /// The default global properties to use. May be null. + /// The loggers to register. May be null and specified to any build instead. + /// Any remote loggers to register. May be null and specified to any build instead. + /// The locations from which to load toolsets. + /// The maximum number of nodes to use for building. + /// If set to true, only critical events will be logged. + /// If set to true, load all projects as read-only. + /// If set to true, it will try to reuse singleton. + public ProjectCollection(IDictionary globalProperties, IEnumerable loggers, IEnumerable remoteLoggers, ToolsetDefinitionLocations toolsetDefinitionLocations, int maxNodeCount, bool onlyLogCriticalEvents, bool loadProjectsReadOnly, bool reuseProjectRootElementCache) { _loadedProjects = new LoadedProjectCollection(); ToolsetLocations = toolsetDefinitionLocations; @@ -311,10 +333,23 @@ public ProjectCollection(IDictionary globalProperties, IEnumerab { ProjectRootElementCache = new SimpleProjectRootElementCache(); } + else if (reuseProjectRootElementCache && s_projectRootElementCache != null) + { + ProjectRootElementCache = s_projectRootElementCache; + } else { - ProjectRootElementCache = new ProjectRootElementCache(autoReloadFromDisk: false, loadProjectsReadOnly); + // When we are reusing ProjectRootElementCache we need to reload XMLs if it has changed between MSBuild Server sessions/builds. + // If we are not reusing, cache will be released at end of build and as we do not support project files will changes during build + // we do not need to auto reload. + bool autoReloadFromDisk = reuseProjectRootElementCache; + ProjectRootElementCache = new ProjectRootElementCache(autoReloadFromDisk, loadProjectsReadOnly); + if (reuseProjectRootElementCache && s_projectRootElementCache == null) + { + s_projectRootElementCache = ProjectRootElementCache; + } } + OnlyLogCriticalEvents = onlyLogCriticalEvents; try @@ -1603,6 +1638,12 @@ protected virtual void Dispose(bool disposing) if (disposing) { ShutDownLoggingService(); + if (ProjectRootElementCache != null) + { + ProjectRootElementCache.ProjectRootElementAddedHandler -= ProjectRootElementCache_ProjectRootElementAddedHandler; + ProjectRootElementCache.ProjectRootElementDirtied -= ProjectRootElementCache_ProjectRootElementDirtiedHandler; + ProjectRootElementCache.ProjectDirtied -= ProjectRootElementCache_ProjectDirtiedHandler; + } Tracing.Dump(); } } diff --git a/src/Build/PublicAPI/net/PublicAPI.Unshipped.txt b/src/Build/PublicAPI/net/PublicAPI.Unshipped.txt index 349a8e57aac..ee20877adfb 100644 --- a/src/Build/PublicAPI/net/PublicAPI.Unshipped.txt +++ b/src/Build/PublicAPI/net/PublicAPI.Unshipped.txt @@ -1,3 +1,4 @@ +Microsoft.Build.Evaluation.ProjectCollection.ProjectCollection(System.Collections.Generic.IDictionary globalProperties, System.Collections.Generic.IEnumerable loggers, System.Collections.Generic.IEnumerable remoteLoggers, Microsoft.Build.Evaluation.ToolsetDefinitionLocations toolsetDefinitionLocations, int maxNodeCount, bool onlyLogCriticalEvents, bool loadProjectsReadOnly, bool reuseProjectRootElementCache) -> void Microsoft.Build.Execution.MSBuildClient Microsoft.Build.Execution.MSBuildClient.Execute(string commandLine, System.Threading.CancellationToken cancellationToken) -> Microsoft.Build.Execution.MSBuildClientExitResult Microsoft.Build.Execution.MSBuildClient.MSBuildClient(string exeLocation, string dllLocation) -> void diff --git a/src/Build/PublicAPI/netstandard/PublicAPI.Unshipped.txt b/src/Build/PublicAPI/netstandard/PublicAPI.Unshipped.txt index 39c901f1b5c..44179d2f0e1 100644 --- a/src/Build/PublicAPI/netstandard/PublicAPI.Unshipped.txt +++ b/src/Build/PublicAPI/netstandard/PublicAPI.Unshipped.txt @@ -1,3 +1,4 @@ +Microsoft.Build.Evaluation.ProjectCollection.ProjectCollection(System.Collections.Generic.IDictionary globalProperties, System.Collections.Generic.IEnumerable loggers, System.Collections.Generic.IEnumerable remoteLoggers, Microsoft.Build.Evaluation.ToolsetDefinitionLocations toolsetDefinitionLocations, int maxNodeCount, bool onlyLogCriticalEvents, bool loadProjectsReadOnly, bool reuseProjectRootElementCache) -> void Microsoft.Build.Execution.MSBuildClient Microsoft.Build.Execution.MSBuildClient.Execute(string commandLine, System.Threading.CancellationToken cancellationToken) -> Microsoft.Build.Execution.MSBuildClientExitResult Microsoft.Build.Execution.MSBuildClient.MSBuildClient(string exeLocation, string dllLocation) -> void diff --git a/src/MSBuild/XMake.cs b/src/MSBuild/XMake.cs index b7d98c179d5..37434c6fc65 100644 --- a/src/MSBuild/XMake.cs +++ b/src/MSBuild/XMake.cs @@ -1082,7 +1082,8 @@ string[] commandLine toolsetDefinitionLocations, cpuCount, onlyLogCriticalEvents, - loadProjectsReadOnly: !preprocessOnly + loadProjectsReadOnly: !preprocessOnly, + reuseProjectRootElementCache: s_isServerNode ); if (toolsVersion != null && !projectCollection.ContainsToolset(toolsVersion)) @@ -1315,7 +1316,14 @@ string[] commandLine FileUtilities.ClearCacheDirectory(); projectCollection?.Dispose(); - BuildManager.DefaultBuildManager.Dispose(); + // Build manager shall be reused for all build sessions. + // If, for one reason or another, this behavior needs to change in future + // please be aware that current code creates and keep running InProcNode even + // when its owning default build manager is disposed resulting in leek of memory and threads. + if (!s_isServerNode) + { + BuildManager.DefaultBuildManager.Dispose(); + } } return success; From e41cf8a6ff737fe197b89d7c856444a9f39b89b6 Mon Sep 17 00:00:00 2001 From: Roman Konecny Date: Fri, 27 May 2022 12:13:16 +0200 Subject: [PATCH 2/7] Do not clear project root element cache if in auto reload. --- src/Build/Evaluation/ProjectRootElementCache.cs | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/src/Build/Evaluation/ProjectRootElementCache.cs b/src/Build/Evaluation/ProjectRootElementCache.cs index 17ecae43227..208a43ed668 100644 --- a/src/Build/Evaluation/ProjectRootElementCache.cs +++ b/src/Build/Evaluation/ProjectRootElementCache.cs @@ -415,6 +415,12 @@ internal override void Clear() /// internal override void DiscardImplicitReferences() { + if (_autoReloadFromDisk) + { + // no need to clear it, as auto reload properly invalidates caches if changed. + return; + } + lock (_locker) { // Make a new Weak cache only with items that have been explicitly loaded, this will be a small number, there will most likely From 447225c121b96cdadf7bec6ca0e8d2ffb15900e2 Mon Sep 17 00:00:00 2001 From: Roman Konecny Date: Fri, 27 May 2022 22:02:32 +0200 Subject: [PATCH 3/7] Reduce if Co-authored-by: Forgind --- src/Build/Definition/ProjectCollection.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/Build/Definition/ProjectCollection.cs b/src/Build/Definition/ProjectCollection.cs index 096fcc073a4..f5d45290cd2 100644 --- a/src/Build/Definition/ProjectCollection.cs +++ b/src/Build/Definition/ProjectCollection.cs @@ -344,7 +344,7 @@ public ProjectCollection(IDictionary globalProperties, IEnumerab // we do not need to auto reload. bool autoReloadFromDisk = reuseProjectRootElementCache; ProjectRootElementCache = new ProjectRootElementCache(autoReloadFromDisk, loadProjectsReadOnly); - if (reuseProjectRootElementCache && s_projectRootElementCache == null) + if (reuseProjectRootElementCache) { s_projectRootElementCache = ProjectRootElementCache; } From 100887b95e7216227fd33cffc51531ae02d057ad Mon Sep 17 00:00:00 2001 From: Roman Konecny Date: Fri, 1 Jul 2022 15:01:49 +0200 Subject: [PATCH 4/7] Emmit BuildTelemetry --- .../BackEnd/BuildManager/BuildManager.cs | 55 ++++++- src/Build/BackEnd/Client/MSBuildClient.cs | 17 ++- src/Build/BackEnd/Node/OutOfProcServerNode.cs | 15 +- .../BackEnd/Node/PartialBuildTelemetry.cs | 51 +++++++ .../BackEnd/Node/ServerNodeBuildCommand.cs | 12 +- src/Build/Microsoft.Build.csproj | 1 + src/Framework/NativeMethods.cs | 18 +++ src/Framework/Telemetry/BuildTelemetry.cs | 135 ++++++++++++++++++ src/Framework/Telemetry/KnownTelemetry.cs | 17 +++ src/Framework/Telemetry/TelemetryBase.cs | 24 ++++ src/MSBuild/MSBuildClientApp.cs | 6 + src/MSBuild/XMake.cs | 17 ++- 12 files changed, 355 insertions(+), 13 deletions(-) create mode 100644 src/Build/BackEnd/Node/PartialBuildTelemetry.cs create mode 100644 src/Framework/Telemetry/BuildTelemetry.cs create mode 100644 src/Framework/Telemetry/KnownTelemetry.cs create mode 100644 src/Framework/Telemetry/TelemetryBase.cs diff --git a/src/Build/BackEnd/BuildManager/BuildManager.cs b/src/Build/BackEnd/BuildManager/BuildManager.cs index c4a9d2c9523..76a05de32d6 100644 --- a/src/Build/BackEnd/BuildManager/BuildManager.cs +++ b/src/Build/BackEnd/BuildManager/BuildManager.cs @@ -25,6 +25,7 @@ using Microsoft.Build.Exceptions; using Microsoft.Build.Experimental.ProjectCache; using Microsoft.Build.Framework; +using Microsoft.Build.Framework.Telemetry; using Microsoft.Build.Graph; using Microsoft.Build.Internal; using Microsoft.Build.Logging; @@ -456,7 +457,7 @@ public void BeginBuild(BuildParameters parameters) _nodeManager?.ShutdownAllNodes(); _taskHostNodeManager?.ShutdownAllNodes(); } - } + } } _previousLowPriority = parameters.LowPriority; @@ -470,6 +471,14 @@ public void BeginBuild(BuildParameters parameters) MSBuildEventSource.Log.BuildStart(); + // Initiate build telemetry data + DateTime now = DateTime.UtcNow; + KnownTelemetry.BuildTelemetry ??= new() + { + StartAt = now, + }; + KnownTelemetry.BuildTelemetry.InnerStartAt = now; + if (BuildParameters.DumpOpportunisticInternStats) { Strings.EnableDiagnostics(); @@ -796,6 +805,13 @@ public BuildSubmission PendBuildRequest(BuildRequestData requestData) VerifyStateInternal(BuildManagerState.Building); var newSubmission = new BuildSubmission(this, GetNextSubmissionId(), requestData, _buildParameters.LegacyThreadingSemantics); + + if (KnownTelemetry.BuildTelemetry != null) + { + KnownTelemetry.BuildTelemetry.Project ??= requestData.ProjectFullPath; + KnownTelemetry.BuildTelemetry.Target ??= string.Join(",", requestData.TargetNames); + } + _buildSubmissions.Add(newSubmission.SubmissionId, newSubmission); _noActiveSubmissionsEvent.Reset(); return newSubmission; @@ -817,6 +833,13 @@ public GraphBuildSubmission PendBuildRequest(GraphBuildRequestData requestData) VerifyStateInternal(BuildManagerState.Building); var newSubmission = new GraphBuildSubmission(this, GetNextSubmissionId(), requestData); + + if (KnownTelemetry.BuildTelemetry != null) + { + KnownTelemetry.BuildTelemetry.Project ??= requestData.ProjectGraphEntryPoints.FirstOrDefault().ProjectFile; + KnownTelemetry.BuildTelemetry.Target ??= string.Join(",", requestData.TargetNames); + } + _graphBuildSubmissions.Add(newSubmission.SubmissionId, newSubmission); _noActiveSubmissionsEvent.Reset(); return newSubmission; @@ -965,6 +988,36 @@ public void EndBuild() } loggingService.LogBuildFinished(_overallBuildSuccess); + + if (KnownTelemetry.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; + NativeMethodsShared.GetOSNameForExtensionsPath(); + + string host = null; + if (BuildEnvironmentState.s_runningInVisualStudio) + { + host = "VS"; + } + else if (!string.IsNullOrEmpty(Environment.GetEnvironmentVariable("MSBUILD_HOST_NAME"))) + { + host = Environment.GetEnvironmentVariable("MSBUILD_HOST_NAME"); + } + else if (!string.IsNullOrEmpty(Environment.GetEnvironmentVariable("VSCODE_CWD")) || Environment.GetEnvironmentVariable("TERM_PROGRAM") == "vscode") + { + host = "VSCode"; + } + KnownTelemetry.BuildTelemetry.Host = host; + + KnownTelemetry.BuildTelemetry.UpdateEventProperties(); + loggingService.LogTelemetry(buildEventContext: null, KnownTelemetry.BuildTelemetry.EventName, KnownTelemetry.BuildTelemetry.Properties); + // Clean telemetry which makes it ready for next build submission. + KnownTelemetry.BuildTelemetry = null; + } } ShutdownLoggingService(loggingService); diff --git a/src/Build/BackEnd/Client/MSBuildClient.cs b/src/Build/BackEnd/Client/MSBuildClient.cs index b2329da56b5..08c3b156233 100644 --- a/src/Build/BackEnd/Client/MSBuildClient.cs +++ b/src/Build/BackEnd/Client/MSBuildClient.cs @@ -15,6 +15,7 @@ using Microsoft.Build.Eventing; using Microsoft.Build.Execution; using Microsoft.Build.Framework; +using Microsoft.Build.Framework.Telemetry; using Microsoft.Build.Internal; using Microsoft.Build.Shared; @@ -152,6 +153,10 @@ public MSBuildClientExitResult Execute(CancellationToken cancellationToken) // Start server it if is not running. bool serverIsAlreadyRunning = ServerNamedMutex.WasOpen(serverRunningMutexName); + if (KnownTelemetry.BuildTelemetry != null) + { + KnownTelemetry.BuildTelemetry.InitialServerState = serverIsAlreadyRunning ? "hot" : "cold"; + } if (!serverIsAlreadyRunning) { CommunicationsUtilities.Trace("Server was not running. Starting server now."); @@ -432,13 +437,23 @@ 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[Traits.UseMSBuildServerEnvVarName] = "0"; + Debug.Assert(KnownTelemetry.BuildTelemetry == null || KnownTelemetry.BuildTelemetry.StartAt.HasValue, "BuildTelemetry.StartAt was not initialized!"); + + PartialBuildTelemetry? partialBuildTelemetry = KnownTelemetry.BuildTelemetry == null + ? null + : new PartialBuildTelemetry( + startedAt: KnownTelemetry.BuildTelemetry.StartAt.GetValueOrDefault(), + initialServerState: KnownTelemetry.BuildTelemetry.InitialServerState, + serverFallbackReason: KnownTelemetry.BuildTelemetry.ServerFallbackReason); + return new ServerNodeBuildCommand( _commandLine, startupDirectory: Directory.GetCurrentDirectory(), buildProcessEnvironment: envVars, CultureInfo.CurrentCulture, CultureInfo.CurrentUICulture, - _consoleConfiguration!); + _consoleConfiguration!, + partialBuildTelemetry); } private ServerNodeHandshake GetHandshake() diff --git a/src/Build/BackEnd/Node/OutOfProcServerNode.cs b/src/Build/BackEnd/Node/OutOfProcServerNode.cs index 6a0b4c94242..dadbaba7765 100644 --- a/src/Build/BackEnd/Node/OutOfProcServerNode.cs +++ b/src/Build/BackEnd/Node/OutOfProcServerNode.cs @@ -6,12 +6,13 @@ using System.Collections.Concurrent; using System.IO; using System.Threading; +using System.Threading.Tasks; using Microsoft.Build.BackEnd; using Microsoft.Build.Shared; using Microsoft.Build.Internal; -using System.Threading.Tasks; using Microsoft.Build.Execution; using Microsoft.Build.BackEnd.Logging; +using Microsoft.Build.Framework.Telemetry; namespace Microsoft.Build.Experimental { @@ -332,6 +333,18 @@ private void HandleServerNodeBuildCommand(ServerNodeBuildCommand command) // Configure console configuration so Loggers can change their behavior based on Target (client) Console properties. 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; + } + // Also try our best to increase chance custom Loggers which use Console static members will work as expected. try { diff --git a/src/Build/BackEnd/Node/PartialBuildTelemetry.cs b/src/Build/BackEnd/Node/PartialBuildTelemetry.cs new file mode 100644 index 00000000000..b9960a0e752 --- /dev/null +++ b/src/Build/BackEnd/Node/PartialBuildTelemetry.cs @@ -0,0 +1,51 @@ +// Copyright (c) Microsoft. All rights reserved. +// Licensed under the MIT license. See LICENSE file in the project root for full license information. + +using System; + +namespace Microsoft.Build.BackEnd; + +/// +/// Part of BuildTelemetry which is collected on client and needs to be sent to server, +/// so server can log BuildTelemetry once it is finished. +/// +internal sealed class PartialBuildTelemetry : ITranslatable +{ + private DateTime _startedAt = default; + private string? _initialServerState = default; + private string? _serverFallbackReason = default; + + public PartialBuildTelemetry(DateTime startedAt, string? initialServerState, string? serverFallbackReason) + { + _startedAt = startedAt; + _initialServerState = initialServerState; + _serverFallbackReason = serverFallbackReason; + } + + /// + /// Constructor for deserialization + /// + private PartialBuildTelemetry() + { + } + + public DateTime? StartedAt => _startedAt; + + public string? InitialServerState => _initialServerState; + + public string? ServerFallbackReason => _serverFallbackReason; + + public void Translate(ITranslator translator) + { + translator.Translate(ref _startedAt); + translator.Translate(ref _initialServerState); + translator.Translate(ref _serverFallbackReason); + } + + internal static PartialBuildTelemetry FactoryForDeserialization(ITranslator translator) + { + PartialBuildTelemetry partialTelemetryData = new(); + partialTelemetryData.Translate(translator); + return partialTelemetryData; + } +} diff --git a/src/Build/BackEnd/Node/ServerNodeBuildCommand.cs b/src/Build/BackEnd/Node/ServerNodeBuildCommand.cs index 32c551b78a8..589d3f9670b 100644 --- a/src/Build/BackEnd/Node/ServerNodeBuildCommand.cs +++ b/src/Build/BackEnd/Node/ServerNodeBuildCommand.cs @@ -24,6 +24,7 @@ internal sealed class ServerNodeBuildCommand : INodePacket private CultureInfo _culture = default!; private CultureInfo _uiCulture = default!; private TargetConsoleConfiguration _consoleConfiguration = default!; + private PartialBuildTelemetry? _partialBuildTelemetry = default; /// /// Retrieves the packet type. @@ -64,6 +65,12 @@ internal sealed class ServerNodeBuildCommand : INodePacket /// public TargetConsoleConfiguration ConsoleConfiguration => _consoleConfiguration; + /// + /// Part of BuildTelemetry which is collected on client and needs to be sent to server, + /// so server can log BuildTelemetry once it is finished. + /// + public PartialBuildTelemetry? PartialBuildTelemetry => _partialBuildTelemetry; + /// /// Private constructor for deserialization /// @@ -80,7 +87,8 @@ public ServerNodeBuildCommand( string startupDirectory, Dictionary buildProcessEnvironment, CultureInfo culture, CultureInfo uiCulture, - TargetConsoleConfiguration consoleConfiguration) + TargetConsoleConfiguration consoleConfiguration, + PartialBuildTelemetry? partialBuildTelemetry) { ErrorUtilities.VerifyThrowInternalNull(consoleConfiguration, nameof(consoleConfiguration)); @@ -90,6 +98,7 @@ public ServerNodeBuildCommand( _culture = culture; _uiCulture = uiCulture; _consoleConfiguration = consoleConfiguration; + _partialBuildTelemetry = partialBuildTelemetry; } /// @@ -104,6 +113,7 @@ public void Translate(ITranslator translator) translator.TranslateCulture(ref _culture); translator.TranslateCulture(ref _uiCulture); translator.Translate(ref _consoleConfiguration, TargetConsoleConfiguration.FactoryForDeserialization); + translator.Translate(ref _partialBuildTelemetry, PartialBuildTelemetry.FactoryForDeserialization); } /// diff --git a/src/Build/Microsoft.Build.csproj b/src/Build/Microsoft.Build.csproj index 2c37f964cfc..dee57aeff4c 100644 --- a/src/Build/Microsoft.Build.csproj +++ b/src/Build/Microsoft.Build.csproj @@ -159,6 +159,7 @@ + diff --git a/src/Framework/NativeMethods.cs b/src/Framework/NativeMethods.cs index 2d3a9027b88..d0c29652824 100644 --- a/src/Framework/NativeMethods.cs +++ b/src/Framework/NativeMethods.cs @@ -758,6 +758,24 @@ internal static string OSName get { return IsWindows ? "Windows_NT" : "Unix"; } } + /// + /// Framework named as presented to users (for example in version info). + /// + internal static string FrameworkName + { + get + { +#if RUNTIME_TYPE_NETCORE + const string frameworkName = ".NET"; +#elif MONO + const string frameworkName = "Mono"; +#else + const string frameworkName = ".NET Framework"; +#endif + return frameworkName; + } + } + /// /// OS name that can be used for the msbuildExtensionsPathSearchPaths element /// for a toolset diff --git a/src/Framework/Telemetry/BuildTelemetry.cs b/src/Framework/Telemetry/BuildTelemetry.cs new file mode 100644 index 00000000000..ae45670e6ea --- /dev/null +++ b/src/Framework/Telemetry/BuildTelemetry.cs @@ -0,0 +1,135 @@ +// Copyright (c) Microsoft. All rights reserved. +// Licensed under the MIT license. See LICENSE file in the project root for full license information. + +using System; +using System.Globalization; + +namespace Microsoft.Build.Framework.Telemetry +{ + /// + /// Telemetry of build. + /// + internal class BuildTelemetry : TelemetryBase + { + public override string EventName => "msbuild/build"; + + /// + /// Time at which build have started. + /// + /// + /// It is time when build started, not when BuildManager start executing build. + /// For example in case of MSBuild Server it is time before we connected or launched MSBuild Server. + /// + public DateTime? StartAt { get; set; } + + /// + /// Time at which inner build have started. + /// + /// + /// It is time when build internally started, i.e. when BuildManager starts it. + /// In case of MSBuild Server it is time when Server starts build. + /// + public DateTime? InnerStartAt { get; set; } + + /// + /// Time at which build have finished. + /// + public DateTime? FinishedAt { get; set; } + + /// + /// Overall build success. + /// + public bool? Success { get; set; } + + /// + /// Build Target. + /// + public string? Target { get; set; } + + /// + /// MSBuild server fallback reason. + /// Either "ServerBusy", "ConnectionError" or null (no fallback). + /// + public string? ServerFallbackReason { get; set; } + + /// + /// Version of MSBuild. + /// + public Version? Version { get; set; } + + /// + /// Display version of the Engine suitable for display to a user. + /// + public string? DisplayVersion { get; set; } + + /// + /// Path to project file. + /// + public string? Project { get; set; } + + /// + /// Host in which MSBuild build was executed. + /// For example: "VS", "VSCode", "Azure DevOps", "GitHub Action", "CLI", ... + /// + public string? Host { get; set; } + + /// + /// State of MSBuild server process before this build. + /// One of 'cold', 'hot', null (if not run as server) + /// + public string? InitialServerState { get; set; } + + /// + /// Framework name suitable for display to a user. + /// + public string? FrameworkName { get; set; } + + public override void UpdateEventProperties() + { + if (StartAt.HasValue && FinishedAt.HasValue) + { + Properties["BuildDurationInMilliseconds"] = (FinishedAt.Value - StartAt.Value).TotalMilliseconds.ToString(CultureInfo.InvariantCulture); + } + if (InnerStartAt.HasValue && FinishedAt.HasValue) + { + Properties["InnerBuildDurationInMilliseconds"] = (FinishedAt.Value - InnerStartAt.Value).TotalMilliseconds.ToString(CultureInfo.InvariantCulture); + } + if (Success.HasValue) + { + Properties["BuildSuccess"] = Success.HasValue.ToString(CultureInfo.InvariantCulture); + } + if (Target != null) + { + Properties["BuildTarget"] = Target; + } + if (ServerFallbackReason != null) + { + Properties["ServerFallbackReason"] = ServerFallbackReason; + } + if (Version != null) + { + Properties["BuildEngineVersion"] = Version.ToString(); + } + if (DisplayVersion != null) + { + Properties["BuildEngineDisplayVersion"] = DisplayVersion; + } + if (Project != null) + { + Properties["ProjectPath"] = Project; + } + if (Host != null) + { + Properties["BuildEngineHost"] = Host; + } + if (InitialServerState != null) + { + Properties["InitialMSBuildServerState"] = InitialServerState; + } + if (FrameworkName != null) + { + Properties["BuildEngineFrameworkName"] = FrameworkName; + } + } + } +} diff --git a/src/Framework/Telemetry/KnownTelemetry.cs b/src/Framework/Telemetry/KnownTelemetry.cs new file mode 100644 index 00000000000..5f32304d7e6 --- /dev/null +++ b/src/Framework/Telemetry/KnownTelemetry.cs @@ -0,0 +1,17 @@ +// Copyright (c) Microsoft. All rights reserved. +// Licensed under the MIT license. See LICENSE file in the project root for full license information. + +namespace Microsoft.Build.Framework.Telemetry; + +/// +/// Static class to help access and modify known telemetries. +/// +internal static class KnownTelemetry +{ + /// + /// Telemetry for build. + /// If null Telemetry is not supposed to be emitted. + /// After telemetry is emitted, sender shall null it. + /// + public static BuildTelemetry? BuildTelemetry { get; set; } +} diff --git a/src/Framework/Telemetry/TelemetryBase.cs b/src/Framework/Telemetry/TelemetryBase.cs new file mode 100644 index 00000000000..26348f1ea4f --- /dev/null +++ b/src/Framework/Telemetry/TelemetryBase.cs @@ -0,0 +1,24 @@ +// Copyright (c) Microsoft. All rights reserved. +// Licensed under the MIT license. See LICENSE file in the project root for full license information. + +using System.Collections.Generic; + +namespace Microsoft.Build.Framework.Telemetry; + +internal abstract class TelemetryBase +{ + /// + /// Gets or sets the name of the event. + /// + public abstract string EventName { get; } + + /// + /// Gets or sets a list of properties associated with the event. + /// + public IDictionary Properties { get; set; } = new Dictionary(); + + /// + /// Translate all derived type members into properties which will be used to build . + /// + public abstract void UpdateEventProperties(); +} diff --git a/src/MSBuild/MSBuildClientApp.cs b/src/MSBuild/MSBuildClientApp.cs index b5187d198a1..e09490ac72d 100644 --- a/src/MSBuild/MSBuildClientApp.cs +++ b/src/MSBuild/MSBuildClientApp.cs @@ -5,6 +5,7 @@ using Microsoft.Build.Shared; using System.Threading; using Microsoft.Build.Experimental; +using Microsoft.Build.Framework.Telemetry; #if RUNTIME_TYPE_NETCORE || MONO using System.IO; @@ -76,6 +77,11 @@ public static MSBuildApp.ExitType Execute( if (exitResult.MSBuildClientExitType == MSBuildClientExitType.ServerBusy || exitResult.MSBuildClientExitType == MSBuildClientExitType.ConnectionError) { + if (KnownTelemetry.BuildTelemetry != null) + { + KnownTelemetry.BuildTelemetry.ServerFallbackReason = exitResult.MSBuildClientExitType.ToString(); + } + // Server is busy, fallback to old behavior. return MSBuildApp.Execute(commandLine); } diff --git a/src/MSBuild/XMake.cs b/src/MSBuild/XMake.cs index b3ff12d4a35..d69a6e34c6f 100644 --- a/src/MSBuild/XMake.cs +++ b/src/MSBuild/XMake.cs @@ -36,6 +36,7 @@ using BinaryLogger = Microsoft.Build.Logging.BinaryLogger; using Microsoft.Build.Shared.Debugging; using Microsoft.Build.Experimental; +using Microsoft.Build.Framework.Telemetry; #nullable disable @@ -215,6 +216,9 @@ string[] args #endif ) { + // Initialize new build telemetry and record start of this build. + KnownTelemetry.BuildTelemetry = new BuildTelemetry { StartAt = DateTime.UtcNow }; + using PerformanceLogEventListener eventListener = PerformanceLogEventListener.Create(); if (Environment.GetEnvironmentVariable("MSBUILDDUMPPROCESSCOUNTERS") == "1") @@ -525,6 +529,9 @@ string[] commandLine #endif ) { + // Initialize new build telemetry and record start of this build, if not initialized already + KnownTelemetry.BuildTelemetry ??= 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, // because tasks in the build can (and occasionally do) load MSBuild format files @@ -3757,15 +3764,7 @@ private static void ThrowInvalidToolsVersionInitializationException(IEnumerable< /// private static void DisplayVersionMessage() { -#if RUNTIME_TYPE_NETCORE - const string frameworkName = ".NET"; -#elif MONO - const string frameworkName = "Mono"; -#else - const string frameworkName = ".NET Framework"; -#endif - - Console.WriteLine(ResourceUtilities.FormatResourceStringStripCodeAndKeyword("MSBuildVersionMessage", ProjectCollection.DisplayVersion, frameworkName)); + Console.WriteLine(ResourceUtilities.FormatResourceStringStripCodeAndKeyword("MSBuildVersionMessage", ProjectCollection.DisplayVersion, NativeMethods.FrameworkName)); } /// From b40795c08bdc061c5ead562c4e230fe0f291b9d5 Mon Sep 17 00:00:00 2001 From: Roman Konecny Date: Fri, 1 Jul 2022 18:11:54 +0200 Subject: [PATCH 5/7] Unit tests --- .../BackEnd/KnownTelemetry_Tests.cs | 121 ++++++++++++++++++ src/Framework/Telemetry/BuildTelemetry.cs | 52 +++++--- 2 files changed, 152 insertions(+), 21 deletions(-) create mode 100644 src/Build.UnitTests/BackEnd/KnownTelemetry_Tests.cs diff --git a/src/Build.UnitTests/BackEnd/KnownTelemetry_Tests.cs b/src/Build.UnitTests/BackEnd/KnownTelemetry_Tests.cs new file mode 100644 index 00000000000..a0ae7a9fafd --- /dev/null +++ b/src/Build.UnitTests/BackEnd/KnownTelemetry_Tests.cs @@ -0,0 +1,121 @@ +// Copyright (c) Microsoft. All rights reserved. +// Licensed under the MIT license. See LICENSE file in the project root for full license information. + +#nullable disable +using System; +using System.Globalization; +using Microsoft.Build.Framework.Telemetry; +using Shouldly; +using Xunit; + +namespace Microsoft.Build.UnitTests.Telemetry; + +public class KnownTelemetry_Tests +{ + [Fact] + public void BuildTelemetryCanBeSetToNull() + { + KnownTelemetry.BuildTelemetry = new BuildTelemetry(); + KnownTelemetry.BuildTelemetry = null; + + KnownTelemetry.BuildTelemetry.ShouldBeNull(); + } + + [Fact] + public void BuildTelemetryCanBeSet() + { + BuildTelemetry buildTelemetry = new BuildTelemetry(); + KnownTelemetry.BuildTelemetry = buildTelemetry; + + KnownTelemetry.BuildTelemetry.ShouldBeSameAs(buildTelemetry); + } + + [Fact] + public void BuildTelemetryConstructedHasNoProperties() + { + BuildTelemetry buildTelemetry = new BuildTelemetry(); + + buildTelemetry.DisplayVersion.ShouldBeNull(); + buildTelemetry.EventName.ShouldBe("build"); + buildTelemetry.FinishedAt.ShouldBeNull(); + buildTelemetry.FrameworkName.ShouldBeNull(); + buildTelemetry.Host.ShouldBeNull(); + buildTelemetry.InitialServerState.ShouldBeNull(); + buildTelemetry.InnerStartAt.ShouldBeNull(); + buildTelemetry.Project.ShouldBeNull(); + buildTelemetry.ServerFallbackReason.ShouldBeNull(); + buildTelemetry.StartAt.ShouldBeNull(); + buildTelemetry.Success.ShouldBeNull(); + buildTelemetry.Target.ShouldBeNull(); + buildTelemetry.Version.ShouldBeNull(); + + buildTelemetry.UpdateEventProperties(); + buildTelemetry.Properties.ShouldBeEmpty(); + } + + [Fact] + public void BuildTelemetryCreateProperProperties() + { + BuildTelemetry buildTelemetry = new BuildTelemetry(); + + DateTime startAt = new DateTime(2023, 01, 02, 10, 11, 22); + DateTime innerStartAt = new DateTime(2023, 01, 02, 10, 20, 30); + DateTime finishedAt = new DateTime(2023, 12, 13, 14, 15, 16); + + buildTelemetry.DisplayVersion = "Some Display Version"; + buildTelemetry.FinishedAt = finishedAt; + buildTelemetry.FrameworkName = "new .NET"; + buildTelemetry.Host = "Host description"; + buildTelemetry.InitialServerState = "hot"; + buildTelemetry.InnerStartAt = innerStartAt; + buildTelemetry.Project = @"C:\\dev\\theProject"; + buildTelemetry.ServerFallbackReason = "busy"; + buildTelemetry.StartAt = startAt; + buildTelemetry.Success = true; + buildTelemetry.Target = "clean"; + buildTelemetry.Version = new Version(1, 2, 3, 4); + + buildTelemetry.UpdateEventProperties(); + buildTelemetry.Properties.Count.ShouldBe(11); + + buildTelemetry.Properties["BuildEngineDisplayVersion"].ShouldBe("Some Display Version"); + buildTelemetry.Properties["BuildEngineFrameworkName"].ShouldBe("new .NET"); + buildTelemetry.Properties["BuildEngineHost"].ShouldBe("Host description"); + buildTelemetry.Properties["InitialMSBuildServerState"].ShouldBe("hot"); + buildTelemetry.Properties["ProjectPath"].ShouldBe(@"C:\\dev\\theProject"); + buildTelemetry.Properties["ServerFallbackReason"].ShouldBe("busy"); + buildTelemetry.Properties["BuildSuccess"].ShouldBe("True"); + buildTelemetry.Properties["BuildTarget"].ShouldBe("clean"); + buildTelemetry.Properties["BuildEngineVersion"].ShouldBe("1.2.3.4"); + + // verify computed + buildTelemetry.Properties["BuildDurationInMilliseconds"] = (finishedAt - startAt).TotalMilliseconds.ToString(CultureInfo.InvariantCulture); + buildTelemetry.Properties["InnerBuildDurationInMilliseconds"] = (finishedAt - innerStartAt).TotalMilliseconds.ToString(CultureInfo.InvariantCulture); + } + + [Fact] + public void BuildTelemetryHandleNullsInRecordedTimes() + { + BuildTelemetry buildTelemetry = new BuildTelemetry(); + + buildTelemetry.StartAt = DateTime.MinValue; + buildTelemetry.FinishedAt = null; + buildTelemetry.UpdateEventProperties(); + buildTelemetry.Properties.ShouldBeEmpty(); + + buildTelemetry.StartAt = null; + buildTelemetry.FinishedAt = DateTime.MaxValue; + buildTelemetry.UpdateEventProperties(); + buildTelemetry.Properties.ShouldBeEmpty(); + + buildTelemetry.InnerStartAt = DateTime.MinValue; + buildTelemetry.FinishedAt = null; + buildTelemetry.UpdateEventProperties(); + buildTelemetry.Properties.ShouldBeEmpty(); + + buildTelemetry.InnerStartAt = null; + buildTelemetry.FinishedAt = DateTime.MaxValue; + buildTelemetry.UpdateEventProperties(); + buildTelemetry.Properties.ShouldBeEmpty(); + } +} diff --git a/src/Framework/Telemetry/BuildTelemetry.cs b/src/Framework/Telemetry/BuildTelemetry.cs index ae45670e6ea..45e7537ff7c 100644 --- a/src/Framework/Telemetry/BuildTelemetry.cs +++ b/src/Framework/Telemetry/BuildTelemetry.cs @@ -11,7 +11,7 @@ namespace Microsoft.Build.Framework.Telemetry /// internal class BuildTelemetry : TelemetryBase { - public override string EventName => "msbuild/build"; + public override string EventName => "build"; /// /// Time at which build have started. @@ -86,49 +86,59 @@ internal class BuildTelemetry : TelemetryBase public override void UpdateEventProperties() { + if (DisplayVersion != null) + { + Properties["BuildEngineDisplayVersion"] = DisplayVersion; + } + if (StartAt.HasValue && FinishedAt.HasValue) { Properties["BuildDurationInMilliseconds"] = (FinishedAt.Value - StartAt.Value).TotalMilliseconds.ToString(CultureInfo.InvariantCulture); } + if (InnerStartAt.HasValue && FinishedAt.HasValue) { Properties["InnerBuildDurationInMilliseconds"] = (FinishedAt.Value - InnerStartAt.Value).TotalMilliseconds.ToString(CultureInfo.InvariantCulture); } - if (Success.HasValue) - { - Properties["BuildSuccess"] = Success.HasValue.ToString(CultureInfo.InvariantCulture); - } - if (Target != null) - { - Properties["BuildTarget"] = Target; - } - if (ServerFallbackReason != null) + + if (FrameworkName != null) { - Properties["ServerFallbackReason"] = ServerFallbackReason; + Properties["BuildEngineFrameworkName"] = FrameworkName; } - if (Version != null) + + if (Host != null) { - Properties["BuildEngineVersion"] = Version.ToString(); + Properties["BuildEngineHost"] = Host; } - if (DisplayVersion != null) + + if (InitialServerState != null) { - Properties["BuildEngineDisplayVersion"] = DisplayVersion; + Properties["InitialMSBuildServerState"] = InitialServerState; } + if (Project != null) { Properties["ProjectPath"] = Project; } - if (Host != null) + + if (ServerFallbackReason != null) { - Properties["BuildEngineHost"] = Host; + Properties["ServerFallbackReason"] = ServerFallbackReason; } - if (InitialServerState != null) + + if (Success.HasValue) { - Properties["InitialMSBuildServerState"] = InitialServerState; + Properties["BuildSuccess"] = Success.HasValue.ToString(CultureInfo.InvariantCulture); } - if (FrameworkName != null) + + if (Target != null) { - Properties["BuildEngineFrameworkName"] = FrameworkName; + Properties["BuildTarget"] = Target; + } + + if (Version != null) + { + Properties["BuildEngineVersion"] = Version.ToString(); } } } From af99810dbda852dec2fe599b013c832c7bf556d2 Mon Sep 17 00:00:00 2001 From: Roman Konecny Date: Mon, 4 Jul 2022 17:51:16 +0200 Subject: [PATCH 6/7] Fix unit tests --- src/Build/BackEnd/BuildManager/BuildManager.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/Build/BackEnd/BuildManager/BuildManager.cs b/src/Build/BackEnd/BuildManager/BuildManager.cs index 76a05de32d6..8a97c6ea687 100644 --- a/src/Build/BackEnd/BuildManager/BuildManager.cs +++ b/src/Build/BackEnd/BuildManager/BuildManager.cs @@ -836,7 +836,7 @@ public GraphBuildSubmission PendBuildRequest(GraphBuildRequestData requestData) if (KnownTelemetry.BuildTelemetry != null) { - KnownTelemetry.BuildTelemetry.Project ??= requestData.ProjectGraphEntryPoints.FirstOrDefault().ProjectFile; + KnownTelemetry.BuildTelemetry.Project ??= requestData.ProjectGraphEntryPoints?.FirstOrDefault().ProjectFile; KnownTelemetry.BuildTelemetry.Target ??= string.Join(",", requestData.TargetNames); } From b96e4e3553121722590fc2b5b7e6c1cde3792bd6 Mon Sep 17 00:00:00 2001 From: Roman Konecny Date: Tue, 12 Jul 2022 18:44:00 +0200 Subject: [PATCH 7/7] Clean forgotten line. --- src/Build/BackEnd/BuildManager/BuildManager.cs | 1 - 1 file changed, 1 deletion(-) diff --git a/src/Build/BackEnd/BuildManager/BuildManager.cs b/src/Build/BackEnd/BuildManager/BuildManager.cs index 8a97c6ea687..d6eaa69285d 100644 --- a/src/Build/BackEnd/BuildManager/BuildManager.cs +++ b/src/Build/BackEnd/BuildManager/BuildManager.cs @@ -996,7 +996,6 @@ public void EndBuild() KnownTelemetry.BuildTelemetry.Version = ProjectCollection.Version; KnownTelemetry.BuildTelemetry.DisplayVersion = ProjectCollection.DisplayVersion; KnownTelemetry.BuildTelemetry.FrameworkName = NativeMethodsShared.FrameworkName; - NativeMethodsShared.GetOSNameForExtensionsPath(); string host = null; if (BuildEnvironmentState.s_runningInVisualStudio)