パフォーマンスアナライザを使用した jlowfruit データの検査

このセクションでは、jlowfruit サンプルコードから作成された実験のデータを調べる方法を示します。

1. 前のセクションで作成した実験がまだ開いていない場合は、jlowfruit ディレクトリからパフォーマンスアナライザを起動して、次のようにして実験をロードできます。

   % analyzer test.1.er

   実験が開くと、パフォーマンスアナライザの「概要」ページが表示されます。

2. 「概要」ページにはメトリック値のサマリーが表示され、メトリックを選択できます。

   

   この実験では、「概要」には、すべてが「ユーザー CPU 時間」だった約 14% の「CPU 時間合計」と、約 14% の「休眠時間」と 71% の「ユーザーロック時間」が示されます。ユーザー Java コード jlowfruit はシングルスレッドであり、その 1 つのスレッドは CPU の制約を受けますが、すべての Java プログラムで多数のシステムスレッドを含む複数のスレッドが使用されます。これらのスレッドの数は、ガベージコレクタのパラメータや、プログラムが実行されたマシンのサイズなどの JVM オプションの選択によって異なります。

   実験は Oracle Solaris システムに記録され、「概要」には記録されたメトリックが 12 個表示されますが、「CPU 時間合計」のみがデフォルトで有効になっています。

   色付きのインジケータがあるメトリックは、Oracle Solaris によって定義された 10 個のマイクロステートで費やされた時間です。これらのメトリックには、さまざまな待ち時間のほかに、一緒にすると「CPU 時間合計」と等しくなる「ユーザー CPU 時間」、「システム CPU 時間」、および「トラップ CPU 時間」が含まれます。「スレッド合計時間」は、すべてのマイクロステートの合計です。

   Linux ではマイクロステートアカウンティングがサポートされないため、Linux マシンでは「CPU 時間合計」のみが記録されます。

   デフォルトでは、「包括的 CPU 合計時間」と「排他的 CPU 合計時間」の両方が選択されています。メトリックの包括的とは、そのメトリックが呼び出すすべての関数またはメソッドで集計されたメソッドを含む、その関数またはメソッドのメトリック値を指します。排他的とは、その関数またはメソッド内で集計されたメトリックのみを指します。

3. 「ホット」ボタンをクリックして、高い値を持つメトリックを選択してデータビューでそれらのメトリックを表示します。

   「休眠時間」と「ユーザーロック時間」の横にあるチェックボックスにチェックマークが付けられました。

   下部にある「メトリックのプレビュー」パネルが更新され、テーブルフォーマットのデータが事前に設定されたデータビューでのメトリックの表示方法が示されます。次に、どのスレッドがどのメトリックを処理するかを確認します。

4. 「表示」ナビゲーションパネルで「スレッド」ビューの名前をクリックするか、メニューバーから「表示」>「スレッド」を選択することで、「スレッド」ビューに切り替えます。

   

   ほとんどすべての「CPU 時間合計」を使用したスレッドは、この単純なアプリケーションでの唯一のユーザー Java スレッドであるスレッド 2 です。

   スレッド 15 は、実際には JVM によって内部で作成されるにもかかわらず、ほとんどの場合ユーザースレッドです。これは、起動中にのみアクティブで、ほとんどの時間が集計されません。実験で、スレッド 15 と似た 2 番目のスレッドが作成されることがあります。

   スレッド 1 はその間中スリープ状態で費やします。

   残りのスレッドは、JVM がそれ自体を内部で同期する方法であるロックの待機にその時間を使用します。これらのスレッドには、HotSpot のコンパイルおよびガベージコレクションに使用されるスレッドが含まれています。このチュートリアルでは、JVM システムの動作を検査しませんが、これは別のチュートリアルであるJava および Java-C++ 混合プロファイリングで検査されます。

5. 「概要」画面に戻って、「休眠時間」と「ユーザーロック時間」のチェックボックスを選択解除します。

6. 「表示」ナビゲーションパネルで「関数」ビューをクリックするか、メニューバーから「表示」>「関数」を選択します。

   

   「関数」ビューには、アプリケーション内の関数のリストがそれぞれの関数のパフォーマンスメトリックとともに表示されます。リストは、最初は各関数で使用された「排他的 CPU 合計時間」でソートされます。「関数」ビューには JVM の関数も多数ありますが、これらは比較的低いメトリックです。リストには、ターゲットアプリケーションのすべての関数とプログラムで使用するすべての共有オブジェクトが含まれています。最上位の関数 (もっともコストが高い関数) がデフォルトで選択されています。

   右側の「選択の詳細」ウィンドウには、選択した関数について記録されたすべてのメトリックが表示されます。

   関数リストの下にある「呼び出し元/呼び出し回数」パネルは、選択した関数に関する詳細情報を提供し、2 つのリストに分割されています。「呼び出し元」リストには選択した関数の呼び出し元が表示され、メトリック値は、その呼び出し元への関数の合計メトリックの属性を示しています。「呼び出し回数」リストは、選択した関数の呼び出し先を示し、呼び出し先の包括的メトリックが選択した関数の合計メトリックにどのように関係したかを示しています。「呼び出し元/呼び出し回数」パネルのいずれかのリストで関数をダブルクリックすると、その関数が、メインの「関数」ビューで選択した関数になります。

7. さまざまな関数を選択してみて、選択の変更によって「関数」ビューのウィンドウが更新される方法を確認します。

   「選択の詳細」ウィンドウには、「ロードオブジェクト」フィールドに示されているように、ほとんどの関数が jlowfruit 実行可能ファイルから生成されることが示されます。

   また、列ヘッダーをクリックしてみて、ソートを「排他的 CPU 合計時間」から「包括的 CPU 合計時間」に変更したり、「名前」でソートに変更したりすることもできます。

8. 「関数」ビューで、2 つのバージョンの初期化タスク jlowfruit.init_bad() と jlowfruit.init_good() を比較します。

   2 つの関数では、「排他的 CPU 合計時間」はほとんど同じですが、包括的時間はたいへん異なることがわかります。jlowfruit.init_bad() 関数は、呼び出し先で費やす時間が原因で遅くなります。両方の関数が同じ呼び出し先を呼び出しますが、そのルーチンで費やす時間には大差があります。2 つのルーチンのソースを検査することで理由を確認できます。

9. 関数 jlowfruit.init_good() を選択してから、「ソース」ビューをクリックするか、メニューバーから「表示」>「ソース」を選択します。

10. ウィンドウを調整して、コードの領域をさらに確保します。上マージンの下矢印をクリックして「呼び出し元/呼び出し回数」パネルを縮小して、横マージンの右矢印をクリックして「選択の詳細」パネルを縮小します。

    jlowfruit.init_bad() と jlowfruit.init_good() の両方のソースを表示するには、少し上へスクロールしてください。「ソース」ビューは次のスクリーンショットのようになるはずです。

    

    jlowfruit.init_static_routine() への呼び出しは jlowfruit.init_good() のループの外部で行われるのに対して、jlowfruit.init_bad() にはループ内の jlowfruit.init_static_routine() への呼び出しがあります。正しくないバージョンでは、正しいバージョンより約 10 倍長く (ループカウントに対応) かかります。

    この例は、表示されているほどくだらないものではありません。これは、表の行ごとにアイコンが示された表を生成する実際のコードに基づいています。この例では初期化をループ内で行うべきではないことが簡単にわかりますが、実際のコードでは、初期化はライブラリルーチンに組み込まれており、明らかではありませんでした。

    そのコードを実装するために使用されたツールキットでは、2 つのライブラリ呼び出し (API) を使用できました。最初の API では、アイコンが表の行に追加され、2 番目の API では、アイコンのベクトルが表全体に追加されました。最初の API を使用したコーディングの方が簡単ですが、アイコンが追加されるたびに、ツールキットでは、表全体の正しい値を設定するためにすべての行の高さが再計算されました。コードで代替の API を使用して一度にすべてのアイコンを追加したときに、高さの再計算は一度のみ行われました。

11. 次に、「関数」ビューに戻って、2 つのバージョンの挿入タスク jlowfruit.insert_bad() と jlowfruit.insert_good() を調べます。

    jlowfruit.insert_bad() の「排他的 CPU 合計時間」は莫大ですが、jlowfruit.insert_good() ではごくわずかです。各エントリをリストに挿入するために呼び出される関数 jlowfruit.insert_number() での時間を表す、各バージョンの包括的時間と排他的時間の差は同じです。ソースを検査することで理由を確認できます。

12. jlowfruit.insert_bad() を選択して、「ソース」ビューに切り替えます。

    

    jlowfruit.insert_number() への呼び出しを除き、時間は、新しい数値を挿入するために適した場所のリニア検索で表示されるループで使用されます。

13. 次に、下へスクロールして jlowfruit.insert_good() を確認します。

    

    コードは、挿入に適した場所を見つけるためにバイナリ検索を行なっているためより複雑ですが、jlowfruit.insert_number() への呼び出しを除き、費やされる合計時間は jlowfruit.insert_bad() での時間より大幅に少なくなります。この例は、バイナリ検索はリニア検索より効率的である可能性があることを示しています。

    「タイムライン」ビューでは、ルーチンでの違いをグラフィカルに確認することもできます。

14. 「タイムライン」ビューをクリックするか、メニューバーから「ビュー」>「タイムライン」を選択します。

    プロファイリングデータは、すべてのスレッドのプロファイリングクロックのティックごとに 1 つ、一連のイベントとして記録されます。「タイムライン」ビューには、それぞれの個別のイベントが、そのイベントで記録された呼び出しスタックとともに表示されます。呼び出しスタックは、呼び出しスタック内のフレームのリストとして表示され、上部にはリーフ PC (イベントの時点で実行する次の指示)、次にこれを呼び出す呼び出し側などが表示されます。プログラムのメインスレッドでは、呼び出しスタックの上部は常に _start です。

15. 「タイムライン」ツールバーで、関数に色を付けるための「呼び出しスタック関数の色」アイコンをクリックするか、メニューバーから「ツール」>「関数の色」を選択すると、次に示すダイアログボックスが表示されます。

    

    関数の色が変更され、スクリーンショットで正しいバージョンの関数と正しくないバージョンの関数がより明確に区別されます。jlowfruit.init_bad() 関数と jlowfruit.insert_bad() 関数は両方とも赤色で、jlowfruit.init_good() と jlowfruit.insert_good() は両方とも明るい緑です。

16. 「タイムライン」ビューをより似た外観にするには、「関数の色」ダイアログボックスで次を行います。

    • 「凡例」で java メソッドのリストを下へスクロールして、jlowfruit.init_bad() メソッドを見つけます。

    • jlowfruit.init_bad() メソッドを選択して、「見本」で赤色の正方形をクリックし、「選択した関数の設定」ボタンをクリックします。

    • jlowfruit.insert_bad() メソッドを選択して、「見本」で赤色の正方形をクリックし、「選択した関数の設定」ボタンをクリックします。

    • jlowfruit.init_good() メソッドを選択して、「見本」で緑色の正方形をクリックし、「選択した関数の設定」ボタンをクリックします。

    • jlowfruit.insert_good() メソッドを選択して、「見本」で緑色の正方形をクリックし、「選択した関数の設定」ボタンをクリックします。

17. 「タイムライン」のいちばん上のバーを確認します。

    マウスカーソルを最初の列の上に移動するとツールチップで確認できるように、「タイムライン」のいちばん上のバーは「CPU 使用率標本」バーです。「CPU 使用率標本」バーの各セグメントは、その秒の実行の間のターゲットのリソース使用率を示す 1 秒の間隔を表します。

    この例では、セグメントはほとんどが灰色で一部が緑であり、「合計時間」のほんのわずかのみが「ユーザー CPU 時間」の集計に費やされたことを反映しています。マイクロステートへの色のマッピングはスクリーンショットに示されていませんが、「選択の詳細」ウィンドウにはこれが示されます。

18. 「タイムライン」の 2 番目のバーを確認します。

    2 番目のバーはクロックプロファイリング呼び出しスタックのバーで、「1 T:2」というラベルが付いており、プロセス 1 と、この例での主なユーザースレッドであるスレッド 2 を意味します。「クロックプロファイリング呼び出しスタック」バーには、プログラムの実行中に発生するイベントのデータの 2 つのバーが示されます。上部のバーは、呼び出しスタックの色分けされた表現を示し、下部のバーは、各イベントでのスレッドの状態を示します。この例の状態は常に「ユーザー CPU 時間」であるため、緑で塗りつぶされた線で表示されます。

    異なるスレッド番号のラベルが付いた 1 つまたは 2 つの追加のバーが表示されるはずですが、これらのバーには実行の開始時には少数のイベントしかありません。

    「クロックプロファイリング呼び出しスタック」バー内の任意の場所でクリックして、もっとも近いイベントを選択すると、そのイベントの詳細が「選択の詳細」ウィンドウに表示されます。呼び出しスタックのパターンから、スクリーンショットでは明るい緑で示されている jlowfruit.init_good() ルーチンと jlowfruit.insert_good() ルーチンでの時間は、赤色で示されている jlowfruit.init_bad() ルーチンと jlowfruit.insert_bad() ルーチンでの対応する時間よりも大幅に短いことがわかります。

19. 「タイムライン」で正しいルーチンと正しくないルーチンに対応する領域でイベントを選択して、「選択の詳細」ウィンドウの下にある「呼び出しスタック - タイムライン」ウィンドウで呼び出しスタックを確認します。

    「呼び出しスタック」ウィンドウで任意のフレームを選択してから、「ビュー」ナビゲーションバーの「ソース」ビューを選択して、そのソース行のソースに移動します。また、呼び出しスタックでフレームをダブルクリックして「ソース」ビューに移動することも、呼び出しスタックでフレームを右クリックしてポップアップメニューから選択することもできます。

20. 「タイムライン」の上部にあるスライダを使用するか、+ キーを使用するか、またはマウスでダブルクリックすることで、イベントでズームインします。

    十分にズームインすると、表示されるデータは連続していなくても、プロファイルティック (この例では約 10 ミリ秒) ごとに 1 つの個別のイベントで構成されていることがわかります。

    

    「タイムライン」ビューに関する詳細情報のヘルプを表示するには、F1 キーを押します。

21. 「呼び出しツリー」ビューをクリックするか、「ビュー」>「呼び出しツリー」を選択してプログラムの構造を表示します。

    「呼び出しツリー」ビューには、パフォーマンス情報の注釈が付いたプログラムの動的呼び出しグラフが表示されます。