GC ログに関わる JVM コマンドラインオプションまとめ

Full GC による Stop the World でサーバが停止状態に…、そんなときに調査の助けになるのが GC のログ。Permanent 領域が溢れているのか、Java Heap が溢れているのか、Heap が溢れているのなら何のオブジェクトが溢れているのか、メモリリークが発生しているのか。それが分からないと何気に対処のしようがない。
ただ、この GC のログ、それなりの設定をしておかないと解析に耐えないし役に立たない。役に立たないログ出力はディスク容量を圧迫するゴミになる。そういう感じのログを目にして、なんとかならんもんかなー、なんとかせねばなーと検討しており、Oracle のページからそれっぽいオプションを調べてみてる。

Java HotSpot VM Options

当然ながら「Oracle のページ」と書いてあるように、Oracle の JVM が対象であって、他の JVM を使ってる場合は以下の内容は役に立たない。あと、今から検証の段階であって、実際にはまだ試してない。

GC ログ出力

+XX:PrintGCDetails

これ付けてないシステムはヤバい。GC のときの詳細情報を出力するオプション。詳細といったってチョロチョロっと出るだけだが、あると無いとでは大違いになる。
出力は以下のような感じで、New 領域や Tenured (Old)領域が GC 前後でどう変わったのか、GC の所要時間はどれだけかという情報が取得できる。余談だけれど、このあたりのメモリ使用量の推移をグラフ化すると、よく知られた鋸型のグラフが描けておもしろいと思う。

こんな感じのログがでてくる。

1.831: [GC 1.831: [DefNew: 4096K->4096K(4544K), 0.0000118 secs]1.831: [Tenured: 56595K->60544K(60544K), 0.2608705 secs] 60691K->60689K(65088K), 0.2610212 secs]
2.097: [Full GC 2.097: [Tenured: 60544K->60544K(60544K), 0.2638188 secs] 62056K->61982K(65088K), [Perm : 262K->262K(8192K)], 0.2639318 secs]
2.361: [Full GC 2.361: [Tenured: 60544K->60544K(60544K), 0.2532709 secs] 61982K->61982K(65088K), [Perm : 262K->262K(8192K)], 0.2533446 secs]

GCをみる - techlog

タイムスタンプの付加

+XX:PrintGCTimeStamps

最初に知ったときは信じられなかったのだけれど、どうもデフォルトの GC ログはタイムスタンプを出力してくれないっぽい。出力させるためには上記オプションを有効化させる必要があるのだけれど、これによって出力されるのは絶対時刻ではなく、JVM 起動時からの相対時間になる。ヒドい。

もし JVM が Java 6 以降で動いているなら、絶対時刻を出力できる

-XX:+PrintGCDateStamps

が使える。

オブジェクトの年齢情報

-XX:PrintTenuringDistribution

年齢なんて書き方をされると理解が難解になるのだけれど、おそらくは各オブジェクトが Scavenge GC を何回経ているかの統計情報なんだと理解している。
理解の理由は Sun の以下の記述から。

In this example we see that the application seems to be based on a few short-lived objects because after the first copy only 1808712 bytes survive to the following scavange; after 10 hops, 1061472 bytes are finally promoted to the old, so we need 34598776 bytes of free space in survivor to keep aging all these objects
Desired survivor size 107374180 bytes, new threshold 10 (max 10)
- age   1:   17601288 bytes,   17601288 total
- age   2:    1808712 bytes,   19410000 total
- age   3:    1770784 bytes,   21180784 total
- age   4:    2042888 bytes,   23223672 total
- age   5:    2335648 bytes,   25559320 total
- age   6:    2422632 bytes,   27981952 total
- age   7:    2487376 bytes,   30469328 total
- age   8:    1869224 bytes,   32338552 total
- age   9:    1198752 bytes,   33537304 total
- age  10:    1061472 bytes,   34598776 total
http://webcache.googleusercontent.com/search?q=cache:cuwH5i1H8uwJ:bugs.sun.com/bugdatabase/view_bug.do%3Fbug_id%3D6453675+&cd=10&hl=ja&ct=clnk&gl=jp&client=firefox-beta

ヒープダンプ

-XX:HeapDumpPath=./java_pid<pid>.hprof -XX:-HeapDumpOnOutOfMemoryError

OutOfMemoryError (OOME) 発生タイミングでヒープダンプが出力できるようになる。出力先を -XX:HeapDumpPath で指定する。
ヒープダンプ出力中は、試してないが JVM のスレッドが完全停止する、らしい。また、ダンプファイルの大きさは(当然ながら) Java ヒープとして予約しているメモリの大きさと強い相関関係があるので、ディスク容量には注意が必要。また当然ながら HeapDumpPath で指定したパスに対する書き込み権限も必要な点に注意。

JVM が生き続けている場合、OOEM が発生する毎にヒープダンプが出力されてしまうとあっという間に DISK FULL に陥るのではないかと邪推していたのだけれど、

A memory snapshot is captured automatically on first OutOfMemoryError, if the profiled application runs on Sun Java 6 or newer, or on JRockit R28.0.0 or newer.

(解析対象のアプリケーションが Sun の Java 6 以降、あるいは JRockit の R28.0.0 以降で動いている場合、OutOfMemoryError の初回発生タイミングでメモリのスナップショットが自動取得される)
YourKit Java Profiler Help - Out of memory error (OutOfMemoryError and -XX:+HeapDumpOnOutOfMemoryError)

ということで、初回発生時だけのよう。
対応しているのは Java 1.4.2 u12 以降、Java 5.0 u7 以降、Java 6.0 以降になる。それ意外で指定すると、JVM が認識しないため、そもそも JVM 自体が起動しない。

OOEM トリガでのコマンド実行

-XX:OnOutOfMemoryError="<cmd args>;<cmd args>"

OOEM 発生時点で基本的には JVM の状態は異常なので、もはやそれ以降の回復処理を JVM 自身に委ねることはできない。

JVMでOutOfMemoryErrorエラーが発生すると、未解決のままエラーが残されることがあり、クラスタに悪い影響を与える可能性があります。OutOfMemoryErrorが発生した場合の処理として、JVMをリカバリするのではなく、JVMを終了するように構成することをお薦めします。
http://otndnld.oracle.co.jp/document/products/coherence/34/doc_cd/coh.340/B52975-01/docerrata.htm

OutOfMemoryErrorが発生してもスレッドを異空間に葬るだけでJava VMはそのまま動き続ける場合があるけど、当然ながら状態に一貫性のない状態で動いている可能性があるわけで基本的にはとっとと死んで欲しいわけである。一般的に言うところの「不定」状態である。OOMEはErrorであって例外ではない。致命的なJava VMエラーである。OOME発生後にプロセス再起動しないでそのままどうこうしようというのは絶対に避けた方が良い。
OutOfMemoryErrorが発生したときにきちんとJavaプロセスを殺す - nekop's blog

JVM の外の世界にヘルプを求めるために、このオプションを使用する。
引用元のエントリでは、以下のように強制的な JVM の kill を実施している。

-XX:OnOutOfMemoryError="kill -9 %p"

%p は JVM の pid に置換されるようだが、その正式な仕様の文献はまだ見つけられていない。

対応しているのは Java 1.4.2 u12 以降

ヒープ内のクラス毎の統計情報を取得する

-XX:-PrintClassHistogram

このオプションを指定するだけで統計情報が取得されるわけではなく、"このオプションを指定した JVM" に対して QUIT シグナルを送信する必要がある。

PrintClassHistogramオプションは、ヒープ内のクラス統計情報を出力するためのオプションだ。出力時点での各クラスのインスタンスの個数および全インスタンスの合計サイズを、GCログとともに出力する。
(中略)
このオプションを付加してJavaを起動後、そのプロセスに対して一定間隔ごとにSIGQUITシグナルを送信する。
肥え続けるTomcatと胃を痛めるトラブルハッカー：現場から学ぶWebアプリ開発のトラブルハック（8）（2/3 ページ） - ＠IT

出力例は以下のようになる。

num #instances #bytes class name
--------------------------------------
1: 244594 35380344 [C
2: 982063 23569512 java.lang.String
3: 15788 17285632 [B
4: 59009 9135936 <methodKlass>
5: 292468 7019232 java.util.Hashtable$Entry
6: 96069 5493752 [Ljava.util.Hashtable$Entry;
肥え続けるTomcatと胃を痛めるトラブルハッカー：現場から学ぶWebアプリ開発のトラブルハック（8）（2/3 ページ） - ＠IT

当然ながら 1 度の取得では「あぁこのクラスはずいぶんメモリを食っているね」ということしか分からない。
別にメモリを取っているからといって諸悪の根源とは限らない。たとえば Scavenge GC で開放されるのであれば、少々のメモリ容量を使っていたとしても多少目をつぶっても良いと思う。最悪のケースはメモリが GC によって開放されずに留まり続け、さらには増え続けることであって、それを確かめるためには継続観察しかない。
結果として、SIGQUIT を定期的に送るスクリプトを cron あたりに仕込む運用が必要になる。
ただし、SIGQUIT を送った時点で JVM 側で FUll GC が走るという情報がいくつかある。このため、Full GC が走ることによるパフォーマンス劣化の程度は把握しておくことが必要。

javaの起動オプションで-XX:+PrintClassHistogram?を追加することで、SUGQUITシグナルを受信した際に、VMでFullGCが強制的に実行され
http://www.hiihah.info/index.php?実行中のJAVAMVの中身を見てみる

また、Java 5 では GC アルゴリズムによってヒストグラム出力ができないという問題も報告されているので、このあたりは注意が必要。

http://www.acroquest.co.jp/webworkshop/JavaTroubleshooting/trouble023Main.html#trouble7

PrintClassHistogram did not (in 1.5.0 and earlier) work with the parallel scavenging (PS) collector. In 1.5.0 on "server class machines" you get that collector by default. So if you are running on what might be considered a "server-class machine", you will get the PS collector and +PrintClassHistogram will be ignored. This is fixed in Java SE 6 (Mustang) in bug 5023697.

https://forums.oracle.com/forums/thread.jspa?threadID=1540728

ログファイル名

-Xloggc:<filename>

まぁそうですねという内容。これを指定してなかったら、標準出力に出力するっぽい。このため、Tomcat だと catalina.out あたりにでる。

ログローテーション

-XX:-UseGCLogFileRotation -XX:NumberOfGClogFiles=<n> -XX:GCLogFileSize=8K

御親切にログローテーションの機能が入ってる。が、これらのオプションを見て分かるようにローテーションのトリガは時間ではなくログサイズの模様。
ログサイズでのローテーションは個人的には好きではない。

理系学生日記

おまえはいつまで学生気分なのか