{"id":26218,"date":"2020-07-21T15:02:45","date_gmt":"2020-07-21T15:02:45","guid":{"rendered":"https:\/\/devblogs.microsoft.com\/cppblog\/?p=26218"},"modified":"2020-07-21T15:04:19","modified_gmt":"2020-07-21T15:04:19","slug":"improving-code-generation-time-with-cpp-build-insights","status":"publish","type":"post","link":"https:\/\/devblogs.microsoft.com\/cppblog\/improving-code-generation-time-with-cpp-build-insights\/","title":{"rendered":"Improving code generation time with C++ Build Insights"},"content":{"rendered":"

Code generation time is a significant contributor to total build time for optimized builds. During this step of the compilation process, source code is passed through several algorithms that transform your program into an optimized version that can be executed more efficiently. In general, the optimization of a C++ function happens quickly and poses no problem. In exceptional cases, however, some functions can become large and complex enough to put pressure on the optimizer and noticeably slow down your builds. In this article, we show how you can use C++ Build Insights to determine if slow code generation is a problem for you. We demonstrate two ways to diagnose these issues: first manually with the vcperf<\/em><\/strong> analysis tool, and then programmatically with the C++ Build Insights SDK<\/a>. Throughout the tutorial, we show these techniques being used to improve the build time of Chakra, the open-source JavaScript engine, by 7%.<\/p>\n

How to obtain and use vcperf<\/strong><\/span><\/p>\n

The examples in this article make use of vcperf<\/em>, a tool that allows you to capture a trace of your build and to view it in the Windows Performance Analyzer (WPA)<\/a>. The latest version is available in Visual Studio 2019.<\/p>\n

1. Follow these steps to obtain and configure vcperf <\/em>and WPA:<\/strong><\/span><\/p>\n

    \n
  1. Download and install the latest Visual Studio 2019<\/a>.<\/li>\n
  2. Obtain WPA by downloading and installing the latest Windows ADK<\/a>.<\/li>\n
  3. Copy the perf_msvcbuildinsights.dll<\/code> file from your Visual Studio 2019\u2019s MSVC installation directory to your newly installed WPA directory. This file is the C++ Build Insights WPA add-in, which must be available to WPA for correctly displaying the C++ Build Insights events.\n
      \n
    1. MSVC\u2019s installation directory is typically: C:\\Program Files (x86)\\Microsoft Visual Studio\\2019\\{Edition}\\VC\\Tools\\MSVC\\{Version}\\bin\\Hostx64\\x64<\/code>.<\/li>\n
    2. WPA\u2019s installation directory is typically: C:\\Program Files (x86)\\Windows Kits\\10\\Windows Performance Toolkit<\/code>.<\/li>\n<\/ol>\n<\/li>\n
    3. Open the perfcore.ini<\/code> file in your WPA installation directory, and add an entry for the perf_msvcbuildinsights.dll<\/code> file. This tells WPA to load the C++ Build Insights plugin on startup.<\/li>\n<\/ol>\n

      You can also obtain the latest vcperf<\/em> and WPA add-in by cloning and building the vcperf GitHub repository<\/a>. Feel free to use your built copy in conjunction with Visual Studio 2019!<\/p>\n

      2. Follow these steps to collect a trace of your build:<\/strong><\/span><\/p>\n

        \n
      1. Open an elevated x64 Native Tools Command Prompt for VS 2019<\/em><\/strong>.<\/li>\n
      2. Obtain a trace of your build:\n
          \n
        1. Run the following command: vcperf \/start MySessionName<\/code>.<\/li>\n
        2. Build your C++ project from anywhere, even from within Visual Studio (vcperf<\/em> collects events system-wide).<\/li>\n
        3. Run the following command: vcperf \/stop MySessionName outputFile.etl<\/code>. This command will stop the trace, analyze all events, and save everything in the outputFile.etl<\/em> trace file.<\/li>\n<\/ol>\n<\/li>\n
        4. Open the trace you just collected in WPA.<\/li>\n<\/ol>\n

          Using the Functions view in WPA<\/strong><\/span><\/p>\n

          C++ Build Insights has a dedicated view to help diagnose slow code generation time: the Functions<\/strong><\/em> view. After opening your trace in WPA, you can access the view by dragging it from the Graph Explorer<\/strong><\/em> pane to the Analysis<\/strong><\/em> window, as shown below.<\/p>\n

          \"An<\/p>\n

          The Functions view offers 3 presets that you can select from when navigating your build trace:<\/p>\n

            \n
          1. Timelines<\/li>\n
          2. Activity Statistics<\/li>\n
          3. Force Inlinees<\/li>\n<\/ol>\n

            Click on the drop-down menu at the top of the view to select the one you need. This step is illustrated below.<\/p>\n

            \"An<\/p>\n

            In the next 3 sections, we cover each of these presets in turn.<\/p>\n

            Preset #1: Timelines<\/strong><\/span><\/p>\n

            When the Timelines<\/em> preset is active, focus your attention on the graph section at the top of the view. It gives an overview of where function code generation bottlenecks occur in your parallel build. Each timeline represents a thread. The timeline numbers match the ones in the Build Explorer view<\/a>. In this graph, a colored bar represents a function being optimized. The longer the bar, the more time was consumed optimizing this function. Hover over each colored bar to see the name of the function being optimized. The position of the bar on the x axis indicates the time at which the function optimization started. Place a Functions<\/em> view underneath a Build Explorer<\/em> view to understand how the code generation of a function affects the overall build, and if it\u2019s a bottleneck. The Timelines<\/em> preset is shown in the image below.<\/p>\n

            \"An<\/p>\n

            N.B. <\/strong>Accurate parallelism for code generation is only available starting with Visual Studio 2019 version 16.4. In earlier versions, all code generation threads for a given compiler or linker invocation are placed on one timeline. In version 16.4 and above, each code generation thread within a compiler or linker invocation is placed on its own timeline.<\/p>\n

            Preset #2: Activity Statistics<\/strong><\/span><\/p>\n

            The Activity Statistics<\/em> preset shows code generation statistics for the functions in your build. When using this preset, focus your attention on the table at the bottom of the view. By default, functions are sorted by their code generation duration in descending order. Use this preset if you want to quickly identify the functions that take the most time to optimize in your entire build. If you are interested in only a section of your build, click and drag the mouse over the desired time span in the graph section at the top of the view. The values in the table below the graph will automatically adjust to the selected time span. The table displays statistics such as: code generation time, file or DLL in which the function is found, and the compiler or linker invocation that was being executed during the generation of a function. Use the Build Explorer view<\/a> to get more information on an invocation, if desired. Similar to the Timelines<\/em> preset, the colored bars in the graph section at the top of the view indicate the time and duration when the code generation for a given function occurred, except that the information is grouped by function name instead of by thread. The Activity Statistics<\/em> preset is shown below.<\/p>\n

            \"An<\/p>\n

            Preset #3: Force Inlinees<\/strong><\/span><\/p>\n

            The inlining of large function call graphs into a single root function can result in very large functions that take a long time to optimize. An overabundant use of the __forceinline<\/code> keyword is a common cause of this problem, so C++ Build Insights includes a dedicated preset to identify force-inlining issues quickly. When using the Force Inlinees<\/em> preset, focus your attention on the table at the bottom of the view. Expand a function and its ForceInlinee<\/em><\/strong> node to see all the other functions that have been force-inlined in it. Functions that don\u2019t have any force-inlinees are filtered out. The String Value<\/em><\/strong> field contains the name of the force-inlinee, and the Numeric Value<\/em><\/strong> field indicates how much this force-inlinee caused the root-level function to grow in size. The Numeric Value<\/em> is roughly equivalent to the number of intermediate instructions in the function being inlined, so higher is worse. The force-inlinees are sorted by size (i.e. Numeric Value<\/em>) in descending order, allowing you to quickly see the worst offenders. Use this information to try removing some __forceinline<\/code> keywords on large functions. These functions don\u2019t suffer as much from call overhead and are less likely to cause a performance degradation if inlining is omitted. Be careful when using the Numeric Value<\/em> field, as the same function can be force-inlined multiple times and Numeric Value<\/em> is a sum aggregation by default. Expand the String Value<\/em> column for a force-inlinee to see the individual sizes of all inlinees of the same name. The Force Inlinees<\/em> preset is shown below.<\/p>\n

            \"An<\/p>\n

            A note on the function names displayed in the Functions view<\/strong><\/span><\/p>\n

            The Functions<\/em> view shows mangled C++ function names. You can use the undname<\/em><\/strong> utility to demangle the names. To do so, right click on the cell containing the name in WPA, click on Copy Cell<\/em><\/strong>, and pass that value to undname<\/em>, as shown below. The undname<\/em> utility is available in an x64 Native Tools Command Prompt for VS 2019<\/em>.<\/p>\n

            \"A<\/p>\n

            Putting it all together: using the Functions view to speed up Chakra builds<\/strong><\/span><\/p>\n

            In this case study, we use the Chakra open-source JavaScript engine from GitHub to demonstrate how vcperf<\/em> can be used to achieve a 7% build time improvement.<\/p>\n

            Use these steps if you would like to follow along:<\/p>\n

              \n
            1. Clone the ChakraCore GitHub repository<\/a>.<\/li>\n
            2. Change the directory to the root of the freshly cloned repository and run the following command: git checkout c72b4b7<\/code>. This is the commit that was used for the case study below.<\/li>\n
            3. Open the Build\\Chakra.Core.sln<\/code> solution file, starting from the root of the repository.<\/li>\n
            4. Obtain a trace for a full rebuild of the solution:\n
                \n
              1. Open an elevated command prompt with vcperf<\/em> on the PATH.<\/li>\n
              2. Run the following command: vcperf \/start Chakra<\/code><\/li>\n
              3. Rebuild the x64 Test<\/em> configuration of the Build\\Chakra.Core.sln<\/code> solution file in Visual Studio 2019.<\/li>\n
              4. Run the following command: vcperf \/stop Chakra chakra.etl<\/code>. This will save a trace of the build in chakra.etl<\/em>.<\/li>\n<\/ol>\n<\/li>\n
              5. Open the trace in WPA.<\/li>\n<\/ol>\n

                We bring in the Build Explorer<\/em> and Functions<\/em> views and place them one on top of the other. The Functions<\/em> view shows two long code generation activities, labeled A<\/em><\/strong> and B<\/em><\/strong> below. These activities align with an invocation bottleneck shown in the Build Explorer<\/em> view above. We surmise that reducing code generation time for A<\/em> and B<\/em> should help overall build time, given that they are on the critical path. Let’s investigate further.<\/p>\n

                \"An<\/p>\n

                We switch over to the Activity Statistics<\/em> preset in the Functions<\/em> view, and find out that the two functions corresponding to A<\/em> and B<\/em> are named infos_<\/code> and GetToken<\/code>, respectively.<\/p>\n

                \"An<\/p>\n

                Fixing infos_: evaluating initializers at compile time<\/strong><\/span><\/p>\n

                Looking at the code for Chakra, we find that infos_<\/code> is a large global array of Opcode::Info<\/code> objects. It is defined in lib\\wabt\\src\\opcode.cc<\/code>, as shown below. The Opcode::Info<\/code> elements are initialized with the 450+ entries found in lib\\wabt\\src\\opcode.def<\/code>.<\/p>\n

                \/\/ static\r\nOpcode::Info Opcode::infos_[] = {\r\n#define WABT_OPCODE(rtype, type1, type2, type3, mem_size, prefix, code, Name, \\\r\n                    text)                                                     \\\r\n  {text,        Type::rtype, Type::type1,                                     \\\r\n   Type::type2, Type::type3, mem_size,                                        \\\r\n   prefix,      code,        PrefixCode(prefix, code)},\r\n#include \"src\/opcode.def\"\r\n#undef WABT_OPCODE\r\n\r\n    {\"<invalid>\", Type::Void, Type::Void, Type::Void, Type::Void, 0, 0, 0, 0},\r\n};<\/pre>\n
                How is this array related to the infos_<\/code> function that we\u2019re seeing in our Chakra trace? And why is this function slow to generate?<\/p>\n
                Global variables sometimes cannot be initialized at compile time because their initialization involves the execution of some code (e.g. a constructor). In this case, the compiler generates a function known as a dynamic initializer which will be called during program startup to properly initialize the variable. You can easily recognize dynamic initializers in the Functions<\/em> view because their mangled name always starts with ??__E<\/code>.<\/p>\n
                The Chakra trace that we captured earlier tells us that a dynamic initializer function was generated for infos_<\/code>. The reason why this function takes a long time to generate is because the initialization code for the 450+-element infos_<\/code> array is very large and is causing the compiler\u2019s optimization phase to take more time to complete.<\/p>\n
                In the case of infos_<\/code>, all the information required to initialize its elements is known at compile time. It is possible to prevent the generation of a dynamic initializer by enforcing compile-time initialization as follows:<\/p>\n
                  \n
                1. (optionally) making the infos_<\/code> array constexpr<\/code>; and<\/li>\n
                2. making the PrefixCode<\/code> function constexpr<\/code>.<\/li>\n<\/ol>\n
                  The reason why step 1 is a good idea is that compilation will fail if infos_<\/code> ever changes by mistake in a way that prevents compile-time initialization. Without it, the compiler will silently revert back to generating a dynamic initializer function. Step 2 is required because PrefixCode<\/code> is called during the initialization of each Opcode::Info<\/code> element, and compile-time initialization of infos_<\/code> cannot happen if any part of its initialization is not constexpr<\/code>.<\/p>\n
                  See the code for this fix on GitHub<\/a>.<\/p>\n
                  Fixing GetToken: using the reduced optimizer for large functions<\/strong><\/span><\/p>\n
                  The C code for GetToken<\/code> is generated (that\u2019s right, the C code itself is generated) by re2c<\/a>, the open-source software lexer generator. The resulting function is very large and suffers from long optimization time due to its size. Because the C code is generated, it might not be trivial to modify it in a way that would fix our build time issue. When situations like this arise, you can use the ReducedOptimizeHugeFunctions<\/code> switch. This switch prevents the optimizer from using expensive optimizations on large functions, resulting in improved optimization time. You can set the threshold for when the reduced optimizer kicks in by using the ReducedOptimizeThreshold:#<\/code> switch. #<\/code> is the number of instructions that the function must have before triggering the reduced optimizer. The default value is 20,000.<\/p>\n