For most BuildEventArgs we can completely reconstruct the message text from the other fields. Do not allocate and log the Message string in this case, and override Message implementation to recover the message lazily on demand. This way the message never needs to be allocated to travel across nodes or written/read into binlog. It is only materialized when a console/file logger requests it.

For cases where LazyFormattedBuildEventArgs has Arguments, don't flatten and materialize the Message during node packet translation or binlog write/read.

The two improvements above help significantly reduce string allocations, the number of strings logged and the string size. Smaller strings means that deduplication can do a better job reusing strings, and as such most large strings simply dissolve.

Strings before: Total size: 7,770,723, Count: 33,648, Largest: 55,401
Strings after: Total size: 1,382,154, Count: 18,701, Largest: 10,197

Increment the binlog file format version to 13. Write LazyFormattedBuildEventArgs.Arguments array into the binlog if present.

Do not persist Importance for BuildEventArgs that ignore it or where it defaults to low.
Do not write ThreadId into the binlog as it's never used.
Introduce the internal field BuildEventArgs.RawMessage to expose the underlying message field and avoid the side effects of calling Message (which formats using the Arguments).

Add Condition, EvaluatedCondition and OriginallySucceeded on TargetSkippedEventArgs so we can recover the message.

Do not sort item metadata when writing a binlog. We want binlogs to be fully roundtrippable and not lose any information. This is useful for unit-tests that compare against text logs and verify that played back logs are fully identical.

Add a new ILoggingService.LogCommentFromText overload that accepts a string and arguments. This allows us to cache resource strings instead of retrieving them every time.

Do not allocate or set Message when creating ProjectStarted, ProjectFinished, TargetStarted, TargetFinished, TaskStarted or TaskFinished.

Following the pattern set for TaskParameterEventArgs, inject the logic to format resource strings into BuildEventArgs using a static delegate. Later we can refactor and find a better pattern for this, but this works for now.

For TargetSkipped, log either OriginallySucceeded or Condition/EvaluatedCondition, and don't log the Message.

When logging input files and output files for skipped targets, do not concatenate them into huge semicolon-separated strings, but log a TaskParameterEventArgs instead. Introduce two new kinds of TaskParameter: TargetSkippedInputs and TargetSkippedOutputs. However as this is a flat list of files with no itemType, log itemType as null. Adjust the GetParameterText() logic to not write an extra indent or itemType if it is null.

Implement manual node packet translation for ProjectImported, TargetSkipped and Telemetry event args to avoid TranslateDotNet and binary formatter.

When logging input files and output files for skipped targets, do not concatenate them into huge semicolon-separated strings, but log a TaskParameterEventArgs instead. Introduce two new kinds of TaskParameter: TargetSkippedInputs and TargetSkippedOutputs. This way the smaller strings are deduplicated better.

For scalar task parameters, log a string with arguments instead of concatenating it into a single string such as "TaskParameter:a=b".

These concatenated strings are huge and are almost never useful.

Cache resource strings during evaluation instead of retrieving them every time.

Instead of retrieving resource strings every time, cache them, reduce allocations and concatenations. No need to use a resource string to just add 4/8/10/12 spaces.

Primarily this avoids concatenating the final string into a single string, but instead keeps the message separate from the arguments until the final string is requested.

Don't log the image runtime version if it's v4.0.30319 as it's the overwhelming default and carries no useful information.

Use better terminology for inclusion and exclusion lists.

This change looks extensive, but is pretty mechanical. Hard to review, but a significant improvement to allocations and RAR logging overhead.

Allows to turn off perf summary even in diagnostic mode.

Useful for diffing logs (as the perf numbers will be different when playing back a binlog).

Turns out we didn't have good coverage for Serial and Parallel console loggers. Include them in the binary logger roundtrip so we verify that logs from playing back a binlog are exactly identical to the logs from the real build.

Record a binlog every time we build using TestEnvironment, as well as parallel and serial console logs. After the build, playback the binlog into a new serial and console logs and diff the results.

This ensures that all events that happen during our test can be correctly played back from a binlog and result in the exact same output.

I leave a switch to turn it off for individual tests, but if these prove noisy we can turn this validation off entirely by default (and only turn it back on locally when working on logging related changes).

I did have to turn it off for TreatWarningsAsErrorsWhenBuildingSameProjectMultipleTimes because the binlog contained an extra property MSBuildLastTaskResult=true. I'm not exactly sure what is happening there, but one theory is the console log sees the state where that property is not set, then it's being mutated, then the binary log observes the state. Since two logs capture live data from ProjectEvaluationFinished, and access at different times, it may be that this is a case where the evaluation mutates in between. We need to be on the lookout for more cases like this and maybe turn this validation off by default. But it does give us a ton of free coverage for Serial and Parallel loggers. Most of the tests actually only exercise the MockLogger, so it's nice to test the real text loggers too.

I measured the overall duration of "build.cmd -test" and got inconclusive numbers. I think there's no obvious evidence that this change slows down the test run by any significant amount. The durations I got are:

07:34.6 07:38.8
06:45.4 06:52.5
08:09.7 07:28.4
06:49.7 07:32.5

and I'm intentionally not telling which one is which to illustrate that there is no obvious slowdown.

This is safe because the enum is internal and the current name isn't used anywhere.

Also make a separate bool field initialized.