この演習の学習目的:

この演習では、NetBeans Profiler を使用した Java SE アプリケーションのスレッド状態監視の使い方を習得します。これによってサンプルアプリケーションのパフォーマンスを分析することができるようになります。

予備知識:

Swing ライブラリは Java SE アプリケーションのグラフィカルユーザインタフェースを提供するライブラリです。Swing ライブラリでは複数のスレッドが使用されており、NetBeans Profile rは それぞれのスレッドでの処理の量を理解するための強力なツールです。このことを理解することにより、パフォーマンスの問題を解決することができるようになります。

手順:

1. 「ファイル」>「プロジェクトを開く」を選択します。<tutorial_root>/netbeansprofiler/exercises フォルダに移動します。exercise1 フォルダを選択し、「プロジェクトフォルダを開く」ボタンをクリックします。
   
2. 「プロジェクト」ウインドウで exercise1 エントリを右クリックし、「プロジェクトの生成物を削除して構築」を選択します。ふたたび exercise1 エントリを右クリックし、「プロジェクトを実行」を選択します。プログラムによって、次のようなウィンドウが表示されます。

   
   

3. 通知までの時間は 30 秒に設定します。
   
4. 「Start!」ボタンをクリックします。この処理中は、プログラムは正しく再描画されません。
   
5. 「Exit」ボタンをクリックします。この処理中は、ボタンが反応しません。
   
6. このウインドウにほかのアプリケーションのウインドウを重ねてみてください。そうするとこのサンプルアプリケーションは再描画されていないことがわかります。たとえば、次のようになります。

   
   

7. 30 秒後、次のようなメッセージボックスが表示されます。メッセージボックスが表示されたらメッセージボックスの「了解」ボタンをクリックしてください。

   
   

8. そうするとサンプルアプリケーションは再び応答するようになります。「Exit」をクリックして終了します。
   
9. 次に、メニューから「プロファイル」>「主プロジェクトをプロファイル」を選択します。
   
10. 次のようなダイアログが表示され、プロジェクトの構築スクリプトを更新してよいかの問い合わせがあった場合は、「了解」をクリックします。たとえば、次のようになります。

    
    

11. プロファイルダイアログが表示されたら、大きく表示されている「アプリケーションを監視」ボタンをクリックします。
    
12. 「スレッド監視を有効」チェックボックスをチェックします。
    
13. 「実行」ボタンをクリックします。次のような調整情報を最初に取得する必要があるという旨のメッセージが表示された場合は、「了解」をクリックしてください。たとえば、次のようになります。

    

    メニューから 「プロファイル」>「拡張コマンド」>「Profiler の調整を実行」を選択して、調整を行うこともできます。調整が終了すると次のようなダイアログが表示されます。表示されたら「了解」ボタンをクリックします。たとえば、次のようになります。

    

    調整後プロファイルは自動的に開始されます。別途調整を行った後にプロファイルを開始するには手順 9 に戻ってください。

14. アプリケーションの実行が開始されると、IDE は次のような Profiler コントロールパネルを開きます。

    
    

15. プロファイラは、次のようにスレッドの状態をメインウインドウに表示します。

    
    

スレッドの状態を表すために、次の色が使用されています。
• 緑: スレッドが実行中であるか、実行可能状態である状態。
• 紫: スレッドが Thread.sleep() メソッドによって休眠中である状態。
• 黄: スレッドが Object.wait() メソッドによって待機状態である状態。
• 赤: スレッドが同期ブロックまたは同期メソッドでブロックされている状態。


16. 先ほど NetBeans IDE からプロファイラの実行によって起動したサンプルの Swing アプリケーションで 「開始!」ボタンを押し、AWT-EventQueue-0 という名前のスレッドの状態をよく観察してください。このスレッドが 30 秒間緑の状態 (実行中) であることがわかります。次の図はその際の様子です。

    

    このグラフをみることによって、なぜアプリケーションが無反応になるのかがわかります。AWT-EventQueue-0 という名前のスレッドは イベント・ディスパッチ・スレッド (Event Dispatch Thread) と呼ばれるスレッドでウインドウ関連のイベントを処理するために Swing によって使用されているスレッドです。うまく作成された Swing アプリケーションではこのイベント・ディスパッチ・スレッドはほとんど待機状態か、 ほんの少しの間だけ実行しているます。このスレッドはそれぞれのイベントをディスパッチする間のほんの少しだけの時間実行されているのが通常です。もしイベントハンドラがすぐに制御を戻さないと、このサンプルのように応答がなくなってしまうのです。
    

17. 30 秒経過すると、アプリケーションのメッセージボックスが表示されます。メッセージボックスを見つけて(通常は NetBeans IDE ウィンドウの上部に表示される)、「了解」ボタンをクリックします。サンプルアプリケーションの「Exit」ボタンをクリックして終了します。
    
18. プロジェクトウインドウは Profiler コントロールパネルと共有しています。「プロジェクト」タブを選択して、「プロジェクト」ウインドウを表示します。
    
19. プロジェクトウインドウを開き、exercise1 をダブルクリックしてエントリを開きます。そのエントリ中にあるソースパッケージフォルダの profilingthreads をクリックして開きます。次に、DisplayForm.java エントリを右クリックして、「開く」を選択します。
    
20. DisplayForm.java を編集しているウインドウで 132 行目から 157 行目までのコメントアウトを解除します。ヒント: エディタに行番号が表示されていない場合には「表示」>「行番号を表示」を選択します。
    
21. DisplayForm.java を編集しているウインドウで、120 行目から 128 行目までを削除するかコメントアウトします。次の図で強調表示されている部分です。

    
    

22. 「ファイル」>「保存」を選択します。ここまでの操作でイベント・ディスパッチ・スレッドを正しく使用していなかったコードを削除し、 より強固な解決方法に置き換えることができました。これによりこのサンプルアプリケーションは期待どおりに応答するようになります。
    
23. 「構築」>「主プロジェクトを構築」を選択します (または F11 キーを押します)。
    
24. 「プロファイル」>「主プロジェクトをプロファイル」を選択します。
    
25. 「プロファイル」ダイアログが表示されます。大きな「アプリケーションを監視」ボタンをクリックします。
    
26. 「スレッド監視を有効」をチェックします。
    
27. 「実行」ボタンをクリックします。
28. サンプルプログラムが表示されたら、「Start!」ボタンを押します。前回と比べてスレッド状態グラフに違いがあることを確認してみてください。今回は次のようになっているはずです。

    

    イベント・ディスパッチャ・スレッド (AWT-EventQueue-0) が黄色のステータスとなり、 "Our SwingWorker #1" というスレッドが作成され、そのステータスが緑色になっていることを 確認してください。イベント・ディスパッチャ・スレッドがイベントの処理のために時間を費やさなくなったために、 ボタンなどのプログラムの制御は期待どおり応答するようになっています。
    

29. 「Exit」ボタンをクリックしてサンプルプログラムを終了します。
    
30. プロファイラのスレッド状態グラフにある "AWT-EventQueue-0" という名前のスレッドを右クリックし、 「スレッドの詳細」を選択します。すると次のような円グラフが表示され、それぞれの状態においてどれだけ時間が費やされたかを表示します。

    

    このグラフはプログラムのそれぞれのスレッドが期待どおりに時間を消費しているかを判断するのに役立ちます。このサンプルでプログラムを更新したあとでは、イベント・ディスパッチャ・スレッドは そのほとんどの時間が待機状態となっていいることがわかります。これは、Swing アプリケーションの理想的な動作状態です。
    

31. プロジェクトウインドウで exercise1 を右クリックし、「プロジェクトを閉じる」を選択します。

まとめ:

演習では、プロファイラからアプリケーションを実行する方法、プロファイラがスレッドの情報をグラフとして表示し、Swing アプリケーションのパフォーマンスの問題を分析するために問題を掘り下げていく方法を学びました。

ページ先頭へ

この演習の学習目的:

この演習ではアプリケーション内のメソッドで、 どれだけの時間がかかっているかをプロファイラを用いて測定する方法を学びます。

予備知識:

CPU パフォーマンスに関する問題は一般に、アプリケーションの特有の機能と密接な関係があります。たとえば、レポートを作成するシステムで特定の種類のレポートのみがほかのレポートよりも作成に時間がかかってしまうような場合などです。アプリケーションをプロファイリングする際には、アプリケーションの一部だけをプロファイリングすることによってプロファイリングによって発生するオーバーヘッドを劇的に減少させることができます。この演習では、NetBeans Profiler を使って Web アプリケーションにおける CPU の使用状況を計測します。このサンプルアプリケーションはメモリーリークを特定する演習 3 でも使用します。

手順:

1. 「ファイル」>「プロジェクトを開く」を選択します。<tutorial_root>/netbeansprofiler/exercises フォルダに移動します。exercise2 フォルダを選択し、「主プロジェクトとして開く」がチェックされていることを確認します。「プロジェクトフォルダを開く」ボタンをクリックします。
   
2. プロジェクトウインドウで、exercise2 のエントリを選択し、 「構築」>「主プロジェクトの生成物を削除して構築」をメニューから選択します。
3. 次に、メニューから「プロファイル」>「主プロジェクトをプロファイル」を選択します。プロジェクトの構築スクリプトを更新してよいかを確認された場合は、「了解」をクリックします。
4. 「プロファイルタスクの選択」ダイアログが表示されます。
5. 「パフォーマンスを解析」ボタンをクリックします。
   
6. ラジオボタンの「アプリケーションの一部」をクリックし、 「アプリケーションの一部」ラジオボタンの右横にある「選択」ボタンをクリックします。すると、「Root メソッドの指定」ウインドウが表示されます。
   

注: ここから 3 ステップは NetBeans 4.1/NetBeans Profiler Mileston 8 の場合のみです。

7. プロファイルを行う root メソッドを選択します。まず「Root メソッドの指定」ウインドウで、「追加」ボタンをクリックします。すると「メソッドの選択」ウインドウが表示されます。
   
8. 「メソッドの選択」ウインドウで、「選択」ボタンをクリックします。すると「クラスへ移動」ウインドウが表示されます。
   
9. クラス名に Per と入力します。しばらくすると、名前の一致するクラスのリストが表示されます。リストが表示されたら、リストから Performance クラスを選択し「開く」ボタンをクリックします。

   注: 次の 2 ステップは、Profiler v5.0 のみが対象です。

10. 「Root メソッドの指定」ウインドウで、プロファイルする root メソッドを追加するために「プロジェクトから追加...」ボタンをクリックします。「メソッドの選択」ウインドウが表示されます。
    
11. 「クラス名」フィールドに demo.Performance と入力し Enter キーを押します。




12. processRequest メソッドをリストから選択し、「了解」ボタンをクリックします。demo.Performance.processRequest メソッドがプロファイル対象の root メソッドとして選ばれたことになります。これは demo.Performance.processRequest メソッドとそのメソッドが呼び出したすべてのメソッドについてのみプロファイリングを行うことになります。プロファイラは demo.Performance.processRequest から呼び出されるメソッドのグラフを決定し、 どのメソッドをプロファイルすべきかを決定します。これによりプロファイル対象ではないメソッドについてはオーバーヘッドなしのフルスピードで動作するようになります。
    
13. 「Root メソッドの指定」ウインドウで「了解」ボタンをクリックします。
    
14. 「パフォーマンスを解析」ウィンドウで、フィルタのリストから「簡易フィルタ」を選択します。プロファイル対象から除外するメソッドを指定するための「簡易フィルタの設定」ダイアログボックスが表示されます。このダイアログは「簡易フィルタ」の横の省略符号ボタン (...) をクリックして開くこともできます。「除く」ラジオボタンが選択されていることを確認します。「フィルタ値」テキストフィールドに org.apache と入力し、「了解」ボタンをクリックします。org.apache パッケージ (およびその子パッケージ) 内のすべてのメソッドがプロファイルから除外されます。それは、選択された root メソッドからの呼び出しであっても同じです。これによってプロファイルのオーバーヘッドを減らし、不要な情報を除外できます。

    
    

15. 「プロファイルタスクの選択」ウインドウで、「実行」ボタンをクリックします。もし、調整情報のダイアログが表示された場合は、「了解」ボタンをクリックします。その後、Profiler のダイアログが表示されたら調整が完了したことになります。ダイアログの「了解」ボタンをクリックしてダイアログを閉じます。
16. IDE は自動的に Tomcat を起動し、その後さらにブラウザを起動して Web アプリケーションの index.jsp を表示します。このとき、その背後ではプロファイラが起動して情報の取得を開始しています。注意: デフォルトでは、そのときにフォーカスがあるブラウザウインドウに index.jsp ページが表示されます。この演習の資料を見ながら作業を行う場合には別のブラウザウインドウを起動しておいてください。
    
17. Web アプリケーションの一部である root メソッドが起動されるように Web アプリケーションを使用します。これによって先ほど root メソッドとして選択した demo.Performance.processRequest が実行されます。ブラウザで「Performance Problems」をクリックし、パフォーマンスのデモページを開きます。パフォーマンスのデモページで、テキストフィールドに 123456 と入力してください。次に、「optimized」のチェック項目がチェックされていないことを確認してください。「実行」ボタンを押します。すると、123456 以下の最も大きい素数が計算されて表示されます。
    
18. この処理の応答が返ってくるまでには数秒かかかります。これは最大の素数を計算するアルゴリズムのパフォーマンス上の問題があることに加えて processRequest メソッドの Profiler による監視のオーバーヘッドがあるためです。
19. 結果として 123449 がブラウザに表示されます。ふたたび NetBeans の画面で ボタンまたはメニューから「プロファイル」>「収集結果のスナップショットを作成」を選択します。そして「結合」タブをクリックして CPU の使用状況のスナップショットを表示します。次の画面のように、Profiler が表示しているのは最新のパフォーマンスに関するプロファイル結果です。

    

    上のウインドウは root メソッドからの完全なメソッドの呼び出しグラフです。下のウインドウはそれをそれをフラットに表示したものです。これらはアプリケーションのホットスポット (よく実行されている個所) を示したもので、最も実行時間が長いメソッドを示しています。

20. ではこのプロファイ結果を見ていきましょう。processRequest メソッドは合計で 8,078 ミリ秒かけて実行されています。しかし、processRequest メソッド自身はそれほど多くの時間を費やしていないことがわかります。それは processRequest の "セルフタイムe" 項目を見ることでわかります。そこではたったの 6.84 ミリ秒しか時間が費やされていないことがわかります。processRequest から呼ばれているメソッドから最もたくさんの時間を費やしているメソッドを見ていくことにしましょう。リストから探すと alculateメソッドが全体の実行時間の 99.7% を占めていることがわかります。ただし、これは calculate メソッドに与えられている仕事の量から考えればそれほど驚くべきことではありません。
21. アプリケーションがしっかりと最適化されているかどうかを判断する助けを得るために、 NetBeans Profiler はアプリケーションのコードのうちボトルネックとなり期待したほどパフォーマンスが出ていなかったり、 うまくスケールアウトしないような部分を特定する助けをします。ホットスポットリストから calculate 項目をクリックして、実際にどこで時間がかかっているのかを調べていきましょう。calculate メソッドがほかのいかなるメソッドも呼び出していない場合、calculate を選択して右クリックし、「ソースへ」を選択してその部分のソースコードを調査します.そうすれば、再設計されるべき非効率なアルゴリズムを発見できることでしょう。
22. メニューから 「プロファイル」>「収集結果をリセット」を選択してプロファイル結果を Profiler のバッファから消去します。では、calculate メソッドの実行時間と、 最適化されたアルゴリズムの calculate2 とを比較してみましょう。ブラウザで、今度は「optimized」をチェックして、先ほどと同様にテキストフィールドに 123456 を入力して実行をクリックします。結果が表示されるのを待って、NetBeans の画面でプロファイルの結果を取得します。再びメニューから「プロファイル」>「収集結果のスナップショットを作成」を選択します。この結果からは、processRequest メソッドがたったの 72.6 ミリ秒で処理が終了していることがわかります。calculate2 メソッドは 10% 以下の実行時間で同じ結果を返したのです。

    

    
    
23. 注意: ウインドウをは閉じずにそのままにしておいてください。次の演習ではこの続きからはじめます。
    

まとめ:

この演習では Profiler を使用してメソッドのパフォーマンス分析をする方法を学びました。

ページ先頭へ

この演習の学習目的:

この演習は演習 2に続いて Profiler を使ってアプリケーションによって生成されたオブジェクトを監視することによってメモリーリークを発見する方法を学びます。

手順:

1. この演習は演習 2の続きからはじめます。演習 2が終了した状態であることを確認してください。
   
2. メニューから「プロファイル」>「主プロジェクトをプロファイル」を選択します。Profiler によって、現在の Profiler プロセスを停止してよいかの問い合わせに対しては、「はい」を選択して次に進んでください。

   

   「プロファイルタスクの選択」ダイアログが表示されます。

3. 「プロファイルタスクの選択」ダイアログで、大きな「アプリケーションを監視」ボタンをクリックします。
4. 「実行」ボタンをクリックします。Profiler コンソールが左側に表示されます。表示されたらボタンをクリックするか、メニューから「プロファイル」>「表示」>「遠隔測定の概要」を選択します。 NetBeans Profiler は次のような 3 つのグラフを表示します。

   

   このウインドウの左にあるグラフでは Java VM のヒープの状態を示しています。赤で示されている部分がJava VMのヒープサイズを示しています。紫の部分はヒープのうち、実際に使用されている部分を示しています。このサンプルでは現在 6M バイトのヒープが確保され、そのうち、4M バイト少々が Java オブジェクトによって使用されていることを示しています。

   右側にあるグラフは活動中のスレッド数を示しています。

   中央にあるグラフはヒープの重要な統計を示しています。

   • 青色の線はJava VM によって実行されているガーベジコレクション処理が実行時間のうちの何パーセントを占めるかを表しています (数値は右側の Y 軸に表示されています)。Java VM によって処理されるガーベジコレクションの実行中はアプリケーションは使用可能ではありません。青線によって示されているのは Java VM のヒープサイズを拡張することを考慮する参考となります (詳しくは -Xmx パラメータのドキュメントを参照してください)。または、ガーベジコレクションの別のアルゴリズムを採用することを考慮する参考にもなります (詳しくは Tuning Garbage Collection (英語) を参照してください)。
     
   • 赤線は生存している世代を表しています。数値は左の Y 軸に表示されています。生存しているオブジェクトの世代数は、Java VM のヒープ中のすべての Java オブジェクトの生存時間 (オブジェクトが何回のガーベジコレクションを生き抜いたか) です。生存している世代が少ない場合には、ほとんどのヒープ上のオブジェクトは生成されてからまもなく回収されていることがわかります。一方、生存している世代が多い場合や増加している場合には、アプリケーションが新たにオブジェクトを生成しながら、その一方ですでに生成済みの古いオブジェクトが参照を持ちまわっているということを示しています。もし、この古いオブジェクトがもうすでに必要ないものであれば、それはメモリーを無駄遣いしている (すなわちメモリーリークが発生している) ということになります。
5. Profiler では CPU 使用状況やメモリーの使用状況について詳細な分析をすることができます。しかしながら、それらは同時に実行することができません。オブジェクトの生成とガーベジコレクションで回収されているオブジェクトについての詳細な情報を得るためには Profiler の設定を変更します。ボタンを押すか、メニューから「プロファイル」>「プロファイルを変更」を 選択してください。
   
6. 「メモリー使用を解析」ボタンをクリックします。
   
7. ラジオボタンの「オブジェクト作成とガベージコレクションの両方を記録」を選択します。
   
8. 次に「割り当てのスタックトレースを記録」にチェックを入れます。
   
9. 「了解」ボタンを押します。
   
10. これで、アプリケーションがメモリーを効率的に使用しているかを分析するための準備が整いました。Web ブラウザに表示されているデモのページから「Memory Leak」を選択します。
11. メモリーリークのデモページで「Start Leaking」をクリックします。
    
12. すると次の例のように「生存中世代グラフ」が急上昇していることがわかります。これがメモリーリークが起こっている可能性を示しています。

    
    

13. 「プロファイル」>「表示」>「ライブ結果」を選択します。Profiler は動的に Java VM ヒープ上にオブジェクトが作成されていく様子を表示します。デフォルトではクラスごととにそのすべてのインスタンスによって消費されているメモリーのバイト数を基準にソートされています。メモリーリークの疑いがあるとわかった場合、次の例のように「世代数」列をクリックしてソートし、それぞれのクラスごとのオブジェクトの生存時間を表示します。

    
    これら列はオブジェクトの生成とメモリー使用の情報を提供しています。

    • 「割り当てオブジェクト数」はプロファイラが監視しているオブジェクトで、それらがどれだけ生成されたかを示しています。この例では 40 インスタンスの float[] が監視開始から作成されています。デフォルト状態ではこの数字はアプリケーションによって生成されたオブジェクトのおおよそ 10% にあたります。プロファイラはオーバーヘッドを軽減させるために、監視対象とするオブジェクトを絞り込んでいます。これによってアプリケーションがほぼフルスピードの状態で実行することができるようになっています。
      
    • 「ライブオブジェクト数」は生成されたオブジェクトのうち、まだ Java VM のヒープ中で生存していて、 メモリーを使用しているオブジェクト数を示しています。
      
    • 「ライブバイト数」 の 2 つの列はヒープメモリー中のオブジェクトのサイズを示しています。片方はそれをヒストグラムであらわしたもので、もうひとつが数値を表示しているものです。「ライブオブジェクト数」はそのインスタンス数を示しています。
      
    • 「平均生存時間」は「ライブオブジェクト数」を使用して計算されています。オブジェクトのそれぞれの生存時間はそのオブジェクトが何回のガーベジコレクションを生き抜いてきたかで決まります。そのそれぞれの合計生存時間を「ライブオブジェクト数」で割ることによって「平均生存時間」が求められています。
      
    • 「世代数」は「ライブオブジェクト数」を使用して計算されています。「平均生存時間」はオブジェクトが何回のガーベジコレクションを生き抜いてきたかを示すのに対し、 「世代数」はライブオブジェクトそれぞれについて何種類の生存時間があるかを示しています。
      
    
    
14. プログラムが動作し続けているのであれば、Profiler はその状態を常に更新していきます。float[] という項目と double[] という項目に注目してみてください。これらの項目の「世代数」の値が上昇し続けていることがわかります。その結果として、float[] と double[] がリスト中で上昇していきます。最終的には java.util.HashMap$Entry がリストの先頭にくるのですが、これも同じように「世代数」の値が上昇していきます。アプリケーションを実行し続けていくと java.util.HashMap$Entry、float[] と double[] の世代数の値は上昇し続けます。しかし次の例のようにほかのいかなるクラスについても、そのような傾向は見られません。

    
    

15. 世代数の値が上昇し続けている原因を調べるために、メニューから「プロファイル」>「収集結果のスナップショットを作成」を選択します。リストの「世代数」のヘッダーをクリックして世代数についてソートします。次に double[] の項目を右クリックして「割り当てスタックトレースを表示」を選択します。Profiler は次のように double[] オブジェクトを生成したすべてのメソッドを表示します。

    
    ここで、double[] オブジェクトを生成しているメソッドのうちひとつだけが、 とても高い値を示していることに注目してください。そのメソッドとは demo.memoryleak.LeakThread というクラスの run() です。

16. run() メソッドの項目を右クリックし 「ソースへ」を選択します。すると Profiler は次のようにソースコードを表示します。
    double[] と float[] オブジェクトはここで生成されて HashMap に格納されていっていることがわかります。さらにそれらは削除されていません。つまり HashMap によってオブジェクトが参照 されていることによって Java VM のガーベジコレクションによって回収されることを妨害していたのです。オブジェクトが Map に格納されてそのまま忘れられてしまうということは Java で発生するメモリーリークのきわめてよくあるパターンのメモリーリークです。このサンプルでは Map として HashMap を使用していますが、そのため java.util.HashMap$Entry オブジェクトも同じようにリークしているのです。

17. プロファイリングのセッションを終了します。メニューから「プロファイル」>「停止」を選ぶか ボタンをクリックしてください。
    
18. プロジェクトウインドウを開き exercise2 を選択して、メニューより「ファイル」>「プロジェクトを閉じる」を選択します。

まとめ:

この演習では Profiler を使用してアプリケーションによって生成されたオブジェクトの監視を行いました。Profiler によって示されるいくつかの種類のメモリーリークを分析するための情報の使い方を学びました。

ページ先頭へ