ブログズミ: Windows Performance Analayzer で C++ ビルド時間のプロファイルをしてみよう！

Are C++ template instantiations slowing down your build? Read this article to learn how C++ Build Insights can help you find out: https://t.co/00OBxsOttU pic.twitter.com/jUoYlP6gRF
— Kevin Cadieux (@KevinCadieuxMS) May 28, 2020

最近 clang の -ftime-trace オプションと chrome://tracing を使ってビルド時間の可視化をしてみましたが、Microsoft が提供している WPA（Windows Performance Analyzer | Microsoft Docs）も便利そうということで試してみました。

-ftime-trace の記事はこちら→「ブログズミ: [C++] -ftime-trace オプションと Chrome でビルド時間の可視化」

使い方

セットアップ

使い方は↑のツイートのリンク先ブログにも記載されています。

Profiling template metaprograms with C++ Build Insights | C++ Team Blog

必要なのは VS2019 と Windows ADK です。

リンク先からダウンロードしてインストールしてください。

VS2019 では Community Edition でも問題なくプロファイリングできます。

次に VS2019 のインストールディレクトリから perf_msvcbuildinsights.dll を ADK のインストールディレクトリにコピーします。

「C:\Program Files (x86)\Microsoft Visual Studio\2019\{Edition}\VC\Tools\MSVC\{Version}\bin\Hostx64\x64」

→「C:\Program Files (x86)\Windows Kits\10\Windows Performance Toolkit」

（Visual Studio の方のパスは環境によって変わるので適宜変更してください。筆者環境では「C:\Program Files (x86)\Microsoft Visual Studio\2019\Community\VC\Tools\MSVC\14.26.28801\bin\Hostx64\x64」でした）

筆者が試したときは、ADK インストールディレクトリにすでに同名ファイルがありましたので、バックアップを取ってコピーしました。

このコピーをしておかないと C++ Build Insights （Template instantiations や Files）が見られないので注意してください。

トレース

準備が整ったらプロファイルを取得してみましょう。

こちらもブログの手順のとおりに行えば ok です。

まずは、「x64 Native Tools Command Prompt for VS 2019」を管理者権限で起動します。（vcvarsall.bat などから環境セットアップしたプロセスでも ok）

vcperf /start /level3 name

でトレースを開始します。

開始できたら、普通に Visual Studio でビルドしてください。（IDE からでもコマンドからでもどちらでも ok）

ビルドが終わったら vcperf を停止させます。このとき出力ファイルを指定します。

vcperf /stop /templates name output.etl

WPA で表示する

etl ファイルができたら WPA で表示してみましょう。

etl ファイルをダブルクリックすれば WPA が起動します。

ローディングが終わると以下のように表示されます。

あとは、Diagnostics から項目を選んでいけばビルドで何にどれだけ時間がかかっているのかが確認できます。

CircleCI で vcperf

ローカル環境でプロファイルを取得することもできますが、面倒なので CI でやるようにしてみました。今回使用した CI サービスは CircleCI です。
ターゲットとなるのはおなじみ「自作 C++ テスティングフレームワーク」の iutest です。

CircleCI を選択した理由は、すでに -ftime-trace の結果を CircleCI の成果物として保存するようにしていたので、vcperf の成果物も CircleCI に置こうと思ったからです。

それ以外の理由は特にありません。VS2019 がインストールされている Windows エージェントが使用可能なサービスであれば他でも問題ないと思います。（AppVeyor, Azure Pipelines, GitHub Actions, ...）

(※ CI-Spec で調査)

config.yml と計測用に追加したバッチファイルがこちら。

orbs:
  win: circleci/windows@2.2.0

jobs:
  vcperf:
    executor: win/default
    environment:
      CMAKE_GENERATOR_NAME: "Visual Studio 16 2019"
      CMAKE: "C:/CMake/bin/cmake.exe"
    steps:
      - checkout
      - run:
          name: install
          command: |
            $ProgressPreference = "SilentlyContinue"
            Invoke-WebRequest -URI https://github.com/Kitware/CMake/releases/download/v3.16.4/cmake-3.16.4-win64-x64.zip -OutFile $Env:HOMEPATH\cmake-3.16.4-win64-x64.zip
            Expand-Archive $Env:HOMEPATH\cmake-3.16.4-win64-x64.zip -DestinationPath "C:\"
            Rename-Item "C:\cmake-3.16.4-win64-x64" -NewName CMake
      - run:
          name: cmake
          shell: bash.exe
          command: |
            mkdir build && cd build && ${CMAKE} ../projects/cmake -G "${CMAKE_GENERATOR_NAME}" -A x64
      - run:
          name: vcperf
          shell: cmd.exe
          command: .circleci\vcperf_build.bat
      - store_artifacts:
          path: .\iutest.etl

    call tools\VisualStudio\vcperf.bat /start /level3 iutest
%CMAKE% --build .\build
call tools\VisualStudio\vcperf.bat /stop /templates iutest iutest.etl

計測用にバッチファイルを別途用意しているのは config.yml の command で１つずつ処理しようとしたら vcvarsall.bat の exit 0 で処理が止まってしまったからです。

vcvarsall は vcperf.bat から呼び出されるようになってます。

https://github.com/srz-zumix/iutest/tree/master/tools/VisualStudio

もっと良い解決方法あれば教えて下さいmm

このジョブが完了すると Artifacts に iutest.etl がアップロードされています。

ダウンロードして WPA で確認してみましょう。

iutest のプロファイルを見てみる

では CircleCI で取得した etl ファイルを見てみましょう。

Build Explorer

まずは「Build Explorer」の結果↑

どのような処理がどのくらい時間がかかったかがわかります。

１ファイルのコンパイルにおいてどのようなことをしているのかも詳細に確認することができます。

Files

次に「Files」です↑

こちらは各ファイルの処理にどれだけ時間がかかったかがわかります。

また呼び出された回数もわかるので、Count が多いファイルは無駄に include されていないか確認すると良いかもしれません。

↑のようにファイルを展開すると、どこから include されたかどうかが１つずつ確認することができます。

Template Instantiations

最後に「Template Instantiations」です↑

こちらでは template の実体化にかかった時間がわかります。

デフォルトでは「Primary Template Name」が Visible になっているので、すべての引数パターンが template クラス・関数名でまとめて表示されています。

こちらの Visible のチェックを外すと template 引数違いで時間順に並べられます。

これでボトルネックになっている template の実体化が見つけやすくなると思います。

また検索機能を使うことで、↓のように特定の名前に絞って表示することもできます。

Specialization Names のノードを開くと、どこから実体化されたかもわかるようになってます。

改善ポイント

さて、iutest に絞り込んだ場合 iuCsvFileParamsGenerator<float> の実体化がトップでした。

しかしながら、この iuCsvFileParamsGenerator は CSV ファイルからテストパラメータを読み込ませるときにしか実体化されない想定でした。

上記の2枚目の画像を見ていただくと、Count が 155 回記録されています。

今回記録したときのビルドでは複数のテストをビルドしていますので、おそらくテストの数（exe の数）だけ実体化されていそうです。

使うときにだけ実体化されるのが理想なので、詳細を追ってみたところ、iuCsvFileParamsGenerator<float>::ToParam の特殊化がありました。

https://github.com/srz-zumix/iutest/blob/4f45ac420533dfd068da2fb705e4ac3b1cc32813/include/internal/iutest_genparams_from_file.hpp#L100

おそらく、これが原因でしょう。

今回の記事はここまでですが、この修正結果については Twitter かブログで報告したいと思います。

最後に

WPA はプラットフォームは限られますが、clang -ftime-trace + chrome://tracing でプロファイルするよりも、ビルド時間のボトルネックになりやすい Template Instantiation を調べやすくていい感じだなと思いました。

セットアップや使い方も簡単なのでぜひやってみてください。

では。

追記（2020/06/15）

CSV の特殊化消えた。 pic.twitter.com/wbP4NlN4IG
— ずみっくす@あつまれCIサービス (@srz_zumix) June 13, 2020

iuCsvFileParamsGenerator の特殊化をなくして、もっと低レベルでの特殊化（クラス外に追い出した）ところワーストから消えてることを確認しました。

今回の計測前後の etl ファイルをこちらに置いておいたので興味がある方は分析してみてください。

https://github.com/srz-zumix/iutest/issues/463

ブログズミ

ページ

2020年6月2日火曜日

Windows Performance Analayzer で C++ ビルド時間のプロファイルをしてみよう！

使い方