Optimize logging by moving message importance checks earlier by ladipro · Pull Request #6381 · dotnet/msbuild

ladipro · 2021-04-28T20:56:15Z

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.

Forgind

I like it! Thanks for making these changes!

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

Forgind · 2021-04-29T20:57:19Z

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

Could this break someone if they set the MSBUILDNOINPROCNODE flag partway through the build? I vaguely remember a case similar to that.

As with many escape hatches, we may get into an interesting state if different processes run with different environment variables. I don't think this change is making much of a difference, though, as we're still reading the value from the current process, potentially at a different time. To break something, there would have to be an entity setting the variable on the current running process which is very unlikely.

The ultimate fix would be to take a snapshot of the relevant environment variables in the main node, and either make them part of the handshake (connect only to nodes running with the same variables), or be sending them with requests (to avoid reading them in remote nodes altogether). Honestly, it looks like an overkill.

Found the bug I was thinking of:
https://devdiv.visualstudio.com/DevDiv/_workitems/edit/1197992
I'm not sure we should support this sort of thing, but felt I should call it out.

Oh, wow, if we backported a fix for this in the past, let's definitely not change the behavior. I'll revert the change. Thank you!

src/Framework/IBuildEngineInternal.cs

KirillOsenkov · 2021-04-29T21:52:35Z

Do you think we should tack on a fix for #6305 (expose LogTaskInputs to tasks) in this PR or separately?

It's very similar in nature and should be easy to add if we're modifying the build engine interface anyway.
Here's the prototype I made: 1011f17

Of course use the different API but the intention is the same.

Forgind · 2021-04-29T22:11:03Z

Do you think we should tack on a fix for #6305 (expose LogTaskInputs to tasks) in this PR or separately?

It's very similar in nature and should be easy to add if we're modifying the build engine interface anyway.
Here's the prototype I made: 1011f17

Of course use the different API but the intention is the same.

The effects and solutions seem similar, but the problems they're trying to solve feel different enough to me that I'd slightly prefer them in separate PRs. One tries to eliminate unnecessary abortive attempts at logging messages, and the other eliminates duplicate log messages by fixing a prior bug. I don't mind if you want to add it here, though, and I think both are good improvements.

KirillOsenkov · 2021-04-29T22:51:16Z

I'm just not sure what's the good design here, I guess it's up to you guys to decide on one. It involves how we plan to evolve IBuildEngine* in the future.

src/Framework/IBuildEngineInternal.cs

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

src/Build/Logging/BaseConsoleLogger.cs

src/Build/Logging/ConsoleLogger.cs

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

src/Shared/TaskLoggingHelper.cs

ladipro · 2021-05-21T20:57:41Z

I still have to address a few comments but I wanted to get the new BuildEngineInterface out to get feedback. This is the new mechanism to evolve the build engine API. Instead of adding a new COM-like IBuildEngineN interface in each release, we stop at IBuildEngine10 that lets the caller get a reference to an abstract class, which I believe was the agreement in previous discussions on this topic.

Forgind

Version number (probably best)/dictionary/set/something as discussed in PR reviews, but otherwise LGTM!

Though I'm wondering in retrospect—why did we decide we needed IBuildEngine10 rather than just having "BuildEngineInterface" with a version that we can add things to? (Also may want to rename it, since it isn't technically an interface.)

src/Build/Logging/DistributedLoggers/ConfigurableForwardingLogger.cs

src/Shared/TaskLoggingHelper.cs

src/Framework/BuildEngineInterface.cs

KirillOsenkov · 2021-05-24T20:00:13Z

I wasn't paying much attention, but a reminder that I'm still super interested in exposing LogTaskInputs to tasks, so RAR can turn off its custom logging if we're logging all inputs anyway: #6305

Whatever design we come up with for IBuildEngine*, please keep the scenario ^^ in mind as well. Pretty much please stick bool LogTaskInputs { get; } on there somewhere so tasks can access.

Not saying it should be a part of this PR though!

Thanks!

ladipro · 2021-05-26T13:18:40Z

Will definitely do, @KirillOsenkov. Likely as a separate PR.

ladipro

Though I'm wondering in retrospect—why did we decide we needed IBuildEngine10 rather than just having "BuildEngineInterface" with a version that we can add things to?

The reference in which the build engine is passed around is typed as IBuildEngine. To be able to use a functionality added later, the caller has to cast to another type. This type cannot be a class because IBuildEngine is already implemented by a class - a different one, obviously - and we would basically say that all implementors must derive from this base class, which would be a really bad practice. And impossible in many cases, like when the implementation has an important base class already (hello MarshalByRefObject!).

So to avoid the interface hop, we would have to add a BuildEngineInterface property or parameter to all places that currently take or return IBuildEngine. That would be pretty big API change, maybe with unwanted side-effects. I hope I understood the question, please let me know if you had something else in mind.

(Also may want to rename it, since it isn't technically an interface.)

Yes, not an interface so it doesn't have the leading I. Though kind of like an interface, hence the trailing Interface. I'm totally open to suggestions!

src/Shared/TaskLoggingHelper.cs

src/Framework/BuildEngineInterface.cs

src/Build/Logging/DistributedLoggers/ConfigurableForwardingLogger.cs

azure-pipelines · 2021-05-28T19:46:44Z

Pull request contains merge conflicts.

…e logger

…leForwardingLogger

…s instead

…enarios

…fImportance

ladipro force-pushed the 5992-aggressive-verbosity-checks branch from 0fc5a81 to 5cfb9f6 Compare April 29, 2021 10:04

ladipro changed the title ~~[DRAFT] Optimize logging by moving message importance checks earlier~~ Optimize logging by moving message importance checks earlier Apr 29, 2021

ladipro marked this pull request as ready for review April 29, 2021 11:05

Forgind approved these changes Apr 29, 2021

View reviewed changes

KirillOsenkov added the Area: Logging label Apr 29, 2021