Add ETW trace for PerformDependencyAnalysis #6658
Conversation
I was considering adding bucket.bucketSequenceNumber, but I don't think that's too important. Complicated information can't be easily ( / efficiently) attached to ETW traces
There was a problem hiding this comment.
This is probably the most interesting part of #6616 but not all of it -- we'll need some work in Copy and other unconditionally-called tasks to call that done.
| TargetUpToDateChecker dependencyAnalyzer = new TargetUpToDateChecker(requestEntry.RequestConfiguration.Project, _target, targetLoggingContext.LoggingService, targetLoggingContext.BuildEventContext); | ||
| MSBuildEventSource.Log.PerformDependencyAnalysisStart(); |
There was a problem hiding this comment.
I'd claim that creating the object is part of the time spent (I doubt this matters much though).
| TargetUpToDateChecker dependencyAnalyzer = new TargetUpToDateChecker(requestEntry.RequestConfiguration.Project, _target, targetLoggingContext.LoggingService, targetLoggingContext.BuildEventContext); | |
| MSBuildEventSource.Log.PerformDependencyAnalysisStart(); | |
| MSBuildEventSource.Log.PerformDependencyAnalysisStart(); | |
| TargetUpToDateChecker dependencyAnalyzer = new TargetUpToDateChecker(requestEntry.RequestConfiguration.Project, _target, targetLoggingContext.LoggingService, targetLoggingContext.BuildEventContext); |
| DependencyAnalysisResult dependencyResult = dependencyAnalyzer.PerformDependencyAnalysis(bucket, out changedTargetInputs, out upToDateTargetInputs); | ||
| MSBuildEventSource.Log.PerformDependencyAnalysisStop(); |
There was a problem hiding this comment.
Can this log the result? I think we'll be interested in two aspects:
- Time it takes to decide something's fully up to date (pure overhead in a no-op incremental build)
- Time it takes to decide something's not up to date in "obvious" cases (overhead when we need to build).
There was a problem hiding this comment.
It definitely can...I don't think it can log what the result really means, though. In other words, it can log the int corresponding to the enum, but I don't think it can log what "0" or "4" correspond to. I can add it in anyway, since you can always look it up if it's important to you.
There was a problem hiding this comment.
That's good enough for me too.
src/Framework/MSBuildEventSource.cs
Outdated
| @@ -423,6 +423,18 @@ public void PacketReadSize(int size) | |||
| { | |||
| WriteEvent(55, size); | |||
| } | |||
|
|
|||
| [Event(56, Keywords = Keywords.All)] | |||
| public void PerformDependencyAnalysisStart() | |||
There was a problem hiding this comment.
I think I'd prefer a name like TargetUpToDateCheckStart/Stop; as the comment above notes this "isn't really dependency analysis" so I'd love to avoid propagating the bad name. Thoughts?
There was a problem hiding this comment.
I slightly prefer it this way because 1) there is other work that happens when it does an UTD check, albeit not too much, and 2) consistency is good even if it's slightly wrong consistency. I don't feel at all strongly, though, so I can change it.
|
I added an ETW event to Copy. I'd looked it over before, but it mostly seemed captured by the ExecuteTask ETW. I added something that notes whether it's parallel, but I'm now thinking it would have made more sense to specify how parallel, i.e., an int for parallelism (if parallel) or 1 if not. It also might be useful to put it under a IsEnabled check and include destinationFilesSuccessfullyCopied.Select(f => f.ItemSpec) on Stop events. Will do if you think it's a good idea. I'm not really sure how to find other tasks that run unconditionally, since you suggested away from debugging, and I couldn't (quickly) find documentation on it. |
src/Framework/MSBuildEventSource.cs
Outdated
| } | ||
|
|
||
| [Event(58, Keywords = Keywords.All)] | ||
| public void CopyStart(bool singleThreaded) |
There was a problem hiding this comment.
I think CopyStart/Stop is well covered by ExecuteTaskStart/Stop events. I was hoping for events measuring the up-to-date check within Copy.
Targets run incrementally if they define inputs and outputs and the outputs are up to date with respect to the inputs' timestamps. Some targets do not define inputs and outputs. This is sometimes a bug (especially in custom targets/additions to the standard process) but sometimes intentional behavior because incremental behavior happens at another layer (like inside the Copy task or with tracker-based incremental builds for C++ compilation), can't be represented (like in the case of RAR), or isn't important (targets that just mutate MSBuild item/property state and are quick). One way to do this would be to create a template project, build it, build it again, and see what tasks ran the second time through. Another would be to explicitly look for targets that don't have inputs/outputs. |
ladipro
added
the
merge-when-branch-open
Progress towards #6658 Adds an up-to-date ETW for the Copy task. Also captures metadata copying just because that happens if it was up-to-date. (Should we have a check rather than always copying?)
I was considering adding bucket.bucketSequenceNumber, but I don't think that's too important. Complicated information can't be easily ( / efficiently) attached to ETW traces
Fixes #6616
I should make sure they appear in PerfView before merging.