負荷計測系記事もくじ
https://tera1707.com/entry/2022/02/06/144447#Profile
内容
この動画を見て学んだことのメモ。
Performance Profiling | CPU Usage Tool
前提
VisualStudio2022 とそのツール群を使用。
VisualStudio 2022 17.4.4
学んだこと
このpartでは、診断ツールウインドウではなく、パフォーマンスプロファイラでCPU使用率を計測している。
MSの人がいろいろ試した結果、CPU使用率のサンプル回数は、1秒当たり1000回(=デフォルト)で十分だと思っているとのこと。
1000回/秒サンプルから、2000回/秒にすると、単純にデータの量が大きくなり、解析時の読み込み時間が長くなる。 また、サンプル対象のプログラムに対するオーバーヘッドが高くなりすぎるらしい。
※プロファイリングはリリースモードでビルドしたもので計測すべし。
VS上から計測を始めるときは、Alt＋F2で出したプロファイラ画面の「開始」ボタンを押す。
以前作成した、プロジェクトのバージョンを確認するツールで計測してみた結果がこんな感じ。
計測結果のみかた
「合計CPU」とか「セルフCPU」とは何か？
上で出てきた計測結果について、
動画内で、説明してくれていた。
https://youtu.be/X1-uHpEqNGM?list=PLReL099Y5nRf2cOurn1hI-gSRxsdbC27C&t=169
https://youtu.be/X1-uHpEqNGM?list=PLReL099Y5nRf2cOurn1hI-gSRxsdbC27C&t=195
合計CPUとは？
プロファイラがサンプリングをしたときに、そのメソッドがコールスタックの中に何回いたか、という数字。
上の動画中の図だと、8回サンプルしたときに、メインは毎回いたので8。
functionAは7回いたので7。のような感じ。
セルフCPUとは？
プロファイラがサンプルしたときに、そのメソッドがコールスタックの一番上に何回いたか、という数字。
上の動画中だと、Mainはすっといるけど、一番上にいたのは最初だけなので1。 functionBは、一番上にいたのは2回なので2、のような感じ。
この情報がわかれば、そこに出てくるメソッドに、どれくらいの時間を使ってるかが推定できる。
たとえば、サンプリング回数をデフォルトの1000回/秒にしていると、1サンプルあたり1msになる。
上の「合計CPU」の数が、あるメソッドで例えば20回だと、そのメソッドは、
20回 x 1ms = 20ms
を使っていることになる。
ホットパスとは？
合計CPU時間がおおい（約１・３？）メソッドのコールツリー。 一番CPU食ってるメソッドが呼ばれるまでのツリーが出る。
ここの関数名を押すと、下図の画面になる。その関数までのコールツリーが表示される。
トップファンクションとは？
トップファンクション(上位の関数)は、メソッドとその合計CPU、セルフCPUの表になっている。 これだけ見ても、どこのメソッドがどうCPUを食っているかは詳細にはわからない。
ここの関数名を押すと、下図の画面になる。これもメソッドとその合計CPU、セルフCPUの表。
また、そのコールツリーと合計/セルフCPUの表は、下図の「現在のビュー」を切り替えてやると、行き来できる。
もう少し詳しく見てみる
試しにCPU使用率を計測してみた自分のツール「FileVerUpTool」が、なにか妙に処理に時間がかかっている部分がある。 それがなぜか、ついでに見てみる。
上図のようなツールなのだが、画面右上の「Read」ボタンを押したときに、なにか画面が固まるので調べる。
→FileVerUpTool
タイムチャートで見る範囲を絞る
レポートのタイムチャートの部分は、チャート上をクリック、ドラッグして、見たい範囲を絞ることができる。
上図で、なにか、CPUを長時間食っていそうな部分に範囲を絞ってみた。 そうすると、その範囲内での、上位の関数、ホットパスが表示される。
ホットパスで、CPU食ってそうなメソッドを絞る
そこでホットパスを見ると、
一番下の、System.DateTime.get.Now()というのが、CPUを食ってそうとわかる。
合計CPUが4394、セルフCPUが4394で同じということは、こいつがさらにほかのメソッドを呼ぶことはなく、こいつが時間を食っている。
で、1/1000msサンプルで4394回食うということは、4.394秒間使っている。
さっき範囲を絞って、5.5秒間のデータを表示しているはずなので、
5.5秒中の4.4秒をこれに使っているということになる。（あきらかに食いすぎ。）
で、このSystem.DateTime.get.Now()自体は、自分が実装した部分ではなく、「システムコード」。
なので、その一つ上のFileVerUpTool.Logic.VersionReadWrite.Read()というのが怪しい。
怪しいメソッドを見る
ホットパスの一覧でそのメソッドをダブルクリックすると、コードを開くことができる。
(試したときの私の環境だと、ダブルクリックしてもコードの該当メソッドには飛んでくれず、該当ファイルの一番上が表示されたので、手で下の方にスクロールした)
コードの該当の個所にいくと、下図のような感じで表示された。
このvar currentTime = startTime;という部分に、4654サンプル分の時間(≒4.6秒)もかかっていた。
そういえば、このプロファイルの取得の実験をするために、無駄に時間をかけるような処理を入れてみたのを忘れていた...
(5秒経過するまで、無限whileでぐるぐる回り続けるという処理を入れていた)
時間のかかっているのは、その個所だった。
実際、時間かかってるのはwhileの中だと思うのだが、サンプル数が多いのはwhileの手前の部分になってる。たぶんこれは、Releaseビルドで動かしていたので、最適化がかかって、そのようになったのではと思う。
ためしにDebugビルドでやってみたら、予想通り、下図のようにwhileの中にカウントが集中するようになった。
※プロファイルとるならReleaseがいいよ、というのは、こういう違いがあるからなんだと分かった。。。
データをフィルタする
また、採取したデータをフィルターすることもできる。
「カテゴリ」「スレッド」「設定」のフィルターがある。
カテゴリ
スレッド
設定
フィルターは、今回実験した簡単なアプリだと、使わなくても解析できてしまったが、仕事のアプリなど、複雑な仕組みが入ったものだと、役に立ちそうな気がする。
参考
学ぶために見た動画
https://www.youtube.com/watch?v=X1-uHpEqNGM&list=PLReL099Y5nRf2cOurn1hI-gSRxsdbC27C&index=4
