{"id":26413,"date":"2020-08-27T14:24:35","date_gmt":"2020-08-27T14:24:35","guid":{"rendered":"https:\/\/devblogs.microsoft.com\/cppblog\/?p=26413"},"modified":"2020-08-27T14:24:35","modified_gmt":"2020-08-27T14:24:35","slug":"introducing-vcperf-timetrace-for-cpp-build-time-analysis","status":"publish","type":"post","link":"https:\/\/devblogs.microsoft.com\/cppblog\/introducing-vcperf-timetrace-for-cpp-build-time-analysis\/","title":{"rendered":"Introducing vcperf \/timetrace for C++ build time analysis"},"content":{"rendered":"<p><em>The following blog post was written by guest author Carlos Fraguas from Mercury Steam Entertainment. He describes how he used the <a href=\"https:\/\/devblogs.microsoft.com\/cppblog\/analyze-your-builds-programmatically-with-the-c-build-insights-sdk\/\">C++ Build Insights SDK<\/a> to add the new \/timetrace option in <a href=\"https:\/\/github.com\/microsoft\/vcperf\">vcperf<\/a>, and how he also used it to build custom tools tailored to his team&#8217;s needs. You can follow Carlos on Twitter using handle <a href=\"https:\/\/twitter.com\/MetanoKid\">@MetanoKid<\/a>.<\/em><\/p>\n<hr \/>\n<p>Hello! I\u2019m Carlos Fraguas and I work as a Gameplay Programmer at Mercury Steam Entertainment. Let\u2019s look at how the <a href=\"https:\/\/docs.microsoft.com\/cpp\/build-insights\/get-started-with-cpp-build-insights\">C++ Build Insights SDK<\/a> helped me create tools to decrease build times and how I ended up adding a new visualization option into <a href=\"https:\/\/github.com\/microsoft\/vcperf\"><em>vcperf<\/em><\/a>.<\/p>\n<p><span style=\"font-size: 18pt;\"><strong>Background<\/strong><\/span><\/p>\n<p>There\u2019s one thing programmers dislike the most: waiting for the project to compile. Well, yes, we\u2019ve all laughed with this XKCD comic:<\/p>\n<p><figure id=\"attachment_26414\" aria-labelledby=\"figcaption_attachment_26414\" class=\"wp-caption aligncenter\" ><img decoding=\"async\" class=\"wp-image-26414\" src=\"https:\/\/devblogs.microsoft.com\/cppblog\/wp-content\/uploads\/sites\/9\/2020\/08\/a-webcomic-showing-two-people-sword-fighting-on-of.png\" alt=\"A webcomic showing two people sword-fighting on office chairs. Somebody from the office says: &quot;Hey! Get back to work!&quot; and they reply &quot;Compiling!&quot;\" width=\"413\" height=\"360\" srcset=\"https:\/\/devblogs.microsoft.com\/cppblog\/wp-content\/uploads\/sites\/9\/2020\/08\/a-webcomic-showing-two-people-sword-fighting-on-of.png 413w, https:\/\/devblogs.microsoft.com\/cppblog\/wp-content\/uploads\/sites\/9\/2020\/08\/a-webcomic-showing-two-people-sword-fighting-on-of-300x262.png 300w\" sizes=\"(max-width: 413px) 100vw, 413px\" \/><figcaption id=\"figcaption_attachment_26414\" class=\"wp-caption-text\">Source: XKCD.com (<a href=\"https:\/\/xkcd.com\/303\/\">https:\/\/xkcd.com\/303\/<\/a>) License: <a href=\"https:\/\/xkcd.com\/license.html\">https:\/\/xkcd.com\/license.html<\/a><\/figcaption><\/figure><\/p>\n<p>But it\u2019s really frustrating just watching a progress bar moving up! Long build times discourage iterations in both your project\u2019s features and architecture (i.e. refactoring is costly), so we could argue that keeping your iteration cycle short is key for your team.<\/p>\n<p>Some time ago I started worrying about slow build times and tried to find some tools that could help me find bottlenecks in our build process. It wasn\u2019t until the C++ Build Insights SDK and <em>vcperf <\/em>were released that I could start making real and informed progress towards speeding them up!<\/p>\n<p>There was an issue, though: by the time I started investigating, I wasn\u2019t as familiar with MSVC as my Engine Programmer teammates. And that\u2019s where <em>vcperf<\/em> truly shined: by giving me a visual representation of the build! I could then understand the amount of work that the compiler and linker are doing, and how it\u2019s structured.<\/p>\n<p>However, now that the SDK was available, I wanted to give it a try myself and create some custom reports, tailored for our team and projects. It felt astonishingly easy to set up and get useful info. And yes, it\u2019s as straightforward as Kevin explains in his posts about <a href=\"https:\/\/devblogs.microsoft.com\/cppblog\/finding-build-bottlenecks-with-cpp-build-insights\/\">finding build bottlenecks<\/a>\u00a0or <a href=\"https:\/\/devblogs.microsoft.com\/cppblog\/profiling-template-metaprograms-with-cpp-build-insights\/\">profiling metaprograms<\/a>!<\/p>\n<p>Among those reports, and <a href=\"https:\/\/aras-p.info\/blog\/2019\/01\/16\/time-trace-timeline-flame-chart-profiler-for-Clang\/\">inspired by Aras Pranckevi\u010dius<\/a>, I set myself to add an alternative visualization output for <em>vcperf<\/em>.<\/p>\n<p><span style=\"font-size: 18pt;\"><strong>\/timetrace<\/strong><\/span><\/p>\n<p>The new \/timetrace option lets you build a flame graph viewable in any Chromium-based browser, like the new Microsoft Edge. These are some of its key features:<\/p>\n<ul>\n<li>Easily visualize execution hierarchies: related activities are kept close together.<\/li>\n<li>See what\u2019s going on in the compiler\u2019s front-end and back-end: which files are getting included or how slow code generation is.<\/li>\n<li>Outline expensive function and template instantiations: if it\u2019s on the graph, it may be an issue!<\/li>\n<\/ul>\n<p>A flame graph showing <em>vcperf<\/em>\u2019s build:<\/p>\n<p><img decoding=\"async\" class=\"aligncenter wp-image-26415\" src=\"https:\/\/devblogs.microsoft.com\/cppblog\/wp-content\/uploads\/sites\/9\/2020\/08\/word-image.png\" alt=\"A screen capture showing the use of Microsoft Edge to view a JSON trace obtained by using the \/timetrace switch with vcperf. The trace describes a build of vcperf itself.\" width=\"1366\" height=\"651\" srcset=\"https:\/\/devblogs.microsoft.com\/cppblog\/wp-content\/uploads\/sites\/9\/2020\/08\/word-image.png 1366w, https:\/\/devblogs.microsoft.com\/cppblog\/wp-content\/uploads\/sites\/9\/2020\/08\/word-image-300x143.png 300w, https:\/\/devblogs.microsoft.com\/cppblog\/wp-content\/uploads\/sites\/9\/2020\/08\/word-image-1024x488.png 1024w, https:\/\/devblogs.microsoft.com\/cppblog\/wp-content\/uploads\/sites\/9\/2020\/08\/word-image-768x366.png 768w\" sizes=\"(max-width: 1366px) 100vw, 1366px\" \/><\/p>\n<p>A zoom into one of the files in <em>vcperf<\/em>\u2019s build:<\/p>\n<p><img decoding=\"async\" class=\"aligncenter wp-image-26416\" src=\"https:\/\/devblogs.microsoft.com\/cppblog\/wp-content\/uploads\/sites\/9\/2020\/08\/word-image-1.png\" alt=\"A screen capture showing the use of Microsoft Edge to view a JSON trace obtained by using the \/timetrace switch with vcperf. The trace describes a build of vcperf itself, zoomed into the area that shows the time spent compiling the TimeTraceGenerator.cpp file.\" width=\"1366\" height=\"525\" srcset=\"https:\/\/devblogs.microsoft.com\/cppblog\/wp-content\/uploads\/sites\/9\/2020\/08\/word-image-1.png 1366w, https:\/\/devblogs.microsoft.com\/cppblog\/wp-content\/uploads\/sites\/9\/2020\/08\/word-image-1-300x115.png 300w, https:\/\/devblogs.microsoft.com\/cppblog\/wp-content\/uploads\/sites\/9\/2020\/08\/word-image-1-1024x394.png 1024w, https:\/\/devblogs.microsoft.com\/cppblog\/wp-content\/uploads\/sites\/9\/2020\/08\/word-image-1-768x295.png 768w\" sizes=\"(max-width: 1366px) 100vw, 1366px\" \/><\/p>\n<p>A zoom into <em>vcperf<\/em>\u2019s build showing template instantiations:<\/p>\n<p><img decoding=\"async\" class=\"aligncenter wp-image-26417\" src=\"https:\/\/devblogs.microsoft.com\/cppblog\/wp-content\/uploads\/sites\/9\/2020\/08\/word-image-2.png\" alt=\"A screen capture showing the use of Microsoft Edge to view a JSON trace obtained by using the \/timetrace switch with vcperf. The trace describes a build of vcperf itself, zoomed into an area that shows time spent doing template instantiations.\" width=\"1366\" height=\"369\" srcset=\"https:\/\/devblogs.microsoft.com\/cppblog\/wp-content\/uploads\/sites\/9\/2020\/08\/word-image-2.png 1366w, https:\/\/devblogs.microsoft.com\/cppblog\/wp-content\/uploads\/sites\/9\/2020\/08\/word-image-2-300x81.png 300w, https:\/\/devblogs.microsoft.com\/cppblog\/wp-content\/uploads\/sites\/9\/2020\/08\/word-image-2-1024x277.png 1024w, https:\/\/devblogs.microsoft.com\/cppblog\/wp-content\/uploads\/sites\/9\/2020\/08\/word-image-2-768x207.png 768w\" sizes=\"(max-width: 1366px) 100vw, 1366px\" \/><\/p>\n<p>To generate these graphs yourself, follow these steps:<\/p>\n<ul>\n<li>Clone <a href=\"https:\/\/github.com\/microsoft\/vcperf\">vcperf from GitHub<\/a>.<\/li>\n<li>Obtain a trace of your build:\n<ul>\n<li>Open an elevated command-line prompt.<\/li>\n<li>Run the following command: <code>vcperf \/start SessionName<\/code><\/li>\n<li>Build your C++ project from anywhere, even from within Visual Studio (<em>vcperf <\/em>collects events system-wide).<\/li>\n<li>Run the following command: <code>vcperf \/stop SessionName \/timetrace outputFile.json<\/code>. This command will stop the trace, analyze all events and save the flame graph in the <em>outputFile.json<\/em> trace file.<\/li>\n<\/ul>\n<\/li>\n<li>Open the trace you just collected by navigating to edge:\/\/tracing in Microsoft Edge and start exploring!<\/li>\n<\/ul>\n<p>This is what <em>\/timetrace<\/em> does under the hood:<\/p>\n<ul>\n<li>Loads up the trace.<\/li>\n<li>Subscribes to SDK\u2019s OnStartActivity and OnStopActivity to build hierarchies using parent-child relationships.<\/li>\n<li>Applies filters to keep relevant data only (i.e. functions that compile very quickly may not be interesting).<\/li>\n<li>Calculates new process and thread IDs to keep hierarchies together (instead of using the raw IDs).<\/li>\n<li>Outputs the graph in the expected format.<\/li>\n<\/ul>\n<p><span style=\"font-size: 18pt;\"><strong>How the SDK helped us<\/strong><\/span><\/p>\n<p>Using the C++ Build Insights SDK wasn\u2019t useful just for visualizing our build process. We\u2019ve managed to create a number of small tools to keep analyzing future builds. These were some specific cases where the SDK helped us:<\/p>\n<ul>\n<li>We found a particular default constructor, defined by the compiler, that was taking ~3% of our total build time.\nThat file was included hundreds of times so the constructor got defined once per inclusion. We ended up implementing it ourselves in the <em>cpp<\/em> file to cut that number to one!<\/li>\n<li>We detected unnecessary #include clauses in header files.\nThese were in turn including a lot of headers and that made them slow to be processed by the front-end. We were able to convert a lot of them to forward declarations and reduced coupling!<\/li>\n<li>We built inclusion graphs for our files using the <a href=\"https:\/\/docs.microsoft.com\/visualstudio\/modeling\/directed-graph-markup-language-dgml-reference\"><em>.dgml<\/em><\/a> format.\nAgain, visualizing data really helps!<\/li>\n<li>We decreased the number of compilation batches within a project by unifying compiler options for all of its files (except PCH!), effectively increasing compilation parallelism.\nIn particular, we had two files that ended up creating <em>.obj<\/em> files with the same name. We had fixed it by modifying the ObjectFileName to $(IntDir)\\%(RelativeDir)\\. However, this created as many compilation batches as folders (which usually had a small number of files and yielded idle cores waiting for the next batch to kick off). We solved it by renaming one of the files and restoring the original ObjectFileName to go back to having a single batch!<\/li>\n<li>We were warned about missing \/MP flags in some third-party libraries that we compile as part of the build process.<\/li>\n<li>We found template classes that were expensive to generate and we could refactor.<\/li>\n<\/ul>\n<p>As you can see, the information provided by the SDK helped us in several areas!<\/p>\n<p><span style=\"font-size: 18pt;\"><strong>Final words<\/strong><\/span><\/p>\n<p>Before we finish, I wanted to thank the team behind the <a href=\"https:\/\/devblogs.microsoft.com\/cppblog\/introducing-c-build-insights\/\">C++ Build Insights SDK<\/a> and <em>vcperf <\/em>for these tools, and Kevin Cadieux in particular for all the time and effort put into reviewing \/timetrace.<\/p>\n<p>I hope this new feature helps you make more informed decisions when investigating your build times and empowers you to create your own tools. Feel free to clone the <a href=\"https:\/\/github.com\/microsoft\/vcperf\">vcperf repo<\/a>, explore \/timetrace and tweak it to your needs!<\/p>\n<p>Thanks for reading!<\/p>\n<p>Carlos.<\/p>\n","protected":false},"excerpt":{"rendered":"<p>The following blog post was written by guest author Carlos Fraguas from Mercury Steam Entertainment. He describes how he used the C++ Build Insights SDK to add the new \/timetrace option in vcperf, and how he also used it to build custom tools tailored to his team&#8217;s needs. You can follow Carlos on Twitter using [&hellip;]<\/p>\n","protected":false},"author":6966,"featured_media":26424,"comment_status":"open","ping_status":"closed","sticky":false,"template":"","format":"standard","meta":{"_acf_changed":false,"footnotes":""},"categories":[270,239],"tags":[],"class_list":["post-26413","post","type-post","status-publish","format-standard","has-post-thumbnail","hentry","category-announcement","category-diagnostics"],"acf":[],"blog_post_summary":"<p>The following blog post was written by guest author Carlos Fraguas from Mercury Steam Entertainment. He describes how he used the C++ Build Insights SDK to add the new \/timetrace option in vcperf, and how he also used it to build custom tools tailored to his team&#8217;s needs. You can follow Carlos on Twitter using [&hellip;]<\/p>\n","_links":{"self":[{"href":"https:\/\/devblogs.microsoft.com\/cppblog\/wp-json\/wp\/v2\/posts\/26413","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\/6966"}],"replies":[{"embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/cppblog\/wp-json\/wp\/v2\/comments?post=26413"}],"version-history":[{"count":0,"href":"https:\/\/devblogs.microsoft.com\/cppblog\/wp-json\/wp\/v2\/posts\/26413\/revisions"}],"wp:featuredmedia":[{"embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/cppblog\/wp-json\/wp\/v2\/media\/26424"}],"wp:attachment":[{"href":"https:\/\/devblogs.microsoft.com\/cppblog\/wp-json\/wp\/v2\/media?parent=26413"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/cppblog\/wp-json\/wp\/v2\/categories?post=26413"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/cppblog\/wp-json\/wp\/v2\/tags?post=26413"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}