Java Flight Recorderでトラブルシューティング

18355 ワード
JFR Java-SE-Advanced Java Java-Flight-Recorder Java テキストリンク

背景・目的

Oracle Java7 u40以降から利用できる、有償モニタリング・トラブルシューティングツールであるOracle Java Mission Control(JMC) / Java Flight Recorder(JFR)を使ってみよう。

JMC/JFRとは

  • Oracle Javaの有償製品であるJava SE Advancedが提供する、Javaアプリケーションのモニタリング・トラブルシューティングツール
    • ただし、JMC/JFR自体（必要バイナリ・仕組み）は無償でダウンロードできる(普通の)Oracle JDKに既に含まれているため、個人PCでの検証目的であれば無償で使える。要は有償製品であるJava SE Advancedが提供するのは使用権利のみであり、バイナリ自体は全く一緒。
    • ということで、特別ダウンロード・インストールも不要であり、Oracle JDKが入っていればすぐに使える。
  • ざっくりJMCとJFRを区別すると、
    • JMCはGUI及び簡単なリアルタイムモニタリング、
    • JFRはJavaアプリケーションの動作をレコーディング（飛行機のブラックボックス - Flight Recorderにちなんだ製品名）するプロファイラー
    • ただし一般的には、両方あわせてJMCと言ったり、JFRと言ったりする。
  • レコーディング（プロファイリング）の仕組み自体、OracleのHotSpot JVMの中に入っているので、レコーディングによるオーバヘッドが少ない
  • レコーディングの記録は「.jfr」拡張子のファイルとして出力されるので、このファイルをJMC GUIから閲覧することで分析を行う
  • 元々は旧BEA社（Oracleにより買収）のJVMであるjRockItの機能で、OracleがOracle Java7 u40以降から、Oracle HotSpot JVMでも利用できるように移植したもの
  • 今までJavaのこういった診断ツール・コマンドなどは様々なものがあったが、Oracleとしては、JMC / JFRでほぼカバーできるようにするのが狙い？

検証環境

  • Oracle JDK 8最新
  • OS : Windows 7 (もちろん、JDKが動く環境であればOSの種類は問わない)

参考文献

ダウンロード・インストール

  • JMC/JFR自体はJDKに組み込まれているので、既にJDKがインストールされていれば、追加のダウンロードもインストールも不要！下記の実行方法に従って使い始めればよい。
  • Eclipse Pluginを使いたい場合は以下のサイトからダウンロード（必須ではない）

実行方法

  • JMC/JFR GUIの起動
    • ${JAVA_HOME}\bin\jmc.exeを実行
  • JFRの有効化
    • JVMの起動パラメータに以下のパラメータを追加するのみ！
      • -XX:+UnlockCommercialFeatures -XX:+FlightRecorder
  • JFRの記録開始方法(my_recording.jfrという名前で出力する例)は以下の3つ
    • 1. 起動引数で指定
      • java.exe -XX:+UnlockCommercialFeatures -XX:+FlightRecorder -XX:StartFlightRecording=duration=60s,filename=my_recording.jfr MyJavaApplication
    • 2. jcmdコマンドで開始
      • jcmd <PID> JFR.start duration=60s filename=my_recording.jfr
    • 3. JMC GUIから開始（一番簡単）
      • 次のセクションで記載

手っ取り早くどんなものか動かしてみる

1. 用意するもの

JDKダウンロードサイトにある「Java SE Development Kit 8uXXX Demos and Samples Downloads zip」をダウンロード。
実はこの中にjfrのサンプルファイルも入っている。

  • 場所 ： 上記ダウンロードしたzipファイルの中の sample\missioncontrol\flightrecordingsフォルダ
  • サンプルファイル
    • java2d_demo.jfr ： zipファイルの中の demo\jfc\Java2D\Java2Demo.jar のJFRレコーディングサンプル
    • wldf.jfr ： WebLogicのMedRecサンプルのJFRレコーディングサンプル

2. 既に記録されたjfrファイルを閲覧する

${JAVA_HOME}\bin\jmc.exeを実行

File -> Open File...からjava2d_demo.jfrを選択し、開く。以下のような
画面が見えればOK。

3. 自分で記録してみる

Java Demos and Samplesに入ってるJava2Demo.jarを利用して実際レコーディングしてみる。

Step1. サンプルアプリの実行

以下の要領でJava2Demo.jarファイルを実行

SET JDK_HOME=<JDKパス>
SET PRG=D:\A_Dev\Java\jdk-8u101-windows-x64-demos\jdk1.8.0_101\demo\jfc\Java2D\Java2Demo.jar
SET JVM=-Xmx32m -Xms16m　←　GCを頻繁に発生させるため。必須ではない
SET JFR=-XX:+UnlockCommercialFeatures -XX:+FlightRecorder

%JDK_HOME%\bin\java %JVM% %JFR% -jar %PRG%

Java2Demo.jarの画面イメージはこちら。
負荷を掛ける場合は、タブ「Transforms」を選択し、その画面の右側にあるAnim delayのところを短く設定する。

Step2. JMC画面を起動

jmc.exeを起動すると以下の画面が表示される。左側にJava2Demo.jarのプロセスが見えるはず。
左側の2番目の「The JVM Running Mission Control」プロセスはjmc自分自身のプロセス。

Step3. JMC画面からフライト記録

プロセスの部分を右クリックし、「フライト記録の開始...」を選択。

以下の「フライト記録の開始」画面から、記録時間を「1 min」、イベント設定を「Profiling - サーバー上」に設定。「終了」ボタンをクリックし、記録を開始する。

以下のポップアップが出て、記録が開始される。1分間待ちながら、Java2Demo.jarアプリをいろいろいじってみる（負荷を掛けたり、掛けなかったり）。

Step4. 記録したjfrを閲覧

1分が経過すると、自動で記録し終わった.jfrファイルが立ち上がるはず。

確認ポイント1 - 全般

以下のように記録した1分間の「ヒープ使用量」、「CPU使用率」、「GC一時休止時間」の平均・最大値などがわかる。

確認ポイント2 - GC

左の「メモリー」メインタブを選んで、「ガベージ・コレクション」サブタブを選択。
以下のようにGCが頻繁に発生しているのがわかる。

確認ポイント3 - Hot Methods

左の「コード」メインタブを選んで、「ホット・メソッド」サブタブを選択。
レコーディングした1分間、java.util.HashMap.put, java.awt.TexturePaintContext...が一番頻繁に呼ばれたことがわかる。

JMC / JFR画面構成

全体的な画面構成は、左側のメインタブと各メインタブごとのサブタブで構成。
各メインタブごとの画面構成は以下の通り
（* 画面キャプチャの中のWebLogicメインタブはWebLogic用のプラグインがインストールされている場合表示されるもの）

全般 (General)

メモリー (Memory)

コード (Code)

スレッド (Thread)

I/O

システム (System)

イベント (Event)

各メインタブ・サブタブ一覧

（* 以下、タブ名は英語で記述。いろんなマニュアル・参考文献はほとんど英語が多いため、英語名で慣れた方がやりやすい）

No Main Tab Sub Tab 説明
1_1 General Overview 最大ヒープ使用量、合計CPU使用率およびGC一時休止時間などの基本情報
1_2 JVM Information JVM情報
1_3 System Properties OSレベルで設定されたすべてのシステム・プロパティ
1_4 Recording JFR記録時の情報（どのイベントをONにしたか）
2_1 Memory Overview メモリー使用量に関する一般情報およびガベージ・コレクションに関する統計情報
2_2 Garbage Collections メモリー使用量の経時的推移およびすべてのガベージ・コレクションに関する情報
2_3 GC Times GCの実行にかかった時間とGCのためにアプリケーションが完全に一時休止する時間に関する情報
2_4 GC Configuration GCの構成に関する情報
2_5 Allocations 行われたすべてのメモリー割当て。* TLAB (Thread Local Area Buffer) - 新しいオブジェクトが割り当てられている小さなメモリー領域
2_6 Object Statistics ライブ・セットを持つクラス
3_1 Code Overview 最も多くの実行時間を費やしたパッケージおよびクラスが表示
3_2 Hot Methods 最も多くサンプリングされたメソッド
3_3 Call Tree ホット・メソッドのスレッドを逆順に表示
3_4 Exceptions スローされた例外が表示
3_5 Compilations アプリケーションが実行されていたときにコンパイルされたメソッドが表示
3_6 Class Loading 時間の経過とともにロードされたクラス数、実際にロードされたクラスおよびアンロードされたクラスが表示
4_1 Thread Overview CPU使用率およびスレッド数の経時的な推移
4_2 Hot Threads ほとんどのコード実行を行うスレッドが表示
4_3 Contention ロックの競合情報
4_4 Latencies スリープまたは待機の呼出し、ソケットからの読取り、ファイルI/Oの待機など、その他の待機時間の原因を表示
4_5 Thread Dumps 記録内でトリガーできる定期的なスレッド・ダンプが表示
4_6 Lock Instances 同期のために最も待機しているオブジェクトの正確なインスタンスが表示
5_1 I/O Overview
5_2 File Reads File I/O読取り
5_3 File Writes File I/O書込み
5_4 Socket Reads Network I/O読取り
5_5 Socket Writes Network I/O書込み
6_1 System Overview CPU, Memory, OS情報
6_2 Process 記録時のシステムプロセス情報
6_3 Environment 記録時のシステム環境変数情報
7_1 Event Overview
7_2 Log
7_3 Graph
7_4 Threads
7_5 Stack Traces
7_6 Histogram
質問の問合せ-util関数とテストユニットの作成
[AVA]19日目(文字列に関連するクラス/キャラクタセット(CharacterSet)