diff --git a/documentation/specs/event-source.md b/documentation/specs/event-source.md index 03b9e7d5087..7164804a6c1 100644 --- a/documentation/specs/event-source.md +++ b/documentation/specs/event-source.md @@ -5,23 +5,30 @@ ## EventSource in MSBuild EventSource is primarily used to profile code. For MSBuild specifically, a major goal is to reduce the time it takes to run, as measured (among other metrics) by the Regression Prevention System (RPS), i.e., running specific scenarios. To find which code segments were likely candidates for improvement, EventSources were added around a mix of code segments. Larger segments that encompass several steps within a build occur nearly every time MSBuild is run and take a long time. They generally run relatively few times. Smaller methods with well-defined purposes may occur numerous times. Profiling both types of events provides both broad strokes to identify large code segments that underperform and, more specifically, which parts of them. Profiled functions include: -* MSBuildExe: Executes MSBuild from the command line. -* Build: Sets up a BuildManager to receive build requests. -* BuildProject: Builds a project file. -* RequestThreadProc: A function to requesting a new builder thread. -* LoadDocument: Loads an XMLDocumentWithLocation from a path. -* RarRemoveReferencesMarkedForExclusion: Removes blacklisted references from the reference table, putting primary and dependency references in invalid file lists. -* RarComputeClosure: Resolves references from, for example, properties to explicit values. Used in resolving assembly references (RAR). -* EvaluateCondition: Checks whether a condition is true and removes false conditionals. -* Parse: Parses an XML document into a ProjectRootElement. -* Evaluate: Evaluates a project, running several other parts of MSBuild in the process. -* GenerateResourceOverall: Uses resource APIs to transform resource files into strongly-typed resource classes. -* ExpandGlob: Identifies a list of files that correspond to an item, potentially with a wildcard. -* ApplyLazyItemOperations: Collects a set of items, mutates them in a specified way, and saves the results in a lazy way. -* RarOverall: Initiates the process of resolving assembly references (RAR). -* Save: Saves a project to the file system if dirty, creating directories as necessary. -* Target: Executes a target. -* RarLogResults: Logs the results from having resolved assembly references (RAR). +| Event | Description | +| ------| ------------| +| MSBuildExe | Executes MSBuild from the command line. | +| Build | Sets up a BuildManager to receive build requests. | +| BuildProject | Builds a project file. | +| RequestThreadProc | A function to requesting a new builder thread. | +| LoadDocument | Loads an XMLDocumentWithLocation from a path. +| RarRemoveReferencesMarkedForExclusion | Removes blacklisted references from the reference table, putting primary and dependency references in invalid file lists. | +| RarComputeClosure | Resolves references from, for example, properties to explicit values. Used in resolving assembly references (RAR). | +| EvaluateCondition | Checks whether a condition is true and removes false conditionals. | +| Parse | Parses an XML document into a ProjectRootElement. | +| Evaluate | Evaluates a project, running several other parts of MSBuild in the process. | +| GenerateResourceOverall | Uses resource APIs to transform resource files into strongly-typed resource classes. | +| ExpandGlob | Identifies a list of files that correspond to an item, potentially with a wildcard. | +| ApplyLazyItemOperations | Collects a set of items, mutates them in a specified way, and saves the results in a lazy way. | +| RarOverall | Initiates the process of resolving assembly references (RAR). | +| Save | Saves a project to the file system if dirty, creating directories as necessary. | +| Target | Executes a target. | +| RarLogResults | Logs the results from having resolved assembly references (RAR). | +| SdkResolverServiceInitialize | Initializes SDK resolvers. | +| SdkResolverResolveSdk | A single SDK resolver is called. | +| CachedSdkResolverServiceResolveSdk | The caching SDK resolver service is resolving an SDK. | +| SdkResolverEvent | An SDK resolver logs an event. | +| OutOfProcSdkResolverServiceRequestSdkPathFromMainNode | An out-of-proc node requests an SDK be resolved from the main node. | One can run MSBuild with eventing using the following command: diff --git a/src/Build/BackEnd/Components/SdkResolution/CachingSdkResolverService.cs b/src/Build/BackEnd/Components/SdkResolution/CachingSdkResolverService.cs index 23c505ff896..e1743c63b08 100644 --- a/src/Build/BackEnd/Components/SdkResolution/CachingSdkResolverService.cs +++ b/src/Build/BackEnd/Components/SdkResolution/CachingSdkResolverService.cs @@ -36,10 +36,12 @@ public override void ClearCaches() public override SdkResult ResolveSdk(int submissionId, SdkReference sdk, LoggingContext loggingContext, ElementLocation sdkReferenceLocation, string solutionPath, string projectPath, bool interactive, bool isRunningInVisualStudio) { - MSBuildEventSource.Log.CachedSdkResolverServiceResolveSdkStart(sdk.Name, solutionPath, projectPath); - SdkResult result; + bool wasResultCached = true; + + MSBuildEventSource.Log.CachedSdkResolverServiceResolveSdkStart(sdk.Name, solutionPath, projectPath); + if (Traits.Instance.EscapeHatches.DisableSdkResolutionCache) { result = base.ResolveSdk(submissionId, sdk, loggingContext, sdkReferenceLocation, solutionPath, projectPath, interactive, isRunningInVisualStudio); @@ -57,7 +59,12 @@ public override SdkResult ResolveSdk(int submissionId, SdkReference sdk, Logging */ Lazy resultLazy = cached.GetOrAdd( sdk.Name, - key => new Lazy(() => base.ResolveSdk(submissionId, sdk, loggingContext, sdkReferenceLocation, solutionPath, projectPath, interactive, isRunningInVisualStudio))); + key => new Lazy(() => + { + wasResultCached = false; + + return base.ResolveSdk(submissionId, sdk, loggingContext, sdkReferenceLocation, solutionPath, projectPath, interactive, isRunningInVisualStudio); + })); // Get the lazy value which will block all waiting threads until the SDK is resolved at least once while subsequent calls get cached results. result = resultLazy.Value; @@ -71,7 +78,7 @@ public override SdkResult ResolveSdk(int submissionId, SdkReference sdk, Logging loggingContext.LogWarning(null, new BuildEventFileInfo(sdkReferenceLocation), "ReferencingMultipleVersionsOfTheSameSdk", sdk.Name, result.Version, result.ElementLocation, sdk.Version); } - MSBuildEventSource.Log.CachedSdkResolverServiceResolveSdkStop(sdk.Name, solutionPath, projectPath, result.Success); + MSBuildEventSource.Log.CachedSdkResolverServiceResolveSdkStop(sdk.Name, solutionPath, projectPath, result.Success, wasResultCached); return result; } diff --git a/src/Build/BackEnd/Components/SdkResolution/OutOfProcNodeSdkResolverService.cs b/src/Build/BackEnd/Components/SdkResolution/OutOfProcNodeSdkResolverService.cs index 6ae4a89268e..026897d0b03 100644 --- a/src/Build/BackEnd/Components/SdkResolution/OutOfProcNodeSdkResolverService.cs +++ b/src/Build/BackEnd/Components/SdkResolution/OutOfProcNodeSdkResolverService.cs @@ -4,6 +4,7 @@ using Microsoft.Build.BackEnd.Logging; using Microsoft.Build.Collections; using Microsoft.Build.Construction; +using Microsoft.Build.Eventing; using Microsoft.Build.Framework; using Microsoft.Build.Shared; using System; @@ -26,7 +27,7 @@ internal sealed class OutOfProcNodeSdkResolverService : HostedSdkResolverService /// /// The cache of responses which is cleared between builds. /// - private readonly ConcurrentDictionary _responseCache = new ConcurrentDictionary(MSBuildNameIgnoreCaseComparer.Default); + private readonly ConcurrentDictionary> _responseCache = new ConcurrentDictionary>(MSBuildNameIgnoreCaseComparer.Default); /// /// An event to signal when a response has been received. @@ -63,14 +64,21 @@ public override void PacketReceived(int node, INodePacket packet) /// public override SdkResult ResolveSdk(int submissionId, SdkReference sdk, LoggingContext loggingContext, ElementLocation sdkReferenceLocation, string solutionPath, string projectPath, bool interactive, bool isRunningInVisualStudio) { + bool wasResultCached = true; + + MSBuildEventSource.Log.OutOfProcSdkResolverServiceRequestSdkPathFromMainNodeStart(submissionId, sdk.Name, solutionPath, projectPath); + // Get a cached response if possible, otherwise send the request - var sdkResult = _responseCache.GetOrAdd( + Lazy sdkResultLazy = _responseCache.GetOrAdd( sdk.Name, - key => + key => new Lazy(() => { - var result = RequestSdkPathFromMainNode(submissionId, sdk, loggingContext, sdkReferenceLocation, solutionPath, projectPath, interactive, isRunningInVisualStudio); - return result; - }); + wasResultCached = false; + + return RequestSdkPathFromMainNode(submissionId, sdk, loggingContext, sdkReferenceLocation, solutionPath, projectPath, interactive, isRunningInVisualStudio); + })); + + SdkResult sdkResult = sdkResultLazy.Value; if (sdkResult.Version != null && !SdkResolverService.IsReferenceSameVersion(sdk, sdkResult.Version)) { @@ -78,6 +86,8 @@ public override SdkResult ResolveSdk(int submissionId, SdkReference sdk, Logging loggingContext.LogWarning(null, new BuildEventFileInfo(sdkReferenceLocation), "ReferencingMultipleVersionsOfTheSameSdk", sdk.Name, sdkResult.Version, sdkResult.ElementLocation, sdk.Version); } + MSBuildEventSource.Log.OutOfProcSdkResolverServiceRequestSdkPathFromMainNodeStop(submissionId, sdk.Name, solutionPath, projectPath, _lastResponse.Success, wasResultCached); + return sdkResult; } diff --git a/src/Framework/MSBuildEventSource.cs b/src/Framework/MSBuildEventSource.cs index f8587c129c4..b1ae27b4b37 100644 --- a/src/Framework/MSBuildEventSource.cs +++ b/src/Framework/MSBuildEventSource.cs @@ -485,9 +485,9 @@ public void CachedSdkResolverServiceResolveSdkStart(string sdkName, string solut } [Event(67, Keywords = Keywords.All)] - public void CachedSdkResolverServiceResolveSdkStop(string sdkName, string solutionPath, string projectPath, bool success) + public void CachedSdkResolverServiceResolveSdkStop(string sdkName, string solutionPath, string projectPath, bool success, bool wasResultCached) { - WriteEvent(67, sdkName, solutionPath, projectPath, success); + WriteEvent(67, sdkName, solutionPath, projectPath, success, wasResultCached); } /// @@ -519,6 +519,36 @@ public void ReusableStringBuilderFactoryUnbalanced(int oldHash, int newHash) WriteEvent(70, oldHash, newHash); } -#endregion + [Event(71, Keywords = Keywords.All)] + public void SdkResolverEvent(params object[] args) + { + WriteEvent(71, args); + } + + [Event(72, Keywords = Keywords.All)] + public void SdkResolverEventStart(params object[] args) + { + WriteEvent(72, args); + } + + [Event(73, Keywords = Keywords.All)] + public void SdkResolverEventStop(params object[] args) + { + WriteEvent(73, args); + } + + [Event(74, Keywords = Keywords.All)] + public void OutOfProcSdkResolverServiceRequestSdkPathFromMainNodeStart(int submissionId, string sdkName, string solutionPath, string projectPath) + { + WriteEvent(74, submissionId, sdkName, solutionPath, projectPath); + } + + [Event(75, Keywords = Keywords.All)] + public void OutOfProcSdkResolverServiceRequestSdkPathFromMainNodeStop(int submissionId, string sdkName, string solutionPath, string projectPath, bool success, bool wasResultCached) + { + WriteEvent(75, submissionId, sdkName, solutionPath, projectPath, success, wasResultCached); + } + + #endregion } } diff --git a/src/Framework/PublicAPI/net/PublicAPI.Unshipped.txt b/src/Framework/PublicAPI/net/PublicAPI.Unshipped.txt index e69de29bb2d..ad0d0a96b42 100644 --- a/src/Framework/PublicAPI/net/PublicAPI.Unshipped.txt +++ b/src/Framework/PublicAPI/net/PublicAPI.Unshipped.txt @@ -0,0 +1,3 @@ +virtual Microsoft.Build.Framework.SdkLogger.LogEvent(params object[] args) -> void +virtual Microsoft.Build.Framework.SdkLogger.LogEventStart(params object[] args) -> void +virtual Microsoft.Build.Framework.SdkLogger.LogEventStop(params object[] args) -> void \ No newline at end of file diff --git a/src/Framework/PublicAPI/netstandard/PublicAPI.Unshipped.txt b/src/Framework/PublicAPI/netstandard/PublicAPI.Unshipped.txt index e69de29bb2d..ad0d0a96b42 100644 --- a/src/Framework/PublicAPI/netstandard/PublicAPI.Unshipped.txt +++ b/src/Framework/PublicAPI/netstandard/PublicAPI.Unshipped.txt @@ -0,0 +1,3 @@ +virtual Microsoft.Build.Framework.SdkLogger.LogEvent(params object[] args) -> void +virtual Microsoft.Build.Framework.SdkLogger.LogEventStart(params object[] args) -> void +virtual Microsoft.Build.Framework.SdkLogger.LogEventStop(params object[] args) -> void \ No newline at end of file diff --git a/src/Framework/Sdk/SdkLogger.cs b/src/Framework/Sdk/SdkLogger.cs index 883ddb109dd..92e07ca18fe 100644 --- a/src/Framework/Sdk/SdkLogger.cs +++ b/src/Framework/Sdk/SdkLogger.cs @@ -1,6 +1,8 @@ // Copyright (c) Microsoft. All rights reserved. // Licensed under the MIT license. See LICENSE file in the project root for full license information. +using Microsoft.Build.Eventing; + namespace Microsoft.Build.Framework { /// @@ -15,5 +17,32 @@ public abstract class SdkLogger /// Message string. /// Optional message importances. Default to low. public abstract void LogMessage(string message, MessageImportance messageImportance = MessageImportance.Low); + + /// + /// Logs that an event. + /// + /// An array of arguments to log with the event. + public virtual void LogEvent(params object[] args) + { + MSBuildEventSource.Log.SdkResolverEvent(args); + } + + /// + /// Logs that an event when an operation has started. + /// + /// An array of arguments to log with the event. + public virtual void LogEventStart(params object[] args) + { + MSBuildEventSource.Log.SdkResolverEventStart(args); + } + + /// + /// Logs that an event when an operation has completed. + /// + /// An array of arguments to log with the event. + public virtual void LogEventStop(params object[] args) + { + MSBuildEventSource.Log.SdkResolverEventStop(args); + } } }