トラブルに備えるJVMオプション

JBoss

以前の記事でトラブルが起きた後の初動対応を書いてみたが、いざトラブルに遭遇すると、まず再起動してからどうするか考えるケースが多いと感じている。しかし何も情報がないと『情報がない/再現方法が不明』などの理由からそのままお蔵入りになってしまう。今回はトラブルに事前に備えるために、地味だけど大切なJavaVMのオプションをまとめてみる。

  • GCログの出力とローテーション
  • OutOfMemoryError発生時のヒープダンプ自動出力と出力パス設定
  • JavaVMクラッシュログの出力パス設定

JVMオプションの設定 (OpenJDK/OracleJDK)

JavaVMにはGCおよびヒープメモリの状態をロギングする仕組みや、OufOfMemoryError時にヒープダンプを自動的に出力するような障害に備えて自動的に情報を出力する機能がある。おすすめのオプション*1は以下の通り。

java -Xms?g -Xmx?g -XX:MaxPermSize=?m (JDK8は-XX:MaxMetaspaceSize=?m)
   -Xloggc:/home/test/wildfly-8.0.0.Final/standalone/log/gc.log
   -XX:+PrintGCDetails -XX:+PrintGCDateStamps
   -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=10M
   -XX:+HeapDumpOnOutOfMemoryError
   -XX:HeapDumpPath=/home/test/wildfly-8.0.0.Final/standalone/log/
   -XX:ErrorFile=/home/test/wildfly-8.0.0.Final/standalone/log/hs_err_pid%p.log

GCログの取得

前回にも書いたが、JDK6u34/JDK7u2より-XX:+UserGCLogFileRotationによりGCログのローテーションが可能になっている。例では、-XX:NumberOfGCLogFiles(ファイル数)を5、-XX:GCLogFileSize(サイズがいくつになったらローテーション)を10MBに設定している。

また、-XX:+PrintGCDateStampsもとても便利な設定。デフォルトではJavaVMの起動時間から経過秒数のみログに出力されるが、このオプションを設定すると日付形式で以下の1番左のレコードのように出力してくれる。

2014-03-30T16:58:11.048+0900: 5.114: [Full GC2014-03-30T16:58:11.048+0900: 5.114: [Tenured: 1675K->16783K(349568K), 0.1214210 secs] 95380K->16783K(506816K), [Perm : 26686K->26686K(26688K)], 0.1215920 secs] [Times: user=0.12 sys=0.00, real=0.12 secs]

取得したログのグラフ化にはGCViewerがとても便利。GitHubでメンテナンス続けられている最新版ではjarを配ってないようなので、ソースを取得してmavenでビルドする。

cd GCViewer-1.33
mvn clean package

targetディレクトリ配下にビルドされたGCViewerができるので、java -jar gcviewer-1.33.jarで起動する。簡単なサンプルプログラムに対してgatling使って負荷を掛け続けたときのGCログ表示例を示す。

f:id:n_agetsuma:20140330173021p:plain

様々な色があるが、一番大切なのは青の線が示すUsed Heap(使用ヒープ量)で、このテストアプリではGC後に安定して下がっているので問題ない。メモリリークの傾向があるときは、この青い線がどんどん上がっている傾向が見える。

-XX:+HeapDumpOnOutOfMemoryErrorの設定

HeapDumpOnOutOfMemoryErrorを設定すると、OutOfMemoryErrorが発生したタイミングで、自動的にヒープダンプを取得してくれる。出力先パスは何も指定しないとJavaを起動したカレントディレクトリになるので、-XX:HeapDumpPathを明示的に取得して、アプリケーションサーバのログディレクトリを指定すると情報が一カ所に集まって便利。

このオプションを設定した状態でOutOfMemoryErrorを発生させると、以下のようなメッセージが出力される(JDK7u51の場合)。

java.lang.OutOfMemoryError: Java heap space
Dumping heap to /home/test/wildfly-8.0.0.Final/standalone/log/java_pid4167.hprof ...
Heap dump file created [249928359 bytes in 0.848 secs]

HeapDumpPathで指定したディレクトリにjava_pid<pid>.hprofの名前でヒープダンプが出力されているのがわかる。

余談だが、OutOfMemoryErrorはユーザのプロセス生成数上限(ulimit -u)に達してネイティブスレッドが生成できなくなったときにもスローされるが、この場合はヒープダンプは出力されない。プロセス生成数上限に達した場合は以下のようなメッセージが出力される。

Exception in thread "main" java.lang.OutOfMemoryError: unable to create new native thread
    at java.lang.Thread.start0(Native Method)
    at java.lang.Thread.start(Thread.java:713)

CentOS6.5では一般ユーザのプロセス数上限が1024であり、スレッドもこの上限の範囲となるが、このエラーが発生したときは、何らかの要因により終わらなくなったスレッドが多く残っていることが考えられるので、プロセス生成数上限を拡大しても問題が解決しない場合も多いと思う。

-XX:ErrorFileの設定

JNIで呼び出した自作ライブラリにバグがあったり、JavaVM自体の不具合を踏んだりするとJavaプロセスがクラッシュしてエラーファイルを出力してくれる。この機能はヒープダンプと異なりデフォルトで有効であるが、出力先を集約したい場合は明示的に設定する必要がある。今回の例ではアプリケーションサーバのログディレクトリを出力先としている。

動作中のWildFly8に kill -s SIGSEGV pid すると以下のようなファイルが出力される。

# A fatal error has been detected by the Java Runtime Environment:
#
#  SIGSEGV (0xb) at pc=0x0000003d7300822b, pid=9731, tid=140160209254144

プロセスがクラッシュした原因、クラッシュ時のレジスタ内容、リンクしていた動的ライブラリ(.so)、/proc/meminfoや/proc/cpuinfoなどのマシン情報も含まれているため、これを見るとJDKのJIRAを検索して既知のバグを踏んだかどうかはある程度切り分けられる。

読み方についてはOracle社が公開しているTroubleshooting Guide for HotSpot VMにて解説されている。

まとめ

  • GCログの取得により、メモリリークの有無が確認できる
  • ヒープダンプ出力設定(-XX:+OnHeapDumpOutOfMemoryError)によって、OOMエラー時に自動でヒープダンプを取得する
  • ヒープダンプの出力先は-XX:HeapDumpPathで明示的に指定して、情報を一カ所に集める
  • JVMのエラーログも同様に-XX:ErrorFileで出力先を指定して集める

*1:ヒープサイズの設定やGCストラテジの選択についてはアプリケーションにより異なるので、ここでは言及しない。Java Performanceにヒープサイズの決定プロセスが詳しく書いてあったので、参考になると思う。