Optimize logging by moving message importance checks earlier (#6381)

Fixes #5992 

### Context

Some tasks spend a lot of time producing detailed log messages that end up going nowhere when building on the command line with Normal or Minimum verbosity. The goal of this PR is to expose an API for tasks to call to answer the question _"Are log messages of a given importance going to be consumed by a logger or should I not bother doing the work to create the output and skip calling `LogMessage` altogether?"_

### Changes Made

Added a public method named `LogsMessagesOfImportance` on `TaskLoggingHelper` to answer the question above. This PR focuses on command line scenarios such as `dotnet build` but the logic could be easily used/extended to work with 3rd party loggers (in IDEs for example) if we introduce a mechanism by which loggers promise to ignore too verbose messages. The solution presented herein is a bolt-on, making minimum changes to the existing logging infra. Third party loggers are assumed to be potentially logging everything so if at least one such logger is registered, the optimization is disabled.

The new method is used internally by `TaskLoggingHelper` and by the otherwise spammy RAR task.

### Testing

Existing and new unit tests, manual verification on command line as well as in Visual Studio.

Performance testing has shown ~18 ms improvement in RAR run-time alone when building a single project with `dotnet build`.

### Notes

This PR also introduces a new class `EngineServices` to serve as a replacement for the `IBuildEngineN` interfaces.

eng/build.ps1

@@ -151,11 +151,23 @@ function Set-OptProfVariables() {
 function Check-EditedFiles() {
   # Log VSTS errors for changed lines
   git --no-pager diff HEAD --unified=0 --no-color --exit-code | ForEach-Object { "##vso[task.logissue type=error] $_" }
-  if($LASTEXITCODE -ne 0) {
+  if ($LASTEXITCODE -ne 0) {
     throw "##vso[task.logissue type=error] After building, there are changed files.  Please build locally and include these changes in your pull request."
   }
 }
 
+function Check-RequiredVersionBumps() {
+  # Log VSTS errors for missing required version bumps
+  $versionLineChanged = $false
+  git --no-pager diff --unified --no-color --exit-code -w origin/$env:SYSTEM_PULLREQUEST_TARGETBRANCH HEAD src\Framework\EngineServices.cs `
+    | Select-String -Pattern "int Version =" | ForEach-Object -process { $versionLineChanged = $true }
+  if (($LASTEXITCODE -ne 0) -and (-not $versionLineChanged)) {
+    throw "##vso[task.logissue type=error] Detected changes in Framework\EngineServices.cs without a version bump.  " +
+          "If you are making API changes, please bump the version.  " +
+          "If the changes in the file are cosmetic, please add/change a comment on the Version prop to silence the error."
+  }
+}
+
 try {
   Process-Arguments
 
@@ -165,6 +177,10 @@ try {
 
   $VSSetupDir = Join-Path $ArtifactsDir "VSSetup\$configuration"
 
+  if ($ci -and $build) {
+    Check-RequiredVersionBumps
+  }
+
   Build-Repo
 
   if ($ci -and $build) {

ref/Microsoft.Build.Framework/net/Microsoft.Build.Framework.cs

@@ -152,6 +152,13 @@ public abstract partial class CustomBuildEventArgs : Microsoft.Build.Framework.L
         protected CustomBuildEventArgs(string message, string helpKeyword, string senderName, System.DateTime eventTimestamp, params object[] messageArgs) { }
     }
     public delegate void CustomBuildEventHandler(object sender, Microsoft.Build.Framework.CustomBuildEventArgs e);
+    public abstract partial class EngineServices
+    {
+        public const int Version1 = 1;
+        protected EngineServices() { }
+        public virtual int Version { get { throw null; } }
+        public virtual bool LogsMessagesOfImportance(Microsoft.Build.Framework.MessageImportance importance) { throw null; }
+    }
     public partial class EnvironmentVariableReadEventArgs : Microsoft.Build.Framework.BuildMessageEventArgs
     {
         public EnvironmentVariableReadEventArgs() { }
@@ -186,6 +193,10 @@ public partial interface IBuildEngine
         void LogMessageEvent(Microsoft.Build.Framework.BuildMessageEventArgs e);
         void LogWarningEvent(Microsoft.Build.Framework.BuildWarningEventArgs e);
     }
+    public partial interface IBuildEngine10 : Microsoft.Build.Framework.IBuildEngine, Microsoft.Build.Framework.IBuildEngine2, Microsoft.Build.Framework.IBuildEngine3, Microsoft.Build.Framework.IBuildEngine4, Microsoft.Build.Framework.IBuildEngine5, Microsoft.Build.Framework.IBuildEngine6, Microsoft.Build.Framework.IBuildEngine7, Microsoft.Build.Framework.IBuildEngine8, Microsoft.Build.Framework.IBuildEngine9
+    {
+        Microsoft.Build.Framework.EngineServices EngineServices { get; }
+    }
     public partial interface IBuildEngine2 : Microsoft.Build.Framework.IBuildEngine
     {
         bool IsRunningMultipleNodes { get; }

ref/Microsoft.Build.Framework/netstandard/Microsoft.Build.Framework.cs

@@ -152,6 +152,13 @@ public abstract partial class CustomBuildEventArgs : Microsoft.Build.Framework.L
         protected CustomBuildEventArgs(string message, string helpKeyword, string senderName, System.DateTime eventTimestamp, params object[] messageArgs) { }
     }
     public delegate void CustomBuildEventHandler(object sender, Microsoft.Build.Framework.CustomBuildEventArgs e);
+    public abstract partial class EngineServices
+    {
+        public const int Version1 = 1;
+        protected EngineServices() { }
+        public virtual int Version { get { throw null; } }
+        public virtual bool LogsMessagesOfImportance(Microsoft.Build.Framework.MessageImportance importance) { throw null; }
+    }
     public partial class EnvironmentVariableReadEventArgs : Microsoft.Build.Framework.BuildMessageEventArgs
     {
         public EnvironmentVariableReadEventArgs() { }
@@ -186,6 +193,10 @@ public partial interface IBuildEngine
         void LogMessageEvent(Microsoft.Build.Framework.BuildMessageEventArgs e);
         void LogWarningEvent(Microsoft.Build.Framework.BuildWarningEventArgs e);
     }
+    public partial interface IBuildEngine10 : Microsoft.Build.Framework.IBuildEngine, Microsoft.Build.Framework.IBuildEngine2, Microsoft.Build.Framework.IBuildEngine3, Microsoft.Build.Framework.IBuildEngine4, Microsoft.Build.Framework.IBuildEngine5, Microsoft.Build.Framework.IBuildEngine6, Microsoft.Build.Framework.IBuildEngine7, Microsoft.Build.Framework.IBuildEngine8, Microsoft.Build.Framework.IBuildEngine9
+    {
+        Microsoft.Build.Framework.EngineServices EngineServices { get; }
+    }
     public partial interface IBuildEngine2 : Microsoft.Build.Framework.IBuildEngine
     {
         bool IsRunningMultipleNodes { get; }

ref/Microsoft.Build.Utilities.Core/net/Microsoft.Build.Utilities.Core.cs

@@ -423,6 +423,7 @@ public partial class TaskLoggingHelper : System.MarshalByRefObject
         public bool LogMessagesFromFile(string fileName) { throw null; }
         public bool LogMessagesFromFile(string fileName, Microsoft.Build.Framework.MessageImportance messageImportance) { throw null; }
         public bool LogMessagesFromStream(System.IO.TextReader stream, Microsoft.Build.Framework.MessageImportance messageImportance) { throw null; }
+        public bool LogsMessagesOfImportance(Microsoft.Build.Framework.MessageImportance importance) { throw null; }
         public void LogTelemetry(string eventName, System.Collections.Generic.IDictionary<string, string> properties) { }
         public void LogWarning(string message, params object[] messageArgs) { }
         public void LogWarning(string subcategory, string warningCode, string helpKeyword, string file, int lineNumber, int columnNumber, int endLineNumber, int endColumnNumber, string message, params object[] messageArgs) { }

ref/Microsoft.Build.Utilities.Core/netstandard/Microsoft.Build.Utilities.Core.cs

@@ -265,6 +265,7 @@ public partial class TaskLoggingHelper
         public bool LogMessagesFromFile(string fileName) { throw null; }
         public bool LogMessagesFromFile(string fileName, Microsoft.Build.Framework.MessageImportance messageImportance) { throw null; }
         public bool LogMessagesFromStream(System.IO.TextReader stream, Microsoft.Build.Framework.MessageImportance messageImportance) { throw null; }
+        public bool LogsMessagesOfImportance(Microsoft.Build.Framework.MessageImportance importance) { throw null; }
         public void LogTelemetry(string eventName, System.Collections.Generic.IDictionary<string, string> properties) { }
         public void LogWarning(string message, params object[] messageArgs) { }
         public void LogWarning(string subcategory, string warningCode, string helpKeyword, string file, int lineNumber, int columnNumber, int endLineNumber, int endColumnNumber, string message, params object[] messageArgs) { }

src/Build.UnitTests/BackEnd/LoggingService_Tests.cs

@@ -665,6 +665,11 @@ public void Properties()
             Assert.Equal(1, loggingService.MaxCPUCount);
             loggingService.MaxCPUCount = 5;
             Assert.Equal(5, loggingService.MaxCPUCount);
+
+            // Test MinimumRequiredMessageImportance
+            Assert.Equal(MessageImportance.Low, loggingService.MinimumRequiredMessageImportance);
+            loggingService.RegisterLogger(new ConsoleLogger(LoggerVerbosity.Normal));
+            Assert.Equal(MessageImportance.Normal, loggingService.MinimumRequiredMessageImportance);
         }
 
         #endregion
@@ -718,6 +723,8 @@ public void LoggingPacketReceived()
 
         #endregion
 
+        #region WarningsAsErrors Tests
+
         private static readonly BuildWarningEventArgs BuildWarningEventForTreatAsErrorOrMessageTests = new BuildWarningEventArgs("subcategory", "C94A41A90FFB4EF592BF98BA59BEE8AF", "file", 1, 2, 3, 4, "message", "helpKeyword", "senderName");
 
         /// <summary>
@@ -1000,6 +1007,76 @@ public void TreatWarningsAsMessagesByProjectWhenSpecified(int loggerMode, int no
             return logger;
         }
 
+        #endregion
+
+        #region MinimumRequiredMessageImportance Tests
+
+        [Fact]
+        public void ImportanceReflectsConsoleLoggerVerbosity()
+        {
+            _initializedService.RegisterLogger(new ConsoleLogger(LoggerVerbosity.Quiet));
+            _initializedService.MinimumRequiredMessageImportance.ShouldBe(MessageImportance.High - 1);
+            _initializedService.RegisterLogger(new ConsoleLogger(LoggerVerbosity.Minimal));
+            _initializedService.MinimumRequiredMessageImportance.ShouldBe(MessageImportance.High);
+            _initializedService.RegisterLogger(new ConsoleLogger(LoggerVerbosity.Normal));
+            _initializedService.MinimumRequiredMessageImportance.ShouldBe(MessageImportance.Normal);
+            _initializedService.RegisterLogger(new ConsoleLogger(LoggerVerbosity.Detailed));
+            _initializedService.MinimumRequiredMessageImportance.ShouldBe(MessageImportance.Low);
+            _initializedService.RegisterLogger(new ConsoleLogger(LoggerVerbosity.Diagnostic));
+            _initializedService.MinimumRequiredMessageImportance.ShouldBe(MessageImportance.Low);
+        }
+
+        [Fact]
+        public void ImportanceReflectsConfigurableForwardingLoggerVerbosity()
+        {
+            _initializedService.RegisterLogger(CreateConfigurableForwardingLogger(LoggerVerbosity.Quiet));
+            _initializedService.MinimumRequiredMessageImportance.ShouldBe(MessageImportance.High - 1);
+            _initializedService.RegisterLogger(CreateConfigurableForwardingLogger(LoggerVerbosity.Minimal));
+            _initializedService.MinimumRequiredMessageImportance.ShouldBe(MessageImportance.High);
+            _initializedService.RegisterLogger(CreateConfigurableForwardingLogger(LoggerVerbosity.Normal));
+            _initializedService.MinimumRequiredMessageImportance.ShouldBe(MessageImportance.Normal);
+            _initializedService.RegisterLogger(CreateConfigurableForwardingLogger(LoggerVerbosity.Detailed));
+            _initializedService.MinimumRequiredMessageImportance.ShouldBe(MessageImportance.Low);
+            _initializedService.RegisterLogger(CreateConfigurableForwardingLogger(LoggerVerbosity.Diagnostic));
+            _initializedService.MinimumRequiredMessageImportance.ShouldBe(MessageImportance.Low);
+        }
+
+        [Fact]
+        public void ImportanceReflectsCentralForwardingLoggerVerbosity()
+        {
+            MockHost mockHost = new MockHost();
+            ILoggingService node1LoggingService = LoggingService.CreateLoggingService(LoggerMode.Synchronous, 1);
+            ((IBuildComponent)node1LoggingService).InitializeComponent(mockHost);
+            ILoggingService node2LoggingService = LoggingService.CreateLoggingService(LoggerMode.Synchronous, 2);
+            ((IBuildComponent)node2LoggingService).InitializeComponent(mockHost);
+
+            // CentralForwardingLogger is always registered in in-proc nodes and it does not affect minimum importance.
+            node1LoggingService.RegisterLogger(CreateConfigurableForwardingLogger(LoggerVerbosity.Minimal));
+            node1LoggingService.RegisterLogger(new CentralForwardingLogger());
+            node1LoggingService.MinimumRequiredMessageImportance.ShouldBe(MessageImportance.High);
+
+            // CentralForwardingLogger in out-of-proc nodes means that we are forwarding everything and the minimum importance
+            // is Low regardless of what other loggers are registered.
+            node2LoggingService.RegisterLogger(CreateConfigurableForwardingLogger(LoggerVerbosity.Minimal));
+            node2LoggingService.RegisterLogger(new CentralForwardingLogger());
+            node2LoggingService.MinimumRequiredMessageImportance.ShouldBe(MessageImportance.Low);
+            // Register another ConsoleLogger and verify that minimum importance hasn't changed.
+            node2LoggingService.RegisterLogger(CreateConfigurableForwardingLogger(LoggerVerbosity.Minimal));
+            node2LoggingService.MinimumRequiredMessageImportance.ShouldBe(MessageImportance.Low);
+        }
+
+        [Fact]
+        public void ImportanceReflectsUnknownLoggerVerbosity()
+        {
+            // Minimum message importance is Low (i.e. we're logging everything) even when all registered loggers have
+            // Normal verbosity if at least of one them is not on our whitelist.
+            _initializedService.RegisterLogger(new ConsoleLogger(LoggerVerbosity.Normal));
+            _initializedService.RegisterLogger(new MockLogger() { Verbosity = LoggerVerbosity.Normal });
+            _initializedService.RegisterLogger(CreateConfigurableForwardingLogger(LoggerVerbosity.Normal));
+            _initializedService.MinimumRequiredMessageImportance.ShouldBe(MessageImportance.Low);
+        }
+        #endregion
+
         #region PrivateMethods
 
         /// <summary>
@@ -1084,6 +1161,17 @@ private LoggerDescription CreateLoggerDescription(string loggerClassName, string
                                                                              );
             return centralLoggerDescrption;
         }
+
+        /// <summary>
+        /// Creates a new <see cref="ConfigurableForwardingLogger"/> with the given verbosity.
+        /// </summary>
+        private ConfigurableForwardingLogger CreateConfigurableForwardingLogger(LoggerVerbosity verbosity)
+        {
+            return new ConfigurableForwardingLogger()
+            {
+                Verbosity = verbosity
+            };
+        }
         #endregion
 
         #region HelperClasses

src/Build.UnitTests/BackEnd/MockLoggingService.cs

@@ -223,6 +223,11 @@ public bool IncludeTaskInputs
             set { }
         }
 
+        public MessageImportance MinimumRequiredMessageImportance
+        {
+            get => MessageImportance.Low;
+        }
+
         public void AddWarningsAsMessages(BuildEventContext buildEventContext, ISet<string> codes)
         {
             throw new NotImplementedException();

src/Build/BackEnd/BuildManager/BuildManager.cs

@@ -3113,7 +3113,7 @@ private void CancelAndMarkAsFailure()
         /// <summary>
         /// The logger registered to the logging service when no other one is.
         /// </summary>
-        private class NullLogger : ILogger
+        internal class NullLogger : ILogger
         {
             #region ILogger Members
 

src/Build/BackEnd/Components/Logging/ILoggingService.cs

@@ -207,6 +207,15 @@ bool IncludeTaskInputs
             set;
         }
 
+        /// <summary>
+        /// Returns the minimum logging importance that must be logged because there is a possibility that
+        /// at least one registered logger consumes it.
+        /// </summary>
+        MessageImportance MinimumRequiredMessageImportance
+        {
+            get;
+        }
+
         #endregion
 
         /// <summary>

src/Build/BackEnd/Components/Logging/LoggingService.cs

@@ -222,6 +222,12 @@ internal partial class LoggingService : ILoggingService, INodePacketHandler, IBu
         /// </summary>
         private IDictionary<int, ISet<string>> _warningsAsMessagesByProject;
 
+        /// <summary>
+        /// The minimum message importance that must be logged because there is a possibility that a logger consumes it.
+        /// Null means that the optimization is disabled or no relevant logger has been registered.
+        /// </summary>
+        private MessageImportance? _minimumRequiredMessageImportance;
+
         #region LoggingThread Data
 
         /// <summary>
@@ -702,6 +708,19 @@ public ICollection<string> RegisteredSinkNames
             }
         }
 
+        /// <summary>
+        /// Returns the minimum logging importance that must be logged because there is a possibility that
+        /// at least one registered logger consumes it.
+        /// </summary>
+        public MessageImportance MinimumRequiredMessageImportance
+        {
+            get
+            {
+                // If we haven't set the field return the default of "all messages must be logged".
+                return _minimumRequiredMessageImportance ?? MessageImportance.Low;
+            }
+        }
+
         #endregion
 
         #region Members
@@ -1120,7 +1139,7 @@ public void LogBuildEvent(BuildEventArgs buildEvent)
         #endregion
 
         /// <summary>
-        /// This method will becalled from multiple threads in asynchronous mode.
+        /// This method will be called from multiple threads in asynchronous mode.
         ///
         /// Determine where to send the buildevent either to the filters or to a specific sink.
         /// When in Asynchronous mode the event should to into the logging queue (as long as we are initialized).
@@ -1553,10 +1572,57 @@ private void InitializeLogger(ILogger logger, IEventSource sourceForLogger)
                 InternalLoggerException.Throw(e, null, "FatalErrorWhileInitializingLogger", true, logger.GetType().Name);
             }
 
+            // Update the minimum guaranteed message importance based on the newly added logger.
+            UpdateMinimumMessageImportance(logger);
+
             // Keep track of the loggers so they can be unregistered later on
             _loggers.Add(logger);
         }
 
+        /// <summary>
+        /// Updates <see cref="_minimumRequiredMessageImportance"/> based on the given <paramref name="logger"/>.
+        /// </summary>
+        /// <param name="logger">The newly registered logger.</param>
+        /// <remarks>
+        /// This method contains knowledge about several logger classes used by MSBuild. The goal is to optimize common scenarios,
+        /// such as building on the command line with normal or minimum verbosity. If the user registers an external custom logger,
+        /// we will fall back to "minimum importance" == Low because we don't know how the logger processes messages, therefore we
+        /// must feed it everything.
+        /// </remarks>
+        private void UpdateMinimumMessageImportance(ILogger logger)
+        {
+            var innerLogger = (logger is Evaluation.ProjectCollection.ReusableLogger reusableLogger) ? reusableLogger.OriginalLogger : logger;
+
+            MessageImportance? minimumImportance = innerLogger switch
+            {
+                Build.Logging.ConsoleLogger consoleLogger => consoleLogger.GetMinimumMessageImportance(),
+                Build.Logging.ConfigurableForwardingLogger forwardingLogger => forwardingLogger.GetMinimumMessageImportance(),
+
+                // Central forwarding loggers are used in worker nodes if logging verbosity could not be optimized, i.e. in cases
+                // where we must log everything. They can be ignored in inproc nodes.
+                CentralForwardingLogger => (_nodeId > 1 ? MessageImportance.Low : null),
+
+                // The null logger has no effect on minimum verbosity.
+                Execution.BuildManager.NullLogger => null,
+
+                // If the logger is not on our whitelist, there are no importance guarantees. Fall back to "any importance".
+                _ => MessageImportance.Low
+            };
+
+            if (minimumImportance != null)
+            {
+                if (_minimumRequiredMessageImportance == null)
+                {
+                    _minimumRequiredMessageImportance = minimumImportance;
+                }
+                else
+                {
+                    int newMinImportance = Math.Max((int)_minimumRequiredMessageImportance, (int)minimumImportance);
+                    _minimumRequiredMessageImportance = (MessageImportance)newMinImportance;
+                }
+            }
+        }
+
         /// <summary>
         /// When an exception is raised in the logging thread, we do not want the application to terminate right away.
         /// Whidbey and orcas msbuild have the logger exceptions occurring on the engine thread so that the host can
@@ -1609,8 +1675,7 @@ private void TryRaiseProjectFinishedEvent(BuildEventArgs args)
         /// </summary>
         private string GetAndVerifyProjectFileFromContext(BuildEventContext context)
         {
-            string projectFile;
-            _projectFileMap.TryGetValue(context.ProjectContextId, out projectFile);
+            _projectFileMap.TryGetValue(context.ProjectContextId, out string projectFile);
 
             // PERF: Not using VerifyThrow to avoid boxing an int in the non-error case.
             if (projectFile == null)