У меня есть решение с 109 проектами. Комбинация всех приложений .NET, Silverlight, MVC, веб-приложений, консолей.
Теперь я создаю его на консоли с помощью msbuild. Это занимает некоторое время. Понятное - много проектов, много файлов.
Но когда я создаю его второй раз сразу после первого - он по-прежнему занимает много времени, даже если ничего не построено - журнал diag msbuild подтверждает его.
Например, вот резюме производительности задачи для первой полной сборки:
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
Fine. Теперь я снова запускаю ту же командную строку и получаю следующее:
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.
Это задает следующие вопросы:
- Почему
ResolveAssemblyReferenceзанимает так много времени во второй сборке? Все файлы кеша, созданные в первой сборке, все еще существуют. Ничего не изменилось. Итак, почему он принимает почти то же самое, что и раньше - 97 секунд против 106 секунд? - Почему
ValidateXamlиCompileXamlработают вообще? Я имею в виду, что ничего не изменилось с момента полной сборки!
Теперь я повторяю тот же эксперимент, но на этот раз я строю с devenv в командной строке вместо msbuild. Как и в msbuild, параллельные сборки не используются, а уровень журнала находится в диалоге.
devenv не представляет такого приятного резюме в конце, его нужно агрегировать вручную из резюме каждого проекта.
Результаты поразили меня. Я использовал следующую powershell script для агрегирования прошедшего времени:
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 секунды!!!.
Я также написал powershell script для агрегирования статистики:
Param(
[Parameter(Mandatory=$True,Position=1)][string]$log
)
[email protected]{}
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
Запуск в журнале первой (полной) сборки приводит к следующему выводу:
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
Теперь для второй сборки результаты:
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
Мы говорим о том же решении здесь!
Наконец, вот скрипты, которые я использовал для сборки с помощью решения:
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 - это кусок хлама, и я никогда не должен использовать его в командной строке для создания моих С# -решений. https://connect.microsoft.com/VisualStudio/feedback/details/586358/msbuild-ignores-projectsection-projectdependencies-in-sln-file-and-attempts-to-build-projects-in-wrong-order добавляет этому чувству.
Но, возможно, я все-таки не прав, и простая настройка сделает msbuild эффективной во второй сборке, поскольку devenv есть.
Любые идеи о том, как заставить msbuild вести себя безопасно во второй сборке?
РЕДАКТИРОВАТЬ 1
Задача CompileXaml является частью цели MarkupCompilePass1, найденной в 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>
Как мы видим, нет входов и выходов.
Далее, журнал diag msbuild для второй сборки не содержит никаких подозрительных слов, таких как "перестройка".
Наконец, я хотел бы заметить, что и msbuild, и devenv осуществлялись при одинаковых обстоятельствах, и никто не использовал многопоточную сборку. Тем не менее разница неистоща - более 5 минут (msbuild) против 3 секунд (devenv, командная строка).
Еще одна загадка для меня.
РЕДАКТИРОВАТЬ 2
Теперь я знаю, как работает devenv. Он использует эвристику, чтобы определить, должен ли текущий проект быть передан в msbuild в первую очередь. Эта эвристика включена по умолчанию, но ее можно отключить, установив для свойства DisableFastUpToDateCheck msbuild значение true.
Теперь для построения командной строки devenv требуется больше 3 секунд, чтобы выяснить, нужно ли запускать msbuild или нет. В целом для решения, подобного моему, может потребоваться 20 секунд или даже 30 секунд, чтобы решить, что ничего не нужно передавать в msbuild.
Эта эвристика является единственной причиной этого огромного разного времени. Я думаю, что команда Visual Studio признала низкое качество стандартных скриптов сборки (где такие задачи, как MarkupCompilePass1, не управляются входами и выходами) и решили придумать способ пропустить msbuild в первую очередь.
Но есть улов - эвристика проверяет только файл csproj, ни один из импортированных файлов целей не проверяется. Кроме того, он ничего не знает о неявных зависимостях, таких как TypeScript файлы, на которые ссылаются другие файлы TypeScript. Итак, если ваши файлы TypeScript ссылаются на другие TypeScript файлы, принадлежащие другому проекту и не связанные явно с файлом проекта, эвристика не знает о них, и вам лучше иметь DisableFastUpToDateCheck = true. Сборка будет медленнее, но, по крайней мере, она будет правильной.
В нижней строке - я не знаю, как исправить msbuild и, по-видимому, деввеновцы тоже. Это, по-видимому, причина, по которой они изобретают эвристику.
