PerformanceSummary is difficult to interpret with nesting, plain wrong with recursion
- Dominant language
- C#
- Stars
- 5.5k
- Forks
- 1.5k
- Avg merge
- 1d 8h
- Merged PRs (30d)
- 141
Description
`msbuild /m:1 /clp:PerformanceSummary` the following..
``` xml
```
...and you'll get something like this:
```
Microsoft (R) Build Engine version 16.0.440-preview+gc689feb344 for .NET Framework
Copyright (C) Microsoft Corporation. All rights reserved.
Project Performance Summary:
111984 ms D:\Temp\ProfilingRepro\Repro.csproj 4 calls
32320 ms B 1 calls
28213 ms C 1 calls
19109 ms D 1 calls
Target Performance Summary:
19109 ms D 1 calls
28212 ms C 1 calls
32320 ms B 1 calls
32341 ms A 1 calls
Task Performance Summary:
32314 ms Exec 3 calls
79650 ms MSBuild 3 calls
Time Elapsed 00:00:32.36
```
The call tree is A (~ 0 seconds exclusive) -> B (~4 seconds exclusive) -> C (~9 seconds exclusive)-> D (~19 seconds exclusive).
The project is obviously contrived, but demonstrates things you can observe with real nested project references and multi-targeting.
The first problem is that only inclusive times are reported. Without also reporting exclusive times or providing any visualization of the tree, these are easy to misinterpret.
It gets much worse when the nesting involves any recursion
> 111984 ms D:\Temp\ProfilingRepro\Repro.csproj 4 calls
> 79650 ms MSBuild 3 calls
Huh? The whole single proc build took ~32s, how did 4 builds of Repro.csproj take ~112s? Ditto for 3 calls to MSBuild taking ~79s?
The answer is that we're incorrectly double counting:
Repro.csproj ~= (D ~= 19s) + (C ~= 9s+ 19s) + (B ~= 4s + 9s + 19s) + (A ~= 0s + 4s + 9s + 19s).
MSBuild ~= (D ~= 19s) + (C ~= 9s + 19s) + (B ~= 4s + 9s + 19s)
Contributor guide
No contributing guide indexed for this repository
Assessment
This issue has not been assessed yet.