{"id":3943,"date":"2010-04-01T14:23:00","date_gmt":"2010-04-01T14:23:00","guid":{"rendered":"https:\/\/blogs.msdn.microsoft.com\/vcblog\/2010\/04\/01\/vc-tip-get-detailed-build-throughput-diagnostics-using-msbuild-compiler-and-linker\/"},"modified":"2019-02-18T18:45:34","modified_gmt":"2019-02-18T18:45:34","slug":"vc-tip-get-detailed-build-throughput-diagnostics-using-msbuild-compiler-and-linker","status":"publish","type":"post","link":"https:\/\/devblogs.microsoft.com\/cppblog\/vc-tip-get-detailed-build-throughput-diagnostics-using-msbuild-compiler-and-linker\/","title":{"rendered":"VC++ Tip: Get detailed build throughput diagnostics using MSBuild, compiler and linker"},"content":{"rendered":"

<\/p>\n

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

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

Using MSBuild<\/p>\n

<\/strong><\/font><\/span><\/u><\/p>\n

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”.<\/p>\n

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.<\/p>\n

1>—— Rebuild All started: Project: mfc-app, Configuration: Debug Win32 ——<\/p>\n

<\/span><\/p>\n

1>Build started 1\/12\/2010 5:31:58 PM.<\/p>\n

<\/span><\/p>\n

1>_PrepareForClean:<\/p>\n

<\/span><\/p>\n

1>  Deleting file “Debugmfc-app.lastbuildstate”.<\/p>\n

<\/span><\/p>\n

1>InitializeBuildStatus:<\/p>\n

<\/span><\/p>\n

1>  Creating “Debugmfc-app.unsuccessfulbuild” because “AlwaysCreate” was specified.<\/p>\n

<\/span><\/p>\n

1>ClCompile:<\/p>\n

<\/span><\/p>\n

1>  stdafx.cpp<\/p>\n

<\/span><\/p>\n

……………<\/p>\n

<\/span><\/p>\n

1>  ChildFrm.cpp<\/p>\n

<\/span><\/p>\n

1>  Generating Code…<\/p>\n

<\/span><\/p>\n

1>Manifest:<\/p>\n

<\/span><\/p>\n

1>  Deleting file “Debugmfc-app.exe.embed.manifest”.<\/p>\n

<\/span><\/p>\n

1>LinkEmbedManifest:<\/p>\n

<\/span><\/p>\n

1>  mfc-app.vcxproj -> C:Usersuserdocumentsvisual studio 2010Projectsmfc-appDebugmfc-app.exe<\/p>\n

<\/span><\/p>\n

1>FinalizeBuildStatus:<\/p>\n

<\/span><\/p>\n

1>  Deleting file “Debugmfc-app.unsuccessfulbuild”.<\/p>\n

<\/span><\/p>\n

1>  Touching “Debugmfc-app.lastbuildstate”.<\/p>\n

<\/span><\/p>\n

1><\/p>\n

<\/span><\/p>\n

1>Project Performance Summary:<\/p>\n

<\/span><\/p>\n

1>    17877 ms  C:Usersuserdocumentsvisual studio 2010Projectsmfc-appmfc-appmfc-app.vcxproj   1 calls<\/p>\n

<\/span><\/p>\n

1>              17877 ms  rebuild                                    1 calls<\/p>\n

<\/span><\/p>\n

1><\/p>\n

<\/span><\/p>\n

1>Target Performance Summary:<\/p>\n

<\/span><\/p>\n

1>        0 ms  CreateCustomManifestResourceNames          1 calls<\/p>\n

<\/span><\/p>\n

……………<\/p>\n

<\/span><\/p>\n

1>      630 ms  LinkEmbedManifest                          1 calls<\/p>\n

<\/span><\/p>\n

1>      956 ms  Manifest                                   1 calls<\/p>\n

<\/span><\/p>\n

1>     2419 ms  Link                                       1 calls<\/p>\n

<\/span><\/p>\n

1>    12738 ms  ClCompile                                  1 calls<\/p>\n

<\/span><\/p>\n

1><\/p>\n

<\/span><\/p>\n

1>Task Performance Summary:<\/p>\n

<\/span><\/p>\n

1>        0 ms  FindUnderPath                              2 calls<\/p>\n

<\/span><\/p>\n

……………<\/p>\n

<\/span><\/p>\n

1>     3035 ms  Link                                       2 calls<\/p>\n

<\/span><\/p>\n

1>    12733 ms  CL                                         2 calls<\/p>\n

<\/span><\/p>\n

1><\/p>\n

<\/span><\/p>\n

1>Build succeeded.<\/p>\n

<\/span><\/p>\n

1><\/p>\n

<\/span><\/p>\n

1>Time Elapsed 00:00:17.89<\/p>\n

<\/span><\/p>\n

========== Rebuild All: 1 succeeded, 0 failed, 0 skipped ==========<\/span><\/p>\n

Compiler and Linker switches<\/p>\n

<\/font><\/span><\/u><\/h2>\n

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. <\/p>\n

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<\/a> \ud83d\ude09 )<\/p>\n

Note on hidden switches: <\/p>\n

<\/b><\/p>\n

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. <\/span><\/p>\n

<\/b><\/p>\n

Usage<\/p>\n

<\/b><\/p>\n

·         <\/span><\/span><\/span>To get less verbose output, use “cl \/Bt” or “link \/time”<\/p>\n

·         <\/span><\/span><\/span>To get more verbose output, use “cl \/Bt+” or “link \/time+” (Works in VS2010 only)<\/p>\n

Using compiler switch “\/Bt”<\/p>\n

<\/font><\/span><\/u><\/h2>\n

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<\/font><\/a>) and c2 (back end compiler<\/font><\/a>)<\/p>\n

1>—— Rebuild All started: Project: mfc-app, Configuration: Debug Win32 ——<\/p>\n

<\/span><\/p>\n

1>Build started 1\/13\/2010 10:44:51 AM.<\/p>\n

<\/span><\/p>\n

1>_PrepareForClean:<\/p>\n

<\/span><\/p>\n

1>  Deleting file “Debugmfc-app.lastbuildstate”.<\/p>\n

<\/span><\/p>\n

1>InitializeBuildStatus:<\/p>\n

<\/span><\/p>\n

1>  Creating “Debugmfc-app.unsuccessfulbuild” because “AlwaysCreate” was specified.<\/p>\n

<\/span><\/p>\n

1>ClCompile:<\/p>\n

<\/span><\/p>\n

1>  stdafx.cpp<\/p>\n

<\/span><\/p>\n

1>  time(C:Program Files (x86)Microsoft Visual Studio 10.0VCbinc1xx.dll)=6.914s<\/p>\n

<\/span><\/p>\n

1>  time(C:Program Files (x86)Microsoft Visual Studio 10.0VCbinc2.dll)=0.064s<\/span><\/p>\n

<\/span><\/p>\n

……<\/p>\n

<\/span><\/p>\n

1>  Generating Code…<\/p>\n

<\/span><\/p>\n

1>  time(C:Program Files (x86)Microsoft Visual Studio 10.0VCbinc2.dll)=0.011s<\/p>\n

<\/span><\/p>\n

……<\/p>\n

<\/span><\/p>\n

1>  time(C:Program Files (x86)Microsoft Visual Studio 10.0VCbinc2.dll)=0.005s<\/p>\n

<\/span><\/p>\n

1>Manifest:<\/p>\n

<\/span><\/p>\n

1>  Deleting file “Debugmfc-app.exe.embed.manifest”.<\/p>\n

<\/span><\/p>\n

1>LinkEmbedManifest:<\/p>\n

<\/span><\/p>\n

1>  mfc-app.vcxproj -> C:Usersuserdocumentsvisual studio 2010Projectsmfc-appDebugmfc-app.exe<\/p>\n

<\/span><\/p>\n

1>FinalizeBuildStatus:<\/p>\n

<\/span><\/p>\n

1>  Deleting file “Debugmfc-app.unsuccessfulbuild”.<\/p>\n

<\/span><\/p>\n

1>  Touching “Debugmfc-app.lastbuildstate”.<\/p>\n

<\/span><\/p>\n

1><\/p>\n

<\/span><\/p>\n

1>Build succeeded.<\/p>\n

<\/span><\/p>\n

1><\/p>\n

<\/span><\/p>\n

1>Time Elapsed 00:00:10.92<\/p>\n

<\/span><\/p>\n

========== Rebuild All: 1 succeeded, 0 failed, 0 skipped ==========<\/span><\/p>\n

Using linker switch “\/time”<\/p>\n

<\/font><\/span><\/u><\/h2>\n

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<\/font><\/a><\/p>\n

Note on LTCG: Link time code generation<\/font><\/a> or LTCG<\/font><\/a> 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.<\/p>\n

1>—— Rebuild All started: Project: mfc-app, Configuration: Debug Win32 ——<\/p>\n

<\/span><\/p>\n

1>Build started 1\/13\/2010 10:47:39 AM.<\/p>\n

<\/span><\/p>\n

1>_PrepareForClean:<\/p>\n

<\/span><\/p>\n

1>  Deleting file “Debugmfc-app.lastbuildstate”.<\/p>\n

<\/span><\/p>\n

1>InitializeBuildStatus:<\/p>\n

<\/span><\/p>\n

1>  Creating “Debugmfc-app.unsuccessfulbuild” because “AlwaysCreate” was specified.<\/p>\n

<\/span><\/p>\n

1>ClCompile:<\/p>\n

<\/span><\/p>\n

….<\/p>\n

<\/span><\/p>\n

1>  Generating Code…<\/p>\n

<\/span><\/p>\n

1>Link:<\/p>\n

<\/span><\/p>\n

1>  Pass 1: Interval #1, time = 0.187s<\/p>\n

<\/span><\/p>\n

1>    Wait PDB close: Total time = 0.484s<\/p>\n

<\/span><\/p>\n

1>  Pass 2: Interval #2, time = 0.578s<\/p>\n

<\/span><\/p>\n

1>  Final: Total time = 0.765s<\/span><\/p>\n

<\/span><\/p>\n

1>Manifest:<\/p>\n

<\/span><\/p>\n

1>  Deleting file “Debugmfc-app.exe.embed.manifest”.<\/p>\n

<\/span><\/p>\n

1>LinkEmbedManifest:<\/p>\n

<\/span><\/p>\n

1>  IncrPass2: Interval #1, time = 0.062s<\/p>\n

<\/span><\/p>\n

1>  IncrPass2: Interval #2, time = 0.032s<\/p>\n

<\/span><\/p>\n

1>  Final: Total time = 0.094s<\/span><\/p>\n

<\/span><\/p>\n

1>  mfc-app.vcxproj -> C:Usersuserdocumentsvisual studio 2010Projectsmfc-appDebugmfc-app.exe<\/p>\n

<\/span><\/p>\n

1>FinalizeBuildStatus:<\/p>\n

<\/span><\/p>\n

1>  Deleting file “Debugmfc-app.unsuccessfulbuild”.<\/p>\n

<\/span><\/p>\n

1>  Touching “Debugmfc-app.lastbuildstate”.<\/p>\n

<\/span><\/p>\n

1><\/p>\n

<\/span><\/p>\n

1>Build succeeded.<\/p>\n

<\/span><\/p>\n

1><\/p>\n

<\/span><\/p>\n

1>Time Elapsed 00:00:10.82<\/p>\n

<\/span><\/p>\n

========== Rebuild All: 1 succeeded, 0 failed, 0 skipped ==========<\/p>\n

<\/span><\/p>\n

\n

 <\/p>\n<\/p>\n

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. <\/p>\n

Thanks<\/a>,<\/p>\n

Vikas Bhatia<\/p>\n

<\/span><\/p>\n

VC++ Team<\/p>\n

\n<\/p>\n

<\/font><\/p>\n

 <\/p>\n

<\/font><\/p>\n","protected":false},"excerpt":{"rendered":"

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 […]<\/p>\n","protected":false},"author":289,"featured_media":35994,"comment_status":"open","ping_status":"closed","sticky":false,"template":"","format":"standard","meta":{"_acf_changed":false,"footnotes":""},"categories":[1],"tags":[77,78,65,25,13],"class_list":["post-3943","post","type-post","status-publish","format-standard","has-post-thumbnail","hentry","category-cplusplus","tag-build-throughput","tag-build-times","tag-compiler","tag-linker","tag-msbuild"],"acf":[],"blog_post_summary":"

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 […]<\/p>\n","_links":{"self":[{"href":"https:\/\/devblogs.microsoft.com\/cppblog\/wp-json\/wp\/v2\/posts\/3943","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/devblogs.microsoft.com\/cppblog\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/devblogs.microsoft.com\/cppblog\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/cppblog\/wp-json\/wp\/v2\/users\/289"}],"replies":[{"embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/cppblog\/wp-json\/wp\/v2\/comments?post=3943"}],"version-history":[{"count":0,"href":"https:\/\/devblogs.microsoft.com\/cppblog\/wp-json\/wp\/v2\/posts\/3943\/revisions"}],"wp:featuredmedia":[{"embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/cppblog\/wp-json\/wp\/v2\/media\/35994"}],"wp:attachment":[{"href":"https:\/\/devblogs.microsoft.com\/cppblog\/wp-json\/wp\/v2\/media?parent=3943"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/cppblog\/wp-json\/wp\/v2\/categories?post=3943"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/cppblog\/wp-json\/wp\/v2\/tags?post=3943"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}