自上次构建解决方案以来没有发生任何变化，为什么msbuild如此缓慢? [英] Why msbuild is so slow when nothing has changed since the last build of the solution?
问题描述
我有109个项目的解决方案.所有-.NET，Silverlight，MVC，Web应用程序，控制台应用程序的组合.
I have a solution with 109 projects. A mix of all - .NET, Silverlight, MVC, Web Applications, Console applications.
现在，我使用msbuild在控制台上构建它.需要一些时间.可以理解-很多项目，很多文件.
Now I build it on the console using msbuild. It takes some time. Understandable - lots of projects, lots of files.
但是当我在第一次构建之后第二次构建它时-即使实际上没有构建任何东西，仍然要花费很多时间-diag msbuild日志会确认它.
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声明Time Elapsed 00:08:39.44
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声明Time Elapsed 00:05:25.70.
msbuild claims Time Elapsed 00:05:25.70.
这提出了以下问题:
- 为什么
ResolveAssemblyReference在第二个构建中要花费这么多时间?在第一个版本中创建的所有缓存文件仍然存在.什么也没有变.那么，为什么要花几乎与以前相同的时间-97秒和106秒? - 为什么
ValidateXaml和CompileXaml都在运行?我的意思是，自完整版本以来，什么都没有改变！
- Why
ResolveAssemblyReferencetakes 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
ValidateXamlandCompileXamlare running at all? I mean nothing has changed at all since the full build!
现在，我重复相同的实验，但是这次我在命令行上使用devenv而不是msbuild进行构建.与msbuild一样，不使用并行构建，并且日志级别在诊断上.
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最后没有显示出如此好的摘要，必须从每个项目的摘要中手动汇总.
devenv does not present such a nice summary at the end, it has to be aggregated manually from the per project summaries.
结果令我惊讶.我使用以下powershell脚本来汇总经过的时间:
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()
在命令行上使用devenv从完全相同的角度构建完全相同的解决方案，而第一次构建是00:06:10.9000000，而第二次构建是00:00:03.1000000. 只有3秒钟！！！
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 !!!.
我还编写了一个powershell脚本来汇总统计信息:
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
我的测试告诉我msbuild是一堆垃圾，我绝不应该在命令行上使用它来构建我的C#解决方案.
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.
但是也许我毕竟是错的，简单的调整会使msbuild在第二个版本上的效率与devenv一样.
But maybe I am wrong after all and a simple tweak would make msbuild as efficient on the second build as devenv is.
有什么想法可以使msbuild在第二个构建中表现得合理吗?
Any ideas how to make msbuild behave sanely on the second build?
编辑1
CompileXaml任务是在 C:\ Program Files(x86)\ MSBuild \ Microsoft \ Silverlight \ v5.0 \ Microsoft.Silverlight.Common.targets 中找到的MarkupCompilePass1目标的一部分. >:
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.
接下来，用于第二个构建的diag msbuild日志不包含任何可疑词，例如正在重建".
Next, the diag msbuild log for the second build does not contain any suspicious words like "rebuilding".
最后，我想注意到msbuild和devenv都是在完全相同的情况下使用的，没有一个使用多线程构建.然而，差异却是惊人的-超过5分钟(msbuild)vs 3秒(devenv，命令行).
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.
编辑2
我现在进一步了解 devenv 构建的工作方式.它使用启发式方法来确定是否必须首先将当前项目移交给msbuild.默认情况下启用此启发式，但可以通过将DisableFastUpToDateCheck msbuild属性设置为true来禁用.
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.
现在，使用命令行devenv构建实际上要花费3秒钟以上的时间来确定是否需要运行msbuild.总而言之，像我这样的解决方案可能需要20秒钟甚至30秒钟的时间来决定不需要将任何内容传递给msbuild.
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.
这种启发性是造成时间上巨大差异的唯一原因.我猜想Visual Studio团队认识到标准构建脚本的质量很差(其中MarkupCompilePass1之类的任务不是由输入和输出驱动的)，并决定首先提出一种跳过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.
但是有一个问题-启发式仅检查csproj文件，没有检查任何导入的目标文件.此外，它对隐式依赖一无所知-就像从其他TypeScript文件引用的TypeScript文件一样.因此，如果您的TypeScript文件引用了其他TypeScript文件，这些文件属于不同的项目，并且未从该项目文件中明确链接到该文件-启发式方法将不知道它们，而您最好使用DisableFastUpToDateCheck = true.构建速度会变慢，但至少会正确.
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.
最重要的是-我不知道如何修复msbuild，显然也不知道如何修复.这似乎是他们发明启发式技术的原因.
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.
推荐答案
首先，查看您正在生成的诊断日志.实际上，首先使用文件记录器而不是控制台操作员将控制台输出传递到日志，然后查看它们的日志！
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!
实际上，而不是/v:diag >msbuild.log，请使用:
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.
现在检查该诊断性MsBuild日志，并检查CTRL + F以查找需要花费很长时间才能运行的目标.即使没有任何变化，您是否看到任何指示目标再次运行的字眼?要跳过构建，目标将需要具有定义的输入和输出.如果输入(.cs)比输出(.dll，.pdb)更新，则表明必须进行某些更改并触发新的构建
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
我认为这些CompileXaml目标位于WinFx目标中，并且确实定义了输入和输出，您可以为那些长期运行的情况之一找到输出文本，并确定是否导致错误重建吗?它是否说因为找不到Y而完全重建X"?
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
msbuild.exe /m
这将跨多个线程分别构建项目.
This will build projects separately across multiple threads.
这篇关于自上次构建解决方案以来没有发生任何变化，为什么msbuild如此缓慢?的文章就介绍到这了，希望我们推荐的答案对大家有所帮助，也希望大家多多支持IT屋！
