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
- Anonymous
August 28, 2006
Carl Daniel (code) and Robert Downey (code) each wrote and posted code to show the changesets between...