From c1949e67a91db80f6367e6653b95e5fbf0403a6e Mon Sep 17 00:00:00 2001 From: Rainer Sigwald Date: Mon, 9 Aug 2021 17:05:22 -0500 Subject: [PATCH] Add ETW events for SDK resolution SDK resolution can be a nontrivial part of evaluation time, so add events to quantify the different phases: 1. `CachedSdkResolverServiceResolveSdk` for each time the evaluator sees an SDK. 2. `SdkResolverResolveSdk` for each time an actual resolver is called to do resolution (a subset of 1 because most results are cached). 3. `SdkResolverServiceInitialize` around the loading of the resolvers. --- .../CachingSdkResolverService.cs | 5 +++ .../SdkResolution/SdkResolverService.cs | 6 +++ src/Framework/MSBuildEventSource.cs | 38 ++++++++++++++++++- 3 files changed, 48 insertions(+), 1 deletion(-) diff --git a/src/Build/BackEnd/Components/SdkResolution/CachingSdkResolverService.cs b/src/Build/BackEnd/Components/SdkResolution/CachingSdkResolverService.cs index 3f541b05568..e5c4095acb9 100644 --- a/src/Build/BackEnd/Components/SdkResolution/CachingSdkResolverService.cs +++ b/src/Build/BackEnd/Components/SdkResolution/CachingSdkResolverService.cs @@ -6,6 +6,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 Microsoft.Build.Utilities; @@ -35,6 +36,8 @@ 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) @@ -66,6 +69,8 @@ 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/SdkResolverService.cs b/src/Build/BackEnd/Components/SdkResolution/SdkResolverService.cs index 6f90dacaeb4..fba2c4925b1 100644 --- a/src/Build/BackEnd/Components/SdkResolution/SdkResolverService.cs +++ b/src/Build/BackEnd/Components/SdkResolution/SdkResolverService.cs @@ -11,6 +11,7 @@ using System.Collections.Concurrent; using System.Collections.Generic; using System.Reflection; +using Microsoft.Build.Eventing; namespace Microsoft.Build.BackEnd.SdkResolution { @@ -115,7 +116,9 @@ public virtual SdkResult ResolveSdk(int submissionId, SdkReference sdk, LoggingC try { + MSBuildEventSource.Log.SdkResolverResolveSdkStart(); result = (SdkResult)sdkResolver.Resolve(sdk, context, resultFactory); + MSBuildEventSource.Log.SdkResolverResolveSdkStop(sdkResolver.Name, sdk.Name, solutionPath, projectPath, result?.Path, result?.Success ?? false); } catch (Exception e) when ((e is FileNotFoundException || e is FileLoadException) && sdkResolver.GetType().GetTypeInfo().Name.Equals("NuGetSdkResolver", StringComparison.Ordinal)) { @@ -232,8 +235,11 @@ private void Initialize(LoggingContext loggingContext, ElementLocation location) return; } + MSBuildEventSource.Log.SdkResolverServiceInitializeStart(); _resolvers = _sdkResolverLoader.LoadResolvers(loggingContext, location); + MSBuildEventSource.Log.SdkResolverServiceInitializeStop(_resolvers.Count); } + } private void SetResolverState(int submissionId, SdkResolver resolver, object state) diff --git a/src/Framework/MSBuildEventSource.cs b/src/Framework/MSBuildEventSource.cs index 3581225789d..e32cb633fbc 100644 --- a/src/Framework/MSBuildEventSource.cs +++ b/src/Framework/MSBuildEventSource.cs @@ -429,7 +429,7 @@ public void TargetUpToDateStop(int result) { WriteEvent(57, result); } - + [Event(58, Keywords = Keywords.All)] public void CopyUpToDateStart(string path) { @@ -454,6 +454,42 @@ public void WriteLinesToFileUpToDateStop(string fileItemSpec, bool wasUpToDate) WriteEvent(61, fileItemSpec, wasUpToDate); } + [Event(62, Keywords = Keywords.All)] + public void SdkResolverServiceInitializeStart() + { + WriteEvent(62); + } + + [Event(63, Keywords = Keywords.All)] + public void SdkResolverServiceInitializeStop(int resolverCount) + { + WriteEvent(63, resolverCount); + } + + [Event(64, Keywords = Keywords.All)] + public void SdkResolverResolveSdkStart() + { + WriteEvent(64); + } + + [Event(65, Keywords = Keywords.All)] + public void SdkResolverResolveSdkStop(string resolverName, string sdkName, string solutionPath, string projectPath, string sdkPath, bool success) + { + WriteEvent(65, resolverName, sdkName, solutionPath, projectPath, sdkPath, success); + } + + [Event(66, Keywords = Keywords.All)] + public void CachedSdkResolverServiceResolveSdkStart(string sdkName, string solutionPath, string projectPath) + { + WriteEvent(66, sdkName, solutionPath, projectPath); + } + + [Event(67, Keywords = Keywords.All)] + public void CachedSdkResolverServiceResolveSdkStop(string sdkName, string solutionPath, string projectPath, bool success) + { + WriteEvent(67, sdkName, solutionPath, projectPath, success); + } + #endregion } }