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 2^nd 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!