MSBuild is taking very long time to execute

Question

I have a TFS Build that takes around 70 minutes or so to complete, but it used to take around 2 minutes to complete,so something has probably changed on the build agent that casue this.

In the log I get very little information about what is taking so long.

What is the best approach to narrow the problem down?

Answer 1

I found a way to get more details in the build log.

I did this by setting the "Logging Verbosity" to the value Diagnostic:

In the detailed text log file I could then see exactly how long each task took:

Task Performance Summary:
    2 ms  CreateCSharpManifestResourceName           1 calls
    4 ms  AssignCulture                              7 calls
    5 ms  ConvertToAbsolutePath                      7 calls
    8 ms  ReadLinesFromFile                          7 calls
    9 ms  RemoveDuplicates                          14 calls
   11 ms  Delete                                    11 calls
   15 ms  WriteLinesToFile                           8 calls
   19 ms  FindAppConfigFile                          7 calls
   22 ms  AssignProjectConfiguration                 6 calls
   24 ms  GetFrameworkPath                           7 calls
   26 ms  AssignTargetPath                          35 calls
   35 ms  SetBuildProperties                         1 calls
   41 ms  FindUnderPath                             35 calls
   44 ms  MakeDir                                   13 calls
   81 ms  MSBuild.Community.Tasks.XmlRead           16 calls
  123 ms  Message                                   67 calls
  131 ms  GetBuildProperties                         2 calls
  185 ms  GetReferenceAssemblyPaths                  6 calls
  186 ms  WorkspaceItemConverterTask                 1 calls
  340 ms  CreateItem                                21 calls
  390 ms  Combine                                    8 calls
  913 ms  UpdateConfiguration                        3 calls
 1029 ms  BuildStep                                  6 calls
 3301 ms  MSBuild.ExtensionPack.Web.Iis7AppPool      4 calls
 4768 ms  UpdateBuildNumberDropLocation              1 calls
 5411 ms  CreateWorkspaceTask                        1 calls
 5685 ms  Label                                      1 calls
 6360 ms  StyleCopTask                               5 calls
 7922 ms  ResolveAssemblyReference                   7 calls
 9028 ms  Csc                                        7 calls
10190 ms  DeleteWorkspaceTask                        1 calls
10195 ms  Folder.CleanFolder                         6 calls
10295 ms  GetImpactedTests                           1 calls
15302 ms  GenCheckinNotesUpdateWorkItems             1 calls
18229 ms  Exec                                       6 calls
19456 ms  RemoveDir                                  8 calls
20001 ms  MSBuild.Community.Tasks.Sleep              2 calls
22521 ms  Copy                                     301 calls
22715 ms  Folder.CopyFolder                         12 calls
28062 ms  CallTarget                                18 calls
41211 ms  Get                                        1 calls
3418260 ms  SqlCmd                                   8 calls
10539420 ms  MSBuild                                43 calls

Answer 2

When you view the Build Log it tells you exactly how long was spent in each step. For example if you look at the screenshot below it tells me:

• The build took 2:48 in total
• It took 2 seconds to download the source
• It took 2:32 to compile + test
• 2:24 of that was spent doing the build/compile

If I were to keep scrolling I can see how the 2:24 of compile time was broken down by project, and I can figure out where the other 0:24 of the build was spent.