Add more SdkResolverService events and allow SdkResolvers to log events

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:
 

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<SdkResult> resultLazy = cached.GetOrAdd(
                     sdk.Name,
-                    key => new Lazy<SdkResult>(() => base.ResolveSdk(submissionId, sdk, loggingContext, sdkReferenceLocation, solutionPath, projectPath, interactive, isRunningInVisualStudio)));
+                    key => new Lazy<SdkResult>(() =>
+                    {
+                        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;
         }

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
         /// <summary>
         /// The cache of responses which is cleared between builds.
         /// </summary>
-        private readonly ConcurrentDictionary<string, SdkResult> _responseCache = new ConcurrentDictionary<string, SdkResult>(MSBuildNameIgnoreCaseComparer.Default);
+        private readonly ConcurrentDictionary<string, Lazy<SdkResult>> _responseCache = new ConcurrentDictionary<string, Lazy<SdkResult>>(MSBuildNameIgnoreCaseComparer.Default);
 
         /// <summary>
         /// An event to signal when a response has been received.
@@ -63,21 +64,30 @@ public override void PacketReceived(int node, INodePacket packet)
         /// <inheritdoc cref="ISdkResolverService.ResolveSdk"/>
         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<SdkResult> sdkResultLazy = _responseCache.GetOrAdd(
                 sdk.Name,
-                key =>
+                key => new Lazy<SdkResult>(() =>
                 {
-                    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))
             {
                 // MSB4240: Multiple versions of the same SDK "{0}" cannot be specified. The SDK version "{1}" already specified by "{2}" will be used and the version "{3}" will be ignored.
                 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;
         }
 

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);
         }
 
         /// <remarks>
@@ -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
     }
 }

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

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

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
 {
     /// <summary>
@@ -15,5 +17,32 @@ public abstract class SdkLogger
         /// <param name="message">Message string.</param>
         /// <param name="messageImportance">Optional message importances. Default to low.</param>
         public abstract void LogMessage(string message, MessageImportance messageImportance = MessageImportance.Low);
+
+        /// <summary>
+        /// Logs that an event.
+        /// </summary>
+        /// <param name="args">An array of arguments to log with the event.</param>
+        public virtual void LogEvent(params object[] args)
+        {
+            MSBuildEventSource.Log.SdkResolverEvent(args);
+        }
+
+        /// <summary>
+        /// Logs that an event when an operation has started.
+        /// </summary>
+        /// <param name="args">An array of arguments to log with the event.</param>
+        public virtual void LogEventStart(params object[] args)
+        {
+            MSBuildEventSource.Log.SdkResolverEventStart(args);
+        }
+
+        /// <summary>
+        /// Logs that an event when an operation has completed.
+        /// </summary>
+        /// <param name="args">An array of arguments to log with the event.</param>
+        public virtual void LogEventStop(params object[] args)
+        {
+            MSBuildEventSource.Log.SdkResolverEventStop(args);
+        }
     }
 }