15

我有一个包含 109 个项目的解决方案。混合所有 - .NET、Silverlight、MVC、Web 应用程序、控制台应用程序。

现在我使用 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

美好的。现在我再次运行相同的命令行并得到以下信息:

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

这提出了以下问题:

  1. 为什么ResolveAssemblyReference在第二次构建中花费这么多时间?在第一次构建中创建的所有缓存文件仍然存在。什么也没有变。那么为什么它与以前几乎相同 - 97 秒对 106 秒?
  2. 为什么ValidateXaml并且CompileXaml正在运行?我的意思是自完整构建以来没有任何改变!

现在我重复相同的实验,但这次我devenv在命令行上构建而不是msbuild. 与 msbuild 一样,不使用并行构建,并且日志级别为 diag。

devenv最后没有提供这么好的总结,它必须从每个项目的总结中手动聚合。

结果让我吃惊。我使用以下 powershell 脚本来汇总经过的时间:

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 脚本来汇总统计信息:

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

在第一个(完整)构建的日志上运行它会产生以下输出:

     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

我们在这里谈论完全相同的解决方案!

最后,这是我使用该解决方案构建的脚本:

构建:

@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

开发环境:

@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# 解决方案。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任务是在C:\Program Files (x86)\MSBuild\Microsoft\Silverlight\v5.0\Microsoft.Silverlight.Common.targetsMarkupCompilePass1中找到的目标的一部分:

<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 日志不包含任何可疑词,例如“rebuilding”。

最后,我想注意到 msbuild 和 devenv 都是在完全相同的情况下执行的,并且没有一个使用多线程构建。然而差异是巨大的——超过 5 分钟(msbuild)与 3 秒(devenv,命令行)。

对我来说仍然是一个完全的谜。

编辑 2

我现在更了解devenv构建是如何工作的。它使用启发式方法来确定当前项目是否必须首先移交给 msbuild。此启发式默认启用,但可以通过将DisableFastUpToDateCheckmsbuild 属性设置为 来禁用true

现在,命令行 devenv 构建实际上需要 3 秒以上才能确定是否需要运行 msbuild。总而言之,对于像我这样的解决方案,可能需要 20 秒甚至 30 秒才能确定不需要将任何内容传递给 msbuild。

这种启发式方法是造成这种巨大时间差异的唯一原因。我猜 Visual Studio 团队认识到标准构建脚本的质量很差(其中像 MarkupCompilePass1 这样的任务不是由输入和输出驱动的),并决定首先想出一种跳过 msbuild 的方法。

但是有一个问题——启发式只检查 csproj 文件,没有检查导入的目标文件。此外,它对隐式依赖一无所知——比如从其他 TypeScript 文件引用的 TypeScript 文件。因此,如果您的 TypeScript 文件引用了属于不同项目且未从项目文件显式链接的其他 TypeScript 文件 - 启发式不知道它们,您最好拥有DisableFastUpToDateCheck = true. 构建会更慢,但至少它是正确的。

底线 - 我不知道如何修复 msbuild,显然 devenv 人也不知道。这似乎是他们发明启发式的原因。

4

1 回答 1

4

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.

于 2014-03-28T20:55:12.300 回答