2 診断ツール

Java Mission Controlで実行可能なトラブルシューティング・アクティビティ。

• Java管理コンソール(JMX)が実行中のJVMに接続し、主な特性をリアルタイムに収集して表示します。
• JVMのユーザー指定のカスタム・アクションとルールのトリガーを設定します。
• 試験的プラグイン(WLS、DTrace、JOverflowおよび他のJMCツールのプラグイン)でトラブルシューティング・アクティビティを実行します。
  • DTraceプラグインはDScript言語を拡張したもので、自己記述型のイベントを生成します。Javaフライト・レコーダのように可視化できます。
  • JOverflowはヒープの未使用領域(空/疎コレクション)を分析するためのもう1つのプラグイン・ツールです。JOverflowプラグインの使用を最適化するには、JDK 8以降のリリースの使用をお薦めします。
• Java Mission ControlのJavaフライト記録(JFR)はイベントの分析に使用できます。事前構成済のタブを使用すると、コード、メモリーとGC、スレッドとI/Oといったよく使用される様々な領域で簡単にドリルダウンできます。一般イベント・タブと操作イベント・タブを組み合せて使用することで、特定のプロパティのイベント・セットを詳細にドリルダウンし、手早く焦点を絞ることができます。通常、「イベント」タブにはチェック・ボックスがあり、「操作セット」内のイベントのみが表示されます。
  • JFRをJMCクライアント用のプラグインとして使用すると、論理的にグループ化された表、グラフおよびダイアルに診断情報が表示されます。これを使用すると、問題に焦点を当てるために必要となる期間および詳細レベルを選択できます。「Javaフライト・レコーダ」を参照してください。
• Java Mission Controlプラグインは、Java Management Extensions (JMX)エージェントを使用してJVMに接続します。JMXは、アプリケーション、デバイス、サービス、Java仮想マシンなどのリソースを管理およびモニタリングするための標準APIです。

  JMCの詳細は、JMCのドキュメントを参照してください。

連続記録とプロファイリング記録の2種類のフライト記録があります。

• 連続記録: 連続記録は、常時オンの記録で、たとえば、最近6時間のデータを保存します。アプリケーションで問題が発生した場合は、たとえば、最後の1時間のデータをダンプし、問題発生時に何が起こったかを調べることができます。

  連続記録のデフォルト設定は、低いオーバーヘッドで記録プロファイルを使用することです。このプロファイルは、ヒープの統計や割当てプロファイリングを取得しませんが、役立つデータを大量に収集します。

  連続記録は、常に実行されていることが重要であり、あまり発生しない問題をデバッグする際に便利です。記録は、jcmdまたはJMCのいずれかを使用して手動でダンプできます。また、特定の条件が満たされたときにフライト記録をダンプするためにJMCにトリガーを設定することもできます。

• プロファイリング記録: プロファイリング記録は、オンになると、一定時間実行した後、停止する記録です。通常、プロファイリング記録では、より多くのイベントが有効であり、パフォーマンスへの影響がいくらか大きくなる場合があります。オンにするイベントは、プロファイリング記録の使用に応じて変更できます。

  プロファイリング記録の一般的なユース・ケースは次のとおりです。

  • 最もよく実行されるメソッドおよび最も多くのオブジェクトが作成される場所のプロファイルを記録する。

  • メモリー・リーク発生の指標となる、ヒープ使用量の増加を示しているクラスを探す。

  • 同期に起因するボトルネックおよび多数のこのようなユース・ケースを探す。

  プロファイリング記録は、特定の問題のトラブルシューティングをしていない場合にも、多くの情報を提供します。プロファイリング記録では、アプリケーションの全体像を見て、ボトルネックまたは改善の必要な領域を見つけることができます。

フライト記録を簡単に管理するには、Java Mission Control (JMC)を使用します。

前提条件:

開始するには、図2-1に示すように左端のフレームのJVMブラウザで自分のサーバーを見つけます。

図2-1 Java Mission Control - サーバーを見つける

「図2-1 Java Mission Control - サーバーを見つける」の説明

デフォルトでは、ローカルで実行中のすべてのJVM一覧が表示されます。リモートJVM (JMCを実行しているユーザーと同じ有効ユーザーで実行)はリモートJMXエージェントを使用するように設定する必要があります。次に、新しいJVM接続ボタンをクリックし、ネットワークの詳細を入力します。

JDK 8u40より前のリリースでは、-XX:+UnlockCommercialFeatures -XX:FlightRecorderフラグを指定してJVMが起動されている必要がありました。

JDK 8u40リリースからは、Javaフライト・レコーダを実行時に有効にすることができます。

1. 実行中の記録の確認: JVMブラウザのノードを展開して実行中の記録を表示します。図2-2は、実行中の連続記録(無限大記号を持つ)と一定時間のプロファイリング記録を示しています。

   図2-2 Java Mission Control - 実行中の記録

   
   「図2-2 Java Mission Control - 実行中の記録」の説明

   任意の記録を右クリックして、記録をダンプ、編集または停止します。プロファイリング記録を停止しても記録ファイルは作成され、プロファイリング記録を閉じると記録が破棄されます。

2. 連続記録のダンプ: JVMブラウザで連続記録を右クリックし、ファイルへのダンプを選択します。図2-3に示すように、表示されるダイアログ・ボックスで、使用可能なすべてのデータまたは記録の最後の部分のみをダンプすることを選択します。

   図2-3 Java Mission Control - 連続記録のダンプ

   
   「図2-3 Java Mission Control - 連続記録のダンプ」の説明
3. 新しい記録の開始: 新しい記録を開始するには、記録するJVMを右クリックし、「フライト記録の開始」を選択します。図2-4に示すようなウィンドウが表示されます。

   図2-4 Java Mission Control - フライト記録の開始

   
   「図2-4 Java Mission Control - フライト記録の開始」の説明

   図2-4に示すように、「一定時間の記録」(プロファイリング記録)または「連続記録」のいずれかを選択します。連続記録の場合は、保存するイベントの最大サイズまたは最大保持時間も指定します。

   「イベント設定」を選択することもできます。独自のテンプレートを作成することもできますが、すべてのユース・ケースの99%では、連続テンプレート(記録オーバーヘッドが非常に低い )またはプロファイリング・テンプレート(より多くのデータと若干のオーバヘッド)のいずれかを選択できます。注意: プロファイリング記録の通常のオーバーヘッドは2%程度です。

   完了後、「次へ」をクリックします。図2-5に示すように、次の画面では、様々なユース・ケースに合わせてテンプレートに修正を加えることができます。

   図2-5 Java Mission Control - プロファイリングのイベント・オプション

   
   「図2-5 Java Mission Control - プロファイリングのイベント・オプション」の説明

   デフォルトの設定では、データとパフォーマンスのバランスが良くとれています。いくつかのケースでは、別のイベントを追加する場合があります。たとえば、メモリー・リークを調査し、多くのJavaヒープを消費するオブジェクトを見つける場合は、ヒープ統計を有効にします。これにより、記録の開始時と終了時に2つのOldコレクションがトリガーされるので、待機時間が増えます。また、キャッチされた例外も含め、スローされたすべての例外を表示することも選択できます。一部のアプリケーションでは、多くのイベントが生成されます。

   しきい値は、記録イベントの長さです。たとえば、デフォルトでは、10msを超える同期イベントが収集されます。これは、スレッドが10msを超えてロックを待機している場合、イベントが保存されることを意味します。短い競合の詳細データを取得するには、この値を下げることができます。

   「スレッド・ダンプ」の設定は、定期的なスレッド・ダンプを実行するためのオプションを提供します。これらは、診断コマンドThread.printの使用、またはjstackツールの使用により取得されるような、通常のテキストのスレッド・ダンプです。スレッド・ダンプは、イベントを補完します。

コマンド行で起動フラグを使用して、プロファイリング記録の作成、連続記録、診断コマンドの使用を行います。

1. プロファイリング記録の開始: -XX:StartFlightRecordingオプションを使用して、アプリケーションの起動時に一定時間の記録を設定できます。JFRは商用の機能なので、-XX:+UnlockCommercialFeaturesオプションを指定する必要があります。次の例は、MyAppアプリケーションを実行し、JVMを起動してから20秒後に60秒間の記録を開始し、それをmyrecording.jfrという名前のファイルに保存する方法を示しています。

   java -XX:+UnlockCommercialFeatures -XX:+FlightRecorder -XX:StartFlightRecording=delay=20s,duration=60s,name=myrecording,filename=C:\TEMP\myrecording.jfr,settings=profile MyApp

   settingsパラメータにはテンプレートへのパスまたはテンプレート名を指定します。デフォルトのテンプレートはjre/lib/jfrフォルダにあります。2つの標準プロファイルがあります: デフォルトは、主に連続記録のために作成されたオーバーヘッドの低い設定で、プロファイルは、より多くのデータを収集し、主にプロファイリング記録用です。

2. 連続記録の開始: -XX:FlightRecorderOptionsを使用して、コマンド行から連続記録を開始することもできます。これらのフラグは、必要に応じて後でダンプできる連続記録を開始します。次の例は、連続記録を示しています。一時データはディスクに保存され(/tmpフォルダ)、6時間のデータが保存されます。

   java -XX:+UnlockCommercialFeatures -XX:+FlightRecorder -XX:FlightRecorderOptions=defaultrecording=true,disk=true,repository=/tmp,maxage=6h,settings=default MyApp

   注意:

   実際に記録をダンプするときは、ダンプ・ファイルのための新しい場所を指定するので、リポジトリ内のファイルは一時的です。

   Javaフライト記録の構成および管理の詳細は、Java Flight Recorderランタイム・ガイドを参照してください。

3. 診断コマンドの使用:

   Javaコマンド行の診断コマンドを使用して記録を制御することもできます。診断コマンドを実行するもっとも単純な方法は、Javaインストール・ディレクトリにある jcmdツールを使用することです。詳細は、「jcmdユーティリティ」を参照してください。

条件が満たされた場合にフライト記録を自動的に開始またはダンプするようにJava Mission Controlを設定できます。これはJMXコンソールから実行します。JMXコンソールを起動するには、JVMブラウザでアプリケーションを見つけてそれを右クリックし、JMXブラウザの起動を選択します。

図2-6に示すように、画面の下部にある「トリガー」タブを選択します。

図2-6 Java Mission Control - 自動記録

「図2-6 Java Mission Control - 自動記録」の説明

アプリケーション内の任意のMBeanにトリガーを作成することがきます。高いCPU使用率、デッドロック・スレッド、過剰なライブ・セットなどのいくかの一般的な条件のためのデフォルト・トリガーが設定されています。「追加」を選択して、アプリケーション内の任意のMBean(アプリケーションに固有のものを含む)を選択します。トリガーを選択するとき、満たす必要のある条件も選択できます。詳細は、右上の疑問符をクリックして組込みのヘルプを参照してください。

複数のトリガーを実行するには、トリガーの横のボックスをクリックします。

条件を選択したら、「アクション」タブをクリックします。次に、条件が満たされたときに実行する処理を選択します。最後に、図2-7に示すように、連続記録のダンプまたは期間限定のフライト記録の開始のいずれかを選択します。

図2-7 Java Mission Control - トリガーの使用

「図2-7 Java Mission Control - トリガーの使用」の説明

フライト記録を作成して、Mission Controlでそれを開くことができます。

• Mission Controlを開き、「JVMブラウザ」タブを選択する。
• Mission Controlを実行しているJVMオプションを選択して短い記録を作成する。

  フライト記録を開くと、「全般」、「メモリー」、「コード」、「スレッド」、「I/O」、「システム」および「イベント」などのいくつかのメイン・タブが表示されます。プラグインがインストールされている場合は、他のメイン・タブも表示されることがあります。これらのメイン・タブには、それぞれのサブタブがあります。疑問符をクリックして組込みのヘルプのメイン・タブおよびサブタブに関する項を参照してください。

範囲ナビゲータを使用して、フライト記録を検査します。

各タブの上部のビューに、範囲ナビゲータがあります。

図2-8 フライト記録の検査 - 範囲ナビゲータ

「図2-8 フライト記録の検査 - 範囲ナビゲータ」の説明

図2-8の縦棒は、記録内のイベントを表します。棒の高さが高いほど、より多くのイベントがその時点で発生しています。選択された時間の端をドラッグして、記録のズーム・インまたはズーム・アウトができます。範囲ナビゲータをダブルクリックすると、ズーム・アウトして記録全体が表示されます。すべてのサブタブに同じズーム・レベルを適用するには、「選択の同期」チェック・ボックスをクリックします。

詳細は、組込みヘルプの範囲ナビゲータの使用に関する項を参照してください。イベントの名前は、タブの名前どおりです。

「全般」タブのフライト記録を検査します。

「全般」タブには、アプリケーション全般について説明するいくつかのサブタブが含まれています。図2-9に示すように、最初のサブタブは「概要」で、ここには最大ヒープ使用量、合計CPU使用率およびGC一時休止時間などの基本情報が表示されます。

図2-9 フライト記録の検査 - 「全般」タブ

「図2-9 フライト記録の検査 - 「全般」タブ」の説明

また、CPU使用率の経時的推移、アプリケーションでの使用状況とマシンでの合計を調べます。このタブは、アプリケーションで直接に問題が発生したときに調べるための便利なタブです。たとえば、100%近くまで急上昇しているCPU使用率、低すぎるCPU使用率、またはガベージ・コレクションの一時休止などに注意してください。

注意: ヒープ統計を指定して開始されたプロファイリング記録は、記録の開始時と終了時に、他のコレクションよりも長くかかる可能性がある、2つのOldコレクションを取得します。

また、「JVM情報」サブタブには、JVM情報が表示されます。起動パラメータのサブタブの「システム・プロパティ」には、設定されたすべてのシステム・プロパティが表示され、「記録」には、オンにされたイベントなど、特定の記録に関する情報が表示されます。すべてのタブおよびサブタブについて組込みの詳細を参照するには、疑問符をクリックしてください。

「メモリー」タブのフライト記録を検査します。

「メモリー」タブには、ガベージ・コレクション、割当てパターンおよびオブジェクト統計に関する情報が含まれています。このタブは、メモリー・リークのデバッグおよびGCのチューニングのために特に役立ちます。

「概要」タブには、メモリー使用量に関する一般情報およびガベージ・コレクションに関する統計情報が表示されます。注意: 「概要」タブのグラフでは、目盛の最大値がマシンで使用可能な物理メモリーです。そのため、Javaヒープは、下部のわずかな部分のみを取る場合があります。

「メモリー」タブの3つのサブタブは次のとおりです。

• 「ガベージ・コレクション」タブ: 「ガベージ・コレクション」タブには、メモリー使用量の経時的推移およびすべてのガベージ・コレクションに関する情報が表示されます。

  図2-10 フライト記録の検査 - ガベージ・コレクション

  
  「図2-10 フライト記録の検査 - ガベージ・コレクション」の説明

  図2-10に示すように、ヒープ使用量のスパイク状のパターンはまったく正常です。ほとんどのアプリケーションでは、一時オブジェクトが絶えず割り当てられています。条件が満たされると、ガベージ・コレクション(GC)がトリガーされ、使用されなくなったすべてのオブジェクトが削除されます。したがって、ヒープ使用量は、GCがトリガーされるまで絶え間なく増加した後、急激に減少します。

  JavaのほとんどのGCには、何らかの小規模なガベージ・コレクションがあります。Old GCではJavaヒープ全体が対象となり、他のGCではヒープの一部を調べる場合があります。Oldコレクション後のヒープ使用量は、アプリケーションで使用されているメモリーであり、ライブ・セットと呼ばれています。

  ヒープ統計を有効にして生成されるフライト記録は、Old GCで開始および終了します。GCの一覧からそのOld GCを選択し、「全般」タブを選択して「GC理由」を参照すると、ヒープ検査によるGCの開始であることがわかります。通常、これらのGCは、他のGCよりも少し時間がかかります。

  メモリー・リークに対処するための最適な方法としては、最初と最後のOld GCでの「GC後のヒープ」の値を確認してください。この値が経時的に増加している場合は、メモリー・リークの可能性があります。

  「GC回数」タブには、GCの実行にかかった時間とGCのためにアプリケーションが完全に一時休止する時間に関する情報があります。「GC構成」タブには、GCの構成に関する情報があります。これらのタブの詳細は、右上の疑問符をクリックして組込みのヘルプを参照してください。

• 「割当て」タブ: 図2-11では、行われたすべてのメモリー割当ての選択を示しています。Javaの小さなオブジェクトは、TLAB (Thread Local Area Buffer)に割り当てられます。TLABは、新しいオブジェクトが割り当てられている小さなメモリー領域です。TLABが一杯になると、スレッドが新しいものを取得します。すべてのメモリー割当てをログすると、オーバーヘッドが生じるので、新しいTLABをトリガーしたすべての割当てがログされます。大きいオブジェクトは、TLAB外に割り当てられ、これらもログされます。

  図2-11 フライト記録の検査 - 「割当て」タブ

  
  「図2-11 フライト記録の検査 - 「割当て」タブ」の説明

  各クラスのメモリー割当てを推定するには、「新しいTLABの割当て」タブ、「割当て」タブの順に選択します。これらの割当ては、新しいTLABをトリガーするために起こるオブジェクトの割当てです。char型の配列は、新しいTLABを最も多くトリガーします。どれだけのメモリーがchar型の配列として割り当てられているかは不明です。TLABのサイズは、char型の配列によって割り当てられるメモリーを推定するのに役立ちます。

  図2-11は、最も多くのメモリーを割り当てるchar型の配列の例です。いずれかのクラスをクリックして、これらの割当てのスタック・トレースを参照してください。記録の例では、すべての割当てプレッシャの44%がchar型の配列に由来し、27%がStringBuilder.toStringから呼び出されるArray.copyOfRangeに由来することを示しています。通常、StringBuilder.toStringは、Throwable.printStackTraceおよびStackTraceElement.toStringによって呼び出されます。これらのメソッドの呼出しを確認するには、さらに展開します。

  注意: アプリケーションによる一時オブジェクトの割当てが多いほど、アプリケーションで必要なガベージ・コレクションが増えます。「割当て」タブは、ほとんどの割当てを見つけてアプリケーションのGCプレッジャを減らすことに役立ちます。「TLAB外の割当て」タブでは、通常、「新しいTLABの割当て」タブよりもメモリー・プレッシャが少ない、大きいメモリー割当てを参照できます。

• 「オブジェクト統計」タブ: 「オブジェクト統計」タブには、ほとんどのライブ・セットを持つクラスが表示されます。ライブ・セットについて理解するには、「「メモリー」タブ」の「ガベージ・コレクション」サブタブを参照してください。図2-12では、フライト記録のヒープ統計を示しています。データを表示するには、フライト記録のヒープ統計を有効にしてください。下部の「上位の増加」タブでは、フライト記録中に各オブジェクト・タイプのサイズがどれだけ増加したかを示しています。特定のオブジェクト・タイプのサイズが大きく増加した場合にはメモリー・リークを示していますが、わずかな変動は正常です。特に、標準Javaクラス以外の上位の増加を調査します。

  図2-12 フライト記録の検査 - 「オブジェクト統計」タブ

  
  「図2-12 フライト記録の検査 - 「オブジェクト統計」タブ」の説明

「コード」タブのフライト記録を検査します。

「コード」タブには、アプリケーションが時間の大半を費やしている場所の情報が含まれます。「概要」サブタブには、最も多くの実行時間を費やしたパッケージおよびクラスが表示されます。これはサンプリングからのデータです。JFRでは、一定の間隔で実行中のスレッドのサンプルを取ります。実際のコードを実行しているスレッドのみがサンプリングされ、スリープ中、ロックまたはI/Oを待機中のスレッドは表示されません。

実際のコードを実行するためのアプリケーション時間の詳細は、「ホット・メソッド」サブタブを参照してください。

図2-13 フライト記録の検査 - 「コード」タブ

「図2-13 フライト記録の検査 - 「コード」タブ」の説明

図2-13では、最も多くサンプリングされたメソッドを示しています。これらの呼出し元を確認するには、サンプルを展開します。HashMap.getEntryの呼出しが多い場合は、最も多く呼び出したメソッドが見つかるまでこのノードを展開します。このタブは、アプリケーションのボトルネックを見つけるのに最適です。

「呼出しツリー」サブタブでは、同じイベントが下から(Thread.runなどから)順に表示されます。

「例外」サブタブには、スローされた例外が表示されます。デフォルトではエラーのみがログされますが、すべての例外を含めるには、新しい記録を開始するときにこの設定を変更します。

「コンパイル」サブタブには、アプリケーションが実行されていたときにコンパイルされたメソッドが表示されます。

「クラスのロード」サブタブには、時間の経過とともにロードされたクラス数、実際にロードされたクラスおよびアンロードされたクラスが表示されます。このサブタブは、記録の開始時にクラス・ロード・イベントが有効であった場合にのみ情報が表示されます。

これらのタブの詳細は、右上の疑問符をクリックして組込みのヘルプを参照してください。

「スレッド」タブのフライト記録を検査します。

「スレッド」タブには、スレッド、ロックの競合およびその他の待機時間に関する情報が含まれます。

「概要」サブタブには、CPU使用率およびスレッド数の経時的な推移が示されます。

「ホット・スレッド」サブタブには、ほとんどのコード実行を行うスレッドが表示されます。この情報は、「コード」タブの「ホット・メソッド」サブタブと同じサンプリング・データに基づいています。

「競合」タブは、ロックの競合に起因するボトルネックを見つけるのに役立ちます。

図2-14 フライト記録の検査 - 「競合」タブ

「図2-14 フライト記録の検査 - 「競合」タブ」の説明

「待機時間」サブタブは、たとえば、スリープまたは待機の呼出し、ソケットからの読取り、ファイルI/Oの待機など、その他の待機時間の原因を示します。

「スレッド・ダンプ」サブタブには、記録内でトリガーできる定期的なスレッド・ダンプが表示されます。

「ロック・インスタンス」サブタブには、同期のために最も待機しているオブジェクトの正確なインスタンスが表示されます。

これらのタブの詳細は、右上の疑問符をクリックして組込みのヘルプを参照してください。

「I/O」タブには、ファイルの読取り、ファイルの書込み、ソケットの読取りおよびソケットの書込みに関する情報が表示されます。

「システム」タブは、アプリケーションが実行されているマシンのCPU、メモリーおよびOSに関する詳細を提供します。

また、環境変数およびJVMと同時に実行されている他のプロセスも表示されます。

「イベント」タブには、記録のすべてのイベントが表示されます。

これは様々な方法で使用できる詳細タブです。これらのタブの詳細は、右上の疑問符をクリックして組込みのヘルプを参照してください。

使用可能な診断コマンドはHotSpot VMのバージョンごとに異なる場合があるので、jcmd <process id/main class> helpを使用して、使用可能なすべてのオプションを確認することをお薦めします。

• HotSpotおよびJDKのバージョンIDの出力
  jcmd <process id/main class> VM.version
• VMに設定されているすべてのシステム・プロパティの出力

  数百行の情報が表示される可能性があります。

  jcmd <process id/main class> VM.system_properties

• VMで使用されるすべてのフラグの出力

  フラグを指定していない場合でも、いくつかのデフォルト値(初期ヒープ・サイズや最大ヒープ・サイズなど)が表示されます。

  jcmd <process id/main class> VM.flags

• 稼働時間(秒)の出力

  jcmd <process id/main class> VM.uptime

• クラス・ヒストグラムの作成

  出力結果が冗長になる可能性があるので、出力をファイルにリダイレクトできます。内部クラスとアプリケーション固有のクラスの両方がリストに含まれます。メモリーの消費量が最も多いクラスから降順に表示されます。

  jcmd <process id/main class> GC.class_histogram

• ヒープ・ダンプの作成

  jcmd GC.heap_dump filename=Myheapdump

  これはjmap -dump:file=<file> <pid>を使用する方法と同じですが、推奨ツールはjcmdです。

• ヒープ・ヒストグラムの作成

  jcmd <process id/main class> GC.class_histogram filename=Myheaphistogram

  これはjmap -histo <pid>を使用する方法と同じですが、推奨ツールはjcmdです。

• スタック・トレースのあるすべてのスレッドの出力

  jcmd <process id/main class> Thread.print

jcmdユーティリティを使用してトラブルシューティングします。

• 記録の開始

  たとえば、識別子が7060の実行中Javaプロセスで2分間の記録を開始し、それを現在のディレクトリのmyrecording.jfrに保存するには、次を使用します。

  jcmd 7060 JFR.start name=MyRecording settings=profile delay=20s duration=2m filename=C:\TEMP\myrecording.jfr

• 記録の確認

  JFR.check診断コマンドは、実行中の記録を確認します。次に例を示します。

  jcmd 7060 JFR.check

• 記録の停止

  JFR.stop診断コマンドは、実行中の記録を停止し、記録データを破棄することもできます。次に例を示します。

  jcmd 7060 JFR.stop

• 記録のダンプ

  JFR.dump診断コマンドは、実行中の記録を停止し、記録をファイルにダンプすることもできます。次に例を示します。

  jcmd 7060 JFR.dump name=MyRecording filename=C:\TEMP\myrecording.jfr

• ヒープ・ダンプの作成

  ヒープ・ダンプを作成する推奨方法を次に示します。

  jcmd <pid> GC.heap_dump filename=Myheapdump

• ヒープ・ヒストグラムの作成

  ヒープ・ヒストグラムを作成する推奨方法を次に示します。

  jcmd <pid> GC.class_histogram filename=Myheaphistogram

ネイティブ・メモリー・トラッキングを使用してメモリー・リークを検知する手順。

1. 次のコマンドライン・オプションを使用して、サマリーまたは詳細なトラッキングが指定されたJVMを起動します: -XX:NativeMemoryTracking=summaryまたは-XX:NativeMemoryTracking=detail。
2. 初期のベースラインを設定します。NMTベースライン機能を使用して、開発とメンテナンスのときに比較するベースラインを取得するには、次を実行します: jcmd <pid> VM.native_memory baseline。
3. 次を使用して、メモリーの変更をモニターします: jcmd <pid> VM.native_memory detail.diff
4. アプリケーションのメモリー・リークが少量の場合、それが明らかになるまで時間がかかる場合があります。

ネイティブ・メモリー・トラッキングはメモリーをモニターし、開発またはメンテナンス時にアプリケーションのメモリー使用量が増え始めないように設定できます。

• サンプル出力の解釈: 次のサンプル出力から、予約済メモリーとコミット済メモリーを確認できます。コミット済メモリーのみが実際に使用されることに注意してください。たとえば、-Xms100m -Xmx1000mで実行した場合、JVMでは1000MBがJavaヒープ用に予約されます。初期のヒープ・サイズは100MBのみであるため、最初に100MBのみがコミットされます。アドレス領域がほぼ無制限である64ビット・マシンの場合、JVMで多くのメモリーが予約されても問題はありません。コミットされるメモリーが次第に増加し、スワッピングやネイティブ・メモリー不足(OOM)状態になる可能性がある場合に、問題が発生します。

  アリーナは、mallocを使用して割り当てられるメモリー・チャンクです。スコープを終了またはコード領域を離れるとき、これらのチャンクからメモリーがバルクで解放されます。これらのチャンクは、一時メモリーを保持するために他のサブシステムで再利用できます(プリスレッドの割当てなど)。アリーナのmallocポリシーでは、メモリー・リークがないことが確認されます。したがって、個々のオブジェクトではなく、Arena全体が追跡されます。一部の初期メモリーは追跡できません。

  NMTを有効にすると、JVMパフォーマンスが5-10%低下し、NMTのメモリー使用量により、すべてのmallocメモリーに2マシン・ワードがmallocヘッダーとして追加されます。NMTのメモリー使用量も、NMTにより追跡されます。

  Total:  reserved=664192KB,  committed=253120KB                                           <--- total memory tracked by Native Memory Tracking
   
  -                 Java Heap (reserved=516096KB, committed=204800KB)                      <--- Java Heap
                              (mmap: reserved=516096KB, committed=204800KB)
   
  -                     Class (reserved=6568KB, committed=4140KB)                          <--- class metadata
                              (classes #665)                                               <--- number of loaded classes
                              (malloc=424KB, #1000)                                        <--- malloc'd memory, #number of malloc
                              (mmap: reserved=6144KB, committed=3716KB)
   
  -                    Thread (reserved=6868KB, committed=6868KB)
                              (thread #15)                                                 <--- number of threads
                              (stack: reserved=6780KB, committed=6780KB)                   <--- memory used by thread stacks
                              (malloc=27KB, #66)
                              (arena=61KB, #30)                                            <--- resource and handle areas
   
  -                      Code (reserved=102414KB, committed=6314KB)
                              (malloc=2574KB, #74316)
                              (mmap: reserved=99840KB, committed=3740KB)
   
  -                        GC (reserved=26154KB, committed=24938KB)
                              (malloc=486KB, #110)
                              (mmap: reserved=25668KB, committed=24452KB)
   
  -                  Compiler (reserved=106KB, committed=106KB)
                              (malloc=7KB, #90)
                              (arena=99KB, #3)
   
  -                  Internal (reserved=586KB, committed=554KB)
                              (malloc=554KB, #1677)
                              (mmap: reserved=32KB, committed=0KB)
   
  -                    Symbol (reserved=906KB, committed=906KB)
                              (malloc=514KB, #2736)
                              (arena=392KB, #1)
   
  -           Memory Tracking (reserved=3184KB, committed=3184KB)
                              (malloc=3184KB, #300)
   
  -        Pooled Free Chunks (reserved=1276KB, committed=1276KB)
                              (malloc=1276KB)
   
  -                   Unknown (reserved=33KB, committed=33KB)
                              (arena=33KB, #1)

• 詳細データの取得: ネイティブ・メモリー使用量の詳細ビューを取得するには、次のコマンドライン・オプションを使用してJVMを起動します: -XX:NativeMemoryTracking=detailこれは、最も多くのメモリーを割り当てるメソッドを正確に追跡します。NMTを有効にすると、JVMパフォーマンスが5-10%低下し、NMTのメモリー使用量により、すべてのmallocメモリーに2ワードがmallocヘッダーとして追加されます。NMTのメモリー使用量も、NMTにより追跡されます。

  次の例は、追跡レベルが詳細に設定された仮想メモリーのサンプル出力を示しています。このサンプル出力を得るための1つの方法は、jcmd <pid> VM.native_memory detailを実行することです。

  Virtual memory map:
   
  [0x8f1c1000 - 0x8f467000] reserved 2712KB for Thread Stack
  		from [Thread::record_stack_base_and_size()+0xca]
  	[0x8f1c1000 - 0x8f467000] committed 2712KB from [Thread::record_stack_base_and_size()+0xca]
   
  [0x8f585000 - 0x8f729000] reserved 1680KB for Thread Stack
  		from [Thread::record_stack_base_and_size()+0xca]
  	[0x8f585000 - 0x8f729000] committed 1680KB from [Thread::record_stack_base_and_size()+0xca]
   
  [0x8f930000 - 0x90100000] reserved 8000KB for GC
  		from [ReservedSpace::initialize(unsigned int, unsigned int, bool, char*, unsigned int, bool)+0x555]
  	[0x8f930000 - 0x90100000] committed 8000KB from [PSVirtualSpace::expand_by(unsigned int)+0x95]
   
  [0x902dd000 - 0x9127d000] reserved 16000KB for GC
  		from [ReservedSpace::initialize(unsigned int, unsigned int, bool, char*, unsigned int, bool)+0x555]
  	[0x902dd000 - 0x9127d000] committed 16000KB from [os::pd_commit_memory(char*, unsigned int, unsigned int, bool)+0x36]
   
  [0x9127d000 - 0x91400000] reserved 1548KB for Thread Stack
  		from [Thread::record_stack_base_and_size()+0xca]
  	[0x9127d000 - 0x91400000] committed 1548KB from [Thread::record_stack_base_and_size()+0xca]
   
  [0x91400000 - 0xb0c00000] reserved 516096KB for Java Heap                                                                            <--- reserved memory range
  		from [ReservedSpace::initialize(unsigned int, unsigned int, bool, char*, unsigned int, bool)+0x190]                  <--- callsite that reserves the memory
  	[0x91400000 - 0x93400000] committed 32768KB from [VirtualSpace::initialize(ReservedSpace, unsigned int)+0x3e8]               <--- committed memory range and its callsite
  	[0xa6400000 - 0xb0c00000] committed 172032KB from [PSVirtualSpace::expand_by(unsigned int)+0x95]                             <--- committed memory range and its callsite
   
  [0xb0c61000 - 0xb0ce2000] reserved 516KB for Thread Stack
  		from [Thread::record_stack_base_and_size()+0xca]
  	[0xb0c61000 - 0xb0ce2000] committed 516KB from [Thread::record_stack_base_and_size()+0xca]
   
  [0xb0ce2000 - 0xb0e83000] reserved 1668KB for GC
  		from [ReservedSpace::initialize(unsigned int, unsigned int, bool, char*, unsigned int, bool)+0x555]
  	[0xb0ce2000 - 0xb0cf0000] committed 56KB from [PSVirtualSpace::expand_by(unsigned int)+0x95]
  	[0xb0d88000 - 0xb0d96000] committed 56KB from [CardTableModRefBS::resize_covered_region(MemRegion)+0xebf]
  	[0xb0e2e000 - 0xb0e83000] committed 340KB from [CardTableModRefBS::resize_covered_region(MemRegion)+0xebf]
   
  [0xb0e83000 - 0xb7003000] reserved 99840KB for Code
  		from [ReservedSpace::initialize(unsigned int, unsigned int, bool, char*, unsigned int, bool)+0x555]
  	[0xb0e83000 - 0xb0e92000] committed 60KB from [VirtualSpace::initialize(ReservedSpace, unsigned int)+0x3e8]
  	[0xb1003000 - 0xb139b000] committed 3680KB from [VirtualSpace::initialize(ReservedSpace, unsigned int)+0x37a]
   
  [0xb7003000 - 0xb7603000] reserved 6144KB for Class
  		from [ReservedSpace::initialize(unsigned int, unsigned int, bool, char*, unsigned int, bool)+0x555]
  	[0xb7003000 - 0xb73a4000] committed 3716KB from [VirtualSpace::initialize(ReservedSpace, unsigned int)+0x37a]
   
  [0xb7603000 - 0xb760b000] reserved 32KB for Internal
  		from [PerfMemory::create_memory_region(unsigned int)+0x8ba]
   
  [0xb770b000 - 0xb775c000] reserved 324KB for Thread Stack
  		from [Thread::record_stack_base_and_size()+0xca]
  	[0xb770b000 - 0xb775c000] committed 324KB from [Thread::record_stack_base_and_size()+0xca]

• NMTベースラインからの差分の取得: サマリーおよび詳細レベルの追跡では、アプリケーションが起動され実行された後、ベースラインを設定できます。これを行うには、アプリケーションのウォーム・アップ後にjcmd <pid> VM.native_memory baselineを実行します。次に、jcmd <pid> VM.native_memory summary.diffまたはjcmd <pid> VM.native_memory detail.diffを実行できます。

  次の例は、ベースラインの設定以降に使用されたネイティブ・メモリーの差分サマリーのサンプル出力を示し、これはメモリー・リークを見つけるのに優れた方法です。

  Total:  reserved=664624KB  -20610KB, committed=254344KB -20610KB                         <--- total memory changes vs. earlier baseline. '+'=increase '-'=decrease
   
  -                 Java Heap (reserved=516096KB, committed=204800KB)
                              (mmap: reserved=516096KB, committed=204800KB)
   
  -                     Class (reserved=6578KB +3KB, committed=4530KB +3KB)
                              (classes #668 +3)                                            <--- 3 more classes loaded
                              (malloc=434KB +3KB, #930 -7)                                 <--- malloc'd memory increased by 3KB, but number of malloc count decreased by 7
                              (mmap: reserved=6144KB, committed=4096KB)
   
  -                    Thread (reserved=60KB -1129KB, committed=60KB -1129KB)
                              (thread #16 +1)                                              <--- one more thread
                              (stack: reserved=7104KB +324KB, committed=7104KB +324KB)
                              (malloc=29KB +2KB, #70 +4)
                              (arena=31KB -1131KB, #32 +2)                                 <--- 2 more arenas (one more resource area and one more handle area)
   
  -                      Code (reserved=102328KB +133KB, committed=6640KB +133KB)
                              (malloc=2488KB +133KB, #72694 +4287)
                              (mmap: reserved=99840KB, committed=4152KB)
   
  -                        GC (reserved=26154KB, committed=24938KB)
                              (malloc=486KB, #110)
                              (mmap: reserved=25668KB, committed=24452KB)
   
  -                  Compiler (reserved=106KB, committed=106KB)
                              (malloc=7KB, #93)
                              (arena=99KB, #3)
   
  -                  Internal (reserved=590KB +35KB, committed=558KB +35KB)
                              (malloc=558KB +35KB, #1699 +20)
                              (mmap: reserved=32KB, committed=0KB)
   
  -                    Symbol (reserved=911KB +5KB, committed=911KB +5KB)
                              (malloc=519KB +5KB, #2921 +180)
                              (arena=392KB, #1)
   
  -           Memory Tracking (reserved=2073KB -887KB, committed=2073KB -887KB)
                              (malloc=2073KB -887KB, #84 -210)
   
  -        Pooled Free Chunks (reserved=2624KB -15876KB, committed=2624KB -15876KB)
                              (malloc=2624KB -15876KB)

  次の例は、ベースライン以降に使用されたネイティブ・メモリーの差分詳細を示すサンプル出力で、これはメモリー・リークを見つけるのに優れた方法です。

  Details:
   
  [0x01195652] ChunkPool::allocate(unsigned int)+0xe2
                              (malloc=482KB -481KB, #8 -8)
   
  [0x01195652] ChunkPool::allocate(unsigned int)+0xe2
                              (malloc=2786KB -19742KB, #134 -618)
   
  [0x013bd432] CodeBlob::set_oop_maps(OopMapSet*)+0xa2
                              (malloc=591KB +6KB, #681 +37)
   
  [0x013c12b1] CodeBuffer::block_comment(int, char const*)+0x21                <--- [callsite address] method name + offset
                              (malloc=562KB +33KB, #35940 +2125)               <--- malloc'd amount, increased by 33KB #malloc count, increased by 2125
   
  [0x0145f172] ConstantPool::ConstantPool(Array<unsigned char>*)+0x62
                              (malloc=69KB +2KB, #610 +15)
   
  ...
   
  [0x01aa3ee2] Thread::allocate(unsigned int, bool, unsigned short)+0x122
                              (malloc=21KB +2KB, #13 +1)
   
  [0x01aa73ca] Thread::record_stack_base_and_size()+0xca
                              (mmap: reserved=7104KB +324KB, committed=7104KB +324KB)

JConsoleを使用して、データをモニターします。

次のリストは、JConsoleツールを使用してモニターできるデータの概要を示しています。各見出しはツール内のタブ・ペインに対応しています。

• 概要

  このペインには、ヒープ・メモリー使用量、スレッド数、クラス数、およびCPU使用率の経時的推移を示すグラフが表示されます。この概要では、いくつかのリソースのアクティビティを一度に視覚化できます。

• メモリー

  • 選択された1つのメモリー領域(ヒープ、非ヒープ、各種メモリー・プール)について

    • メモリー使用量の経時的推移を示すグラフ

    • 現在のメモリー・サイズ

    • コミットされたメモリーの量

    • 最大メモリー・サイズ

  • ガベージ・コレクタの情報(実行されたコレクションの回数や、ガベージ・コレクションの実行に費やされた合計時間など)

  • 現在使用中のヒープおよび非ヒープ・メモリーのパーセントを示すグラフ

  さらにこのペインでは、ガベージ・コレクションの実行を要求できます。

• スレッド

  • スレッド使用量の経時的推移を示すグラフ。

  • ライブ・スレッド: 現在のライブ・スレッド数。

  • ピーク: JVM起動後のライブ・スレッドの最大数。

  • 選択された1つのスレッドの名前、状態、およびスタック・トレース、およびブロックされたスレッドの場合は、スレッドが獲得を待機しているシンクロナイザとロックを所有しているスレッド。

  • 「デッドロックの検出」ボタンは、デッドロック検出を実行する要求をターゲット・アプリケーションに送信し、各デッドロック・サイクルをそれぞれ異なるタブに表示します。

• クラス

  • ロード済クラス数の経時的推移を示すグラフ

  • 現在メモリーにロードされているクラスの数

  • JVMの起動後にメモリーにロードされたクラスの合計数(その後アンロードされたものも含む)

  • JVMの起動後にメモリーからアンロードされたクラスの合計数

• VMサマリー

  • 一般的な情報(JConsole接続データ、JVMの稼働時間、JVMで消費されたCPU時間、コンパイラ名、合計コンパイル時間など)。

  • スレッドおよびクラスのサマリー情報

  • メモリーおよびガベージ・コレクションの情報(ファイナライズ保留中のオブジェクトの数など)

  • オペレーティング・システムに関する情報(物理特性、実行中のプロセス用の仮想メモリー量、スワップ領域など)

  • JVM自体に関する情報(引数やクラス・パスなど)

• MBeans

  このペインには、接続済のJMXエージェントに登録されたすべてのプラットフォームおよびアプリケーションMBeanを示すツリー構造が表示されます。ツリー内でMBeanを選択すると、その属性、操作、通知、およびその他の情報が表示されます。

  • 操作(存在する場合)を呼び出せます。たとえば、com.sun.managementドメインに含まれるHotSpotDiagnostic MBeanの操作dumpHeapは、ヒープ・ダンプを実行します。この操作の入力パラメータは、ターゲットVMが実行されているマシン上でのヒープ・ダンプ・ファイルのパス名になります。

  • 書込み可能な属性値を設定できます。たとえば、特定のVMフラグの値を設定、設定解除、または変更するには、HotSpotDiagnostic MBeanのsetVMOption操作を呼び出します。フラグは、DiagnosticOptions属性の値のリストによって示されます。

  • 通知(存在する場合)をサブスクライブするには、「サブスクライブ」および「サブスクライブ解除」ボタンを使用します。

JConsoleは、ローカル・アプリケーションとリモート・アプリケーションの両方をモニターできます。接続先JMXエージェントを指定する引数付きでツールを起動した場合、ツールは指定されたアプリケーションのモニタリングを自動的に開始します。

ローカル・アプリケーションをモニターするには、コマンドjconsolepid (pidはアプリケーションのプロセスID)を実行します。

リモート・アプリケーションをモニターするには、コマンドjconsolehostname: portnumber (hostnameはアプリケーションを実行しているホストの名前、portnumberはJMXエージェントの有効化時に指定したポート番号)を実行します。

jconsoleコマンドを引数なしで実行した場合、このツールはまず、モニター対象のローカルまたはリモート・プロセスを指定するための「新規接続」ウィンドウを表示します。「接続」メニューを使えば別のホストにいつでも接続できます。

最新のJDKリリースでは、モニター対象アプリケーションを起動する際にオプションは不要です。

モニタリング・ツールの出力例として、図2-15はヒープ・メモリー使用量のグラフを示しています。

図2-15 JConsoleからのサンプル出力

「図2-15 JConsoleからのサンプル出力」の説明

jdbユーティリティはリモート・デバッグに使用するデバッガ・コネクタをモニターするために使用します。

JDIでは、コネクタを使用してデバッガをターゲットJVMに接続します。JDKには従来、ターゲットJVMとのデバッグ・セッションを開始して確立するコネクタと、(TCP/IPまたは共有メモリー・トランスポートを使用した)リモート・デバッグに使用されるコネクタが付属しています。

JDKにはさらに、Java言語デバッガからクラッシュ・ダンプやハングアップ・プロセスに接続することを許可する、Serviceability Agent (SA)コネクタもいくつか付属しています。これは、クラッシュまたはハング・アップの際にアプリケーションが何をしていたのかを確認するのに役立つ可能性があります。

これらのコネクタはSACoreAttachingConnector、SADebugServerAttachingConnector、およびSAPIDAttachingConnectorです。

これらのコネクタは通常、NetBeans統合開発環境(IDE)や商用IDEなどのエンタープライズ・デバッガで使用されます。次の項では、jdbコマンド行デバッガでこれらのコネクタを使用する方法を示します。

コマンドjdb -listconnectorsは、使用可能なコネクタの一覧を出力します。コマンドjdb -helpは、コマンドの使用方法のヘルプを出力します。

Java Platform, Standard Editionツール・リファレンスのjdbユーティリティに関する項を参照してください

SAコア接続コネクタは、デバッガをコア・ファイルに接続するために使用されます。

$ jdb -connect sun.jvm.hotspot.jdi.SACoreAttachingConnector:javaExecutable=$JAVA_HOME/bin/java,core=core.20441

デバッガがインストールされたマシン上で、SAデバッグ・サーバー接続コネクタを使用してデバッグ・サーバーに接続できます。

$ jsadebugd $JAVA_HOME/bin/java core.20441

$ jdb -connect sun.jvm.hotspot.jdi.SADebugServerAttachingConnector:debugServerName=machine1

jinfoの出力には、java.class.pathおよびsun.boot.class.pathの設定が表示されます。

$ jinfo $JAVA_HOME/bin/java core.29620

jmap -heapコマンドを使用してJavaヒープ情報を取得します。

$ jmap -heap 29620
Attaching to process ID 29620, please wait...
Debugger attached successfully.
Client compiler detected.
JVM version is 1.6.0-rc-b100

using thread-local object allocation.
Mark Sweep Compact GC

Heap Configuration:
   MinHeapFreeRatio = 40
   MaxHeapFreeRatio = 70
   MaxHeapSize      = 67108864 (64.0MB)
   NewSize          = 2228224 (2.125MB)
   MaxNewSize       = 4294901760 (4095.9375MB)
   OldSize          = 4194304 (4.0MB)
   NewRatio         = 8
   SurvivorRatio    = 8
   PermSize         = 12582912 (12.0MB)
   MaxPermSize      = 67108864 (64.0MB)

Heap Usage:
New Generation (Eden + 1 Survivor Space):
   capacity = 2031616 (1.9375MB)
   used     = 70984 (0.06769561767578125MB)
   free     = 1960632 (1.8698043823242188MB)
   3.4939673639112905% used
Eden Space:
   capacity = 1835008 (1.75MB)
   used     = 36152 (0.03447723388671875MB)
   free     = 1798856 (1.7155227661132812MB)
   1.9701276506696428% used
From Space:
   capacity = 196608 (0.1875MB)
   used     = 34832 (0.0332183837890625MB)
   free     = 161776 (0.1542816162109375MB)
   17.716471354166668% used
To Space:
   capacity = 196608 (0.1875MB)
   used     = 0 (0.0MB)
   free     = 196608 (0.1875MB)
   0.0% used
tenured generation:
   capacity = 15966208 (15.2265625MB)
   used     = 9577760 (9.134063720703125MB)
   free     = 6388448 (6.092498779296875MB)
   59.98769400974859% used
Perm Generation:
   capacity = 12582912 (12.0MB)
   used     = 1469408 (1.401336669921875MB)
   free     = 11113504 (10.598663330078125MB)
   11.677805582682291% used

-histoオプションを指定してjmapコマンドを使用すると、クラス固有のヒープ・ヒストグラムを取得できます。

$ jmap -histo 29620
num   #instances    #bytes  class name
--------------------------------------
  1:      1414     6013016  [I
  2:       793      482888  [B
  3:      2502      334928  <constMethodKlass>
  4:       280      274976  <instanceKlassKlass>
  5:       324      227152  [D
  6:      2502      200896  <methodKlass>
  7:      2094      187496  [C
  8:       280      172248  <constantPoolKlass>
  9:      3767      139000  [Ljava.lang.Object;
 10:       260      122416  <constantPoolCacheKlass>
 11:      3304      112864  <symbolKlass>
 12:       160       72960  java2d.Tools$3
 13:       192       61440  <objArrayKlassKlass>
 14:       219       55640  [F
 15:      2114       50736  java.lang.String
 16:      2079       49896  java.util.HashMap$Entry
 17:       528       48344  [S
 18:      1940       46560  java.util.Hashtable$Entry
 19:       481       46176  java.lang.Class
 20:        92       43424  javax.swing.plaf.metal.MetalScrollButton
... more lines removed here to reduce output...
1118:         1           8  java.util.Hashtable$EmptyIterator
1119:         1           8  sun.java2d.pipe.SolidTextRenderer
Total    61297    10152040

& jmap -histo /net/koori.sfbay/onestop/jdk/6.0/promoted/all/b100/binaries/solaris-sparcv9/bin/java core
Attaching to core core from executable /net/koori.sfbay/onestop/jdk/6.0/
promoted/all/b100/binaries/solaris-sparcv9/bin/java, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 1.6.0-rc-b100
Iterating over heap. This may take a while...
Heap traversal took 8.902 seconds.

Object Histogram:

Size    Count    Class description
-------------------------------------------------------
4151816    2941    int[]
2997816    26403    * ConstMethodKlass
2118728    26403    * MethodKlass
1613184    39750    * SymbolKlass
1268896    2011    * ConstantPoolKlass
1097040    2011    * InstanceKlassKlass
882048    1906    * ConstantPoolCacheKlass
758424    7572    char[]
733776    2518    byte[]
252240    3260    short[]
214944    2239    java.lang.Class
177448    3341    * System ObjArray
176832    7368    java.lang.String
137792    3756    java.lang.Object[]
121744    74    long[]
72960    160    java2d.Tools$3
63680    199    * ObjArrayKlassKlass
53264    158    float[]
... more lines removed here to reduce output...

Permanent世代は、クラスやメソッド・オブジェクトなどの仮想マシン自体を反映したデータをすべて保持するヒープ領域です。

Exception in thread thread_name java.lang.OutOfMemoryError: PermGen space

$ jmap -permstat 29620
Attaching to process ID 29620, please wait...
Debugger attached successfully.
Client compiler detected.
JVM version is 1.6.0-rc-b100
12674 intern Strings occupying 1082616 bytes.
finding class loader instances ..Unknown oop at 0xd0400900
Oop's klass is 0xd0bf8408
Unknown oop at 0xd0401100
Oop's klass is null
done.
computing per loader stat ..done.
please wait.. computing liveness.........................................done.
class_loader    classes bytes   parent_loader   alive?  type

<bootstrap>     1846 5321080  null        live   <internal>
0xd0bf3828  0      0      null         live    sun/misc/Launcher$ExtClassLoader@0xd8c98c78
0xd0d2f370  1    904      null         dead    sun/reflect/DelegatingClassLoader@0xd8c22f50
0xd0c99280  1   1440      null         dead    sun/reflect/DelegatingClassLoader@0xd8c22f50
0xd0b71d90  0      0   0xd0b5b9c0    live java/util/ResourceBundle$RBClassLoader@0xd8d042e8
0xd0d2f4c0  1    904      null         dead    sun/reflect/DelegatingClassLoader@0xd8c22f50
0xd0b5bf98  1    920   0xd0b5bf38      dead    sun/reflect/DelegatingClassLoader@0xd8c22f50
0xd0c99248  1    904      null         dead    sun/reflect/DelegatingClassLoader@0xd8c22f50
0xd0d2f488  1    904      null         dead    sun/reflect/DelegatingClassLoader@0xd8c22f50
0xd0b5bf38  6   11832  0xd0b5b9c0      dead    sun/reflect/misc/MethodUtil@0xd8e8e560
0xd0d2f338  1    904      null         dead    sun/reflect/DelegatingClassLoader@0xd8c22f50
0xd0d2f418  1    904      null         dead    sun/reflect/DelegatingClassLoader@0xd8c22f50
0xd0d2f3a8  1    904     null          dead    sun/reflect/DelegatingClassLoader@0xd8c22f50
0xd0b5b9c0  317 1397448 0xd0bf3828     live    sun/misc/Launcher$AppClassLoader@0xd8cb83d8
0xd0d2f300  1    904      null         dead    sun/reflect/DelegatingClassLoader@0xd8c22f50
0xd0d2f3e0  1    904      null         dead    sun/reflect/DelegatingClassLoader@0xd8c22f50
0xd0ec3968  1   1440      null         dead    sun/reflect/DelegatingClassLoader@0xd8c22f50
0xd0e0a248  1    904      null         dead    sun/reflect/DelegatingClassLoader@0xd8c22f50
0xd0c99210  1    904      null         dead    sun/reflect/DelegatingClassLoader@0xd8c22f50
0xd0d2f450  1    904      null         dead    sun/reflect/DelegatingClassLoader@0xd8c22f50
0xd0d2f4f8  1    904      null         dead    sun/reflect/DelegatingClassLoader@0xd8c22f50
0xd0e0a280  1    904      null         dead    sun/reflect/DelegatingClassLoader@0xd8c22f50

total = 22      2186    6746816   N/A   alive=4, dead=18       N/A    

jstackコマンド行ユーティリティは、指定されたプロセスまたはコア・ファイルに接続し、仮想マシンに接続されたすべてのスレッド(JavaスレッドやVM内部スレッドも含む)のスタック・トレースを出力する以外に、オプションでネイティブ・スタック・フレームも出力します。このユーティリティではデッドロック検出も実行されます。

コア・ダンプからスタック・トレースを取得するにはjstackコマンドを使用します。

$ jstack $JAVA_HOME/bin/java core

jstackユーティリティは、混合スタックの出力に使用することもできます(つまり、Javaスタックの他にネイティブ・スタック・フレームも出力できます)。ネイティブ・フレームとは、VMコードやJNI/ネイティブ・コードに関連付けられたC/C++フレームのことです。

$ jstack -m 21177
Attaching to process ID 21177, please wait...
Debugger attached successfully.
Client compiler detected.
JVM version is 1.6.0-rc-b100
Deadlock Detection:

Found one Java-level deadlock:
=============================

"Thread1":
  waiting to lock Monitor@0x0005c750 (Object@0xd4405938, a java/lang/String),
  which is held by "Thread2"
"Thread2":
  waiting to lock Monitor@0x0005c6e8 (Object@0xd4405900, a java/lang/String),
  which is held by "Thread1"

Found a total of 1 deadlock.

----------------- t@1 -----------------
0xff2c0fbc    __lwp_wait + 0x4
0xff2bc9bc    _thrp_join + 0x34
0xff2bcb28    thr_join + 0x10
0x00018a04    ContinueInNewThread + 0x30
0x00012480    main + 0xeb0
0x000111a0    _start + 0x108
----------------- t@2 -----------------
0xff2c1070    ___lwp_cond_wait + 0x4
0xfec03638    bool Monitor::wait(bool,long) + 0x420
0xfec9e2c8    bool Threads::destroy_vm() + 0xa4
0xfe93ad5c    jni_DestroyJavaVM + 0x1bc
0x00013ac0    JavaMain + 0x1600
0xff2bfd9c    _lwp_start
----------------- t@3 -----------------
0xff2c1070    ___lwp_cond_wait + 0x4
0xff2ac104    _lwp_cond_timedwait + 0x1c
0xfec034f4    bool Monitor::wait(bool,long) + 0x2dc
0xfece60bc    void VMThread::loop() + 0x1b8
0xfe8b66a4    void VMThread::run() + 0x98
0xfec139f4    java_start + 0x118
0xff2bfd9c    _lwp_start
----------------- t@4 -----------------
0xff2c1070    ___lwp_cond_wait + 0x4
0xfec195e8    void os::PlatformEvent::park() + 0xf0
0xfec88464    void ObjectMonitor::wait(long long,bool,Thread*) + 0x548
0xfe8cb974    void ObjectSynchronizer::wait(Handle,long long,Thread*) + 0x148
0xfe8cb508    JVM_MonitorWait + 0x29c
0xfc40e548    * java.lang.Object.wait(long) bci:0 (Interpreted frame)
0xfc40e4f4    * java.lang.Object.wait(long) bci:0 (Interpreted frame)
0xfc405a10    * java.lang.Object.wait() bci:2 line:485 (Interpreted frame)
... more lines removed here to reduce output...
----------------- t@12 -----------------
0xff2bfe3c    __lwp_park + 0x10
0xfe9925e4    AttachOperation*AttachListener::dequeue() + 0x148
0xfe99115c    void attach_listener_thread_entry(JavaThread*,Thread*) + 0x1fc
0xfec99ad8    void JavaThread::thread_main_inner() + 0x48
0xfec139f4    java_start + 0x118
0xff2bfd9c    _lwp_start
----------------- t@13 -----------------
0xff2c1500    _door_return + 0xc
----------------- t@14 -----------------
0xff2c1500    _door_return + 0xc

スレッド・ダンプは、仮想マシン内のすべてのJavaスレッドのスレッド・スタック(スレッドの状態など)で構成されています。

スレッド・ダンプによってアプリケーションが終了することはなく、スレッド情報が出力された後もアプリケーションは続行します。

次の例はスレッド・ダンプを示しています。

Full thread dump Java HotSpot(TM) Client VM (1.6.0-rc-b100 mixed mode):

"DestroyJavaVM" prio=10 tid=0x00030400 nid=0x2 waiting on condition [0x00000000..0xfe77fbf0]
   java.lang.Thread.State: RUNNABLE

"Thread2" prio=10 tid=0x000d7c00 nid=0xb waiting for monitor entry [0xf36ff000..0xf36ff8c0]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at Deadlock$DeadlockMakerThread.run(Deadlock.java:32)
        - waiting to lock <0xf819a938> (a java.lang.String)
        - locked <0xf819a970> (a java.lang.String)

"Thread1" prio=10 tid=0x000d6c00 nid=0xa waiting for monitor entry [0xf37ff000..0xf37ffbc0]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at Deadlock$DeadlockMakerThread.run(Deadlock.java:32)
        - waiting to lock <0xf819a970> (a java.lang.String)
        - locked <0xf819a938> (a java.lang.String)

"Low Memory Detector" daemon prio=10 tid=0x000c7800 nid=0x8 runnable [0x00000000..0x00000000]
   java.lang.Thread.State: RUNNABLE

"CompilerThread0" daemon prio=10 tid=0x000c5400 nid=0x7 waiting on condition [0x00000000..0x00000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" daemon prio=10 tid=0x000c4400 nid=0x6 waiting on condition [0x00000000..0x00000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" daemon prio=10 tid=0x000b2800 nid=0x5 in Object.wait() [0xf3f7f000..0xf3f7f9c0]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0xf4000b40> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116)
        - locked <0xf4000b40> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:132)
        at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)

"Reference Handler" daemon prio=10 tid=0x000ae000 nid=0x4 in Object.wait() [0xfe57f000..0xfe57f940]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0xf4000a40> (a java.lang.ref.Reference$Lock)
        at java.lang.Object.wait(Object.java:485)
        at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
        - locked <0xf4000a40> (a java.lang.ref.Reference$Lock)

"VM Thread" prio=10 tid=0x000ab000 nid=0x3 runnable 

"VM Periodic Task Thread" prio=10 tid=0x000c8c00 nid=0x9 waiting on condition 

この出力は、空白行で区切られたいくつかのスレッド・エントリで構成されます。Javaスレッド(Java言語コードを実行できるスレッド)がまず出力され、それらの後にVM内部スレッドに関する情報が続きます。各スレッド・エントリは、ヘッダー行とその後に続くスレッド・スタック・トレースで構成されます。

ヘッダー行には、スレッドに関する次の情報が含まれます。

• スレッド名

• スレッドがデーモン・スレッドかどうかのマーク

• スレッド優先度(prio)

• スレッドID (tid)。メモリー内のスレッド構造体のアドレスです

• ネイティブ・スレッドのID (nid)

• スレッド・ダンプ時にスレッドが実行していた内容を示す、スレッド状態詳細は、表2-6を参照してください。

• アドレス範囲(スレッドのおおよその有効なスタック領域を表す)

Ctrl+Breakハンドラは、スレッドのデッドロック検出にも使用できます。

Ctrl+Breakハンドラは、スレッド・スタックだけでなく、デッドロック検出アルゴリズムも実行します。デッドロックが検出された場合、次の例に示すように、Ctrl+Breakハンドラは、デッドロックされた各スレッドに関するスレッド・ダンプの後に追加情報を出力します。

Found one Java-level deadlock:
=============================
"Thread2":
  waiting to lock monitor 0x000af330 (object 0xf819a938, a java.lang.String),
  which is held by "Thread1"
"Thread1":
  waiting to lock monitor 0x000af398 (object 0xf819a970, a java.lang.String),
  which is held by "Thread2"

Java stack information for the threads listed above:
===================================================
"Thread2":
        at Deadlock$DeadlockMakerThread.run(Deadlock.java:32)
        - waiting to lock <0xf819a938> (a java.lang.String)
        - locked <0xf819a970> (a java.lang.String)
"Thread1":
        at Deadlock$DeadlockMakerThread.run(Deadlock.java:32)
        - waiting to lock <0xf819a970> (a java.lang.String)
        - locked <0xf819a938> (a java.lang.String)

Found 1 deadlock.

JVMフラグ-XX:+PrintConcurrentLocksが設定されている場合、Ctrl+Breakハンドラは各スレッドが所有している並行ロックのリストも出力します。

Ctrl+Breakハンドラはヒープ・サマリーの出力にも使用できます。

次の例では、様々な世代(ヒープ領域)がそのサイズ、使用量、アドレス範囲とともに示されています。アドレス範囲は特に、pmapなどのツールでプロセスを調査する場合にも役立ちます。

Heap
 def new generation   total 1152K, used 435K [0x22960000, 0x22a90000, 0x22e40000
)
  eden space 1088K,  40% used [0x22960000, 0x229ccd40, 0x22a70000)
  from space 64K,   0% used [0x22a70000, 0x22a70000, 0x22a80000)
  to   space 64K,   0% used [0x22a80000, 0x22a80000, 0x22a90000)
 tenured generation   total 13728K, used 6971K [0x22e40000, 0x23ba8000, 0x269600
00)
   the space 13728K,  50% used [0x22e40000, 0x2350ecb0, 0x2350ee00, 0x23ba8000)
 compacting perm gen  total 12288K, used 1417K [0x26960000, 0x27560000, 0x2a9600
00)
   the space 12288K,  11% used [0x26960000, 0x26ac24f8, 0x26ac2600, 0x27560000)
    ro space 8192K,  62% used [0x2a960000, 0x2ae5ba98, 0x2ae5bc00, 0x2b160000)
    rw space 12288K,  52% used [0x2b160000, 0x2b79e410, 0x2b79e600, 0x2bd60000)

JVMフラグ-XX:+PrintClassHistogramが設定されている場合、Ctrl+Breakハンドラはヒープ・ヒストグラムを生成します。

Oracle Solaris 10オペレーティング・システムに含まれるDTraceツールを使用すれば、オペレーティング・システムのカーネルおよびユーザー・レベルのプログラムの動的トレースを行えます。

このツールでは、システム・コールの入口と出口、ユーザー・モード関数の入口と出口、およびその他多くのプローブ・ポイントでのスクリプトがサポートされます。スクリプトは、安全なポインタ・セマンティクスを備えた、Cに似た言語であるDプログラミング言語で記述されます。これらのスクリプトは、問題のトラブルシューティングやパフォーマンス問題の解決に役立つ可能性があります。

dtraceコマンドは、DTraceツールに対する汎用のフロント・エンドです。このコマンドには、D言語を呼び出したり、バッファ内のトレース・データを取得したり、トレース・データを書式設定/出力するための一連の基本ルーチンにアクセスしたりするための、単純なインタフェースが用意されています。

カスタマイズされた独自のDTraceスクリプトをD言語で記述したり、すでに様々なサイト上で入手可能な多くのスクリプトから1つ以上をダウンロードして使用したりすることもできます。

これらのプローブは、プロバイダと呼ばれるカーネル・モジュールによって配布され計測されます。プローブ・プロバイダによって提供されるトレースのタイプには、ユーザー命令トレース、関数境界トレース、カーネル・ロック計測、プロファイル割込み、システム・コール・トレースなどがあり、その他にもたくさんあります。独自のスクリプトを記述する場合は、D言語を使用してそれらのプローブを有効にします。この言語では、条件付きトレースや出力のフォーマットも可能です。

dtrace -lコマンドを使用すると、使用しているOracle Solarisオペレーティング・システムで使用可能な一連のプロバイダやプローブを調べることができます。

DTraceToolkitは、Oracle Solaris DTraceのオープン・コミュニティで開発されたドキュメント付きの有用なスクリプトを集めたものです。DTraceToolkitに関する項を参照してください。

Solaris動的トレース・ガイドを参照してください。

Java HotSpot VMにはhotspotおよびhotspot_jniという2つの組込みプローブ・プロバイダが含まれるようになりました。

これらのプロバイダは、VMの内部状態やアクティビティだけでなく、実行中のJavaアプリケーションもモニターするために使用できるプローブを配布します。

JVMプローブ・プロバイダは次のように分類できます。

• VMのライフ・サイクル: VMの初期化の開始と終了、およびVMのシャットダウン

• スレッドのライフ・サイクル: スレッドの開始と停止、スレッド名、スレッドIDなど

• クラスのロード: Javaクラスのロードとアンロード

• ガベージ・コレクション: ガベージ・コレクションの開始と停止、システム全体またはメモリー・プール別

• メソッドのコンパイル: メソッドのコンパイルの開始と終了、メソッドのロードとアンロード

• モニター・プローブ: 待機イベント、通知イベント、競合するモニターへの出入り

• アプリケーションの追跡: メソッドに入る、メソッドから戻る、Javaオブジェクトの割当て

ネイティブ・コードからJavaコードへの呼出しの場合、ネイティブ・コードはJNIインタフェース経由で呼出しを行う必要があります。hotspot_jniプロバイダは、Javaコードを呼び出したりVMの状態を検査したりするためにJNIインタフェースに用意されているメソッドごとに、入口と出口におけるDTraceプローブを管理します。

プローブ・ポイントで現在のスレッドのスタック・トレースを出力するには、ustack組込み関数を使用できます。この関数は、C/C++ネイティブ関数の名前だけでなく、Javaメソッドの名前も出力します。次の例は、あるスレッドがreadシステム・コールを呼び出したときに必ず完全なスタック・トレースを出力する単純なDスクリプトです。

#!/usr/sbin/dtrace -s
syscall::read:entry 
/pid == $1 && tid == 1/ {    
   ustack(50, 0x2000);
}

前の例のスクリプトはread.dというファイルに格納され、次の例に示すように、トレース対象のJavaプロセスのPIDを指定することで実行されます。

read.d pid

Javaアプリケーションで多数のI/Oが生成されたり、なんらかの予期しない遅延が発生したりした場合、DTraceツールやそのustack()アクションを使用すれば、問題を診断しやすくなる可能性があります。

Oracle Solaris 10オペレーティング・システムのpmapユーティリティの改善。

pmapユーティリティは、Oracle Solaris 10オペレーティング・システムでスタック・セグメントがテキスト[stack]付きで出力されるように改善されました。このテキストはスタックの場所を見つけるのに役立ちます。

次の例は、改善されたpmapユーティリティによるスタック・トレースを示しています。

19846:    /net/myserver/export1/user/j2sdk6/bin/java -Djava.endorsed.d
00010000      72K r-x--  /export/disk09/jdk/6/rc/b63/binaries/solsparc/bin/java
00030000      16K rwx--  /export/disk09/jdk/6/rc/b63/binaries/solsparc/bin/java
00034000   32544K rwx--    [ heap ]
D1378000      32K rwx-R    [ stack tid=44 ]
D1478000      32K rwx-R    [ stack tid=43 ]
D1578000      32K rwx-R    [ stack tid=42 ]
D1678000      32K rwx-R    [ stack tid=41 ]
D1778000      32K rwx-R    [ stack tid=40 ]
D1878000      32K rwx-R    [ stack tid=39 ]
D1974000      48K rwx-R    [ stack tid=38 ]
D1A78000      32K rwx-R    [ stack tid=37 ]
D1B78000      32K rwx-R    [ stack tid=36 ]
[.. more lines removed here to reduce output ..]
FF370000       8K r-x--  /usr/lib/libsched.so.1
FF380000       8K r-x--  /platform/sun4u-us3/lib/libc_psr.so.1
FF390000      16K r-x--  /lib/libthread.so.1
FF3A4000       8K rwx--  /lib/libthread.so.1
FF3B0000       8K r-x--  /lib/libdl.so.1
FF3C0000     168K r-x--  /lib/ld.so.1
FF3F8000       8K rwx--  /lib/ld.so.1
FF3FA000       8K rwx--  /lib/ld.so.1
FFB80000      24K -----    [ anon ]
FFBF0000      64K rwx--    [ stack ]
 total    167224K

Oracle Solaris 10オペレーティング・システムのpstackユーティリティの改善。

Oracle Solaris 10オペレーティング・システムより前は、pstackユーティリティはJavaをサポートしていませんでした。解釈済みおよびコンパイル済みJavaメソッドの両方で、16進アドレスを出力していました。

Oracle Solaris 10オペレーティング・システム以降のpstackコマンド行ツールは、コア・ファイルまたはライブ・プロセスから混合モードのスタック・トレース(JavaおよびC/C++フレーム)を出力します。このユーティリティは、解釈済、コンパイル済、およびインライン化されたJavaメソッドに対し、Javaメソッド名を出力します。

Java Platform Debugger Architecture (JPDA)は、デバッガやデバッガに似たツールが使用するために設計されたアーキテクチャです。

Java Platform Debugger Architectureは、2つのプログラミング・インタフェースおよびワイヤ・プロトコルで構成されています。

• Java Virtual Machine Tool Interface (JVM TI)は、仮想マシンへのインタフェースです。「JVM Tool Interface」を参照してください。

• Java Debug Interface (JDI)は、ユーザー・コード・レベルでの情報および要求を定義します。これは、Javaプログラミング言語アプリケーションをデバッグするためのPure Javaプログラミング言語インタフェースです。JPDAでは、JDIは、デバッガのプロセスから見たデバッグ対象プロセスの仮想マシンのリモート・ビューです。これはフロント・エンドによって実装されます。デバッガに似たアプリケーション(IDE、デバッガ、トレーサ、モニタリング・ツールなど)はクライアントとなります。モジュールjdk.jdiを参照してください。

• Java Debug Wire Protocol (JDWP)は、デバッグされるプロセスと、JDIを実装したデバッガ・フロント・エンドとの間で転送される、情報および要求の形式を定義します。

jdbユーティリティは、コマンド行デバッガの例としてJDKに含まれています。jdbユーティリティは、JDIを使ってターゲットVMを起動または接続します。「jdbユーティリティ」を参照してください。

JDIを使用すれば、従来のデバッガ・タイプのツールだけでなく、ポストモーテム診断の際や、ツールが非協力的なプロセス(ハングアップ・プロセスなど)に接続する必要があるシナリオで役に立つツールを開発することもできます。