The enterprise builds are huge and take a significant amount of build time. MSBuild offers an option to track the performance of each task and target executed in the build process which would be quite helpful for builders to identify the performance problems and improve the build time. I’m attempting to provide some details on how this can be plugged into TeamBuild.

 

MSBuild loggers have an option called PerformanceSummary to log this data. The user will need to add the following command line option to the msbuild process that runs on the build machine (refer here for more details on how to pass additional options to msbuild command line in TeamBuild):

 

/logger:FileLogger,Microsoft.Build.Engine;logfile=buildperf.log;encoding=Unicode;performancesummary

 

This creates the build log file that contains performance data buildperf.log at <builddir>\<teamproject>\<buildtype>\buildtype on the build machine. Currently, I could not find a way to upload this to drop location, because it needs to be uploaded after msbuild process exits and we currently don’t have a way to do this. BTW, this option is enabled in 'diagnostic' mode. So, user can pass '/v:diag' to msbuild command line and get this data in BuildLog.txt itself. It will have lots of other noise though.

 

Here is a snapshot of the performance data that msbuild process would log:

 

Project Performance Summary:

1302 ms  d:\builddir\TestProject\Take1\Sources\WindowsApplication1\WindowsApplication1\WindowsApplication1.csproj   1 calls

1593 ms  d:\builddir\TestProject\Take1\Sources\WindowsApplication2\WindowsApplication2.sln   1 calls

18549 ms  d:\builddir\TestProject\Take1\BuildType\TFSBuild.proj   1 calls

 

Target Performance Summary:

        * ms  Build                                      1 calls

        * ms  CoreCompile                                1 calls

        0 ms  Clean                                      1 calls

        0 ms  BeforeResGen                               1 calls

        0 ms  PostBuild                                  1 calls

        0 ms  BuildNumberOverrideTarget                  1 calls

        0 ms  BeforeClean                                1 calls

        0 ms  _CheckForInvalidConfigurationAndPlatform   1 calls

        0 ms  BeforeDropBuild                            1 calls

        0 ms  GetCopyToOutputDirectoryItems              1 calls

        0 ms  PackageBinaries                            1 calls

        0 ms  _CleanGetCurrentAndPriorFileWrites         1 calls

        0 ms  GetTargetPath                              1 calls

        0 ms  PreBuild                                   1 calls

        0 ms  _CopyFilesMarkedCopyLocal                  1 calls

        0 ms  _CheckForCompileOutputs                    1 calls

        0 ms  AssignTargetPaths                          1 calls

        0 ms  Compile                                    2 calls

        0 ms  BeforeBuild                                1 calls

        0 ms  _CopySourceItemsToOutputDirectory          1 calls

        0 ms  AfterBuild                                 1 calls

        0 ms  AfterResGen                                1 calls

        0 ms  AfterResolveReferences                     1 calls

        0 ms  Test                                       1 calls

        0 ms  AfterCompile                               2 calls

        0 ms  CoreBuild                                  1 calls

        0 ms  GetRedistLists                             1 calls

        0 ms  PrepareResources                           1 calls

        0 ms  AfterEndToEndIteration                     1 calls

        0 ms  AfterLabel                                 1 calls

        0 ms  ResolveReferences                          1 calls

        0 ms  BeforeEndToEndIteration                    1 calls

        0 ms  ValidateSolutionConfiguration              1 calls

        0 ms  BuildOnlySettings                          1 calls

        0 ms  DropBuild                                  1 calls

        0 ms  ResGen                                     1 calls

        0 ms  PrepareResourceNames                       1 calls

        0 ms  SplitResourcesByCulture                    1 calls

        0 ms  BeforeResolveReferences                    1 calls

        0 ms  AfterGet                                   1 calls

        0 ms  TeamBuild                                  1 calls

        0 ms  PrepareRdlFiles                            1 calls

        0 ms  CompileRdlFiles                            1 calls

        0 ms  AfterTest                                  1 calls

        0 ms  BeforeGet                                  1 calls

        0 ms  AfterDropBuild                             1 calls

        0 ms  BeforeLabel                                1 calls

        0 ms  EndToEndIteration                          1 calls

        0 ms  PrepareForRun                              1 calls

        0 ms  AfterClean                                 1 calls

        0 ms  GetFrameworkPaths                          1 calls

       10 ms  CopyFilesToOutputDirectory                 1 calls

       10 ms  PrepareForBuild                            1 calls

       10 ms  CopyLogFiles                               1 calls

       10 ms  CreateManifestResourceNames                1 calls

       10 ms  IncrementalClean                           1 calls

       20 ms  InitializeBuild                            1 calls

       40 ms  CoreClean                                  1 calls

       50 ms  CoreResGen                                 1 calls

       50 ms  CoreDropBuild                              1 calls

      150 ms  ResolveAssemblyReferences                  1 calls

      150 ms  BeforeTest                                 1 calls

      170 ms  InitializeEndToEndIteration                1 calls

      180 ms  BeforeCompile                              2 calls

      220 ms  CheckSettingsForEndToEndIteration          1 calls

     1332 ms  WindowsApplication2                        1 calls

     1462 ms  CoreLabel                                  1 calls

     2354 ms  InitializeWorkspace                        1 calls

     3976 ms  CoreGet                                    1 calls

     5318 ms  GetChangeSetsAndUpdateWorkItems            1 calls

        (* = timing was not recorded because of reentrancy)

 

Task Performance Summary:

        * ms  MSBuild                                    1 calls

        0 ms  RemoveDuplicates                           2 calls

        0 ms  CreateCSharpManifestResourceName           1 calls

        0 ms  GetFrameworkSDKPath                        1 calls

        0 ms  FindUnderPath                              5 calls

        0 ms  ReadLinesFromFile                          1 calls

        0 ms  AssignTargetPath                           5 calls

        0 ms  AssignCulture                              1 calls

        0 ms  CreateProperty                            12 calls

        0 ms  GetFrameworkPath                           1 calls

       10 ms  MakeDir                                    5 calls

       10 ms  Delete                                     1 calls

       10 ms  TeamBuildMessage                           3 calls

       10 ms  CreateItem                                17 calls

       20 ms  RemoveDir                                  1 calls

       20 ms  WriteLinesToFile                           2 calls

       30 ms  Message                                   11 calls

       50 ms  GenerateResource                           1 calls

       60 ms  Copy                                       8 calls

      140 ms  ResolveAssemblyReference                   1 calls

      170 ms  UpdateBuildNumberDropLocation              1 calls

      250 ms  DeleteWorkspaceTask                        1 calls

      671 ms  Csc                                        1 calls

     1342 ms  CallTarget                                 1 calls

     1462 ms  Label                                      1 calls

     2103 ms  CreateWorkspaceTask                        1 calls

     3706 ms  Get                                        1 calls

     5318 ms  GenCheckinNotesUpdateWorkItems             1 calls

        (* = timing was not recorded because of reentrancy)

 

 

The first section gives details about the time taken to complete each project. The 2nd section gives details at an indiviudal target level and the the final secion explains about average time taken by each task.

 

In the above example, the end-to-end build took 18.549 secs to complete from which Get action took 3.976 secs, creating workspace took 2.354 secs, gathering changesets took 5.318 secs and the actual compilation took 1.332 secs.

 

Namaste!