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 ILoggingService CreateLoggingService(
 
                 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;
@@ -33,9 +39,18 @@ private void EventSource_AnyEventRaised(object sender, BuildEventArgs e)
                 return;
             }
 
+            try
+            {
             buildCheckManager.ProcessEvaluationFinishedEventArgs(
                 loggingContextFactory.CreateLoggingContext(e.BuildEventContext!),
                 projectEvaluationFinishedEventArgs);
+            }
+            catch (Exception exception)
+            {
+                Debugger.Launch();
+                Console.WriteLine(exception);
+                throw;
+            }
 
             buildCheckManager.EndProjectEvaluation(BuildCheckDataSource.EventArgs, e.BuildEventContext!);
         }
@@ -75,17 +90,69 @@ 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;
+            }
+        }
+
+        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 BuildStatsTable(string title, Dictionary<string, TimeSpan> rowData)
+    {
+        string headerSeparator = $"=============";
+        string rowSeparator = $"{Environment.NewLine}----------{Environment.NewLine}";
+
+        string header = $"{headerSeparator}{Environment.NewLine}{title}{Environment.NewLine}{headerSeparator}{Environment.NewLine}";
+
+        string rows = string.Join(rowSeparator, rowData.Select(a => $"{a.Key} | {a.Value}"));
+
+        return $"{header}{rows}{Environment.NewLine}";
+    }
+
+    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");
@@ -273,6 +277,7 @@ private void SetupAnalyzersForNewProject(string projectFullPath, BuildEventConte
                     _loggingService.LogErrorFromText(buildEventContext, null, null, null,
                         new BuildEventFileInfo(projectFullPath),
                         e.Message);
+                    _loggingService.LogCommentFromText(buildEventContext, MessageImportance.High, $"Dismounting analyzer '{analyzerFactoryContext.FriendlyName}'");
                     analyzersToRemove.Add(analyzerFactoryContext);
                 }
             }
@@ -297,8 +302,7 @@ public void ProcessEvaluationFinishedEventArgs(
             => _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 +314,14 @@ public Dictionary<string, TimeSpan> CreateTracingStats()
                 }
             }
 
+            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 +333,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 @@ void ProcessEvaluationFinishedEventArgs(
 
     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 @@ public void ProcessEvaluationFinishedEventArgs(AnalyzerLoggingContext buildAnaly
     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/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,

src/MSBuild/CommandLineSwitches.cs

@@ -47,6 +47,7 @@ internal enum ParameterlessSwitch
             FileLogger8,
             FileLogger9,
             DistributedFileLogger,
+            AnalyzeStats,
 #if DEBUG
             WaitForDebugger,
 #endif
@@ -222,6 +223,7 @@ internal ParameterizedSwitchInfo(
             new ParameterlessSwitchInfo(  new string[] { "filelogger8", "fl8" },                     ParameterlessSwitch.FileLogger8,           null),
             new ParameterlessSwitchInfo(  new string[] { "filelogger9", "fl9" },                     ParameterlessSwitch.FileLogger9,           null),
             new ParameterlessSwitchInfo(  new string[] { "distributedfilelogger", "dfl" },           ParameterlessSwitch.DistributedFileLogger, null),
+            new ParameterlessSwitchInfo(  new string[] { "analyzeStats" },                           ParameterlessSwitch.AnalyzeStats,          null),
 #if DEBUG
             new ParameterlessSwitchInfo(  new string[] { "waitfordebugger", "wfd" },                 ParameterlessSwitch.WaitForDebugger,       null),
 #endif