Extend property assignment event (The feature is opted-out by default) #11106

YuliiaKovalova · 2024-12-06T16:15:02Z

Fixes #2711
and connected to KirillOsenkov/MSBuildStructuredLog#839

Context

The feature is opted-out by default due to perf considerations !
This implementation covers cases:

property coming from a command-line argument (e.g. /p:) (previously had a Global source)
as an output of a target
as an output of a task
exact property location if it comes from xml during evaluation

Also, the message formatting logic was changed for PropertyReassignmentEventArgs and PropertyInitialValueSetEventArgs to have it optimized for existing deduplication logic.
The event save all the unique data and format it on the receiving side (e.g. LogViewer).

The measurements were taken for the latest OrchardCode

	No property init/reassignment logged	Property init/reassignment logged
Binlog Size	162.932 KB	196.269 KB
Build Time	533.4s	579.0s
BinLog allocations	Total opening time: 1:00.416, Loading: 27.490 s, Analyzing: 7.036 s, Indexing: 21.540 s, Reading files: 400 ms, Allocated: 35,920,765,696 bytes, Nodes: 219,551,777, Strings: 436,574	Total opening time: 1:28.087, Loading: 39.449 s, Analyzing: 6.991 s, Indexing: 37.275 s, Reading files: 403 ms, Allocated: 39,507,530,416 bytes, Nodes: 224,560,814, Strings: 489,542

Conclusions:

Metric	Analysis
Binlog Size	The binlog size increased from 162.932 KB to 196.269 KB, an increase of about 20%.
Build Time	The build time increased from 533.4s to 579.0s, an increase of approximately 8.5%.
BinLog allocations	Memory Allocation: Increased from ~35.9 GB to ~39.5 GB (+10% memory usage), Node and String Count: Nodes increased by 2.3% and Strings increased by 12.1%, Loading time increased significantly (from 27.5s to 39.4s), Indexing time increased (from 21.5s to 37.3s)

…ops in targets/tasks

…gic on bin log side

JanKrivanek

I have couple comments to consider.

The main thing before signoff - this is currently not a default behavior (neither with /bl) - correct? Property tracking needs to be explicitly opted in - right?
Please add that info into the PR description (as otherwise the 8.5% perf hit might be bit concerning and might need a bit more deeper look)

src/Build/Evaluation/Evaluator.cs

src/Shared/EnumUtilities.cs

src/Build/BackEnd/Components/RequestBuilder/IntrinsicTasks/PropertyGroupIntrinsicTask.cs

Co-authored-by: Jan Krivanek <[email protected]>

KirillOsenkov · 2025-01-22T02:27:06Z

How do I enable the feature for testing? What setting value did you use for perf testing?

KirillOsenkov · 2025-01-22T02:39:19Z

src/Build/Logging/BinaryLogger/BuildEventArgsReader.cs

@@ -1176,7 +1176,9 @@ private BuildEventArgs ReadPropertyReassignmentEventArgs()
                propertyName,
                previousValue,
                newValue,
-                location,
+                fields.File,


In the Reader we can't change the logic without also checking the version. Because if we're reading an old binlog, this is going to read corrupt data.

You can add if (version >= 25) ... read new stuff, otherwise leave the current logic

You changed the reader to read the File, Line and Column separately, but the writer still writes Location as a single string

KirillOsenkov · 2025-01-22T02:40:21Z

src/Build/Logging/BinaryLogger/BuildEventArgsWriter.cs

@@ -567,11 +567,12 @@ private BinaryLogRecordKind Write(CriticalBuildMessageEventArgs e)

        private BinaryLogRecordKind Write(PropertyReassignmentEventArgs e)
        {
-            WriteMessageFields(e, writeMessage: false, writeImportance: true);
+            WriteMessageFields(e, writeMessage: true, writeImportance: true);


why is this changing to true?

previously, the message was provided by logviewer resources.
In this PR I attempted to pass a localized Message from MSBuild

KirillOsenkov · 2025-01-22T02:50:47Z

I'm seeing something weird, and it's not because of your PR.

Location for property reassignment is being logged as null, so the property reassignment messages end up looking like this:

But with your PR the location is there:

I don't understand what's going on.

KirillOsenkov · 2025-01-22T02:58:30Z

There are two things I did to investigate the binlog size increase:

use File -> Statistics in the viewer, then right-click on the Statistics node (the last one in the tree) and click Copy children, then diff for an old binlog and new binlog
under Statistics -> Strings, expand and select the only node under Strings, then press Space (this will view all the strings in the text editor) - diff those, I notice a lot of new strings with this change (primarily strings for file, line and column appended) - these shouldn't be added

For diffing, pick a simple console application, and do an incremental build (not clean build), setting MsBuildLogPropertyTracking to the right value. What is the default value for it currently? Why are property reassignment messages even logged when the value is 0 (the current default)?

KirillOsenkov · 2025-01-22T03:07:40Z

Ah, I see:

msbuild/src/Build/Evaluation/PropertyTrackingEvaluatorDataWrapper.cs

Lines 320 to 323 in 4042363

    
           // Either we want to specifically track property reassignments 
        
           // or we do not want to track nothing - in which case the prop reassignment is enabled by default. 
        
           if ((_settings & PropertyTrackingSetting.PropertyReassignment) == PropertyTrackingSetting.PropertyReassignment || 
        
               (_settings == 0 && ChangeWaves.AreFeaturesEnabled(ChangeWaves.Wave17_10)))

KirillOsenkov · 2025-01-22T03:17:59Z

I'm not quite sure, but I think we might have lost the location for property reassignment with #10102 (FYI @JanKrivanek)

KirillOsenkov · 2025-01-22T03:19:04Z

MSBuild 17.12 (the one I use) doesn't log PropertyReassignmentEventArgs, it logs a message, which the viewer than parses, and there is no location there

KirillOsenkov · 2025-01-22T03:23:04Z

Wait, no, I'm super confused. The location was only null for properties coming from toolset. For properties coming from XML the location is there and was passed as a string argument (one of 4 args). This is good, we have an opportunity to be better than the current state.

KirillOsenkov · 2025-01-22T03:25:28Z

src/Build/Evaluation/PropertyTrackingEvaluatorDataWrapper.cs

+                    location?.File,
+                    location?.Line ?? 0,
+                    location?.Column ?? 0,
+                    message: ResourceUtilities.GetResourceString("PropertyReassignment"))


why do we need this? I think we can leave the message null.

Even if we needed this, we could call GetResourceString once and cache it, since it never changes, and it's pretty expensive.

src/Build/Evaluation/PropertyTrackingEvaluatorDataWrapper.cs

KirillOsenkov · 2025-01-22T03:27:06Z

src/Build/Evaluation/PropertyTrackingEvaluatorDataWrapper.cs

+                location?.File,
+                location?.Line ?? 0,
+                location?.Column ?? 0,
+                ResourceUtilities.GetResourceString("PropertyAssignment"))


I'd avoid getting this string at all.

KirillOsenkov · 2025-01-22T03:28:04Z

src/Framework/PropertyInitialValueSetEventArgs.cs

+        {
+            get
+            {
+                var formattedSource = File != null ? $"{File} ({LineNumber},{ColumnNumber})" : PropertySource;


we probably want to cache this in case Message gets called multiple times, need to see what other EventArgs classes do when they override Message

We could get the string from resources here, since we know what string we want.

KirillOsenkov · 2025-01-22T03:29:01Z

src/Framework/PropertyReassignmentEventArgs.cs

-
-                return RawMessage;
+                string formattedLocation = File != null ? $"{File} ({LineNumber},{ColumnNumber})" : Location;
+                return string.Format(RawMessage, PropertyName, NewValue, PreviousValue, formattedLocation);


Same, look into caching the formatted result and look into getting the resource string here.

JanKrivanek · 2025-01-22T07:34:47Z

Wait, no, I'm super confused. The location was only null for properties coming from toolset. For properties coming from XML the location is there and was passed as a string argument (one of 4 args). This is good, we have an opportunity to be better than the current state.

Did we have the location for props comming from toolset before? Or is that regression?

YuliiaKovalova · 2025-01-22T10:09:55Z

How do I enable the feature for testing? What setting value did you use for perf testing?

please set MsBuildLogPropertyTracking=15

YuliiaKovalova added 3 commits December 6, 2024 16:41

add location to the initial property assignment event and tracking pr…

d9f7791

…ops in targets/tasks

extend condition

1988391

fix typo

c034187

YuliiaKovalova mentioned this pull request Dec 6, 2024

Extend PropertyInitialValueSetEventArgs and PropertyReassignmentEventArgs KirillOsenkov/MSBuildStructuredLog#839

Open

YuliiaKovalova added 7 commits December 9, 2024 14:50

add separate categorization of properties specified in command line

9de0ce2

fix null ref exception

b1ed4a4

fix invalid condition for property source

9bd143e

change the event content to get dedupe functionality

923e833

add extra ctor to PropertyReassignmentEventArgs to improve parsing lo…

bf37922

…gic on bin log side

change location formatting

7da96c3

adjust the tests to the code changes

e7f4df1

YuliiaKovalova marked this pull request as ready for review December 11, 2024 15:24

YuliiaKovalova requested a review from KirillOsenkov December 11, 2024 15:24

remove extra using

047bd55

YuliiaKovalova requested a review from rainersigwald December 11, 2024 15:44

Merge branch 'dotnet:main' into dev/ykovalova/property_assignment

b81fac7

JanKrivanek reviewed Jan 6, 2025

View reviewed changes

src/Build/Evaluation/Evaluator.cs Outdated Show resolved Hide resolved

src/Shared/EnumUtilities.cs Outdated Show resolved Hide resolved

src/Build/BackEnd/Components/RequestBuilder/IntrinsicTasks/PropertyGroupIntrinsicTask.cs Outdated Show resolved Hide resolved

Update src/Build/Evaluation/Evaluator.cs

6ed8628

Co-authored-by: Jan Krivanek <[email protected]>

YuliiaKovalova changed the title ~~Extend property assignment event~~ Extend property assignment event (The feature is opted-out by default) Jan 6, 2025

YuliiaKovalova mentioned this pull request Jan 6, 2025

Enum.ToString method is resulting in slow performance. Fix it. #11229

Merged

This was referenced Jan 8, 2025

Engineering improvements #11241

Open

dotnet test on .NET Framework test suite requires runtime identifier? microsoft/testfx#4469

Closed

Merge branch 'dotnet:main' into dev/ykovalova/property_assignment

05dad6d

KirillOsenkov reviewed Jan 22, 2025

View reviewed changes

src/Build/Evaluation/PropertyTrackingEvaluatorDataWrapper.cs Outdated Show resolved Hide resolved

KirillOsenkov reviewed Jan 22, 2025

View reviewed changes

YuliiaKovalova added 4 commits January 22, 2025 11:15

remove changewave check and enumutils

9964cb9

fix review comments

001d4e4

extra changes

fd197e3

apply renaming

ee7b601

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Extend property assignment event (The feature is opted-out by default) #11106

Extend property assignment event (The feature is opted-out by default) #11106

YuliiaKovalova commented Dec 6, 2024 •

edited

Loading

JanKrivanek left a comment

KirillOsenkov commented Jan 22, 2025

KirillOsenkov Jan 22, 2025

KirillOsenkov Jan 22, 2025

KirillOsenkov Jan 22, 2025

YuliiaKovalova Jan 22, 2025

KirillOsenkov commented Jan 22, 2025

KirillOsenkov commented Jan 22, 2025

KirillOsenkov commented Jan 22, 2025

KirillOsenkov commented Jan 22, 2025

KirillOsenkov commented Jan 22, 2025

KirillOsenkov commented Jan 22, 2025

KirillOsenkov Jan 22, 2025

KirillOsenkov Jan 22, 2025

KirillOsenkov Jan 22, 2025

KirillOsenkov Jan 22, 2025

KirillOsenkov Jan 22, 2025

JanKrivanek commented Jan 22, 2025

YuliiaKovalova commented Jan 22, 2025

Extend property assignment event (The feature is opted-out by default) #11106

Are you sure you want to change the base?

Extend property assignment event (The feature is opted-out by default) #11106

Conversation

YuliiaKovalova commented Dec 6, 2024 • edited Loading

Context

JanKrivanek left a comment

Choose a reason for hiding this comment

KirillOsenkov commented Jan 22, 2025

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

KirillOsenkov commented Jan 22, 2025

KirillOsenkov commented Jan 22, 2025

KirillOsenkov commented Jan 22, 2025

KirillOsenkov commented Jan 22, 2025

KirillOsenkov commented Jan 22, 2025

KirillOsenkov commented Jan 22, 2025

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

JanKrivanek commented Jan 22, 2025

YuliiaKovalova commented Jan 22, 2025

YuliiaKovalova commented Dec 6, 2024 •

edited

Loading