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

@@ -2991,7 +2991,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, _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/BuildCheck/Infrastructure/BuildCheckConnectorLogger.cs

@@ -6,6 +6,7 @@
 using System.Linq;
 using Microsoft.Build.BackEnd.Logging;
 using Microsoft.Build.BuildCheck.Acquisition;
+using Microsoft.Build.BuildCheck.Utilities;
 using Microsoft.Build.Experimental.BuildCheck;
 using Microsoft.Build.Framework;
 using static Microsoft.Build.BuildCheck.Infrastructure.BuildCheckManagerProvider;
@@ -20,17 +21,21 @@ internal sealed class BuildCheckConnectorLogger : ILogger
 
     internal BuildCheckConnectorLogger(
         IBuildAnalysisLoggingContextFactory loggingContextFactory,
-        IBuildCheckManager buildCheckManager)
+        IBuildCheckManager buildCheckManager,
+        bool areStatsEnabled)
     {
         _buildCheckManager = buildCheckManager;
         _loggingContextFactory = loggingContextFactory;
+        _areStatsEnabled = areStatsEnabled;
         _eventHandlers = GetBuildEventHandlers();
     }
 
     public LoggerVerbosity Verbosity { get; set; }
 
     public string? Parameters { get; set; }
 
+    private bool _areStatsEnabled { get; set; }
+
     public void Initialize(IEventSource eventSource)
     {
         eventSource.AnyEventRaised += EventSource_AnyEventRaised;
@@ -80,9 +85,6 @@ 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,
@@ -92,8 +94,44 @@ private void EventSource_BuildFinished(object sender, BuildFinishedEventArgs e)
 
         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.Substring(BuildCheckConstants.infraStatPrefix.Length);
+                infraStats[newKey] = stat.Value;
+            }
+            else
+            {
+                analyzerStats[stat.Key] = stat.Value;
+            }
+        }
+
+        BuildCheckTracingEventArgs statEvent = new BuildCheckTracingEventArgs(_stats, true)
+        { BuildEventContext = loggingContext.BuildEventContext };
+
+        loggingContext.LogBuildEvent(statEvent);
+
+        MessageImportance importance = _areStatsEnabled ? MessageImportance.High : MessageImportance.Low;
+        loggingContext.LogCommentFromText(importance, $"BuildCheck run times{Environment.NewLine}");
+        string infraData = BuildCsvString("Infrastructure run times", infraStats);
+        loggingContext.LogCommentFromText(importance, infraData);
+        string analyzerData = BuildCsvString("Analyzer run times", analyzerStats);
+        loggingContext.LogCommentFromText(importance, 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;
     }
 
     private Dictionary<Type, Action<BuildEventArgs>> GetBuildEventHandlers() => new()
@@ -102,7 +140,14 @@ private void EventSource_BuildFinished(object sender, BuildFinishedEventArgs e)
         { typeof(ProjectEvaluationStartedEventArgs), (BuildEventArgs e) => HandleProjectEvaluationStartedEvent((ProjectEvaluationStartedEventArgs) e) },
         { typeof(ProjectStartedEventArgs), (BuildEventArgs e) => _buildCheckManager.StartProjectRequest(BuildCheckDataSource.EventArgs, e.BuildEventContext!) },
         { typeof(ProjectFinishedEventArgs), (BuildEventArgs e) => _buildCheckManager.EndProjectRequest(BuildCheckDataSource.EventArgs, e.BuildEventContext!) },
-        { typeof(BuildCheckTracingEventArgs), (BuildEventArgs e) => _stats.Merge(((BuildCheckTracingEventArgs)e).TracingData, (span1, span2) => span1 + span2) },
+        { typeof(BuildCheckTracingEventArgs), (BuildEventArgs e) => 
+        {
+            if(!((BuildCheckTracingEventArgs)e).IsAggregatedGlobalReport)
+            {
+                _stats.Merge(((BuildCheckTracingEventArgs)e).TracingData, (span1, span2) => span1 + span2);
+            }
+        }
+        },
         { typeof(BuildCheckAcquisitionEventArgs), (BuildEventArgs e) => _buildCheckManager.ProcessAnalyzerAcquisition(((BuildCheckAcquisitionEventArgs)e).ToAnalyzerAcquisitionData(), e.BuildEventContext!) },
     };
 }

src/Build/BuildCheck/Infrastructure/BuildCheckManagerProvider.cs

@@ -3,6 +3,7 @@
 
 using System;
 using System.Collections.Generic;
+using System.Diagnostics;
 using System.Linq;
 using System.Threading;
 using Microsoft.Build.BackEnd;
@@ -88,15 +89,21 @@ internal BuildCheckManager(ILoggingService loggingService)
         /// <param name="buildCheckDataSource"></param>
         public void SetDataSource(BuildCheckDataSource buildCheckDataSource)
         {
+            Stopwatch stopwatch = new Stopwatch();
+            stopwatch.Start();
             if (!_enabledDataSources[(int)buildCheckDataSource])
             {
                 _enabledDataSources[(int)buildCheckDataSource] = true;
                 RegisterBuiltInAnalyzers(buildCheckDataSource);
             }
+            stopwatch.Stop();
+            _tracingReporter.analyzerSetDataSourceTime = stopwatch.Elapsed;
         }
 
         public void ProcessAnalyzerAcquisition(AnalyzerAcquisitionData acquisitionData, BuildEventContext buildEventContext)
         {
+            Stopwatch stopwatch = new Stopwatch();
+            stopwatch.Start();
             if (IsInProcNode)
             {
                 var analyzersFactories = _acquisitionModule.CreateBuildAnalyzerFactories(acquisitionData, buildEventContext);
@@ -116,6 +123,8 @@ public void ProcessAnalyzerAcquisition(AnalyzerAcquisitionData acquisitionData,
 
                 _loggingService.LogBuildEvent(eventArgs);
             }
+            stopwatch.Stop();
+            _tracingReporter.analyzerAcquisitionTime = stopwatch.Elapsed;
         }
 
         private static T Construct<T>() where T : new() => new();
@@ -266,7 +275,8 @@ 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 stopwatch = new Stopwatch();
+            stopwatch.Start();
             List<BuildAnalyzerFactoryContext> analyzersToRemove = new();
             foreach (BuildAnalyzerFactoryContext analyzerFactoryContext in _analyzersRegistry)
             {
@@ -294,6 +304,9 @@ private void SetupAnalyzersForNewProject(string projectFullPath, BuildEventConte
                 _tracingReporter.AddStats(analyzerToRemove!.BuildAnalyzer.FriendlyName, analyzerToRemove.Elapsed);
                 analyzerToRemove.BuildAnalyzer.Dispose();
             }
+
+            stopwatch.Stop();
+            _tracingReporter.newProjectAnalyzersTime = stopwatch.Elapsed;
         }
 
         public void ProcessEvaluationFinishedEventArgs(
@@ -302,8 +315,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)
             {
@@ -315,6 +327,7 @@ public Dictionary<string, TimeSpan> CreateTracingStats()
                 }
             }
 
+            _tracingReporter.AddAnalyzerInfraStats();
             return _tracingReporter.TracingStats;
         }
 
@@ -326,9 +339,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

@@ -44,7 +44,7 @@ void ProcessEvaluationFinishedEventArgs(
 
     void ProcessAnalyzerAcquisition(AnalyzerAcquisitionData acquisitionData, BuildEventContext buildEventContext);
 
-    Dictionary<string, TimeSpan> CreateTracingStats();
+    Dictionary<string, TimeSpan> CreateAnalyzerTracingStats();
 
     void FinalizeProcessing(LoggingContext loggingContext);
 

src/Build/BuildCheck/Infrastructure/NullBuildCheckManager.cs

@@ -31,8 +31,6 @@ public void ProcessAnalyzerAcquisition(AnalyzerAcquisitionData acquisitionData,
     {
     }
 
-    public Dictionary<string, TimeSpan> CreateTracingStats() => throw new NotImplementedException();
-
     public void FinalizeProcessing(LoggingContext loggingContext)
     {
     }
@@ -60,4 +58,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

@@ -6,13 +6,20 @@
 using System.Linq;
 using System.Text;
 using System.Threading.Tasks;
+using Microsoft.Build.BuildCheck.Utilities;
+using Microsoft.Build.Experimental.BuildCheck;
 
 namespace Microsoft.Build.BuildCheck.Infrastructure;
 
 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))
@@ -24,4 +31,15 @@ public void AddStats(string name, TimeSpan subtotal)
             TracingStats[name] = subtotal;
         }
     }
+
+    public void AddAnalyzerInfraStats()
+    {
+        var infraStats = new Dictionary<string, TimeSpan>() {
+                { $"{BuildCheckConstants.infraStatPrefix}analyzerAcquisitionTime", analyzerAcquisitionTime },
+                { $"{BuildCheckConstants.infraStatPrefix}analyzerSetDataSourceTime", analyzerSetDataSourceTime },
+                { $"{BuildCheckConstants.infraStatPrefix}newProjectAnalyzersTime", newProjectAnalyzersTime }
+            };
+
+        TracingStats.Merge(infraStats, (span1, span2) => span1 + span2);
+    }
 }

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

@@ -187,6 +187,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/Framework/BuildCheck/BuildCheckEventArgs.cs

@@ -30,6 +30,17 @@ internal BuildCheckTracingEventArgs()
     {
     }
 
+    internal BuildCheckTracingEventArgs(Dictionary<string, TimeSpan> data, bool isAggregatedGlobalReport) : this(data)
+    {
+        IsAggregatedGlobalReport = isAggregatedGlobalReport;
+    }
+
+    /// <summary>
+    /// When true, the tracing information is from the whole build for logging purposes
+    /// When false, the tracing is being used for communication between nodes and central process
+    /// </summary>
+    public bool IsAggregatedGlobalReport { 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,

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