From 7c0ec511457b47e60451abeb5592650e66a95b60 Mon Sep 17 00:00:00 2001 From: Jeff Kluge Date: Thu, 9 Dec 2021 09:29:39 -0800 Subject: [PATCH 1/4] Add more SdkResolverService events and allow SdkResolvers to log events --- .../CachingSdkResolverService.cs | 20 +++++++-- .../OutOfProcNodeSdkResolverService.cs | 22 +++++++--- .../Components/SdkResolution/SdkLogger.cs | 16 +++++++ src/Framework/MSBuildEventSource.cs | 44 ++++++++++++++++++- .../PublicAPI/net/PublicAPI.Unshipped.txt | 3 ++ .../netstandard/PublicAPI.Unshipped.txt | 3 ++ src/Framework/Sdk/SdkLogger.cs | 18 ++++++++ 7 files changed, 114 insertions(+), 12 deletions(-) diff --git a/src/Build/BackEnd/Components/SdkResolution/CachingSdkResolverService.cs b/src/Build/BackEnd/Components/SdkResolution/CachingSdkResolverService.cs index 23c505ff896..ddaaf313d27 100644 --- a/src/Build/BackEnd/Components/SdkResolution/CachingSdkResolverService.cs +++ b/src/Build/BackEnd/Components/SdkResolution/CachingSdkResolverService.cs @@ -36,8 +36,6 @@ 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; if (Traits.Instance.EscapeHatches.DisableSdkResolutionCache) @@ -57,7 +55,21 @@ 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(() => + { + MSBuildEventSource.Log.CachedSdkResolverServiceResolveSdkStart(sdk.Name, solutionPath, projectPath); + + SdkResult result = base.ResolveSdk(submissionId, sdk, loggingContext, sdkReferenceLocation, solutionPath, projectPath, interactive, isRunningInVisualStudio); + + MSBuildEventSource.Log.CachedSdkResolverServiceResolveSdkStop(sdk.Name, solutionPath, projectPath, result.Success); + + return result; + })); + + if (resultLazy.IsValueCreated) + { + MSBuildEventSource.Log.CachedSdkResolverServiceResolveSdkFromCache(sdk.Name, solutionPath, projectPath, resultLazy.Value.Success); + } // 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 +83,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); + return result; } diff --git a/src/Build/BackEnd/Components/SdkResolution/OutOfProcNodeSdkResolverService.cs b/src/Build/BackEnd/Components/SdkResolution/OutOfProcNodeSdkResolverService.cs index 6ae4a89268e..c190a6d22a5 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. @@ -64,13 +65,16 @@ 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) { // Get a cached response if possible, otherwise send the request - var sdkResult = _responseCache.GetOrAdd( + Lazy sdkResultLazy = _responseCache.GetOrAdd( sdk.Name, - key => - { - var result = RequestSdkPathFromMainNode(submissionId, sdk, loggingContext, sdkReferenceLocation, solutionPath, projectPath, interactive, isRunningInVisualStudio); - return result; - }); + key => new Lazy(() => RequestSdkPathFromMainNode(submissionId, sdk, loggingContext, sdkReferenceLocation, solutionPath, projectPath, interactive, isRunningInVisualStudio))); + + if (sdkResultLazy.IsValueCreated) + { + MSBuildEventSource.Log.OutOfProcSdkResolverServiceResolveSdkFromCache(submissionId, sdk.Name, solutionPath, projectPath, sdkResultLazy.Value.Success); + } + + SdkResult sdkResult = sdkResultLazy.Value; if (sdkResult.Version != null && !SdkResolverService.IsReferenceSameVersion(sdk, sdkResult.Version)) { @@ -105,6 +109,8 @@ private void HandleResponse(SdkResult response) private SdkResult RequestSdkPathFromMainNode(int submissionId, SdkReference sdk, LoggingContext loggingContext, ElementLocation sdkReferenceLocation, string solutionPath, string projectPath, bool interactive, bool isRunningInVisualStudio) { + MSBuildEventSource.Log.OutOfProcSdkResolverServiceRequestSdkPathFromMainNodeStart(submissionId, sdk.Name, solutionPath, projectPath); + // Clear out the last response for good measure _lastResponse = null; @@ -119,6 +125,8 @@ private SdkResult RequestSdkPathFromMainNode(int submissionId, SdkReference sdk, // Keep track of the element location of the reference _lastResponse.ElementLocation = sdkReferenceLocation; + MSBuildEventSource.Log.OutOfProcSdkResolverServiceRequestSdkPathFromMainNodeStop(submissionId, sdk.Name, solutionPath, projectPath, _lastResponse.Success); + // Return the response which was set by another thread. In the case of shutdown, it should be null. return _lastResponse; } diff --git a/src/Build/BackEnd/Components/SdkResolution/SdkLogger.cs b/src/Build/BackEnd/Components/SdkResolution/SdkLogger.cs index 182cda8da52..71ec3070e80 100644 --- a/src/Build/BackEnd/Components/SdkResolution/SdkLogger.cs +++ b/src/Build/BackEnd/Components/SdkResolution/SdkLogger.cs @@ -2,6 +2,7 @@ // Licensed under the MIT license. See LICENSE file in the project root for full license information. using Microsoft.Build.BackEnd.Logging; +using Microsoft.Build.Eventing; using Microsoft.Build.Framework; using SdkLoggerBase = Microsoft.Build.Framework.SdkLogger; @@ -20,6 +21,21 @@ public SdkLogger(LoggingContext loggingContext) _loggingContext = loggingContext; } + public override void LogEvent(params object[] args) + { + MSBuildEventSource.Log.SdkResolverEvent(args); + } + + public override void LogEventStart(params object[] args) + { + MSBuildEventSource.Log.SdkResolverEventStart(args); + } + + public override void LogEventStop(params object[] args) + { + MSBuildEventSource.Log.SdkResolverEventStop(args); + } + public override void LogMessage(string message, MessageImportance messageImportance = MessageImportance.Low) { _loggingContext.LogCommentFromText(messageImportance, message); diff --git a/src/Framework/MSBuildEventSource.cs b/src/Framework/MSBuildEventSource.cs index f8587c129c4..ec26ea48436 100644 --- a/src/Framework/MSBuildEventSource.cs +++ b/src/Framework/MSBuildEventSource.cs @@ -519,6 +519,48 @@ 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 CachedSdkResolverServiceResolveSdkFromCache(string sdkName, string solutionPath, string projectPath, bool success) + { + WriteEvent(74, sdkName, solutionPath, projectPath, success); + } + + [Event(75, Keywords = Keywords.All)] + public void OutOfProcSdkResolverServiceRequestSdkPathFromMainNodeStart(int submissionId, string sdkName, string solutionPath, string projectPath) + { + WriteEvent(75, submissionId, sdkName, solutionPath, projectPath); + } + + [Event(76, Keywords = Keywords.All)] + public void OutOfProcSdkResolverServiceRequestSdkPathFromMainNodeStop(int submissionId, string sdkName, string solutionPath, string projectPath, bool success) + { + WriteEvent(76, submissionId, sdkName, solutionPath, projectPath, success); + } + + [Event(77, Keywords = Keywords.All)] + public void OutOfProcSdkResolverServiceResolveSdkFromCache(int submissionId, string sdkName, string solutionPath, string projectPath, bool success) + { + WriteEvent(77, submissionId, sdkName, solutionPath, projectPath, success); + } + + #endregion } } diff --git a/src/Framework/PublicAPI/net/PublicAPI.Unshipped.txt b/src/Framework/PublicAPI/net/PublicAPI.Unshipped.txt index e69de29bb2d..1ba0281ecff 100644 --- a/src/Framework/PublicAPI/net/PublicAPI.Unshipped.txt +++ b/src/Framework/PublicAPI/net/PublicAPI.Unshipped.txt @@ -0,0 +1,3 @@ +abstract Microsoft.Build.Framework.SdkLogger.LogEvent(params object[] args) -> void +abstract Microsoft.Build.Framework.SdkLogger.LogEventStart(params object[] args) -> void +abstract 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..1ba0281ecff 100644 --- a/src/Framework/PublicAPI/netstandard/PublicAPI.Unshipped.txt +++ b/src/Framework/PublicAPI/netstandard/PublicAPI.Unshipped.txt @@ -0,0 +1,3 @@ +abstract Microsoft.Build.Framework.SdkLogger.LogEvent(params object[] args) -> void +abstract Microsoft.Build.Framework.SdkLogger.LogEventStart(params object[] args) -> void +abstract 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..dd8d6a2c667 100644 --- a/src/Framework/Sdk/SdkLogger.cs +++ b/src/Framework/Sdk/SdkLogger.cs @@ -15,5 +15,23 @@ 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 abstract void LogEvent(params object[] args); + + /// + /// Logs that an event when an operation has started. + /// + /// An array of arguments to log with the event. + public abstract void LogEventStart(params object[] args); + + /// + /// Logs that an event when an operation has completed. + /// + /// An array of arguments to log with the event. + public abstract void LogEventStop(params object[] args); } } From 18e92d1e16251d3b520ccd879ea3add63d2e7b53 Mon Sep 17 00:00:00 2001 From: Jeff Kluge Date: Mon, 13 Dec 2021 09:14:03 -0800 Subject: [PATCH 2/4] Address comments --- .../CachingSdkResolverService.cs | 22 ++++++----------- .../OutOfProcNodeSdkResolverService.cs | 15 ++++++------ .../Components/SdkResolution/SdkLogger.cs | 16 ------------- src/Framework/MSBuildEventSource.cs | 24 +++++-------------- .../PublicAPI/net/PublicAPI.Unshipped.txt | 6 ++--- .../netstandard/PublicAPI.Unshipped.txt | 6 ++--- src/Framework/Sdk/SdkLogger.cs | 17 ++++++++++--- 7 files changed, 40 insertions(+), 66 deletions(-) diff --git a/src/Build/BackEnd/Components/SdkResolution/CachingSdkResolverService.cs b/src/Build/BackEnd/Components/SdkResolution/CachingSdkResolverService.cs index ddaaf313d27..2e891f1efaa 100644 --- a/src/Build/BackEnd/Components/SdkResolution/CachingSdkResolverService.cs +++ b/src/Build/BackEnd/Components/SdkResolution/CachingSdkResolverService.cs @@ -38,6 +38,10 @@ public override SdkResult ResolveSdk(int submissionId, SdkReference sdk, Logging { SdkResult result; + bool wasResultCached = false; + + MSBuildEventSource.Log.CachedSdkResolverServiceResolveSdkStart(sdk.Name, solutionPath, projectPath); + if (Traits.Instance.EscapeHatches.DisableSdkResolutionCache) { result = base.ResolveSdk(submissionId, sdk, loggingContext, sdkReferenceLocation, solutionPath, projectPath, interactive, isRunningInVisualStudio); @@ -55,21 +59,9 @@ public override SdkResult ResolveSdk(int submissionId, SdkReference sdk, Logging */ Lazy resultLazy = cached.GetOrAdd( sdk.Name, - key => new Lazy(() => - { - MSBuildEventSource.Log.CachedSdkResolverServiceResolveSdkStart(sdk.Name, solutionPath, projectPath); - - SdkResult result = base.ResolveSdk(submissionId, sdk, loggingContext, sdkReferenceLocation, solutionPath, projectPath, interactive, isRunningInVisualStudio); - - MSBuildEventSource.Log.CachedSdkResolverServiceResolveSdkStop(sdk.Name, solutionPath, projectPath, result.Success); - - return result; - })); + key => new Lazy(() => base.ResolveSdk(submissionId, sdk, loggingContext, sdkReferenceLocation, solutionPath, projectPath, interactive, isRunningInVisualStudio))); - if (resultLazy.IsValueCreated) - { - MSBuildEventSource.Log.CachedSdkResolverServiceResolveSdkFromCache(sdk.Name, solutionPath, projectPath, resultLazy.Value.Success); - } + wasResultCached = resultLazy.IsValueCreated; // 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; @@ -83,7 +75,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, wasResultCached); return result; } diff --git a/src/Build/BackEnd/Components/SdkResolution/OutOfProcNodeSdkResolverService.cs b/src/Build/BackEnd/Components/SdkResolution/OutOfProcNodeSdkResolverService.cs index c190a6d22a5..1c58f662274 100644 --- a/src/Build/BackEnd/Components/SdkResolution/OutOfProcNodeSdkResolverService.cs +++ b/src/Build/BackEnd/Components/SdkResolution/OutOfProcNodeSdkResolverService.cs @@ -64,15 +64,16 @@ 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 = false; + + MSBuildEventSource.Log.OutOfProcSdkResolverServiceRequestSdkPathFromMainNodeStart(submissionId, sdk.Name, solutionPath, projectPath); + // Get a cached response if possible, otherwise send the request Lazy sdkResultLazy = _responseCache.GetOrAdd( sdk.Name, key => new Lazy(() => RequestSdkPathFromMainNode(submissionId, sdk, loggingContext, sdkReferenceLocation, solutionPath, projectPath, interactive, isRunningInVisualStudio))); - if (sdkResultLazy.IsValueCreated) - { - MSBuildEventSource.Log.OutOfProcSdkResolverServiceResolveSdkFromCache(submissionId, sdk.Name, solutionPath, projectPath, sdkResultLazy.Value.Success); - } + wasResultCached = sdkResultLazy.IsValueCreated; SdkResult sdkResult = sdkResultLazy.Value; @@ -82,6 +83,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; } @@ -109,8 +112,6 @@ private void HandleResponse(SdkResult response) private SdkResult RequestSdkPathFromMainNode(int submissionId, SdkReference sdk, LoggingContext loggingContext, ElementLocation sdkReferenceLocation, string solutionPath, string projectPath, bool interactive, bool isRunningInVisualStudio) { - MSBuildEventSource.Log.OutOfProcSdkResolverServiceRequestSdkPathFromMainNodeStart(submissionId, sdk.Name, solutionPath, projectPath); - // Clear out the last response for good measure _lastResponse = null; @@ -125,8 +126,6 @@ private SdkResult RequestSdkPathFromMainNode(int submissionId, SdkReference sdk, // Keep track of the element location of the reference _lastResponse.ElementLocation = sdkReferenceLocation; - MSBuildEventSource.Log.OutOfProcSdkResolverServiceRequestSdkPathFromMainNodeStop(submissionId, sdk.Name, solutionPath, projectPath, _lastResponse.Success); - // Return the response which was set by another thread. In the case of shutdown, it should be null. return _lastResponse; } diff --git a/src/Build/BackEnd/Components/SdkResolution/SdkLogger.cs b/src/Build/BackEnd/Components/SdkResolution/SdkLogger.cs index 71ec3070e80..182cda8da52 100644 --- a/src/Build/BackEnd/Components/SdkResolution/SdkLogger.cs +++ b/src/Build/BackEnd/Components/SdkResolution/SdkLogger.cs @@ -2,7 +2,6 @@ // Licensed under the MIT license. See LICENSE file in the project root for full license information. using Microsoft.Build.BackEnd.Logging; -using Microsoft.Build.Eventing; using Microsoft.Build.Framework; using SdkLoggerBase = Microsoft.Build.Framework.SdkLogger; @@ -21,21 +20,6 @@ public SdkLogger(LoggingContext loggingContext) _loggingContext = loggingContext; } - public override void LogEvent(params object[] args) - { - MSBuildEventSource.Log.SdkResolverEvent(args); - } - - public override void LogEventStart(params object[] args) - { - MSBuildEventSource.Log.SdkResolverEventStart(args); - } - - public override void LogEventStop(params object[] args) - { - MSBuildEventSource.Log.SdkResolverEventStop(args); - } - public override void LogMessage(string message, MessageImportance messageImportance = MessageImportance.Low) { _loggingContext.LogCommentFromText(messageImportance, message); diff --git a/src/Framework/MSBuildEventSource.cs b/src/Framework/MSBuildEventSource.cs index ec26ea48436..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); } /// @@ -538,27 +538,15 @@ public void SdkResolverEventStop(params object[] args) } [Event(74, Keywords = Keywords.All)] - public void CachedSdkResolverServiceResolveSdkFromCache(string sdkName, string solutionPath, string projectPath, bool success) - { - WriteEvent(74, sdkName, solutionPath, projectPath, success); - } - - [Event(75, Keywords = Keywords.All)] public void OutOfProcSdkResolverServiceRequestSdkPathFromMainNodeStart(int submissionId, string sdkName, string solutionPath, string projectPath) { - WriteEvent(75, submissionId, sdkName, solutionPath, projectPath); + WriteEvent(74, submissionId, sdkName, solutionPath, projectPath); } - [Event(76, Keywords = Keywords.All)] - public void OutOfProcSdkResolverServiceRequestSdkPathFromMainNodeStop(int submissionId, string sdkName, string solutionPath, string projectPath, bool success) - { - WriteEvent(76, submissionId, sdkName, solutionPath, projectPath, success); - } - - [Event(77, Keywords = Keywords.All)] - public void OutOfProcSdkResolverServiceResolveSdkFromCache(int submissionId, string sdkName, string solutionPath, string projectPath, bool success) + [Event(75, Keywords = Keywords.All)] + public void OutOfProcSdkResolverServiceRequestSdkPathFromMainNodeStop(int submissionId, string sdkName, string solutionPath, string projectPath, bool success, bool wasResultCached) { - WriteEvent(77, submissionId, sdkName, solutionPath, projectPath, success); + 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 1ba0281ecff..ad0d0a96b42 100644 --- a/src/Framework/PublicAPI/net/PublicAPI.Unshipped.txt +++ b/src/Framework/PublicAPI/net/PublicAPI.Unshipped.txt @@ -1,3 +1,3 @@ -abstract Microsoft.Build.Framework.SdkLogger.LogEvent(params object[] args) -> void -abstract Microsoft.Build.Framework.SdkLogger.LogEventStart(params object[] args) -> void -abstract Microsoft.Build.Framework.SdkLogger.LogEventStop(params object[] args) -> void \ No newline at end of file +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 1ba0281ecff..ad0d0a96b42 100644 --- a/src/Framework/PublicAPI/netstandard/PublicAPI.Unshipped.txt +++ b/src/Framework/PublicAPI/netstandard/PublicAPI.Unshipped.txt @@ -1,3 +1,3 @@ -abstract Microsoft.Build.Framework.SdkLogger.LogEvent(params object[] args) -> void -abstract Microsoft.Build.Framework.SdkLogger.LogEventStart(params object[] args) -> void -abstract Microsoft.Build.Framework.SdkLogger.LogEventStop(params object[] args) -> void \ No newline at end of file +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 dd8d6a2c667..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 { /// @@ -20,18 +22,27 @@ public abstract class SdkLogger /// Logs that an event. /// /// An array of arguments to log with the event. - public abstract void LogEvent(params object[] args); + 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 abstract void LogEventStart(params object[] args); + 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 abstract void LogEventStop(params object[] args); + public virtual void LogEventStop(params object[] args) + { + MSBuildEventSource.Log.SdkResolverEventStop(args); + } } } From 4b8e91b6da540f7083317890f92e6455ef63dca9 Mon Sep 17 00:00:00 2001 From: Jeff Kluge Date: Tue, 14 Dec 2021 08:57:20 -0800 Subject: [PATCH 3/4] Address comments --- .../SdkResolution/CachingSdkResolverService.cs | 9 ++++++--- .../SdkResolution/OutOfProcNodeSdkResolverService.cs | 9 ++++++--- 2 files changed, 12 insertions(+), 6 deletions(-) diff --git a/src/Build/BackEnd/Components/SdkResolution/CachingSdkResolverService.cs b/src/Build/BackEnd/Components/SdkResolution/CachingSdkResolverService.cs index 2e891f1efaa..e1743c63b08 100644 --- a/src/Build/BackEnd/Components/SdkResolution/CachingSdkResolverService.cs +++ b/src/Build/BackEnd/Components/SdkResolution/CachingSdkResolverService.cs @@ -38,7 +38,7 @@ public override SdkResult ResolveSdk(int submissionId, SdkReference sdk, Logging { SdkResult result; - bool wasResultCached = false; + bool wasResultCached = true; MSBuildEventSource.Log.CachedSdkResolverServiceResolveSdkStart(sdk.Name, solutionPath, projectPath); @@ -59,9 +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; - wasResultCached = resultLazy.IsValueCreated; + 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; diff --git a/src/Build/BackEnd/Components/SdkResolution/OutOfProcNodeSdkResolverService.cs b/src/Build/BackEnd/Components/SdkResolution/OutOfProcNodeSdkResolverService.cs index 1c58f662274..026897d0b03 100644 --- a/src/Build/BackEnd/Components/SdkResolution/OutOfProcNodeSdkResolverService.cs +++ b/src/Build/BackEnd/Components/SdkResolution/OutOfProcNodeSdkResolverService.cs @@ -64,16 +64,19 @@ 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 = false; + bool wasResultCached = true; MSBuildEventSource.Log.OutOfProcSdkResolverServiceRequestSdkPathFromMainNodeStart(submissionId, sdk.Name, solutionPath, projectPath); // Get a cached response if possible, otherwise send the request Lazy sdkResultLazy = _responseCache.GetOrAdd( sdk.Name, - key => new Lazy(() => RequestSdkPathFromMainNode(submissionId, sdk, loggingContext, sdkReferenceLocation, solutionPath, projectPath, interactive, isRunningInVisualStudio))); + key => new Lazy(() => + { + wasResultCached = false; - wasResultCached = sdkResultLazy.IsValueCreated; + return RequestSdkPathFromMainNode(submissionId, sdk, loggingContext, sdkReferenceLocation, solutionPath, projectPath, interactive, isRunningInVisualStudio); + })); SdkResult sdkResult = sdkResultLazy.Value; From 02adc9067f13c76cf44bb65e24c1e0f68efe990d Mon Sep 17 00:00:00 2001 From: Jeff Kluge Date: Tue, 14 Dec 2021 09:05:28 -0800 Subject: [PATCH 4/4] Add documentation --- documentation/specs/event-source.md | 41 +++++++++++++++++------------ 1 file changed, 24 insertions(+), 17 deletions(-) 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: