CPUパフォーマンスの解析

この節の要点

• 各メソッドにどの程度CPU時間が費やされているか測定するためには、プルダウンメニューセッションの構成からメソッドを選択し、プロファイルボタンを選択する。
• 1回分の測定結果はスナップショットとよばれる記録として保存できる。
• スナップショットを比較する際、合計時間にプラスの符号が付いているメソッドは、開いているプロファイルの同名メソッドと比較して比較するスナップショットのプロファイルが遅い、逆にマイナスの符号が付いているメソッドは速いことを意味する。

先に述べたプロファイリングの構成と開始タブのセッションの構成プルダウンメニューからメソッドを選択すると、各メソッドが処理に費やした時間とその割合を可視化するCPUパフォーマンスの解析ができるメソッドタブ(図8)を開くことができます。

ここから、第5週の課題5のプログラムを元にプロファイリングしてみたいと思います。課題5のプログラムは、図10のシミュレーションフローを改変して、図44のシミュレーションフローで構成したと思います。この改変にどの程度影響があるか見てみましょう。

解析を開始する前に、サンプリングするメソッドの範囲を指定したほうが結果が見やすくなります。右上端にある設定ボタンを選択すると、図9のようにプロファイルプルダウンリストが表示されます。ここからプロジェクトのクラスを選びます。

その後、メソッドタブの左上にある緑三角のプロファイルボタンを選択すると、メソッドプロファイラが起動します。プログラムの実行が終わると、図10のようにダイアログボックスが立ち上がって、測定が完了します。

ここで、図10のダイアログが立ち上がった場合は、実行時間が短すぎてスナップショットを作成するには不十分である場合です。プロファイラがスナップショット(比較可能な測定結果)を作成できません。

課題5の場合は、シミュレーションの試行回数が不足しています。初期設定が20年間のシミュレーションでしたから、80年間のシミュレーションに直してみましょう。すると図11のような結果になると思います。

プログラムを改変した前後の性能を比較するためには、1回分の測定結果であるスナップショットとよばれる記録を取ると便利です。

図11にスナップショットが作成できる程度に実行時間が確保できた場合の、プロファイリング完了時のスクリーンショットを示します。ここでは、スナップショットの比較を行いたいので、ダイアログボックスが表示された場合は、ひとまずはいを選択してください。

すると、図12のように、プロファイリング実行時刻が割り当てられたスナップショットが未保存の状態で開かれます。

スナップショットでは、プログラム中で頻出したあるいは計算時間が比較的全体の割合に対して大きいメソッドに関して、処理にかかった時間が記録されています。図12ではmainメソッドの処理時間のみしか、表示されていませんが、ツリービュー表示ができるので、クリックすると図13のように更なる内訳を表示してくれます。

ここで、セルフタイムと呼ばれる項目がありますが、この項目は、それ以外に表示されたメソッドの処理時間を差し引いた、メソッドの実行時間になります。

具体的に図13のスナップショットを読み解くと、mainメソッドは、2種類のprintメソッド(全体に対する割合65.1%+33.5%)と、nextメソッド(全体に対する割合1.4%)の処理時間が大部分を占めており、それ以外の処理にmainメソッドが費やした時間すなわちセルフタイムは非常に小さい(全体に対する割合0%)ことがわかります。さらに、2種類のprintメソッド内の処理の内訳を見ると図14のようになっていました。

これらを見る限り、第5週で言及したように、他の処理よりも表示処理(標準出力)に時間がかかってしまうことが改めて解ると思います。

このスナップショットをより具体的に比較するために保存します。図15のように左上にある保存アイコンをクリックしてください。

すると、図16のスナップショットペインに保存したスナップショットが表示されます。

図16のスナップショットペインはメニューバーのウィンドウ(W) > プロファイル(G) > スナップショット(S)を選択することで表示できます。

スナップショットが時刻名だと判別が困難になるので、図17のように変更したいスナップショットを右クリックして、右クリックメニューを開き名前の変更...を選択して、名前を変更しましょう。

ここでは、スナップショット名を「図44のシミュレーションフロー」としました。次に、mainメソッドの内部を第5週の図10のフローになるように変更後、図8から図17までの手順を同様に踏んでスナップショットを作成します。なおこのスナップショット名は「図10のシミュレーションフロー」としました。

ここまで手順を踏まえると、スナップショットペインが図18になるはずです。

ここで、スナップショットペインで「図44のシミュレーションフロー」をダブルクリックしてスナップショットを表示させます。そして図19のように、スナップショットの表示画面の上部ツールバーに他のスナップショットと比較...ボタンがあるので、これを選びます。

すると、図20のように比較するスナップショットを選択ダイアログがたちあがるので、プロジェクトから(P)のラジオボタンが選択されていることを確認し、「図10のシミュレーションフロー」を選択した状態で、OKを選択します。

その結果、図14のような割合表示ではなく、図21のような差分表示がなされます。

ここまでの手順を踏むことで、第5週の図44のシミュレーションフローに対して、第5週の図10のシミュレーションフローの各メソッドがどの程度速度差を持つか、表示することになります。

図21にて、合計時間に、プラスの符号が付いているメソッドは開いているプロファイルに対して 比較するスナップショットのプロファイル が その秒数だけ遅い ことを示しており、マイナスの符号が付いているメソッドは逆に その秒数だけ速い ことを示しています。

具体的にいえば、図21においては、OneDimensionalSpace.printメソッドは+312ms、mainメソッドについては+643ms、なので図10のシミュレーションフローの方が遅い、ことを表しています。