TeamSystemNotes

In my last post on Monitoring Build Performance I showed a report that you can use to identify when your builds aren’t performing as expected. So how do you drill into a particular build to find out where the most time was spent?

One way to do this is to run your build with diagnostic logging by passing /v:diag when you queue the build. This will increase MSBuild’s logging verbosity to diagnostic and at this level of logging when the build completes a list of each target executed and how long it was executed for will be added to the build log. For example:

      144 ms  CoreTest                                   1 calls
      467 ms  CoreDropBuild                              1 calls
      471 ms  CoreGetChangesetsAndUpdateWorkItems        1 calls
      529 ms  InitializeEndToEndIteration                1 calls
     1031 ms  CoreSimian                                 1 calls
     1295 ms  CoreInitializeWorkspace                    1 calls
     1322 ms  CoreLabel                                  1 calls
     1367 ms  Build                                      3 calls
     1888 ms  CoreCompileSolution                        1 calls
     1986 ms  CoreCompileConfiguration                   1 calls
     2179 ms  CallCompile                                1 calls
     2799 ms  CoreCompile                                3 calls
     9744 ms  CoreGet                                    1 calls

This assumes that you know before the build is executed that you want to investigate its performance, what if you want to investigate the performance of an already completed build? Or what if your log files are an unmanageable size with diagnostic logging enabled. In these circumstances we can query how long each step takes from the Team Build operational database (TfsBuild).

Caveat: The operational databases are undocumented, unsupported, you should never insert, update, or delete rows, and you should be careful querying them to minimise performance impact caused by read locks.

Still reading? Of course you are. The query below returns a list of the build steps for a particular build in descending order by duration. You’ll need to set the DefinitionName and BuildNumber to the relevant values for the build you want to query, but watch out, the values in these columns do not match exactly what you see in the user interface. The values in the database have a trailing backslash and replace some characters (for example, underscore) with a right angle bracket. You should query the build definition and build tables to check the exact values to query for.

SELECT Name,
       Message,
       CONVERT(datetime, LEFT(StartTime,23) + 'Z', 127) AS StartTime,
       CONVERT(datetime, LEFT(FinishTime,23) + 'Z', 127) AS FinishTime,
       Status,
       DATEDIFF(s,
           CONVERT(datetime, LEFT(StartTime,23) + 'Z', 127),
           CONVERT(datetime, LEFT(FinishTime,23) + 'Z', 127)
       )/60.0 AS Duration
  FROM (
           SELECT BI.NodeId,
                  BIF.FieldName,
                  BIF.FieldValue
             FROM tbl_BuildDefinition BD
                  INNER JOIN tbl_Build B ON BD.DefinitionId = B.DefinitionId
                  INNER JOIN tbl_BuildInformation BI ON B.BuildId = BI.BuildId
                  INNER JOIN tbl_BuildInformationField BIF ON BI.NodeId = BIF.NodeId
                  INNER JOIN tbl_BuildInformationType IT ON BI.NodeType = IT.NodeType
            WHERE BD.DefinitionName = 'Main>Daily\'
                  AND B.BuildNumber = '699.0.1.793\'
                  AND IT.TypeName = 'BuildStep'
                  AND BI.ParentId IS NULL
        ) SourceTable
        PIVOT
        (
            MIN(FieldValue) FOR FieldName IN ( FinishTime, Message, Name, StartTime, Status )
        ) PivotTable
ORDER BY Duration DESC

For example:

Developers love nothing more than complaining about how long their builds take, sometimes their complaints are justified and sometimes they’re not. Even worse sometimes performance degrades slowly over time and no one notices.

To better quantify how long builds are taking I created a Build Performance report that is emailed to me monthly. This report gives the minimum, maximum, and average build duration (in minutes) for each of our main build definitions over the last 12 months.

Below is an example of that report and you can download the Build Performance Report Definition for SQL Server 2005 Reporting Services from here. If you want to restrict the build definitions that are included you can add an additional condition to the WHERE clause:

AND (
    [Build].[Build Type] LIKE ‘DEV_._’
    OR [Build].[Build Type] = ‘Main’
)

This report was made better thanks to SSW’s Rules to Better MS SQL Reporting Services.