Add more SdkResolverService events and allow SdkResolvers to log events

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

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.
@@ -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<SdkResult> sdkResultLazy = _responseCache.GetOrAdd(
                 sdk.Name,
-                key =>
-                {
-                    var result = RequestSdkPathFromMainNode(submissionId, sdk, loggingContext, sdkReferenceLocation, solutionPath, projectPath, interactive, isRunningInVisualStudio);
-                    return result;
-                });
+                key => new Lazy<SdkResult>(() => 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;
         }

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);

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
     }
 }

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

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

src/Framework/Sdk/SdkLogger.cs

@@ -15,5 +15,23 @@ 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 abstract void LogEvent(params object[] 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 abstract void LogEventStart(params object[] 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 abstract void LogEventStop(params object[] args);
     }
 }