Adding tracking of properties with relevant events. #4461

maneely · 2019-06-21T21:11:52Z

Description

This change introduces opt-in functionality that will track property usage and generate three events:

Environment Variables Read (new)
Uninitialized Properties Read (new)
Property Reassigned (already exists)

Opt-in is via the environment variable, MSBuildLogPropertyTracking=1.

It's implemented via a new class named PropertyTrackingEvaluatorDataWraper that implements IEvaluatorData<> and wraps the Evaluator's instance of IEvaluatorData<> to intercept get and set property calls.

Resolves #3432
Related to #2713

Customer Impact

BuildXL needs to know what environment variables took part in a build to correctly generate a graph. Without this functionality, environment variables that modify the graph will not be properly detected which will produce incorrect cache hits.

Regression?

No

Risk

Low risk, net new functionality which is opt-in. Performance testing shows no impact with these changes.

Test changes in this PR

New unit tests

src/Framework/EnvironmentVariableReadEventArgs.cs

src/Build/Evaluation/Evaluator.cs

src/Build/Evaluation/PropertyTrackingEvaluatorDataWrapper.cs

src/Build/Evaluation/Evaluator.cs

src/Build/Logging/BinaryLogger/BuildEventArgsWriter.cs

src/Build/Logging/BinaryLogger/BinaryLogRecordKind.cs

src/Build.UnitTests/Evaluation/Evaluator_Tests.cs

src/Build/Logging/BinaryLogger/BinaryLogger.cs

AndyGerlicher · 2019-06-26T20:43:13Z

@KirillOsenkov FYI

rainersigwald · 2019-07-02T20:43:42Z

Some big questions before diving into the details:

Does this really need to be opt-in? I expected these to be produced all the time. Is the tracking extremely expensive?
Did you investigate the scope option we discussed earlier? Why did you go this different route?

maneely · 2019-07-02T20:58:22Z

For opt-in, we didn't want each project to be storing a hashset of up to 1K properties each for this. This includes not just environment reads, but reads of uninitialized properties and it adds up.

For scope, we never discussed what you meant by "Build a scope environment" in our mail thread. I asked for clarification but didn't receive a response. In the meantime, @jeffkl , @cdmihai , @AndyGerlicher , @smera , and I contributed to what you see here. Can you explain what you had in mind?

rainersigwald · 2019-07-02T21:46:38Z

I think using the existing scope mechanisms would resolve the impact-of-tracking concerns, especially if the uninitialized-property code follows the existing flag.

MSBuild doesn't have much notion of a scope, since all properties and items within a project are accessible almost all the time. But there is one:

https://github.com/microsoft/msbuild/blob/404539a96a51ab801862fefad5e987ee6b93e9ec/src/Build/BackEnd/Components/RequestBuilder/Lookup.cs#L20-L54

The actual Scope is later but that comment is much more informative:

https://github.com/microsoft/msbuild/blob/404539a96a51ab801862fefad5e987ee6b93e9ec/src/Build/BackEnd/Components/RequestBuilder/Lookup.cs#L1290

It's not clear to me offhand whether that can be directly used at evaluation time, or a separate related implementation would be required.

src/Build.UnitTests/Evaluation/Evaluator_Tests.cs

src/Build/Logging/BinaryLogger/BinaryLogger.cs

rainersigwald

Am I correct that the current state is that this is opt-in via environment variable only, and thus that it removes reassignment-tracking from the non-opted-in binlog case?

src/Build.UnitTests/Evaluation/Evaluator_Tests.cs

src/Build/Definition/Project.cs

rainersigwald · 2019-07-29T17:03:14Z

src/Build/Evaluation/PropertyTrackingEvaluatorDataWrapper.cs

This check seems good, but is the described behavior a bug, @cdmihai?

src/Build/Logging/BinaryLogger/BinaryLogRecordKind.cs

src/Build/Resources/Strings.resx

rainersigwald

Let's turn this on, and consider turning it on by default when the binlog is on in a subsequent build, after perf measurement.

edgarrs · 2019-08-07T20:46:25Z

AB#1550971

….Data.

Co-Authored-By: Rainer Sigwald <[email protected]>

…ogger settings are more discrete.

… once.

Failing test: ``` Microsoft.Build.UnitTests.Evaluation.EvaluationLogging_Tests.GivenOneProjectThereShouldBeOneStartedAndOneEndedEvent [FAIL] Shouldly.ShouldAssertException : Shouldly uses your source code to generate its great error messages, build your test project with full debug information to get better error messages The provided expression should start with "Evaluation started" but was "Property reassignment: $(MSBuildFrameworkToolsRoot)="\Microsoft.NET\Framework\" (previous value: "/Library/Frameworks/Mono.framework/Versions/6.4.0/lib/mono") at " Stack Trace: at Shouldly.ShouldlyCoreExtensions.AssertAwesomely[T] (T actual, System.Func`2[T,TResult] specifiedConstraint, System.Object originalActual, System.Object originalExpected, System.Func`1[TResult] customMessage, System.String shouldlyMethod) [0x00056] in <cd631af7e9d7403ea1721c3ce03185bf>:0 at Shouldly.ShouldBeStringTestExtensions.ShouldStartWith (System.String actual, System.String expected, System.Func`1[TResult] customMessage, Shouldly.Case caseSensitivity) [0x00014] in <cd631af7e9d7403ea1721c3ce03185bf>:0 at Shouldly.ShouldBeStringTestExtensions.ShouldStartWith (System.String actual, System.String expected) [0x00000] in <cd631af7e9d7403ea1721c3ce03185bf>:0 at Microsoft.Build.UnitTests.Evaluation.EvaluationLogging_Tests+<>c.<GivenOneProjectThereShouldBeOneStartedAndOneEndedEvent>b__4_0 (Microsoft.Build.Evaluation.Project project, Microsoft.Build.UnitTests.MockLogger firstEvaluationLogger) [0x00033] in <559c19036a814aa4b96da7f3191f05ee>:0 at Microsoft.Build.UnitTests.Evaluation.EvaluationLogging_Tests.AssertLoggingEvents (System.Action`2[T1,T2] loggingTest, Microsoft.Build.UnitTests.MockLogger firstEvaluationLogger, System.Func`2[T,TResult] reevaluationLoggerFactory) [0x000d3] in <559c19036a814aa4b96da7f3191f05ee>:0 at Microsoft.Build.UnitTests.Evaluation.EvaluationLogging_Tests.GivenOneProjectThereShouldBeOneStartedAndOneEndedEvent () [0x00009] in <559c19036a814aa4b96da7f3191f05ee>:0 at (wrapper managed-to-native) System.Reflection.RuntimeMethodInfo.InternalInvoke(System.Reflection.RuntimeMethodInfo,object,object[],System.Exception&) at System.Reflection.RuntimeMethodInfo.Invoke (System.Object obj, System.Reflection.BindingFlags invokeAttr, System.Reflection.Binder binder, System.Object[] parameters, System.Globalization.CultureInfo culture) [0x0006a] in <b60d3e0e49a1407283b1fb67d86fa164>:0 ``` Recent commit: ``` commit 7150dc9 Author: Matt Neely <[email protected]> Date: Mon Aug 19 13:59:31 2019 -0700 Adding tracking of properties with relevant events. (dotnet#4461) ... ``` .. changed how property changes get logged, causing this to show up in the logs, when running the test on mono: ``` Property reassignment: $(MSBuildFrameworkToolsRoot)="\Microsoft.NET\Framework\" (previous value: "/Library/Frameworks/Mono.framework/Versions/6.4.0/lib/mono") at ``` .. before the `Evaluation started` line, causing the test to break. Instead of making assumptions about the exact message strings, we can check for exactly the events that we are interested in - `ProjectEvaluationStartedEvent` and `ProjectEvaluationFinishedEvent`.

Failing test: ``` Microsoft.Build.UnitTests.Evaluation.EvaluationLogging_Tests.GivenOneProjectThereShouldBeOneStartedAndOneEndedEvent [FAIL] Shouldly.ShouldAssertException : Shouldly uses your source code to generate its great error messages, build your test project with full debug information to get better error messages The provided expression should start with "Evaluation started" but was "Property reassignment: $(MSBuildFrameworkToolsRoot)="\Microsoft.NET\Framework\" (previous value: "/Library/Frameworks/Mono.framework/Versions/6.4.0/lib/mono") at " Stack Trace: at Shouldly.ShouldlyCoreExtensions.AssertAwesomely[T] (T actual, System.Func`2[T,TResult] specifiedConstraint, System.Object originalActual, System.Object originalExpected, System.Func`1[TResult] customMessage, System.String shouldlyMethod) [0x00056] in <cd631af7e9d7403ea1721c3ce03185bf>:0 at Shouldly.ShouldBeStringTestExtensions.ShouldStartWith (System.String actual, System.String expected, System.Func`1[TResult] customMessage, Shouldly.Case caseSensitivity) [0x00014] in <cd631af7e9d7403ea1721c3ce03185bf>:0 at Shouldly.ShouldBeStringTestExtensions.ShouldStartWith (System.String actual, System.String expected) [0x00000] in <cd631af7e9d7403ea1721c3ce03185bf>:0 at Microsoft.Build.UnitTests.Evaluation.EvaluationLogging_Tests+<>c.<GivenOneProjectThereShouldBeOneStartedAndOneEndedEvent>b__4_0 (Microsoft.Build.Evaluation.Project project, Microsoft.Build.UnitTests.MockLogger firstEvaluationLogger) [0x00033] in <559c19036a814aa4b96da7f3191f05ee>:0 at Microsoft.Build.UnitTests.Evaluation.EvaluationLogging_Tests.AssertLoggingEvents (System.Action`2[T1,T2] loggingTest, Microsoft.Build.UnitTests.MockLogger firstEvaluationLogger, System.Func`2[T,TResult] reevaluationLoggerFactory) [0x000d3] in <559c19036a814aa4b96da7f3191f05ee>:0 at Microsoft.Build.UnitTests.Evaluation.EvaluationLogging_Tests.GivenOneProjectThereShouldBeOneStartedAndOneEndedEvent () [0x00009] in <559c19036a814aa4b96da7f3191f05ee>:0 at (wrapper managed-to-native) System.Reflection.RuntimeMethodInfo.InternalInvoke(System.Reflection.RuntimeMethodInfo,object,object[],System.Exception&) at System.Reflection.RuntimeMethodInfo.Invoke (System.Object obj, System.Reflection.BindingFlags invokeAttr, System.Reflection.Binder binder, System.Object[] parameters, System.Globalization.CultureInfo culture) [0x0006a] in <b60d3e0e49a1407283b1fb67d86fa164>:0 ``` Recent commit: ``` commit 7150dc9 Author: Matt Neely <[email protected]> Date: Mon Aug 19 13:59:31 2019 -0700 Adding tracking of properties with relevant events. (dotnet#4461) ... ``` .. changed how property changes get logged, causing the following to show up in the logs, when running the test on mono: ``` Property reassignment: $(MSBuildFrameworkToolsRoot)="\Microsoft.NET\Framework\" (previous value: "/Library/Frameworks/Mono.framework/Versions/6.4.0/lib/mono") at ``` .. before the `Evaluation started` line, causing the test to break. Instead of making assumptions about the exact message strings, we can check for exactly the events that we are interested in - `ProjectEvaluationStartedEvent` and `ProjectEvaluationFinishedEvent`.

This reverts commit 7150dc9.

…4663) This reverts commit 7150dc9. This caused MSBuild to allocate a lot more during evaluation and is failing RPS tests in the MSBuild insertion into VS. Without reverting this change, we won't be able to insert into VS.

…otnet#4461)" (dotnet#4663)" This reverts commit faf5e5d.

…otnet#4461)" (dotnet#4663)" This reverts commit faf5e5d. Fixing merge error in a comment. Fix another merge issue. Merge fix.