VC++ Tip: Get detailed build throughput diagnostics using MSBuild, compiler and linker

VC++ Tip: Get detailed build throughput diagnostics using MSBuild, compiler and linker

  • Comments 4

We know that build throughput for applications are a time crunch on developer productivity. We have spent some time on improving linker throughput and other areas in VS2010, and will continue to investigate improving overall build throughput in future releases.

In this blog post, we will describe a couple of options to get diagnostics for your projects using MSBuild and then taking a deeper dive into the compiler and the linker.

Using MSBuild

Using the IDE, you can enable Timing Logging by setting “Tools/Options/Projects and Solutions/VC++ Project Settings/Build Timings” = “Yes” or raise the verbosity of the build to “Diagnostics” from “Tools/Options/Project and Solutions/Build and Run/MSBuild project build output verbosity”.

Using these options, you can get performance summaries per project and also get details on where time is spent on targets and tasks. This sort of information is useful say when you are trying to figure out how long that copy task is taking to copy your files over from across folders.

1>------ Rebuild All started: Project: mfc-app, Configuration: Debug Win32 ------

1>Build started 1/12/2010 5:31:58 PM.

1>_PrepareForClean:

1>  Deleting file "Debug\mfc-app.lastbuildstate".

1>InitializeBuildStatus:

1>  Creating "Debug\mfc-app.unsuccessfulbuild" because "AlwaysCreate" was specified.

1>ClCompile:

1>  stdafx.cpp

...............

1>  ChildFrm.cpp

1>  Generating Code...

1>Manifest:

1>  Deleting file "Debug\mfc-app.exe.embed.manifest".

1>LinkEmbedManifest:

1>  mfc-app.vcxproj -> C:\Users\user\documents\visual studio 2010\Projects\mfc-app\Debug\mfc-app.exe

1>FinalizeBuildStatus:

1>  Deleting file "Debug\mfc-app.unsuccessfulbuild".

1>  Touching "Debug\mfc-app.lastbuildstate".

1>

1>Project Performance Summary:

1>    17877 ms  C:\Users\user\documents\visual studio 2010\Projects\mfc-app\mfc-app\mfc-app.vcxproj   1 calls

1>              17877 ms  rebuild                                    1 calls

1>

1>Target Performance Summary:

1>        0 ms  CreateCustomManifestResourceNames          1 calls

...............

1>      630 ms  LinkEmbedManifest                          1 calls

1>      956 ms  Manifest                                   1 calls

1>     2419 ms  Link                                       1 calls

1>    12738 ms  ClCompile                                  1 calls

1>

1>Task Performance Summary:

1>        0 ms  FindUnderPath                              2 calls

...............

1>     3035 ms  Link                                       2 calls

1>    12733 ms  CL                                         2 calls

1>

1>Build succeeded.

1>

1>Time Elapsed 00:00:17.89

========== Rebuild All: 1 succeeded, 0 failed, 0 skipped ==========

Compiler and Linker switches

There are a couple of “hidden” undocumented switches that you could use to diagnose where you are spending most of your build times. /Bt and /time switches could be valuable to you if you are interested to know about where time is being spent.

We use /Bt+ and /time+ pairings for our internal throughput runs where a tool takes as input the output timings and generates a summary listing of time spent per component. This allows us to get throughput measurements for individual components. (A useful tool for someone to write and contribute to code gallery ;-) )

Note on hidden switches:

These are switches that we sometimes expose for diagnostic purposes. They are not documented and will/could change in future releases. Please use them with discretion.

Usage

·         To get less verbose output, use “cl /Bt” or “link /time”

·         To get more verbose output, use “cl /Bt+” or “link /time+” (Works in VS2010 only)

Using compiler switch “/Bt”

Add “/Bt” to your compiler options directly on the command line or go to project properties and add “/Bt” to Additional options in “Configuration Properties/C/C++/Command Line”. After building, the highlighted text will tell you how much time was spent in c1xx (front end compiler) and c2 (back end compiler)

1>------ Rebuild All started: Project: mfc-app, Configuration: Debug Win32 ------

1>Build started 1/13/2010 10:44:51 AM.

1>_PrepareForClean:

1>  Deleting file "Debug\mfc-app.lastbuildstate".

1>InitializeBuildStatus:

1>  Creating "Debug\mfc-app.unsuccessfulbuild" because "AlwaysCreate" was specified.

1>ClCompile:

1>  stdafx.cpp

1>  time(C:\Program Files (x86)\Microsoft Visual Studio 10.0\VC\bin\c1xx.dll)=6.914s

1>  time(C:\Program Files (x86)\Microsoft Visual Studio 10.0\VC\bin\c2.dll)=0.064s

……

1>  Generating Code...

1>  time(C:\Program Files (x86)\Microsoft Visual Studio 10.0\VC\bin\c2.dll)=0.011s

……

1>  time(C:\Program Files (x86)\Microsoft Visual Studio 10.0\VC\bin\c2.dll)=0.005s

1>Manifest:

1>  Deleting file "Debug\mfc-app.exe.embed.manifest".

1>LinkEmbedManifest:

1>  mfc-app.vcxproj -> C:\Users\user\documents\visual studio 2010\Projects\mfc-app\Debug\mfc-app.exe

1>FinalizeBuildStatus:

1>  Deleting file "Debug\mfc-app.unsuccessfulbuild".

1>  Touching "Debug\mfc-app.lastbuildstate".

1>

1>Build succeeded.

1>

1>Time Elapsed 00:00:10.92

========== Rebuild All: 1 succeeded, 0 failed, 0 skipped ==========

Using linker switch “/time”

Add “/time” to your linker options directly on the command line or go to project properties and add “/time” to Additional options in Configuration Properties->Linker->Command Line. The highlighted text will tell you how much time was spent in each pass of the linker. See more on why linker does multiple passes here

Note on LTCG: Link time code generation or LTCG is where the linker calls the back end (c2.dll) to do code generation. Thus, if you use generate LTCG builds, you may see that a lot of time is spent in the linker though it is the back end compiler that is doing all the work.

1>------ Rebuild All started: Project: mfc-app, Configuration: Debug Win32 ------

1>Build started 1/13/2010 10:47:39 AM.

1>_PrepareForClean:

1>  Deleting file "Debug\mfc-app.lastbuildstate".

1>InitializeBuildStatus:

1>  Creating "Debug\mfc-app.unsuccessfulbuild" because "AlwaysCreate" was specified.

1>ClCompile:

….

1>  Generating Code...

1>Link:

1>  Pass 1: Interval #1, time = 0.187s

1>    Wait PDB close: Total time = 0.484s

1>  Pass 2: Interval #2, time = 0.578s

1>  Final: Total time = 0.765s

1>Manifest:

1>  Deleting file "Debug\mfc-app.exe.embed.manifest".

1>LinkEmbedManifest:

1>  IncrPass2: Interval #1, time = 0.062s

1>  IncrPass2: Interval #2, time = 0.032s

1>  Final: Total time = 0.094s

1>  mfc-app.vcxproj -> C:\Users\user\documents\visual studio 2010\Projects\mfc-app\Debug\mfc-app.exe

1>FinalizeBuildStatus:

1>  Deleting file "Debug\mfc-app.unsuccessfulbuild".

1>  Touching "Debug\mfc-app.lastbuildstate".

1>

1>Build succeeded.

1>

1>Time Elapsed 00:00:10.82

========== Rebuild All: 1 succeeded, 0 failed, 0 skipped ==========

 

If you have any questions or have tips/stories that you would like to share, please post a comment to this blog and we will respond where appropriate.

Thanks,

Vikas Bhatia

VC++ Team

 

  • "If you have any questions or have tips/stories that you would like to share, please post a comment to this blog and we will respond where appropriate."

    Thanks; I've got such a request:  Could we have a post detailing how the Minimal Rebuild (/Gm) option makes its decisions about what to rebuild?  I've found that it often fails to recognize changes to templates as significant.

  • GeeWhiz

    But then what?  Did I miss the part where I can use the results to do something with, or is it really only just gee whiz?  File copy time?  Not a complaint, because I'm sure you think it's slick, but if we can't do anything meaningful with it, it's just a whole lot more noise.  Better would be fully documenting the compiler, the linker, the librarian, and the resource compiler, things we can use all the time.  Pushing a button, walking away to come back to

    Touching "Debug\mfc-app.myself.lastbuildstate".

    is not that useful.

  • I disagree with the previous comment about this just being a "geewhiz" post - this is useful information indeed, especially when trying to optimize complex build environments. It also helps to better correlate build options to output timing.

    If you don't see how this would be useful to you, then it probably isn't. But some of us, it certainly will be.

    Thanks for sharing this, Vikas.

  • @Mark R.: Couldn't agree more. Full ACK!

Page 1 of 1 (4 items)