msbuild icon indicating copy to clipboard operation
msbuild copied to clipboard

Log how properties are initially assigned

Open KirillOsenkov opened this issue 8 years ago • 15 comments

See request here: https://github.com/KirillOsenkov/MSBuildStructuredLog/issues/133

We log when properties are reassigned when they already had a value, but it would be useful to specify how a property was initially assigned - from an environment variable, from /p:, from evaluation (and which location exactly) or from building (which target, task etc).

PropertyAssignmentSource or something.

KirillOsenkov avatar Nov 09 '17 18:11 KirillOsenkov

Yes pretty please! Your log viewer is just an indispensable tool, thank you very much for it! But I lamented not once being unable to figure out where the initial value of a property is coming from.

kkm000 avatar Dec 10 '17 00:12 kkm000

Sounds reasonable. Until this is implemented, I usually use a preprocessed project, searching from the top for <PropertyName to see where it could have gotten assigned.

rainersigwald avatar Feb 15 '18 23:02 rainersigwald

This seems to be working now: export MsBuildLogPropertyTracking=3.

iii-i avatar Jul 06 '22 14:07 iii-i

Implementing this is likely to cause a huge perf overhead (but needs to be measured to confirm). Like Rainer says, the workaround is to preprocess the project and search for the <PropertyName in the preprocessed text. Binlog viewer supports the Preprocess command on any project.

However I think we could implement logging cheaply for some special cases (where we don't have it already):

  1. property coming from a command-line argument (e.g. /p:)
  2. property coming from environment (another PR already in progress that should solve this)
  3. as an output of a target
  4. as an output of a task
  5. from a PropertyGroup inside a target

basically everything but evaluation. I'm worried that logging every property initial assignment for every evaluation will result in way too much new logging args and allocations and create a lot of noise too. I think preprocessor gives a reasonable alternative for those.

KirillOsenkov avatar Jul 06 '22 17:07 KirillOsenkov

@JanKrivanek @AR-May @rokonec @rainersigwald not logging initial assignment for properties and items during evaluation continues to be a huge pain point. Normally binlogs are great, but not having this information often leaves us in the dark and guessing.

I think there's some disabled code from at least two past attempts, as well as event args ready to use such as PropertyInitialValueSetEventArgs. I think it would be nice to build a prototype and see how much it slows the build down as well as how does this impact the binlog size. Maybe our fears are unfounded and the overhead will be negligible?

Checklist for what would be nice:

  • [ ] PropertyInitialValueSetEventArgs for properties assigned during evaluation, contain location in the XML where the assignment happened (inside a <PropertyGroup> presumably)
  • [ ] TaskParameterEventArgs of type TaskParameterMessageKind.AddItem/RemoveItem - has the item list as well as metadata and the location in XML where it happened during initial evaluation.

Both of these would be logged during evaluation.

KirillOsenkov avatar Jan 18 '24 22:01 KirillOsenkov

I suspect we'll also want these events for analyzers (rules like "don't set property X in context Y" or "never set property Q to value Z").

rainersigwald avatar Jan 18 '24 22:01 rainersigwald

Let's use some structured info (not a textual info in BuildMessageEventArgs etc.). We possibly might reuse PropertyReassignmentEventArgs (where previous value is null) - but probably not a good idea as Viewer and other things might already have some assumptions

JanKrivanek avatar Feb 19 '24 12:02 JanKrivanek

we do have the (unused) structured events already, see my comment above

KirillOsenkov avatar Feb 19 '24 14:02 KirillOsenkov

@KirillOsenkov , @rainersigwald , @JanKrivanek could you clarify these points? Before reusing the unused structured events, should I measure the perf impact? Or are we ready to have it at any price? Should these events be an opt-in thing or emitted always?

YuliiaKovalova avatar Feb 21 '24 10:02 YuliiaKovalova

I'd say let's build a prototype and gather some data on the impact to build perf and binlog size, for small and large builds

KirillOsenkov avatar Feb 21 '24 10:02 KirillOsenkov

+1 on prototyping and then measuring on a reasonably sized project (OrchardCore e.g.)

If there is a measurable difference in overall build time and binlog size, then we can think about couple possible optimizations (e.g. the info can be probably be groupped into single message for a single project evaluation, it can possibly be opt-in only similar to requiring MSBUILDLOGPROPERTIESANDITEMSAFTEREVALUATION for props/items values in ProjectEvaluationFinishedEventArgs - though this particular one has very minimum impact when opted in)

JanKrivanek avatar Feb 21 '24 11:02 JanKrivanek

As noted in one of the older messages above, this feature already exists and can be enabled by setting MsBuildLogPropertyTracking. Just wanted to point it out so it doesn't get lost. It looks like it just needs location info added to PropertyInitialValueSetEventArgs.

ladipro avatar Feb 21 '24 14:02 ladipro

Right; there have been at least two attempts to do this, and both were either backed out or disabled. We need to do some archeology to understand what happened and dig through the old PRs.

KirillOsenkov avatar Feb 21 '24 16:02 KirillOsenkov

Right; there have been at least two attempts to do this, and both were either backed out or disabled. We need to do some archeology to understand what happened and dig through the old PRs.

Sounds good! I will approach it at the beginning of March . Thank you for the details.

YuliiaKovalova avatar Feb 21 '24 16:02 YuliiaKovalova