Expose project evaluation metrics via System.Diagnostics.Metrics

scripts/Deploy-MSBuild.ps1

@@ -129,6 +129,7 @@ if ($runtime -eq "Desktop") {
 
         FileToCopy "$bootstrapBinDirectory\System.Buffers.dll"
         FileToCopy "$bootstrapBinDirectory\System.Collections.Immutable.dll"
+        FileToCopy "$bootstrapBinDirectory\System.Diagnostics.DiagnosticSource.dll"
         FileToCopy "$bootstrapBinDirectory\System.Memory.dll"
         FileToCopy "$bootstrapBinDirectory\System.Numerics.Vectors.dll"
         FileToCopy "$bootstrapBinDirectory\System.Reflection.MetadataLoadContext.dll"

src/Build/Evaluation/Evaluator.cs

@@ -16,7 +16,6 @@
 using Microsoft.Build.Collections;
 using Microsoft.Build.Construction;
 using Microsoft.Build.Evaluation.Context;
-using Microsoft.Build.Eventing;
 using Microsoft.Build.Execution;
 using Microsoft.Build.ProjectCache;
 using Microsoft.Build.FileSystem;
@@ -25,6 +24,7 @@
 using Microsoft.Build.Internal;
 using Microsoft.Build.Shared;
 using Microsoft.Build.Shared.FileSystem;
+using Microsoft.Build.TelemetryInfra;
 using static Microsoft.Build.Execution.ProjectPropertyInstance;
 using Constants = Microsoft.Build.Framework.Constants;
 using EngineFileUtilities = Microsoft.Build.Internal.EngineFileUtilities;
@@ -348,61 +348,72 @@ internal static void Evaluate(
             bool interactive = false,
             ProjectEvaluationStage evaluationStage = ProjectEvaluationStage.Full)
         {
-            MSBuildEventSource.Log.EvaluateStart(root.ProjectFileLocation.File);
-            var profileEvaluation = (loadSettings & ProjectLoadSettings.ProfileEvaluation) != 0 || loggingService.IncludeEvaluationProfile;
-            var evaluator = new Evaluator<P, I, M, D>(
-                data,
-                project,
-                root,
-                loadSettings,
-                maxNodeCount,
-                environmentProperties,
-                propertiesFromCommandLine,
-                itemFactory,
-                toolsetProvider,
-                directoryCacheFactory,
-                projectRootElementCache,
-                sdkResolverService,
-                submissionId,
-                evaluationContext,
-                profileEvaluation,
-                interactive,
-                loggingService,
-                buildEventContext,
-                evaluationStage);
+            using EvaluationInstrumentation.EvaluationScope evaluationInstrumentation =
+                EvaluationInstrumentation.StartEvaluation(root.ProjectFileLocation.File, evaluationStage, submissionId);
+            Evaluator<P, I, M, D> evaluator = null;
+            bool evaluationSucceeded = false;
 
             try
             {
-                evaluator.Evaluate();
-            }
-            catch (PathTooLongException ex)
-            {
-                evaluator._evaluationLoggingContext.LogErrorFromText(null, null, null, new BuildEventFileInfo(root.ProjectFileLocation.File),
-                    ex.Message);
+                var profileEvaluation = (loadSettings & ProjectLoadSettings.ProfileEvaluation) != 0 || loggingService.IncludeEvaluationProfile;
+                evaluator = new Evaluator<P, I, M, D>(
+                    data,
+                    project,
+                    root,
+                    loadSettings,
+                    maxNodeCount,
+                    environmentProperties,
+                    propertiesFromCommandLine,
+                    itemFactory,
+                    toolsetProvider,
+                    directoryCacheFactory,
+                    projectRootElementCache,
+                    sdkResolverService,
+                    submissionId,
+                    evaluationContext,
+                    profileEvaluation,
+                    interactive,
+                    loggingService,
+                    buildEventContext,
+                    evaluationStage);
+
+                try
+                {
+                    evaluator.Evaluate();
+                    evaluationSucceeded = true;
+                }
+                catch (PathTooLongException ex)
+                {
+                    evaluator._evaluationLoggingContext.LogErrorFromText(null, null, null, new BuildEventFileInfo(root.ProjectFileLocation.File),
+                        ex.Message);
+                }
             }
             finally
             {
-                IEnumerable globalProperties = null;
-                IEnumerable properties = null;
-                IEnumerable items = null;
+                evaluationInstrumentation.CompleteEvaluation(evaluationSucceeded);
 
-                if (evaluator._evaluationLoggingContext.LoggingService.IncludeEvaluationPropertiesAndItemsInEvaluationFinishedEvent)
+                if (evaluator is not null)
                 {
-                    globalProperties = evaluator._data.GlobalPropertiesDictionary;
-                    properties = Traits.LogAllEnvironmentVariables ? evaluator._data.Properties : evaluator.FilterOutEnvironmentDerivedProperties(evaluator._data.Properties);
-                    items = evaluator._data.Items;
-                }
+                    IEnumerable globalProperties = null;
+                    IEnumerable properties = null;
+                    IEnumerable items = null;
 
-                string skippedMessage = evaluator._projectRootElementCache.ParserIgnoreConfiguration?.GetSkippedSummaryMessage();
-                if (skippedMessage is not null)
-                {
-                    evaluator._evaluationLoggingContext.LogCommentFromText(MessageImportance.Low, skippedMessage);
-                }
+                    if (evaluator._evaluationLoggingContext.LoggingService.IncludeEvaluationPropertiesAndItemsInEvaluationFinishedEvent)
+                    {
+                        globalProperties = evaluator._data.GlobalPropertiesDictionary;
+                        properties = Traits.LogAllEnvironmentVariables ? evaluator._data.Properties : evaluator.FilterOutEnvironmentDerivedProperties(evaluator._data.Properties);
+                        items = evaluator._data.Items;
+                    }
 
-                evaluator._evaluationLoggingContext.LogProjectEvaluationFinished(globalProperties, properties, items, evaluator._evaluationProfiler.ProfiledResult);
-            }
+                    string skippedMessage = evaluator._projectRootElementCache.ParserIgnoreConfiguration?.GetSkippedSummaryMessage();
+                    if (skippedMessage is not null)
+                    {
+                        evaluator._evaluationLoggingContext.LogCommentFromText(MessageImportance.Low, skippedMessage);
+                    }
 
-            MSBuildEventSource.Log.EvaluateStop(root.ProjectFileLocation.File);
+                    evaluator._evaluationLoggingContext.LogProjectEvaluationFinished(globalProperties, properties, items, evaluator._evaluationProfiler.ProfiledResult);
+                }
+            }
         }
 
         /// <summary>
@@ -662,7 +673,6 @@ private static ProjectTargetInstance ReadNewTargetElement(ProjectTargetElement t
         /// </summary>
         private void Evaluate()
         {
-            string projectFile = string.IsNullOrEmpty(_projectRootElement.ProjectFileLocation.File) ? "(null)" : _projectRootElement.ProjectFileLocation.File;
             using (_evaluationProfiler.TrackPass(EvaluationPass.TotalEvaluation))
             {
                 Assumed.Equal(_data.EvaluationId, BuildEventContext.InvalidEvaluationId, "There is no prior evaluation ID. The evaluator data needs to be reset at this point");
@@ -683,11 +693,16 @@ private void Evaluate()
 
                 int globalPropertiesCount;
 
+                EvaluationInstrumentation.EvaluationPassScope passInstrumentation;
                 using (_evaluationProfiler.TrackPass(EvaluationPass.InitialProperties))
                 {
                     // Pass0: load initial properties
                     // Follow the order of precedence so that Global properties overwrite Environment properties
-                    MSBuildEventSource.Log.EvaluatePass0Start(_projectRootElement.ProjectFileLocation.File);
+                    passInstrumentation = EvaluationInstrumentation.StartPass(
+                        _projectRootElement.ProjectFileLocation.File,
+                        EvaluationPass.InitialProperties,
+                        _evaluationStage,
+                        _submissionId);
                     AddBuiltInProperties();
                     AddEnvironmentProperties();
                     AddToolsetProperties();
@@ -701,10 +716,14 @@ private void Evaluate()
 
                 Assumed.NotEqual(_data.EvaluationId, BuildEventContext.InvalidEvaluationId, "Evaluation should produce an evaluation ID");
 
-                MSBuildEventSource.Log.EvaluatePass0Stop(projectFile);
+                passInstrumentation.Complete();
 
                 // Pass1: evaluate properties, load imports, and gather everything else
-                MSBuildEventSource.Log.EvaluatePass1Start(projectFile);
+                passInstrumentation = EvaluationInstrumentation.StartPass(
+                    _projectRootElement.ProjectFileLocation.File,
+                    EvaluationPass.Properties,
+                    _evaluationStage,
+                    _submissionId);
                 using (_evaluationProfiler.TrackPass(EvaluationPass.Properties))
                 {
                     PerformDepthFirstPass(_projectRootElement);
@@ -719,7 +738,7 @@ private void Evaluate()
                 }
 
                 _data.InitialTargets = initialTargets;
-                MSBuildEventSource.Log.EvaluatePass1Stop(projectFile);
+                passInstrumentation.Complete();
 
                 if (_evaluationStage <= ProjectEvaluationStage.Properties)
                 {
@@ -729,7 +748,11 @@ private void Evaluate()
 
                 // Pass2: evaluate item definitions
                 // Don't box via IEnumerator and foreach; cache count so not to evaluate via interface each iteration
-                MSBuildEventSource.Log.EvaluatePass2Start(projectFile);
+                passInstrumentation = EvaluationInstrumentation.StartPass(
+                    _projectRootElement.ProjectFileLocation.File,
+                    EvaluationPass.ItemDefinitionGroups,
+                    _evaluationStage,
+                    _submissionId);
                 using (_evaluationProfiler.TrackPass(EvaluationPass.ItemDefinitionGroups))
                 {
                     foreach (var itemDefinitionGroupElement in _itemDefinitionGroupElements)
@@ -740,7 +763,7 @@ private void Evaluate()
                         }
                     }
                 }
-                MSBuildEventSource.Log.EvaluatePass2Stop(projectFile);
+                passInstrumentation.Complete();
 
                 if (_evaluationStage <= ProjectEvaluationStage.ItemDefinitions)
                 {
@@ -755,8 +778,11 @@ private void Evaluate()
                     lazyEvaluator = new LazyItemEvaluator<P, I, M, D>(_data, _itemFactory, _evaluationLoggingContext, _evaluationProfiler, _evaluationContext);
 
                     // Pass3: evaluate project items
-                    MSBuildEventSource.Log.EvaluatePass3Start(projectFile);
-
+                    passInstrumentation = EvaluationInstrumentation.StartPass(
+                        _projectRootElement.ProjectFileLocation.File,
+                        EvaluationPass.Items,
+                        _evaluationStage,
+                        _submissionId);
                     SynthesizeImportedProjectItems();
 
                     DetectItemGlobRequest();
@@ -796,8 +822,7 @@ private void Evaluate()
                 }
 
                 SynthesizeItemGlobItems();
-
-                MSBuildEventSource.Log.EvaluatePass3Stop(projectFile);
+                passInstrumentation.Complete();
 
                 if (_evaluationStage <= ProjectEvaluationStage.Items)
                 {
@@ -806,7 +831,11 @@ private void Evaluate()
                 }
 
                 // Pass4: evaluate using-tasks
-                MSBuildEventSource.Log.EvaluatePass4Start(projectFile);
+                passInstrumentation = EvaluationInstrumentation.StartPass(
+                    _projectRootElement.ProjectFileLocation.File,
+                    EvaluationPass.UsingTasks,
+                    _evaluationStage,
+                    _submissionId);
                 using (_evaluationProfiler.TrackPass(EvaluationPass.UsingTasks))
                 {
                     // Evaluate the usingtask and add the result into the data passed in
@@ -819,7 +848,7 @@ private void Evaluate()
                         _evaluationContext.FileSystem);
                 }
 
-                MSBuildEventSource.Log.EvaluatePass4Stop(projectFile);
+                passInstrumentation.Complete();
 
                 if (_evaluationStage <= ProjectEvaluationStage.UsingTasks)
                 {
@@ -849,7 +878,11 @@ private void Evaluate()
                 using (_evaluationProfiler.TrackPass(EvaluationPass.Targets))
                 {
                     // Pass5: read targets (but don't evaluate them: that happens during build)
-                    MSBuildEventSource.Log.EvaluatePass5Start(projectFile);
+                    passInstrumentation = EvaluationInstrumentation.StartPass(
+                        _projectRootElement.ProjectFileLocation.File,
+                        EvaluationPass.Targets,
+                        _evaluationStage,
+                        _submissionId);
                     for (var i = 0; i < targetElementsCount; i++)
                     {
                         var element = _targetElements[i];
@@ -903,7 +936,7 @@ private void Evaluate()
                     }
 
                     _data.FinishEvaluation();
-                    MSBuildEventSource.Log.EvaluatePass5Stop(projectFile);
+                    passInstrumentation.Complete();
                 }
             }
 

src/Build/Microsoft.Build.csproj

@@ -72,6 +72,7 @@
     <Reference Include="System.IO.Compression" />
     <PackageReference Include="System.Memory" />
     <PackageReference Include="System.Security.Principal.Windows" />
+    <PackageReference Include="System.Diagnostics.DiagnosticSource" />
     <PackageReference Include="System.Text.Json" />
     <PackageReference Include="System.Collections.Immutable" />
     <PackageReference Include="System.Threading.Tasks.Dataflow" />
@@ -219,6 +220,7 @@
     <Compile Include="Logging\BuildEventArgsExtensions.cs" />
     <Compile Include="Logging\TerminalLogger\**\*.cs" />
     <Compile Include="Logging\ReusableLogger.cs" />
+    <Compile Include="TelemetryInfra\EvaluationInstrumentation.cs" />
     <Compile Include="TelemetryInfra\InternalTelemetryConsumingLogger.cs" />
     <Compile Include="TelemetryInfra\ITelemetryCollector.cs" />
     <Compile Include="TelemetryInfra\TasksDetailsTelemetry.cs" />