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.

Sign up for GitHub

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

Jump to bottom

Miscellaneous logging improvements #6326

Merged
merged 14 commits into from Apr 20, 2021
Merged

Miscellaneous logging improvements #6326

Show file tree
Hide file tree
Changes from 1 commit
Commits
Show all changes
14 commits
Select commit Hold shift + click to select a range
c09a537
Don't log BuildEventArgs.Message where it can be reconstructed.
KirillOsenkov Apr 5, 2021
c9b5e2e
Log TaskParameterEventArgs for inputs/outputs of TargetSkipped
KirillOsenkov Apr 5, 2021
ace9956
Do not allocate a single string for Task Parameter
KirillOsenkov Apr 5, 2021
66acffd
Do not log property reassignment for MSBuildAllProjects
KirillOsenkov Apr 5, 2021
b6540bc
Cache resource strings in RAR logging.
KirillOsenkov Apr 5, 2021
95021b1
Cache resource strings in the Copy task.
KirillOsenkov Apr 5, 2021
c191e15
Use named arguments.
KirillOsenkov Apr 5, 2021
da331c9
Add NOPERFORMANCESUMMARY switch for console loggers.
KirillOsenkov Apr 5, 2021
e270fea
Add TestLoggingForSkippedTargetInputsAndOutputs
KirillOsenkov Apr 5, 2021
6fea565
Compare console logs after binary logging roundtrip.
KirillOsenkov Apr 5, 2021
1de22cd
Add more coverage for console logs from binlog playback.
KirillOsenkov Apr 5, 2021
785ffa1
Fix test to work on unix.
KirillOsenkov Apr 5, 2021
2410c41
Fix typo: HelpHeyword -> HelpKeyword.
KirillOsenkov Apr 8, 2021
ca456ad
Add GetResourceEightSpaces
KirillOsenkov Apr 8, 2021
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
38 changes: 27 additions & 11 deletions src/Build/Evaluation/Evaluator.cs
View file
Open in desktop
Expand Up @@ -1201,7 +1201,7 @@ private void AddToolsetProperties()
// set the property even if there is no matching sub-toolset.
if (!_data.Properties.Contains(Constants.SubToolsetVersionPropertyName))
{
_data.SetProperty(Constants.SubToolsetVersionPropertyName, _data.SubToolsetVersion, false /* NOT global property */, false /* may NOT be a reserved name */);
_data.SetProperty(Constants.SubToolsetVersionPropertyName, _data.SubToolsetVersion, false /* NOT global property */, false /* may NOT be a reserved name */);
}

if (_data.Toolset.SubToolsets.TryGetValue(_data.SubToolsetVersion, out SubToolset subToolset))
Expand Down Expand Up @@ -1315,6 +1315,13 @@ private void LogPropertyReassignment(P predecessor, P property, string location)
string newValue = property.EvaluatedValue;
string oldValue = predecessor?.EvaluatedValue;

if (string.Equals(property.Name, "MSBuildAllProjects", 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.

This looks like it removes the MSBuildALlProjects property altogether, is that the case?

Copy link
Member Author

Choose a reason for hiding this comment

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

It doesn't log any property reassignment messages for MSBuildAllProjects, yes.

Copy link
Member

Choose a reason for hiding this comment

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

Just for clarity, MSBuildAllProjects isn't gone, and its final state is still logged; this only suppresses property reassignment.

{
// There's a huge perf cost to logging this and it increases the binlog size significantly.
// Meanwhile the usefulness of logging this is very low.
return;
}

if (newValue != oldValue)
{
_evaluationLoggingContext.LogComment(
Expand Down Expand Up @@ -1659,6 +1666,15 @@ private List<ProjectRootElement> ExpandAndLoadImports(string directoryOfImportin
return allProjects;
}

private static readonly string CouldNotResolveSdk = ResourceUtilities.GetResourceString("CouldNotResolveSdk");
Copy link
Member

Choose a reason for hiding this comment

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

Some of these (particularly looking at this one) sound like they wouldn't be logged more than ~once per project at most and often wouldn't be logged at all. For those cases, lazier sounds slightly more efficient.

Copy link
Member Author

Choose a reason for hiding this comment

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

At this scale it really doesn't matter. I didn't want to think too hard about which strings are rare.

private static readonly string ProjectImported = ResourceUtilities.GetResourceString("ProjectImported");
cdmihai marked this conversation as resolved.
Show resolved Hide resolved
private static readonly string ProjectImportSkippedEmptyFile = ResourceUtilities.GetResourceString("ProjectImportSkippedEmptyFile");
private static readonly string ProjectImportSkippedExpressionEvaluatedToEmpty = ResourceUtilities.GetResourceString("ProjectImportSkippedExpressionEvaluatedToEmpty");
private static readonly string ProjectImportSkippedFalseCondition = ResourceUtilities.GetResourceString("ProjectImportSkippedFalseCondition");
private static readonly string ProjectImportSkippedInvalidFile = ResourceUtilities.GetResourceString("ProjectImportSkippedInvalidFile");
private static readonly string ProjectImportSkippedMissingFile = ResourceUtilities.GetResourceString("ProjectImportSkippedMissingFile");
private static readonly string ProjectImportSkippedNoMatches = ResourceUtilities.GetResourceString("ProjectImportSkippedNoMatches");

/// <summary>
/// Load and parse the specified project import, which may have wildcards,
/// into one or more ProjectRootElements, if it's Condition evaluates to true
Expand All @@ -1685,7 +1701,7 @@ private List<ProjectRootElement> ExpandAndLoadImports(string directoryOfImportin
ProjectImportedEventArgs eventArgs = new ProjectImportedEventArgs(
importElement.Location.Line,
importElement.Location.Column,
ResourceUtilities.GetResourceString("ProjectImportSkippedFalseCondition"),
ProjectImportSkippedFalseCondition,
importElement.Project,
importElement.ContainingProject.FullPath,
importElement.Location.Line,
Expand Down Expand Up @@ -1778,7 +1794,7 @@ private List<ProjectRootElement> ExpandAndLoadImports(string directoryOfImportin
ProjectImportedEventArgs eventArgs = new ProjectImportedEventArgs(
importElement.Location.Line,
importElement.Location.Column,
ResourceUtilities.GetResourceString("CouldNotResolveSdk"),
CouldNotResolveSdk,
sdkReference.ToString())
{
BuildEventContext = _evaluationLoggingContext.BuildEventContext,
Expand Down Expand Up @@ -1948,7 +1964,7 @@ ProjectRootElement InnerCreate(string _, ProjectRootElementCacheBase __)
ProjectImportedEventArgs eventArgs = new ProjectImportedEventArgs(
importElement.Location.Line,
importElement.Location.Column,
ResourceUtilities.GetResourceString("ProjectImportSkippedExpressionEvaluatedToEmpty"),
ProjectImportSkippedExpressionEvaluatedToEmpty,
unescapedExpression,
importElement.ContainingProject.FullPath,
importElement.Location.Line,
Expand All @@ -1971,7 +1987,7 @@ ProjectRootElement InnerCreate(string _, ProjectRootElementCacheBase __)

bool atleastOneImportIgnored = false;
bool atleastOneImportEmpty = false;

foreach (string importExpressionEscapedItem in ExpressionShredder.SplitSemiColonSeparatedList(importExpressionEscaped))
{
string[] importFilesEscaped = null;
Expand Down Expand Up @@ -2003,7 +2019,7 @@ ProjectRootElement InnerCreate(string _, ProjectRootElementCacheBase __)
ProjectImportedEventArgs eventArgs = new ProjectImportedEventArgs(
importElement.Location.Line,
importElement.Location.Column,
ResourceUtilities.GetResourceString("ProjectImportSkippedNoMatches"),
ProjectImportSkippedNoMatches,
importExpressionEscapedItem,
importElement.ContainingProject.FullPath,
importElement.Location.Line,
Expand Down Expand Up @@ -2151,7 +2167,7 @@ ProjectRootElement InnerCreate(string _, ProjectRootElementCacheBase __)
ProjectImportedEventArgs eventArgs = new ProjectImportedEventArgs(
importElement.Location.Line,
importElement.Location.Column,
ResourceUtilities.GetResourceString("ProjectImported"),
ProjectImported,
importedProjectElement.FullPath,
importElement.ContainingProject.FullPath,
importElement.Location.Line,
Expand Down Expand Up @@ -2185,7 +2201,7 @@ ProjectRootElement InnerCreate(string _, ProjectRootElementCacheBase __)
ProjectImportedEventArgs eventArgs = new ProjectImportedEventArgs(
importElement.Location.Line,
importElement.Location.Column,
ResourceUtilities.GetResourceString("ProjectImportSkippedMissingFile"),
ProjectImportSkippedMissingFile,
importFileUnescaped,
importElement.ContainingProject.FullPath,
importElement.Location.Line,
Expand Down Expand Up @@ -2217,14 +2233,14 @@ ProjectRootElement InnerCreate(string _, ProjectRootElementCacheBase __)
// If IgnoreEmptyImports is enabled, check if the file is considered empty
//
ignoreImport = true;
ignoreImportResource = "ProjectImportSkippedEmptyFile";
ignoreImportResource = ProjectImportSkippedEmptyFile;
}
else if ((_loadSettings & ProjectLoadSettings.IgnoreInvalidImports) != 0)
{
// If IgnoreInvalidImports is enabled, log all other non-handled exceptions and continue
//
ignoreImport = true;
ignoreImportResource = "ProjectImportSkippedInvalidFile";
ignoreImportResource = ProjectImportSkippedInvalidFile;
}

if (ignoreImport)
Expand All @@ -2235,7 +2251,7 @@ ProjectRootElement InnerCreate(string _, ProjectRootElementCacheBase __)
ProjectImportedEventArgs eventArgs = new ProjectImportedEventArgs(
importElement.Location.Line,
importElement.Location.Column,
ResourceUtilities.GetResourceString(ignoreImportResource),
ignoreImportResource,
importFileUnescaped,
importElement.ContainingProject.FullPath,
importElement.Location.Line,
Expand Down
19 changes: 16 additions & 3 deletions src/Build/Evaluation/PropertyTrackingEvaluatorDataWrapper.cs
View file
Open in desktop
Expand Up @@ -259,18 +259,31 @@ private void TrackPropertyInitialValueSet(P property, PropertySource source)
/// <param name="location">The location of this property's reassignment.</param>
private void TrackPropertyReassignment(P predecessor, P property, string location)
{
if ((_settings & PropertyTrackingSetting.PropertyReassignment) != PropertyTrackingSetting.PropertyReassignment) return;
if ((_settings & PropertyTrackingSetting.PropertyReassignment) != PropertyTrackingSetting.PropertyReassignment)
{
return;
}

if (string.Equals(property.Name, "MSBuildAllProjects", 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.

While we're here, I took a look at a binlog to see what other properties stand out. DefineConstants gets about as long as MSBuildAllProjects and is reassigned quite a bit. Any way to log these once at the end of evaluation?

Copy link
Member

Choose a reason for hiding this comment

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

DefaultItemExcludes doesn't get nearly as long or reassigned as many times but it seems worth mentioning.

Copy link
Member Author

Choose a reason for hiding this comment

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

Yes, I've noticed DefaultItemExcludes too, but decided to not go too crazy. DefineConstants is certainly useful, so let's still log that.

Copy link
Member

Choose a reason for hiding this comment

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

I was already familiar with MSBuildAllProjects. How is DefineConstants used?

Copy link
Member

Choose a reason for hiding this comment

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

Also, is it that valuable to remove the initial value logging? That should only happen once, and it should be pretty small at that point, right?

Copy link
Member Author

Choose a reason for hiding this comment

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

DefineConstants is very useful, this is that thing that is passed to Csc that tells the compiler what #ifdef values are considered true.

Copy link
Member Author

Choose a reason for hiding this comment

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

Yeah, not removing the initial logging, just the reassignment. There's a separate bug that the logging of initial values, environment variable reads is not working: #5015

{
// There's a huge perf cost to logging this and it increases the binlog size significantly.
// Meanwhile the usefulness of logging this is very low.
return;
}

string newValue = property.EvaluatedValue;
string oldValue = predecessor.EvaluatedValue;
if (newValue == oldValue) return;
if (newValue == oldValue)
{
return;
}

var args = new PropertyReassignmentEventArgs(
property.Name,
oldValue,
newValue,
location,
ResourceUtilities.FormatResourceStringIgnoreCodeAndKeyword("PropertyReassignment", property.Name, newValue, oldValue, location));
message: null);
args.BuildEventContext = _evaluationLoggingContext.BuildEventContext;

_evaluationLoggingContext.LogBuildEvent(args);
Expand Down