dotnet / dotnet/msbuild

PerformanceSummary is difficult to interpret with nesting, plain wrong with recursion

Open
#4,189 4 comments 0 reactions 0 assignees View on GitHub
Area: Debuggability needs-design triaged
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.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.