最強のJVMチューニング・ツール: GCログを可視化するGCViewerとリモート接続でプロファイリング可能なVisualVM

この記事はJVM Advent Calendar 2014 – Qiitaのために書きました。

「GCログ」や「GCViewer」のキーワードからこのサイトに訪れてくれる方が多いので、改めてGCログやヒープダンプの見方についてまとめることにしました。

GCログのビューアとして有名なGCViewerとヒープの解析ツールとしてすごく優秀なVisualVM、この２つを紹介しつつJVMのプロファイリングを行う方法を解説したいと思います。

GCViewerでGCログを見る

まずはGCViewerでGCログを見てみます。
GCViewerでGCログを見るためには、GCログをファイルに出力する必要があります。
GCログをファイルに出力する方法は以前の記事をご参照いただければと思います。
javaを再起動する必要があります。

GCViewerのインストール

GCViewerは下記のページからダウンロードすることができます。

https://github.com/chewiebug/GCViewer/wiki/Changelog

もともとはTagtraumによって開発されたGCViewerですが、2008年で開発をストップしておりjava1.5までにしか対応していません。
これをフォークしてchewiebugさんが開発を続けていてくれているので、こちらを使います。

↑のGitHub上のリポジトリからソースコードをcloneしてきて、最新版をビルドして使っても構いませんが(Mavenでビルド可能)、macユーザはmacバージョンをダウンロードするとapp形式になっているので使いやすいかと思います。

GCViewerの使い方

GCViewerを起動します。

フォルダのアイコンをタップしてGCログを開きます。

このGCログを出力した時のjvmのオプションは下記のとおりです。

/usr/lib/jvm/java/bin/java
 -XX:NewRatio=2
 -XX:SurvivorRatio=2
 -XX:TargetSurvivorRatio=90
 -XX:MaxTenuringThreshold=32
 -Xloggc:gc.log.jdk1.6.0
 -XX:+PrintGCDetails
 -XX:+PrintGCDateStamps
 -XX:+UseConcMarkSweepGC
 -XX:+UseParNewGC
 -XX:+CMSClassUnloadingEnabled
 -XX:+CMSPermGenSweepingEnabled
 -XX:+CMSIncrementalMode
 -XX:+CMSIncrementalPacing
 -XX:CMSIncrementalDutyCycleMin=0
 -XX:+CMSParallelRemarkEnabled
 -XX:PermSize=128M
 -XX:MaxPermSize=128M
 -Xmx14336M
 -Xms14336M

※-XX:+UseConcMarkSweepGCを指定していることからわかるようにGCアルゴリズムはコンカレントGCを選択しています。

上の図だけでも何となくスパイクしているのはわかりますが、これでは線が多すぎて正直良くわかりません。

そこで、見たい情報を絞ります。
メニューのViewから表示する線をいろいろカスタマイズすることができます。

GCViewerのグラフの説明

wikiに書いてある通りですが、それぞれ下記のようになっています。

#	item	説明
1	Full GC Lines	フルGC 黒い垂直線
2	Inc GC Lines	インクリメンタルGC 水色の垂直線
3	GC Times Line	GCに掛かった時間緑の折れ線
4	GC Times Rectangles	o 黒の四角: フルGC o 青の四角: CMSにおけるinital mark o オレンジの四角: CMSにおけるremark o 赤の四角: VM操作によるイベント (“application stopped…”) o グレーの四角: ノーマルGC o ライト・グレーの四角: インクリメンタルGC
5	Total Heap	全ヒープサイズ赤い折れ線
6	Tenured Generation	Old領域のサイズマゼンタ・エリア
7	Young Generation	New領域のサイズオレンジ・エリア
8	Used Heap	使用済みのヒープサイズ青の折れ線
9	Initial mark level	Initial markレベル黄色の折れ線(CMS or G1GCのみ)
10	Concurrent collections	水色の垂直線がmark開始、ピンクの垂直線がコンカレント・リセット

まずは倍率を１０００倍から５０００倍に上げます。
Data Panelも一旦非表示にします。

さて、これを見ると、使用済みヒープと使用済みNew領域は比例しつつ一定の間隔で上下しています。
ここからは特異点は見えないので、一旦非表示にします。
イニシャル・マークレベル（黄色の線）も一定で、分析対象としづらいので非表示にします。

すっきりして少し見やすくなりました。

ここから、

最も時間がかかっているのはイニシャル・マーク
イニシャル・マークは1分間に２回程度発生している

ということが読み取れます。

イニシャル・マーク

では、そもそも、コンカレントGCにおけるイニシャル・マークとは何なのでしょうか。

OracleのドキュメントのReviewing GC with the CMSによると、New領域から参照されているオブジェクトをマークするのだと。
Stop the Worldを伴い、マイナーGC程度のアプリケーション停止を伴うと述べられています。

つまりこのGCログから、1分間に２回程度、1秒くらいのアプリケーション停止が発生している、ということがわかります。
イニシャル・マークが大量に発生しているということはマイナーGCで開放されないメモリ領域が多いということです。
しかしGCログからは、どのようなオブジェクトが使用されていて、マイナーGCで開放されないような参照を持たれているかを追うことはできません。

そこで次に、VisualVMを使ってスレッドダンプとヒープダンプを見ていきます。

VisualVMでリモート接続

VisualVMはJDK1.6に同梱されているのですが、単体でアプリケーションをダウンロードして使用することもできます。
Mac向けのapp形式もあります。

VisualVM | Downloads

ダウンロードして解凍すればすぐに使えます。まずは起動してみます。

リモート・ホストで実行されているjavaプロセスをモニタリングする(jstatd)

VisualVMの素晴らしいところは、ローカルで実行されているjavaプロセスのみならず、リモート・ホスト上で実行されているjavaプロセスのモニタリングも行えるところです。

リモート・ホストで実行されているjavaプロセスに接続するためには、ホスト上に少し仕掛けが必要です。
リモート接続する方法は２つあり、
１つはjstatd（jstatデーモン）を起動しておき、jstatd経由でプロファイリングする方法、
２つめはJMXを利用する方法です。

まずはjstatd経由で接続してみます。

サーバにログインし、jstatd用のポリシーファイルを作成します。

vi jstatd.all.policy
~
grant codebase "file:${java.home}/../lib/tools.jar" {

   permission java.security.AllPermission;

};
~

作成したファイルをパラメータとして渡し、jstatdを実行します。

nohup jstatd -J-Djava.security.policy=/root/jstatd.1.7.all.policy &
# ポートを確認します。
netstat -nap | grep jstat
tcp        0      0 :::1099                     :::*                        LISTEN      17937/jstatd
tcp        0      0 :::52232                    :::*                        LISTEN      17937/jstatd

サーバ側の設定はこれだけです。
さて、VisualVMからつないでみます。

左パネルのリモートを右クリックし、

ホストの追加を行います。

接続が成功するとサーバ上で実行されている全てのjavaプロセスとそのヒープ状況やスレッドの状態を取得することができます。
しかし、使っていただくとわかるのですが、jstatd経由のプロファイリングでは、ヒープやスレッドの概要は取れてもスレッドの詳しい実行状況やヒープダンプ・スレッドダンプの取得、GCの強制実行などができないのです。

jstatd経由でのプロファイリングでは、実行中のjavaプロセスを停止することなくリモートでプロファイリングを行えるのですが、詳しいプロファイリングができないのが弱点です。

リモート・ホストで実行されているjavaプロセスをモニタリングする(JMX)

さてそれではJMX経由でプロファイリングを行ってみます。
JMX経由でのプロファイリングを行うためには、下記のオプションを指定してjavaプロセスを実行する必要があります。

 -Dcom.sun.management.jmxremote
 -Dcom.sun.management.jmxremote.port=7900
 -Dcom.sun.management.jmxremote.authenticate=false # 認証を行うならtrue
 -Dcom.sun.management.jmxremote.ssl=false # sslを使用するならtrue
 -Djava.rmi.server.hostname=a006.hostd.jp

上記のオプションを指定してjavaプロセスを再実行したら、VisualVMで接続してみます。

ホストを右クリックし「JMX接続を追加」を選択します。