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

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: - 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? - 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.