JavaでOutOfMemoryErrorが発生したけど原因がわからないなどトラブル時に確認することがあるGCログについてまとめました。
Java実行時のGCログオプション
GCログの出力方法で簡単なのはJava実行時に-verbose:gc
オプションを指定することです。ログは標準出力に出力されます。
基本的には以下のオプションを指定するのがいいと思います。-verbose:gc
と-Xloggc:<filename>
を一緒に指定するとオーバーライドされるので-verbose:gc
を指定する必要はありません。
オプション | 内容 |
---|---|
-Xloggc:<filename> | GCイベント情報のロギング |
-XX:+PrintGCDetails | 全てのGCで詳細メッセージの出力有効化 |
-XX:+PrintGCDateStamps | 全てのGCで日付スタンプの出力を有効 |
-XX:+UseGCLogFileRotation | GCログのローテーションを有効 |
-XX:NumberOfGCLogFiles=N | GCログのローテーション世代数 |
-XX:GCLogFileSize=N | GCログのローテーション閾値(最小8k) |
その他のGCログ関連のオプション
オプション | 内容 |
---|---|
-XX:+PrintGC | 全てのGCでメッセージの出力を有効 |
-XX:+PrintGCApplicationConcurrentTime | 最後の一時停止(GCの一時停止など)から経過した時間の出力を有効 |
-XX:+PrintGCApplicationStoppedTime | 一時停止(GCの一時停止など)が続いた時間の出力を有効 |
-XX:+PrintGCTaskTimeStamps | 個々のすべてのGCワーカー・スレッド・タスクのタイム・スタンプの出力を有効 |
-XX:+PrintGCTimeStamps | すべてのGCでのタイムスタンプの出力を有効 |
Java Platform, Standard Editionツール・リファレンス
GCログの出力内容
オプション-verbose:gc
で標準出力に出力した場合。
[GC (Allocation Failure) 5345K->3960K(9728K), 0.0013894 secs] [GC (Allocation Failure) 3960K->3960K(9728K), 0.0011112 secs] [Full GC (Allocation Failure) 3960K->2735K(9728K), 0.0036841 secs] [GC (Allocation Failure) 2735K->2735K(9728K), 0.0003498 secs] [Full GC (Allocation Failure) 2735K->2724K(9728K), 0.0035706 secs]
オプション-Xloggc:/usr/local/var/log/gc.log
でロギング。オプションを指定しないと時間はJVM起動時からの経過時間-XX:+PrintGCTimeStamps
で出力される。
0.094: [GC (Allocation Failure) 5307K->3960K(9728K), 0.0012294 secs] 0.095: [GC (Allocation Failure) 3960K->3944K(9728K), 0.0010857 secs] 0.096: [Full GC (Allocation Failure) 3944K->2735K(9728K), 0.0033783 secs] 0.100: [GC (Allocation Failure) 2735K->2735K(9728K), 0.0003185 secs] 0.100: [Full GC (Allocation Failure) 2735K->2724K(9728K), 0.0032798 secs]
オプション-XX:+PrintGCDetails
と-XX:+PrintGCDateStamps
を追加してログの詳細出力、タイムスタンプから日付スタンプへの変更。
2015-05-03T20:52:12.248-0900: 0.104: [GC (Allocation Failure) [PSYoungGen: 1851K->496K(2560K)] 5308K->3960K(9728K), 0.0015781 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 2015-05-03T20:52:12.250-0900: 0.106: [GC (Allocation Failure) [PSYoungGen: 496K->496K(2560K)] 3960K->3960K(9728K), 0.0008585 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 2015-05-03T20:52:12.251-0900: 0.107: [Full GC (Allocation Failure) [PSYoungGen: 496K->0K(2560K)] [ParOldGen: 3464K->2735K(7168K)] 3960K->2735K(9728K), [Metaspace: 2736K->2736K(1056768K)], 0.0035342 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 2015-05-03T20:52:12.254-0900: 0.111: [GC (Allocation Failure) [PSYoungGen: 0K->0K(2560K)] 2735K->2735K(9728K), 0.0002879 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 2015-05-03T20:52:12.255-0900: 0.111: [Full GC (Allocation Failure) [PSYoungGen: 0K->0K(2560K)] [ParOldGen: 2735K->2724K(7168K)] 2735K->2724K(9728K), [Metaspace: 2736K->2736K(1056768K)], 0.0034430 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] Heap PSYoungGen total 2560K, used 61K [0x00000007bfd00000, 0x00000007c0000000, 0x00000007c0000000) eden space 2048K, 3% used [0x00000007bfd00000,0x00000007bfd0f748,0x00000007bff00000) from space 512K, 0% used [0x00000007bff00000,0x00000007bff00000,0x00000007bff80000) to space 512K, 0% used [0x00000007bff80000,0x00000007bff80000,0x00000007c0000000) ParOldGen total 7168K, used 2724K [0x00000007bf600000, 0x00000007bfd00000, 0x00000007bfd00000) object space 7168K, 38% used [0x00000007bf600000,0x00000007bf8a90d8,0x00000007bfd00000) Metaspace used 2768K, capacity 4486K, committed 4864K, reserved 1056768K class space used 300K, capacity 386K, committed 512K, reserved 1048576K
GCログのローテーション
GCログの出力とローテーションに関するオプションは次の通りです。
- -Xloggc:/Users/tasukujp/Documents/gc%p%t.log
- -XX:+UseGCLogFileRotation
- -XX:NumberOfGCLogFiles=3
- -XX:GCLogFileSize=10m
ファイル名には「%p」でプロセスID、「%t」でJVMの起動日時が付加できます。
-XX:NumberOfGCLogFiles=3
の場合はファイル名に「.0〜.2」の連番が付加され、この番号の中でファイルサイズが10m毎にローテーションされます。そのため、現在出力されているファイルを判別するためにファイル名の末尾に「.current」が付いています。
ls -l ~/Documents gc_pid43718_2015-05-03_22-35-23.log.0 gc_pid43718_2015-05-03_22-35-23.log.1 gc_pid43718_2015-05-03_22-35-23.log.2.current
GCViewerでGCログを可視化
取得したGCログはそのままだと分析するにも見辛いのでGCViewerというツールを使って可視化します。GitHubからcloneしてMavenでビルドしましょう。
$ brew install maven // Mavenが無い場合はインストール $ git clone https://github.com/chewiebug/GCViewer.git $ cd GCViewer $ mvn clean install
ビルドが完了するとtargetディレクトリが作成されるのでjava -jar target/gcviewer-1.35-SNAPSHOT.jar
を実行するとGUIが起動します。
フォルダアイコンから出力されたGCログを開くとチャートが表示されます。メニューバーの「View」から表示する線を調整しながら確認しましょう。
以下のログは最終的に「java.lang.OutOfMemoryError: GC overhead limit exceeded」が発生しています。青い線がUsed Heap(使用ヒープ量)で、最初はGC後に安定して下がっていましたが、途中から使用ヒープ量が下がらずにOld領域が枯渇してFull GCが頻発していますね。
ちなみに GC overhead limit exceeded は-XX:+UseGCOverheadLimit
のオプションがデフォルトで有効になっているので、「合計時間の98%がガベージ・コレクションで費やされ、復元されるヒープが2%未満である場合」に OutOfMemoryError がスローされます。
参考記事
最強のJVMチューニング・ツール: GCログを可視化するGCViewerとリモート接続でプロファイリング可能なVisualVM