Instrumentation module for BuildCheck

MSBuild.Dev.slnf

@@ -9,13 +9,13 @@
       "src\\Framework\\Microsoft.Build.Framework.csproj",
       "src\\MSBuild.UnitTests\\Microsoft.Build.CommandLine.UnitTests.csproj",
       "src\\MSBuild\\MSBuild.csproj",
+      "src\\StringTools\\StringTools.csproj",
       "src\\Tasks.UnitTests\\Microsoft.Build.Tasks.UnitTests.csproj",
       "src\\Tasks\\Microsoft.Build.Tasks.csproj",
+      "src\\UnitTests.Shared\\Microsoft.Build.UnitTests.Shared.csproj",
       "src\\Utilities.UnitTests\\Microsoft.Build.Utilities.UnitTests.csproj",
       "src\\Utilities\\Microsoft.Build.Utilities.csproj",
-      "src\\Xunit.NetCore.Extensions\\Xunit.NetCore.Extensions.csproj",
-      "src\\StringTools\\StringTools.csproj",
-      "src\\UnitTests.Shared\\Microsoft.Build.UnitTests.Shared.csproj"
+      "src\\Xunit.NetCore.Extensions\\Xunit.NetCore.Extensions.csproj"
     ]
   }
 }

src/Build/BackEnd/BuildManager/BuildManager.cs

@@ -2992,7 +2992,7 @@ private void OnProjectStarted(object sender, ProjectStartedEventArgs e)
 
                 loggers = (loggers ?? Enumerable.Empty<ILogger>()).Concat(new[]
                 {
-                    new BuildCheckConnectorLogger(new AnalyzerLoggingContextFactory(loggingService), buildCheckManagerProvider.Instance)
+                    new BuildCheckConnectorLogger(new AnalyzerLoggingContextFactory(loggingService), buildCheckManagerProvider.Instance, ((IBuildComponentHost)this).BuildParameters.AreBuildCheckStatsEnabled)
                 });
             }
 

src/Build/BackEnd/BuildManager/BuildParameters.cs

@@ -210,6 +210,7 @@ public class BuildParameters : ITranslatable
         private bool _question;
 
         private bool _isBuildCheckEnabled;
+        private bool _areBuildCheckStatsEnabled;
 
         /// <summary>
         /// The settings used to load the project under build
@@ -314,6 +315,7 @@ internal BuildParameters(BuildParameters other, bool resetEnvironment = false)
             LowPriority = other.LowPriority;
             Question = other.Question;
             IsBuildCheckEnabled = other.IsBuildCheckEnabled;
+            AreBuildCheckStatsEnabled = other.AreBuildCheckStatsEnabled;
             ProjectCacheDescriptor = other.ProjectCacheDescriptor;
         }
 
@@ -847,6 +849,15 @@ public bool IsBuildCheckEnabled
             get => _isBuildCheckEnabled;
             set => _isBuildCheckEnabled = value;
         }
+
+        /// <summary>
+        /// Gets or sets an indication of build analysis statistics enablement.
+        /// </summary>
+        public bool AreBuildCheckStatsEnabled
+        {
+            get => _areBuildCheckStatsEnabled;
+            set => _areBuildCheckStatsEnabled = value;
+        }
 
         /// <summary>
         /// Gets or sets the project cache description to use for all <see cref="BuildSubmission"/> or <see cref="GraphBuildSubmission"/>

src/Build/BackEnd/Components/RequestBuilder/RequestBuilder.cs

@@ -1102,13 +1102,13 @@ private void SetProjectCurrentDirectory()
         /// </summary>
         private async Task<BuildResult> BuildProject()
         {
-            ErrorUtilities.VerifyThrow(_targetBuilder != null, "Target builder is null");
-
             // We consider this the entrypoint for the project build for purposes of BuildCheck processing 
 
             var buildCheckManager = (_componentHost.GetComponent(BuildComponentType.BuildCheckManagerProvider) as IBuildCheckManagerProvider)!.Instance;
             buildCheckManager.SetDataSource(BuildCheckDataSource.BuildExecution);
 
+            ErrorUtilities.VerifyThrow(_targetBuilder != null, "Target builder is null");
+
             // Make sure it is null before loading the configuration into the request, because if there is a problem
             // we do not wand to have an invalid projectLoggingContext floating around. Also if this is null the error will be
             // logged with the node logging context

src/Build/BuildCheck/Infrastructure/BuildCheckConnectorLogger.cs

@@ -8,16 +8,22 @@
 using Microsoft.Build.BackEnd.Logging;
 using Microsoft.Build.BuildCheck.Acquisition;
 using Microsoft.Build.BuildCheck.Logging;
+using Microsoft.Build.BuildCheck.Utilities;
 using Microsoft.Build.Experimental.BuildCheck;
 using Microsoft.Build.Framework;
 
 namespace Microsoft.Build.BuildCheck.Infrastructure;
-internal sealed class BuildCheckConnectorLogger(IBuildAnalysisLoggingContextFactory loggingContextFactory, IBuildCheckManager buildCheckManager)
+internal sealed class BuildCheckConnectorLogger(
+    IBuildAnalysisLoggingContextFactory loggingContextFactory, 
+    IBuildCheckManager buildCheckManager,
+    bool areStatsEnabled)
     : ILogger
 {
     public LoggerVerbosity Verbosity { get; set; }
     public string? Parameters { get; set; }
 
+    private bool _areStatsEnabled = areStatsEnabled;
+
     public void Initialize(IEventSource eventSource)
     {
         eventSource.AnyEventRaised += EventSource_AnyEventRaised;
@@ -62,7 +68,10 @@ private void EventSource_AnyEventRaised(object sender, BuildEventArgs e)
         {
             if (buildCheckBuildEventArgs is BuildCheckTracingEventArgs tracingEventArgs)
             {
-                _stats.Merge(tracingEventArgs.TracingData, (span1, span2) => span1 + span2);
+                if (!tracingEventArgs.IsLogReport)
+                {
+                    _stats.Merge(tracingEventArgs.TracingData, (span1, span2) => span1 + span2);
+                }
             }
             else if (buildCheckBuildEventArgs is BuildCheckAcquisitionEventArgs acquisitionEventArgs)
             {
@@ -75,17 +84,62 @@ private void EventSource_AnyEventRaised(object sender, BuildEventArgs e)
 
     private void EventSource_BuildFinished(object sender, BuildFinishedEventArgs e)
     {
-        _stats.Merge(buildCheckManager.CreateTracingStats(), (span1, span2) => span1 + span2);
-        string msg = string.Join(Environment.NewLine, _stats.Select(a => a.Key + ": " + a.Value));
-
         BuildEventContext buildEventContext = e.BuildEventContext ?? new BuildEventContext(
             BuildEventContext.InvalidNodeId, BuildEventContext.InvalidTargetId,
             BuildEventContext.InvalidProjectContextId, BuildEventContext.InvalidTaskId);
 
         LoggingContext loggingContext = loggingContextFactory.CreateLoggingContext(buildEventContext);
 
-        // Tracing: https://github.com/dotnet/msbuild/issues/9629
-        loggingContext.LogCommentFromText(MessageImportance.High, msg);
+        _stats.Merge(buildCheckManager.CreateAnalyzerTracingStats()!, (span1, span2) => span1 + span2);
+        LogAnalyzerStats(loggingContext);
+    }
+
+    private void LogAnalyzerStats(LoggingContext loggingContext)
+    {
+        Dictionary<string, TimeSpan> infraStats = new Dictionary<string, TimeSpan>();
+        Dictionary<string, TimeSpan> analyzerStats = new Dictionary<string, TimeSpan>();
+
+        foreach (var stat in _stats)
+        {
+            if (stat.Key.StartsWith(BuildCheckConstants.infraStatPrefix))
+            {
+                string newKey = stat.Key.Replace(BuildCheckConstants.infraStatPrefix, string.Empty);
+                infraStats[newKey] = stat.Value;
+            }
+            else
+            {
+                analyzerStats[stat.Key] = stat.Value;
+            }
+        }
+
+        BuildCheckTracingEventArgs statEvent = new BuildCheckTracingEventArgs(_stats, true)
+        { BuildEventContext = loggingContext.BuildEventContext };
+
+        loggingContext.LogBuildEvent(statEvent);
+
+        if (_areStatsEnabled)
+        {
+            loggingContext.LogCommentFromText(MessageImportance.High, $"BuildCheck run times{Environment.NewLine}");
+            string infraData = BuildCsvString("Infrastructure run times", infraStats);
+            loggingContext.LogCommentFromText(MessageImportance.High, infraData);
+
+            string analyzerData = BuildCsvString("Analyzer run times", analyzerStats);
+            loggingContext.LogCommentFromText(MessageImportance.High, analyzerData);
+        }
+        else
+        {
+            loggingContext.LogCommentFromText(MessageImportance.Low, $"BuildCheck run times{Environment.NewLine}");
+            string infraData = BuildCsvString("Infrastructure run times", infraStats);
+            loggingContext.LogCommentFromText(MessageImportance.Low, infraData);
+
+            string analyzerData = BuildCsvString("Analyzer run times", analyzerStats);
+            loggingContext.LogCommentFromText(MessageImportance.Low, analyzerData);
+        }
+    }
+
+    private string BuildCsvString(string title, Dictionary<string, TimeSpan> rowData)
+    {
+        return title + Environment.NewLine + String.Join(Environment.NewLine, rowData.Select(a => $"{a.Key},{a.Value}")) + Environment.NewLine;
     }
 
     public void Shutdown()

src/Build/BuildCheck/Infrastructure/BuildCheckManagerProvider.cs

@@ -2,6 +2,7 @@
 // The .NET Foundation licenses this file to you under the MIT license.
 
 using System;
+using System.CodeDom.Compiler;
 using System.Collections.Generic;
 using System.Collections.ObjectModel;
 using System.Diagnostics;
@@ -16,6 +17,7 @@
 using Microsoft.Build.BuildCheck.Acquisition;
 using Microsoft.Build.BuildCheck.Analyzers;
 using Microsoft.Build.BuildCheck.Logging;
+using Microsoft.Build.BuildCheck.Utilities;
 using Microsoft.Build.Collections;
 using Microsoft.Build.Construction;
 using Microsoft.Build.Evaluation;
@@ -44,6 +46,8 @@ internal static IBuildComponent CreateComponent(BuildComponentType type)
         return new BuildCheckManagerProvider();
     }
 
+    internal static Stopwatch _stopwatch = new Stopwatch();
+
     public void InitializeComponent(IBuildComponentHost host)
     {
         ErrorUtilities.VerifyThrow(host != null, "BuildComponentHost was null");
@@ -89,15 +93,20 @@ private sealed class BuildCheckManager : IBuildCheckManager
         /// <param name="buildCheckDataSource"></param>
         public void SetDataSource(BuildCheckDataSource buildCheckDataSource)
         {
+            _stopwatch.Start();
             if (!_enabledDataSources[(int)buildCheckDataSource])
             {
                 _enabledDataSources[(int)buildCheckDataSource] = true;
                 RegisterBuiltInAnalyzers(buildCheckDataSource);
             }
+            _stopwatch.Stop();
+            _tracingReporter.analyzerSetDataSourceTime = _stopwatch.Elapsed;
+            _stopwatch.Reset();
         }
 
         public void ProcessAnalyzerAcquisition(AnalyzerAcquisitionData acquisitionData)
         {
+            _stopwatch.Start();
             if (IsInProcNode)
             {
                 var factory = _acquisitionModule.CreateBuildAnalyzerFactory(acquisitionData);
@@ -117,6 +126,9 @@ public void ProcessAnalyzerAcquisition(AnalyzerAcquisitionData acquisitionData)
 
                 _loggingService.LogBuildEvent(eventArgs);
             }
+            _stopwatch.Stop();
+            _tracingReporter.analyzerAcquisitionTime = _stopwatch.Elapsed;
+            _stopwatch.Reset();
         }
 
         internal BuildCheckManager(ILoggingService loggingService)
@@ -260,7 +272,7 @@ private void SetupAnalyzersForNewProject(string projectFullPath, BuildEventConte
             // On an execution node - we might remove and dispose the analyzers once project is done
 
             // If it's already constructed - just control the custom settings do not differ
-
+            _stopwatch.Start();
             List<BuildAnalyzerFactoryContext> analyzersToRemove = new();
             foreach (BuildAnalyzerFactoryContext analyzerFactoryContext in _analyzersRegistry)
             {
@@ -288,6 +300,10 @@ private void SetupAnalyzersForNewProject(string projectFullPath, BuildEventConte
                 _tracingReporter.AddStats(analyzerToRemove!.BuildAnalyzer.FriendlyName, analyzerToRemove.Elapsed);
                 analyzerToRemove.BuildAnalyzer.Dispose();
             }
+
+            _stopwatch.Stop();
+            _tracingReporter.newProjectAnalyzersTime = _stopwatch.Elapsed;
+            _stopwatch.Reset();
         }
 
 
@@ -297,8 +313,7 @@ private void SetupAnalyzersForNewProject(string projectFullPath, BuildEventConte
             => _buildEventsProcessor
                 .ProcessEvaluationFinishedEventArgs(buildAnalysisContext, evaluationFinishedEventArgs);
 
-        // Tracing: https://github.com/dotnet/msbuild/issues/9629
-        public Dictionary<string, TimeSpan> CreateTracingStats()
+        public Dictionary<string, TimeSpan> CreateAnalyzerTracingStats()
         {
             foreach (BuildAnalyzerFactoryContext analyzerFactoryContext in _analyzersRegistry)
             {
@@ -310,6 +325,14 @@ private void SetupAnalyzersForNewProject(string projectFullPath, BuildEventConte
                 }
             }
 
+            var infraStats = new Dictionary<string, TimeSpan>() {
+                { $"{BuildCheckConstants.infraStatPrefix}analyzerAcquisitionTime", _tracingReporter.analyzerAcquisitionTime },
+                { $"{BuildCheckConstants.infraStatPrefix}analyzerSetDataSourceTime", _tracingReporter.analyzerSetDataSourceTime },
+                { $"{BuildCheckConstants.infraStatPrefix}newProjectAnalyzersTime", _tracingReporter.newProjectAnalyzersTime }
+            };
+
+            _tracingReporter.TracingStats.Merge(infraStats, (span1, span2) => span1 + span2);
+
             return _tracingReporter.TracingStats;
         }
 
@@ -321,9 +344,11 @@ public void FinalizeProcessing(LoggingContext loggingContext)
                 return;
             }
 
-            BuildCheckTracingEventArgs eventArgs =
-                new(CreateTracingStats()) { BuildEventContext = loggingContext.BuildEventContext };
-            loggingContext.LogBuildEvent(eventArgs);
+            var analyzerEventStats = CreateAnalyzerTracingStats();
+
+            BuildCheckTracingEventArgs analyzerEventArg =
+                new(analyzerEventStats) { BuildEventContext = loggingContext.BuildEventContext };
+            loggingContext.LogBuildEvent(analyzerEventArg);
         }
 
         public void StartProjectEvaluation(BuildCheckDataSource buildCheckDataSource, BuildEventContext buildEventContext,

src/Build/BuildCheck/Infrastructure/IBuildCheckManager.cs

@@ -36,7 +36,7 @@ internal interface IBuildCheckManager
 
     void ProcessAnalyzerAcquisition(AnalyzerAcquisitionData acquisitionData);
 
-    Dictionary<string, TimeSpan> CreateTracingStats();
+    Dictionary<string, TimeSpan> CreateAnalyzerTracingStats();
 
     void FinalizeProcessing(LoggingContext loggingContext);
 

src/Build/BuildCheck/Infrastructure/NullBuildCheckManager.cs

@@ -25,8 +25,6 @@ internal class NullBuildCheckManager : IBuildCheckManager
     public void SetDataSource(BuildCheckDataSource buildCheckDataSource) { }
     public void ProcessAnalyzerAcquisition(AnalyzerAcquisitionData acquisitionData) { }
 
-    public Dictionary<string, TimeSpan> CreateTracingStats() => throw new NotImplementedException();
-
     public void FinalizeProcessing(LoggingContext loggingContext)
     { }
 
@@ -48,4 +46,6 @@ public void YieldProject(BuildCheckDataSource buildCheckDataSource, BuildEventCo
 
     public void ResumeProject(BuildCheckDataSource buildCheckDataSource, BuildEventContext buildEventContext)
     { }
+
+    public Dictionary<string, TimeSpan> CreateAnalyzerTracingStats() => new Dictionary<string, TimeSpan>();
 }

src/Build/BuildCheck/Infrastructure/TracingReporter.cs

@@ -13,6 +13,11 @@ internal class TracingReporter
 {
     internal Dictionary<string, TimeSpan> TracingStats { get; } = new();
 
+    // Infrastructure time keepers, examples for now
+    internal TimeSpan analyzerAcquisitionTime;
+    internal TimeSpan analyzerSetDataSourceTime;
+    internal TimeSpan newProjectAnalyzersTime;
+
     public void AddStats(string name, TimeSpan subtotal)
     {
         if (TracingStats.TryGetValue(name, out TimeSpan existing))

src/Build/BuildCheck/Utilities/Constants.cs

@@ -0,0 +1,19 @@
+// Licensed to the .NET Foundation under one or more agreements.
+// The .NET Foundation licenses this file to you under the MIT license.
+
+using System;
+using System.Collections.Generic;
+using System.Linq;
+using System.Text;
+using System.Threading.Tasks;
+
+namespace Microsoft.Build.BuildCheck.Utilities
+{
+    /// <summary>
+    /// Constants to be shared within BuildCheck infrastructure
+    /// </summary>
+    internal static class BuildCheckConstants
+    {
+        internal const string infraStatPrefix = "infrastructureStat_";
+    }
+}

src/Build/Microsoft.Build.csproj

@@ -186,6 +186,7 @@
     <Compile Include="BuildCheck\Logging\IBuildAnalysisLoggingContextFactory.cs" />
     <Compile Include="BuildCheck\OM\EvaluatedPropertiesAnalysisData.cs" />
     <Compile Include="BuildCheck\OM\ParsedItemsAnalysisData.cs" />
+    <Compile Include="BuildCheck\Utilities\Constants.cs" />
     <Compile Include="BuildCheck\Utilities\EnumerableExtensions.cs" />
     <Compile Include="Evaluation\IItemTypeDefinition.cs" />
     <Compile Include="FileAccess\DesiredAccess.cs" />

src/BuildCheck.UnitTests/EndToEndTests.cs

@@ -120,7 +120,7 @@ public void SampleAnalyzerIntegrationTest(bool buildInOutOfProcessNode, bool ana
         _env.SetEnvironmentVariable("MSBUILDNOINPROCNODE", buildInOutOfProcessNode ? "1" : "0");
         _env.SetEnvironmentVariable("MSBUILDLOGPROPERTIESANDITEMSAFTEREVALUATION", "1");
         string output = RunnerUtilities.ExecBootstrapedMSBuild(
-            $"{Path.GetFileName(projectFile.Path)} /m:1 -nr:False -restore" +
+            $"{Path.GetFileName(projectFile.Path)} /m:1 -nr:False -restore -analyzeStats" +
             (analysisRequested ? " -analyze" : string.Empty), out bool success);
         _env.Output.WriteLine(output);
         success.ShouldBeTrue();

src/Framework/BuildCheck/BuildCheckEventArgs.cs

@@ -28,6 +28,12 @@ internal sealed class BuildCheckTracingEventArgs(Dictionary<string, TimeSpan> tr
     internal BuildCheckTracingEventArgs() : this(new Dictionary<string, TimeSpan>())
     { }
 
+    internal BuildCheckTracingEventArgs(Dictionary<string, TimeSpan> data, bool isLogReport) : this(data)
+    {
+        IsLogReport = isLogReport;
+    }
+
+    public bool IsLogReport { get; private set; } = false;
     public Dictionary<string, TimeSpan> TracingData { get; private set; } = tracingData;
 
     internal override void WriteToStream(BinaryWriter writer)

src/MSBuild.UnitTests/CommandLineSwitches_Tests.cs

@@ -1186,6 +1186,7 @@ public void InvalidToolsVersionErrors()
                                         lowPriority: false,
                                         question: false,
                                         isBuildCheckEnabled: false,
+                                        areBuildCheckStatsEnabled: false,
                                         inputResultsCaches: null,
                                         outputResultsCache: null,
                                         saveProjectResult: false,