Console logger support for IncludeEvaluationPropertiesAndItems #6535

KirillOsenkov · 2021-06-08T02:35:11Z

This PR supersedes #6514

Console logger support for IncludeEvaluationPropertiesAndItems.

Includes #6520, but we can take this commit out if it's merged separately.

OutputItems was pretty much duplicated in ParallelConsoleLogger. Unify with the base implementation and extract methods that need to be replaced by the derived type.

Support for reading project configuration description either from ProjectStartedEventArgs.Items or ProjectEvaluationFinishedEventArgs.Items.

Skip TestItemsWithUnexpandableMetadata. Issue #6518 is tracking. More work is needed to understand the desired behavior of the system under test and then fix the test to test the desired behavior.

Skip NullMetadataOnLegacyOutputItems_InlineTask. The feature the test is testing is broken, but the test passes because it doesn't specify diag verbosity for its logger. We will only log task outputs with diag verbosity. Issue #6521 is tracking.

Opt test out of LogPropertiesAndItemsAfterEvaluation. OutOfProcNodeForwardCertainproperties is explicitly testing a feature where only some properties are forwarded from a different process on ProjectStartedEventArgs. When we move properties to ProjectEvaluationFinished the test loses meaning. So force it into the old behavior via an escape hatch.

Forgind

I think this should work, though some of the unification with BaseConsoleLogger was hard to follow. Most worried about the possible NRE.

Forgind · 2021-06-08T15:23:34Z

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

+                    _includeEvaluationPropertiesAndItems = sinks.Any() && sinks.All(sink => sink.IncludeEvaluationPropertiesAndItems);
+                }
+
+                return _includeEvaluationPropertiesAndItems ?? false;


Is it possible for it to still be null here?

sorry what? the nullable? no, it will be assigned to a boolean on line 523, but that doesn't convince the compiler, so I had to add ?? false to convert the bool? to bool

Ok, glad I wasn't missing something. You should be able to just add ! instead.

No, I don't think the bang will work to convert bool? to bool:
https://sharplab.io/#v2:C4LghgzsA0AmIGoA+ABATARgLACgUGYACdQgYUIG9dCbiiUAWQgWQAoBKS62ngIwHt+AGwD8hXoQC8hAHYBXIUIDc3HjQHDxaKeMIixAMzBCIAUxU41tDUPFFpvAIQWeAX1yugA=

<confusion>
I thought that was exactly what the bang was supposed to do. Ah, well.

ah, I see :) The bang is used to force Nullable Reference Types (the new hotness), but ?? x is used to convert a nullable Value Type to the underlying value type. Nullable value types (Nullable) was introduced way back in C# 2 in 2005

src/Build/Logging/BaseConsoleLogger.cs

Forgind · 2021-06-08T17:31:17Z

src/Build/Logging/BaseConsoleLogger.cs

-                    }
-                    catch (InvalidProjectFileException e)
+                    IMetadataContainer metadataContainer => metadataContainer.EnumerateMetadata(),
+                    IItem<ProjectMetadata> iitem => iitem.Metadata?.Select(m => new KeyValuePair<string, string>(m.Name, m.EvaluatedValue)),


This looks cleaner, but I'd curious about whether you can inline this to avoid allocating an IEnumerable. Probably not because of the null unless you wanted it really messy.

Also, do you need to unescape the value?

not sure about inlining

good question about unescaping, need to see whether the values on iitem.Metadata are already unescaped...

Forgind · 2021-06-08T17:34:18Z

src/Build/Logging/BaseConsoleLogger.cs

+
+        protected virtual void WriteItemSpec(string itemSpec)
+        {
+            WriteLinePretty("    " + itemSpec);


Just to check—this will not allocate the string of spaces every time, right?

it won't allocate the string literal, but it will allocate the string for the concatenated total, and it's terrible.

Fortunately we may have an intern this summer who may help look into rewriting the console loggers to avoid allocations.

Forgind · 2021-06-10T19:22:57Z

src/Build/Logging/ParallelLogger/ParallelConsoleLogger.cs

@@ -540,20 +540,38 @@ public override void ProjectStartedHandler(object sender, ProjectStartedEventArg
                }
            }

-            ReadProjectConfigurationDescription(e.BuildEventContext, e.Items);
+            var projectKey = (e.BuildEventContext.NodeId, e.BuildEventContext.ProjectContextId);


Can e.BuildEventContext be null here?

No, BuildEventContext should always be set

OutOfProcNodeForwardCertainproperties is explicitly testing a feature where only some properties are forwarded from a different process on ProjectStartedEventArgs. When we move properties to ProjectEvaluationFinished the test loses meaning. So force it into the old behavior via an escape hatch.

The feature the test is testing is broken, but the test passes because it doesn't specify diag verbosity for its logger. We will only log task outputs with diag verbosity. Issue #6521 is tracking.

Issue #6518 is tracking. More work is needed to understand the desired behavior of the system under test and then fix the test to test the desired behavior.

Call IEventSource4.IncludeEvaluationPropertiesAndItems() OutputItems was pretty much duplicated in ParallelConsoleLogger. Unify with the base implementation and extract methods that need to be replaced by the derived type. Support for reading project configuration description either from ProjectStartedEventArgs.Items or ProjectEvaluationFinishedEventArgs.Items.

rainersigwald

Looks reasonable to me.

On the larger issue, I have a thought; I bet you can explain why it's bad. Could we log the data in both places, but only have the binlog record it at end-of-evaluation? And when replaying a binlog read it from the correlated end-of-evaluation to the ProjectStarted?

KirillOsenkov · 2021-06-21T21:34:25Z

It's actually a reasonable thought. I don't see why it would be bad, perhaps it's worth implementing.

Remember though you'll only get the properties and items on ProjectStarted in the central node, since they are not serialized across. But it would achieve backwards compatibility (parity with what it used to be). Perhaps I should have built it this way to begin with!

The other question is combined with the other workarounds we've built, is it necessary anymore?

KirillOsenkov · 2021-06-21T21:35:54Z

One thing that comes to mind is populating properties and items on ProjectStarted would decrease performance and increase allocations (since we would be walking the expensive data structures and copy-on-writing). So we'd lose some of those hard-won perf wins that we so tightly optimized.

KirillOsenkov requested review from rainersigwald and Forgind June 8, 2021 02:35

KirillOsenkov mentioned this pull request Jun 8, 2021

Only log properties and items on evaluation if ALL loggers support it #6514

Closed

Forgind reviewed Jun 10, 2021

View reviewed changes

Forgind approved these changes Jun 11, 2021

View reviewed changes

KirillOsenkov added 4 commits June 15, 2021 15:21

Skip NullMetadataOnLegacyOutputItems_InlineTask

55be3a5

The feature the test is testing is broken, but the test passes because it doesn't specify diag verbosity for its logger. We will only log task outputs with diag verbosity. Issue #6521 is tracking.

Skip TestItemsWithUnexpandableMetadata

264a797

Issue #6518 is tracking. More work is needed to understand the desired behavior of the system under test and then fix the test to test the desired behavior.

KirillOsenkov force-pushed the dev/kirillo/loggers branch from 4d7c370 to c813836 Compare June 15, 2021 22:21

rainersigwald approved these changes Jun 21, 2021

View reviewed changes

KirillOsenkov mentioned this pull request Jun 25, 2021

Diagnostic build log not emitting properties anymore? #6609

Open

Forgind added the merge-when-branch-open PRs that are approved, except that there is a problem that means we are not merging stuff right now. label Jun 26, 2021

AR-May merged commit 78f0280 into main Jun 30, 2021

KirillOsenkov deleted the dev/kirillo/loggers branch July 1, 2021 02:07

KirillOsenkov mentioned this pull request Aug 31, 2021

MSBuild eval items only appear on first of multi-targeting inner-builds KirillOsenkov/MSBuildStructuredLog#531

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Console logger support for IncludeEvaluationPropertiesAndItems #6535

Console logger support for IncludeEvaluationPropertiesAndItems #6535

KirillOsenkov commented Jun 8, 2021

Forgind left a comment

Forgind Jun 8, 2021

KirillOsenkov Jun 10, 2021

Forgind Jun 10, 2021

KirillOsenkov Jun 11, 2021

Forgind Jun 11, 2021 •

edited

KirillOsenkov Jun 11, 2021

Forgind Jun 8, 2021

KirillOsenkov Jun 10, 2021

Forgind Jun 8, 2021

KirillOsenkov Jun 10, 2021

Forgind Jun 10, 2021

KirillOsenkov Jun 10, 2021

rainersigwald left a comment

KirillOsenkov commented Jun 21, 2021

KirillOsenkov commented Jun 21, 2021

Console logger support for IncludeEvaluationPropertiesAndItems #6535

Console logger support for IncludeEvaluationPropertiesAndItems #6535

Conversation

KirillOsenkov commented Jun 8, 2021

Forgind left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Forgind Jun 11, 2021 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

rainersigwald left a comment

Choose a reason for hiding this comment

KirillOsenkov commented Jun 21, 2021

KirillOsenkov commented Jun 21, 2021

Forgind Jun 11, 2021 •

edited