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

Created on 20 Feb 2019 · 4Comments · Source: dotnet/msbuild

msbuild /m:1 /clp:PerformanceSummary the following..

<Project>
  <Target Name="A">
     <MSBuild Projects="$(MSBuildProjectFile)" Targets="B" />
  </Target>

  <Target Name="B">
      <Exec Command="ping -n 5 localhost" />
      <MSBuild Projects="$(MSBuildProjectFile)" Targets="C" />
  </Target>

  <Target Name="C">
      <Exec Command="ping -n 10 localhost" />
      <MSBuild Projects="$(MSBuildProjectFile)" Targets="D" />
  </Target>

  <Target Name="D">
      <Exec Command="ping -n 20 localhost" />
  </Target>
</Project>

...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)

Debuggability Needs Design

Source

nguerrera

All 4 comments

Another related thing is that evaluation cost is attributed to the first target that causes it, and also reported separately. I think it would be useful to see Target costs exclusive of evaluation. See https://github.com/aspnet/AspNetCore/issues/12942#issuecomment-519554818

nguerrera on 8 Aug 2019

👍1

The output used to call out double counting but that message seems to have been removed.