Measuring Performance of TeamBuild Build Process


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!


Comments (1)

  1. Buck Hodges says:

    Carl Daniel (code) and Robert Downey (code) each wrote and posted code to show the changesets between…