Why msbuild is so slow when nothing has changed since the last build of the solution?

Question

I have a solution with 109 projects. A mix of all - .NET, Silverlight, MVC, Web Applications, Console applications.

Now I build it on the console using msbuild. It takes some time. Understandable - lots of projects, lots of files.

But when I build it the second time right after the first - it still takes lots of time, even if nothing is actually built - the diag msbuild log confirms it.

For example, here is the Task performance summary for the first full build:

Task Performance Summary:
    4 ms  GetSilverlightItemsFromProperty            1 calls
   13 ms  Move                                       1 calls
   20 ms  GetReferenceAssemblyPaths                 27 calls
   28 ms  GetFrameworkPath                         190 calls
   29 ms  ValidateSilverlightFrameworkPaths        163 calls
   72 ms  AssignCulture                            192 calls
   75 ms  ResolveKeySource                         179 calls
   79 ms  MakeDir                                  200 calls
   95 ms  CreateProperty                           260 calls
  100 ms  CreateCSharpManifestResourceName         122 calls
  102 ms  Delete                                   442 calls
  112 ms  GenerateResource                           3 calls
  123 ms  CopyFilesToFolders                         1 calls
  177 ms  ReadLinesFromFile                        190 calls
  179 ms  CreateHtmlTestPage                        31 calls
  181 ms  CallTarget                               190 calls
  184 ms  GetSilverlightFrameworkPath              163 calls
  211 ms  Message                                  573 calls
  319 ms  CreateSilverlightAppManifest              97 calls
  354 ms  FileClassifier                           119 calls
  745 ms  ConvertToAbsolutePath                    190 calls
  868 ms  PackagePlatformExtensions                 94 calls
  932 ms  AssignProjectConfiguration               190 calls
 1625 ms  CategorizeSilverlightReferences          163 calls
 1722 ms  ResourcesGenerator                        60 calls
 2467 ms  WriteLinesToFile                         118 calls
 5589 ms  RemoveDuplicates                         380 calls
 8207 ms  FindUnderPath                            950 calls
17720 ms  XapPackager                               97 calls
38162 ms  Copy                                     857 calls
38934 ms  CompileXaml                              119 calls
40567 ms  Exec                                      14 calls
55275 ms  ValidateXaml                             119 calls
65845 ms  AssignTargetPath                         1140 calls
83792 ms  Csc                                      108 calls
105906 ms  ResolveAssemblyReference                 190 calls
1163988 ms  MSBuild                                  471 calls

msbuild claims Time Elapsed 00:08:39.44

Fine. Now I run the same command line again and get the following:

Task Performance Summary:
    1 ms  GetSilverlightItemsFromProperty            1 calls
   11 ms  WriteLinesToFile                           1 calls
   17 ms  GetReferenceAssemblyPaths                 27 calls
   24 ms  GetFrameworkPath                         190 calls
   32 ms  ValidateSilverlightFrameworkPaths        163 calls
   43 ms  CopyFilesToFolders                         1 calls
   47 ms  GenerateResource                           3 calls
   60 ms  ResolveKeySource                         179 calls
   66 ms  MakeDir                                  200 calls
   69 ms  AssignCulture                            192 calls
   70 ms  PackagePlatformExtensions                 94 calls
   76 ms  Delete                                   432 calls
   89 ms  CreateProperty                           260 calls
   98 ms  CreateCSharpManifestResourceName         122 calls
  136 ms  GetSilverlightFrameworkPath              163 calls
  156 ms  CallTarget                               190 calls
  182 ms  CreateHtmlTestPage                        31 calls
  207 ms  XapPackager                               97 calls
  215 ms  ReadLinesFromFile                        190 calls
  217 ms  Message                                  573 calls
  271 ms  CreateSilverlightAppManifest              97 calls
  350 ms  FileClassifier                           119 calls
  526 ms  ConvertToAbsolutePath                    190 calls
  795 ms  AssignProjectConfiguration               190 calls
 1658 ms  CategorizeSilverlightReferences          163 calls
 2237 ms  Exec                                       2 calls
 5703 ms  RemoveDuplicates                         380 calls
 6948 ms  Copy                                     426 calls
 7550 ms  FindUnderPath                            950 calls
17126 ms  CompileXaml                              119 calls
54495 ms  ValidateXaml                             119 calls
78953 ms  AssignTargetPath                         1140 calls
97374 ms  ResolveAssemblyReference                 190 calls
603295 ms  MSBuild                                  471 calls

msbuild claims Time Elapsed 00:05:25.70.

This poses the following questions:

1. Why ResolveAssemblyReference takes so much time in the second build? All the cache files created in the first build are still there. Nothing has changed. So how come it is taking almost the same as before - 97 seconds vs 106 seconds?
2. Why ValidateXaml and CompileXaml are running at all? I mean nothing has changed at all since the full build!

Now I repeat the same experiment, but this time I build with devenv on the command line instead of msbuild. As with msbuild no parallel builds are used and the log level is on diag.

devenv does not present such a nice summary at the end, it has to be aggregated manually from the per project summaries.

The results amazed me. I used the following powershell script to aggregate the elapsed time:

Param(
  [Parameter(Mandatory=$True,Position=1)][string]$log
)
[timespan]::FromMilliseconds((sls -SimpleMatch "Time Elapsed" $log |% {[timespan]::Parse(($_ -split ' ')[2]) } | measure -Sum TotalMilliseconds).Sum).ToString()

Building exactly the same solution from exactly the same standing point with devenv on the command line took 00:06:10.9000000 the first build and 00:00:03.1000000 the second. It is just 3 seconds !!!.

I have also written a powershell script to aggregate the statistics:

Param(
  [Parameter(Mandatory=$True,Position=1)][string]$log
)
$summary=@{}
cat $log |% { 
  if ($collect) {
    if ($_ -eq "") {
      $collect = $false;
    } else { 
      $tmp = ($_ -replace '\s+', ' ') -split ' ';
      $cur = $summary[$tmp[3]];
      if (!$cur) { 
        $cur = @(0, 0);
        $summary[$tmp[3]] = $cur;
      }
      $cur[0] += $tmp[1];
      $cur[1] += $tmp[4];
    }
  } else { 
    $collect = $_ -eq "Task Performance Summary:" 
  } 
}
$summary.Keys |% {
  $stats = $summary[$_];
  $ms = $stats[0];
  $calls = $stats[1];
  [string]::Format("{0,10} ms {1,-40} {2} calls", $ms,$_,$calls);
} | sort

Running it on the log of the first (full) build produces the following output:

     5 ms ValidateSilverlightFrameworkPaths        82 calls
     7 ms Move                                     1 calls
     9 ms GetFrameworkPath                         108 calls
    11 ms GetReferenceAssemblyPaths                26 calls
    14 ms AssignCulture                            109 calls
    16 ms ReadLinesFromFile                        108 calls
    18 ms CreateCSharpManifestResourceName         61 calls
    18 ms ResolveKeySource                         97 calls
    23 ms Delete                                   268 calls
    26 ms CreateProperty                           131 calls
    41 ms MakeDir                                  118 calls
    66 ms CallTarget                               108 calls
    70 ms Message                                  326 calls
    75 ms ResolveNonMSBuildProjectOutput           104 calls
   101 ms GenerateResource                         1 calls
   107 ms GetSilverlightFrameworkPath              82 calls
   118 ms CreateHtmlTestPage                       16 calls
   153 ms FileClassifier                           60 calls
   170 ms CreateSilverlightAppManifest             49 calls
   175 ms AssignProjectConfiguration               108 calls
   279 ms ConvertToAbsolutePath                    108 calls
   891 ms CategorizeSilverlightReferences          82 calls
   926 ms PackagePlatformExtensions                47 calls
  1291 ms ResourcesGenerator                       60 calls
  2193 ms WriteLinesToFile                         108 calls
  3687 ms RemoveDuplicates                         216 calls
  5538 ms FindUnderPath                            540 calls
  6157 ms MSBuild                                  294 calls
 16496 ms Exec                                     4 calls
 19699 ms XapPackager                              49 calls
 21281 ms Copy                                     378 calls
 28362 ms ValidateXaml                             60 calls
 29526 ms CompileXaml                              60 calls
 66846 ms AssignTargetPath                         654 calls
 81650 ms Csc                                      108 calls
 82759 ms ResolveAssemblyReference                 108 calls

Now, for the second build the results are:

     1 ms AssignCulture                            1 calls
     1 ms CreateProperty                           1 calls
     1 ms Delete                                   2 calls
     1 ms ValidateSilverlightFrameworkPaths        1 calls
     3 ms AssignTargetPath                         6 calls
     3 ms ConvertToAbsolutePath                    1 calls
     3 ms PackagePlatformExtensions                1 calls
     3 ms ReadLinesFromFile                        1 calls
     3 ms ResolveKeySource                         1 calls
     4 ms ResolveNonMSBuildProjectOutput           1 calls
     5 ms CreateCSharpManifestResourceName         1 calls
     5 ms GetFrameworkPath                         1 calls
    10 ms CategorizeSilverlightReferences          1 calls
    11 ms CallTarget                               1 calls
    11 ms FileClassifier                           1 calls
    11 ms FindUnderPath                            5 calls
    11 ms MakeDir                                  1 calls
    13 ms Copy                                     2 calls
    17 ms GetSilverlightFrameworkPath              1 calls
    17 ms RemoveDuplicates                         2 calls
    30 ms AssignProjectConfiguration               1 calls
    32 ms Message                                  25 calls
   239 ms ResolveAssemblyReference                 1 calls
   351 ms MSBuild                                  2 calls
   687 ms CompileXaml                              1 calls
  1413 ms ValidateXaml                             1 calls

We are talking about exactly the same solution here !

Finally, here are the scripts I used to build with the solution:

msbuild:

@setlocal

set SHELFSET=msbuild

set MSBUILDLOGVERBOSERARSEARCHRESULTS=true
set AppConfig=app.config
set Disable_CopyWebApplication=true
set MvcBuildViews=false

call \tmp\undo.cmd
del /a:-R /s/q *.*
tf unshelve %SHELFSET% /recursive /noprompt

msbuild DataSvc.sln
msbuild Main.sln /v:diag > \tmp\00.Main.msbuild.full.log
msbuild Main.sln /v:diag > \tmp\01.Main.msbuild.incr.log
msbuild Main.sln /v:diag > \tmp\02.Main.msbuild.incr.log

@endlocal

devenv:

@setlocal

set SHELFSET=msbuild

set MSBUILDLOGVERBOSERARSEARCHRESULTS=true
set AppConfig=app.config
set Disable_CopyWebApplication=true
set MvcBuildViews=false

call \tmp\undo.cmd
del /a:-R /s/q *.*
tf unshelve %SHELFSET% /recursive /noprompt

msbuild DataSvc.sln
devenv  Main.sln /build > \tmp\00.Main.devenv.full.log
devenv  Main.sln /build > \tmp\01.Main.devenv.incr.log
devenv  Main.sln /build > \tmp\02.Main.devenv.incr.log

@endlocal

My tests tell me that msbuild is a piece of junk and I should never use it on the command line to build my C# solutions. https://connect.microsoft.com/VisualStudio/feedback/details/586358/msbuild-ignores-projectsection-projectdependencies-in-sln-file-and-attempts-to-build-projects-in-wrong-order adds to this feeling.

But maybe I am wrong after all and a simple tweak would make msbuild as efficient on the second build as devenv is.

Any ideas how to make msbuild behave sanely on the second build?

EDIT 1

The CompileXaml task is part of the MarkupCompilePass1 target found in C:\Program Files (x86)\MSBuild\Microsoft\Silverlight\v5.0\Microsoft.Silverlight.Common.targets:

<Target Name="MarkupCompilePass1"
      DependsOnTargets="$(CompileXamlDependsOn)" 
      Condition="'@(Page)@(ApplicationDefinition)' != '' " >

    <CompileXaml 
           LanguageSourceExtension="$(DefaultLanguageSourceExtension)"
           Language="$(Language)" 
           SilverlightPages="@(Page)" 
           SilverlightApplications="@(ApplicationDefinition)" 
           ProjectPath="$(MSBuildProjectFullPath)"
           RootNamespace="$(RootNamespace)"
           AssemblyName="$(AssemblyName)" 
           OutputPath="$(IntermediateOutputPath)"
           SkipLoadingAssembliesInXamlCompiler="$(SkipLoadingAssembliesInXamlCompiler)"
           TargetFrameworkDirectory="$(TargetFrameworkDirectory)" 
           TargetFrameworkSDKDirectory="$(TargetFrameworkSDKDirectory)"
           ReferenceAssemblies ="@(ReferencePath);@(InferredReference->'$(TargetFrameworkDirectory)\%(Identity)')"
           >

        <Output ItemName="Compile" TaskParameter="GeneratedCodeFiles" />

        <!-- Add to the list list of files written. It is used in Microsoft.Common.Targets to clean up 
             for a next clean build 
          -->
        <Output ItemName="FileWrites" TaskParameter="GeneratedCodeFiles" />
        <Output ItemName="_GeneratedCodeFiles" TaskParameter="GeneratedCodeFiles" />

    </CompileXaml>

    <Message Text="(Out) GeneratedCodeFiles: '@(_GeneratedCodeFiles)'" Condition="'$(MSBuildTargetsVerbose)'=='true'"/>
</Target>

As we can see - no Inputs and no Outputs.

Next, the diag msbuild log for the second build does not contain any suspicious words like "rebuilding".

Finally, I would like to notice that both msbuild and devenv were exercised under exactly the same circumstances and none employed the multi threaded build. Yet the difference is abysmal - more than 5 minutes (msbuild) vs 3 seconds (devenv, command line).

Still a complete mystery to me.

EDIT 2

I know now more about how devenv build works. It uses a heuristic to determine whether the current project has to be handed over to msbuild in the first place. This heuristic is enabled by default, but can be disabled by setting the DisableFastUpToDateCheck msbuild property to true.

Now, it actually takes more than 3 seconds for a command line devenv build to figure out whether there is need to run msbuild or not. All in all for the solution like mine it could take 20 seconds or even 30 seconds to decide that nothing needs to be passed to msbuild.

This heuristic is the sole reason for this huge different in time. I guess the Visual Studio team recognised the poor quality of the standard build scripts (where the tasks like MarkupCompilePass1 are not driven by inputs and outputs) and decided to come up with a way to skip msbuild in the first place.

But there is a catch - the heuristic only inspects the csproj file, none of the imported targets files are examined. In addition, it knows nothing about implicit dependencies - like TypeScript files referenced from other TypeScript files. So, if your TypeScript files reference other TypeScript files that belong to a different project and are not linked to explicitly from the project file - the heuristic does not know about them and you had better have DisableFastUpToDateCheck = true. The build will be slower, but at least it will be correct.

Bottom line - I do not know how to fix msbuild and apparently the devenv guys neither. That seems to be the reason for them inventing the heuristic.

Answer 1

First, take a look at that diagnostic log you're generating. Actually, first use a file logger rather than console operators to pipe console output to the log, then take a look at them logs!

Actually, instead of /v:diag >msbuild.log, use this:

/v:min /fl3 /flp3:warningsonly;logfile=msbuild.wrn /fl4 /flp4:errorsOnly;logfile=msbuild.err /fl5 /flp5:Verbosity=diag;logfile=msbuild.log

Now your console buffer thanks you, and so do your developers for including the foresight to keep separate error-only and warning-only logs for debugging.

Now examine that diagnostic MsBuild log, and CTRL+F for the targets that are taking a long time to run. Do you see any verbiage that denotes the target is running again even though nothing has changed? To skip a build, a target will need to have defined inputs and outputs. If the inputs (.cs) are newer than the outputs (.dll, .pdb), then it knows something must have changed and trigger a new build

Those CompileXaml targets I believe are in the WinFx targets and do have defined inputs and outputs, can you locate the output text for one of those long-running cases and determine if an error caused it to rebuild? Does it say "Rebuilding X completely because Y could not be found"?

Lastly, here's a fun trick to speed up your build from the command line!

msbuild.exe /m

This will build projects separately across multiple threads.