Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Allow disabling logging of task parameters and item metadata #5268

Merged
merged 3 commits into from
May 1, 2020

Conversation

KirillOsenkov
Copy link
Member

This enables fine-grained control over whether:

  • to log each parameter (whether input or output)
  • or whether to log item metadata for each ITaskItem[] parameter.

When LogTaskInputs is set the default behavior is still to log all parameters and all item metadata for ITaskItem[] parameters. Since this is very verbose and hurts performance without adding any useful information it is valuable to be able to turn this logging off in certain situations.

This approach allows controlling logging via setting simple properties or environment variables.

I've identified the specific tasks and parameters that we want to restrict logging for that would give us the most gains without losing any significant useful info:

https://github.com/KirillOsenkov/MSBuildStructuredLog/wiki/Task-Parameter-Logging

This enables fine-grained control over whether:

 * to log log each parameter (whether input or output)
 * or whether to log item metadata for each ITaskItem[] parameter.

When LogTaskInputs is set the default behavior is still to log all parameters and all item metadata for ITaskItem[] parameters. Since this is very verbose and hurts performance without adding any useful information it is valuable to be able to turn this logging off in certain situations.

This approach allows controlling logging via setting simple properties or environment variables.

I've identified the specific tasks and parameters that we want to restrict logging for that would give us the most gains without losing any significant useful info:

https://github.com/KirillOsenkov/MSBuildStructuredLog/wiki/Task-Parameter-Logging
@KirillOsenkov
Copy link
Member Author

This is the third alternative to #5235 and #5236.

I believe it's the least invasive and the most flexible and extensible option. One can use plain properties or environment variables defined anywhere and they will be respected if found. This doesn't require as much fundamental changes to the core of MSBuild like the other two approaches. This allows third parties to fully control and override the defaults we provide, either through environment or command line.

I thought about using items instead of properties because the syntax would be nicer:

  <ItemGroup>
    <DisableLogTaskParameter Include="RemoveDuplicates.Inputs" />
    <DisableLogTaskParameterItemMetadata Include="Copy.SourceFiles" />
  </ItemGroup>

However looking up an item would require fetching all items for each parameter, iterating over them to find a match. Items are inherently more expensive, with metadata and whatnot. Also one couldn't use environment variables or pass via command-line /p:foo=bar. Property lookup is faster, lighter weight and can be passed via environment or command-line.

@cdmihai
Copy link
Contributor

cdmihai commented Apr 17, 2020

Nice, I prefer this approach as well.

Regarding items vs properties, the problem of having to loop through items could be averted by building a lookup dictionary in TaskExecutionHost, but, as you said, one cannot set them from the cmd line. And those lookup dictionaries might get hairy. Since this is a niche feature and not a common use case, I find it okay to use the uglier looking properties. :)

@KirillOsenkov
Copy link
Member Author

I ran this on the Roslyn build and the binlog went down from 130 MB to 120 MB.

I'll see if I can turn off more logging to bring this down even further.

@KirillOsenkov
Copy link
Member Author

The viewer footprint after loading went from 3.7 GB to 2.9 GB. On even larger binlogs such as dotnet/runtime the difference will be even more drastic. I think folks loading large binlogs will appreciate.

@KirillOsenkov
Copy link
Member Author

KirillOsenkov commented Apr 26, 2020

I've identified a few more candidates to turn down logging of metadata:

  • ConvertToAbsolutePath.Paths
  • GenerateResource.References
  • JoinItems.Left
  • JoinItems.Right

After these we quickly hit the diminishing returns. Not sure if I should add these or should we just go with the original PR for now. We can always add stuff later.

@KirillOsenkov KirillOsenkov added Area: Logging Performance-Scenario-Build This issue affects build performance. labels Apr 27, 2020
string key = "DisableLogTaskParameter_" + taskAndParameterName;
string metadataKey = "DisableLogTaskParameterItemMetadata_" + taskAndParameterName;

if (string.Equals(lookup.GetProperty(key)?.EvaluatedValue, "true", StringComparison.OrdinalIgnoreCase))
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I feel like there has to be a cleaner way of doing this, but I don't know what it is. Makes me wish for Javascript, in which you can just pass a string, and it will automatically convert it to the relevant boolean.

In any case, it would probably be slightly cleaner to have something like:
parameter.Log = !string.Equals(...);

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If I do the string comparison inside the if, and it matches, it won't evaluate the else if expression.
If I just assign to .Log, both will be always evaluated.
Saving a few microseconds where I can ;)

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

But yes, I feel like there should be an extension method like lookup.IsPropertyTrue(key)

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm not sure whether it saves a few microseconds. Your way avoids accessing the property (and I don't know how long that takes). My way avoids branching, which can take a long time relative to just accessing a cached value. I'm guessing you're right, since these methods are rarely simple, and users will probably normally have a lot of properties.

Also, the lookup.IsPropertyTrue method should be easy to make. See:
Forgind@fa2f35c

src/Tasks/Microsoft.Common.props Outdated Show resolved Hide resolved
@Forgind
Copy link
Member

Forgind commented Apr 29, 2020

I have a very weak preference for putting the other optimizations in a separate PR just because it makes it easier to see what changes are related to what optimizations, but I could be swayed in the other direction, especially because more PRs means more opportunities for flaky failures.

@KirillOsenkov
Copy link
Member Author

Hmm, I feel like this PR is cohesive, meaning there isn't anything you can move out to a separate PR. Unless I'm missing anything?

@Forgind
Copy link
Member

Forgind commented Apr 29, 2020

Oh, yes, this PR is cohesive. I meant these:
ConvertToAbsolutePath.Paths
GenerateResource.References
JoinItems.Left
JoinItems.Right

@KirillOsenkov
Copy link
Member Author

Ah, got it. Yes, absolutely, I was on the fence about those myself.

I'll just be happy to land this as-is.

@KirillOsenkov
Copy link
Member Author

Roslyn build with this change goes down from 10:01 minutes to 9:45 minutes.

Co-authored-by: Rainer Sigwald <raines@microsoft.com>
@rainersigwald rainersigwald merged commit c7c447b into dotnet:master May 1, 2020
Forgind added a commit that referenced this pull request May 4, 2020
* LOC CHECKIN | microsoft/msbuild vs16.6 | 20200420 (#5299)

* Final branding_16.6 (#5273)

* merge

* Enable handshake timeout on Mono (#5318)

I am seeing consistent test hangs on macOS Mono. A node is getting into a bad state and is failing to respond to handshakes. While I do not yet understand the root cause, it is clear that having a timeout on the handshake operation mitigates the issue. The test is now failing but does not hang, saving developer time as well as test pipeline resources.

* Revert "Reverted and rebuilt for localizable strings." (#5246)

This adds back support for logging an error when a task returns false
without logging an error. This was originally added in #4940 but was
reverted because of multiple difficulties.

* Changed error code

* Add escape hatch

* Fix typo

* Filtering for duplicate content files with referencing projects (#4931)

* Updating content filtering based on content copying changes

* Add a flag that is enabled by default on Core; otherwise disabled by default.

* Adding Shutdown Message to Worker Nodes (#5262)

* Changed where Trace is being called and removed old functionality.

* Updating .NET Core branding to .NET (#5286)

* Override default Arcade Xunit configuration (#5302)

* Update Directory.Build.targets

* prevent arcade from injecting its own xunit file

* Don't log @(ReferencePath) at the end of ImplicitlyExpandDesignTimeFacades (#5317)

The actual ItemGroups inside the target already do a good job of logging exactly what items were added and/or removed and in what order and with what metadata.

Emitting an extra low-pri message which is unstructured here just adds noise, slows the builds down, wastes binlog space and is otherwise redundant.

* Compute hashes in parallel in GetFileHash (#5303)

* Compute hashes in parallel. This scales better for larger number of files.

* Use a dedicated write lock

* Allow disabling logging of task parameters and item metadata (#5268)

This enables fine-grained control over whether:

 * to log log each parameter (whether input or output)
 * or whether to log item metadata for each ITaskItem[] parameter.

When LogTaskInputs is set the default behavior is still to log all parameters and all item metadata for ITaskItem[] parameters. Since this is very verbose and hurts performance without adding any useful information it is valuable to be able to turn this logging off in certain situations.

This approach allows controlling logging via setting simple properties or environment variables.

I've identified the specific tasks and parameters that we want to restrict logging for that would give us the most gains without losing any significant useful info:

https://github.com/KirillOsenkov/MSBuildStructuredLog/wiki/Task-Parameter-Logging

* Update dependencies from https://github.com/dotnet/arcade build 20200430.5 (#5325)

- Microsoft.DotNet.Arcade.Sdk: 1.0.0-beta.20221.2 -> 1.0.0-beta.20230.5

Co-authored-by: dotnet-maestro[bot] <dotnet-maestro[bot]@users.noreply.github.com>

* Use environment variable for handshake Resolves #4961 (#5196)

* Use environment variable for handshake Resolves #4961

* Combine means of hashing

* Support transitive project references in static graph (#5326)

Transitive project references are a thing now. Added support to static graph, so that buildxl and qb can avoid adding the transitive refs.
This PR is independent of #5222. Ideally, review this one first, as QB has a stronger dependency on this PR than on #5222.

Design

- transitive references are opt-in, per project evaluation
- once a project opts-in, transitivity is applied for all ProjectReference items
- a project opt-ins by setting the property AddTransitiveProjectReferencesInStaticGraph to true. The sdk does this automatically in Microsoft.Managed.After.Targets.
- interaction with crosstargeting: transitive refs are added only to inner builds, not the outer builds. This mimics vanilla msbuild.

Co-authored-by: Rainer Sigwald <raines@microsoft.com>

Co-authored-by: Martin Chromecek (Moravia IT) <v-chmart@microsoft.com>
Co-authored-by: Ladi Prosek <laprosek@microsoft.com>
Co-authored-by: Sarah Oslund <sfoslund@microsoft.com>
Co-authored-by: Ben Villalobos <villalobosb93@gmail.com>
Co-authored-by: Mihai Codoban <codobanmihai@gmail.com>
Co-authored-by: Kirill Osenkov <KirillOsenkov@users.noreply.github.com>
Co-authored-by: Pranav K <prkrishn@hotmail.com>
Co-authored-by: dotnet-maestro[bot] <42748379+dotnet-maestro[bot]@users.noreply.github.com>
Co-authored-by: dotnet-maestro[bot] <dotnet-maestro[bot]@users.noreply.github.com>
Co-authored-by: Rainer Sigwald <raines@microsoft.com>
sfoslund pushed a commit to sfoslund/msbuild that referenced this pull request May 15, 2020
…5268)

This enables fine-grained control over whether:

 * to log log each parameter (whether input or output)
 * or whether to log item metadata for each ITaskItem[] parameter.

When LogTaskInputs is set the default behavior is still to log all parameters and all item metadata for ITaskItem[] parameters. Since this is very verbose and hurts performance without adding any useful information it is valuable to be able to turn this logging off in certain situations.

This approach allows controlling logging via setting simple properties or environment variables.

I've identified the specific tasks and parameters that we want to restrict logging for that would give us the most gains without losing any significant useful info:

https://github.com/KirillOsenkov/MSBuildStructuredLog/wiki/Task-Parameter-Logging
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Area: Logging Performance-Scenario-Build This issue affects build performance.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants