JavaVMのGCログ出力とGCViewerについて

スポンサーリンク

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ツール・リファレンス

 Java HotSpot VM Options

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でビルドしましょう。

 chewiebug/GCViewer · GitHub

$ 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が起動します。

f:id:tasukujp:20150503091107p:plain

フォルダアイコンから出力されたGCログを開くとチャートが表示されます。メニューバーの「View」から表示する線を調整しながら確認しましょう。

以下のログは最終的に「java.lang.OutOfMemoryError: GC overhead limit exceeded」が発生しています。青い線がUsed Heap(使用ヒープ量)で、最初はGC後に安定して下がっていましたが、途中から使用ヒープ量が下がらずにOld領域が枯渇してFull GCが頻発していますね。

f:id:tasukujp:20150503225721p:plain

ちなみに GC overhead limit exceeded は-XX:+UseGCOverheadLimitのオプションがデフォルトで有効になっているので、「合計時間の98%がガベージ・コレクションで費やされ、復元されるヒープが2%未満である場合」に OutOfMemoryError がスローされます。

参考記事

 JavaのGCログのローテーション - 宮川拓の日記

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