ITお絵かき修行

3歩歩いても忘れないために

JJUG CCC 2017 Springメモ【CD4 Unified JVM Logging: Java 9 から変わる JVM ログ】

JJUG CCC

JJUG CCC 2017 Springに参加した。
表題のセッションに参加したので、参加メモを書いておく。
またJava9のea版を使って自由研究という名の動作確認もしてみた。

※正確な情報・見解は後日公開される(であろう)登壇者のスライドや公式資料等を参照のこと。
JJUG CCC 2017 Spring
■Call for Papers
https://jjug-cfp.cfapps.pez.pivotal.io/submissions/48f28c8d-8c73-4460-906c-4e0c980ae891
■動作確認環境
java version "9-ea"
Java(TM) SE Runtime Environment (build 9-ea+170)
Java HotSpot(TM) 64-Bit Server VM (build 9-ea+170, mixed mode)

【概要】

Java 9 から JEP 271: Unified GC Logging により、従来の GC ログが廃止され、新たな JVM logging framework (JEP 158: Unified JVM Logging) と統合して生まれ変わります。
本セッションではこれまでのロギングと比べて、どのようにフォーマットやオプション指定方法などが異なるのか、そしてどう対処していくべきかについて可能な限り紹介していきます。
本セッションでは java.utl.logging については扱いません。JVM そのもののロギングについて扱います。

※事前に上級者向けとアナウンスされていたが、分量的に中級者向けの内容へ変更？となったらしい
■JEP 271
JEP 271: Unified GC Logging

【内容】

１．なぜ変わるのか
・歴史的経緯によりアドホックに改善されてきた。
　その結果、コンポーネントごとに個別実装がなされてきた。
→マイナーバージョンによってログのフォーマットが変わることもあり、
　発表者の方(NTTでJavaのサポートやってる人)でも全て把握しきれない

・設定が多種多様
→レベル・カテゴリ管理ができない（※デバッグ用のバイナリはあるが自前でビルドが必要）
　→パーサを書くのも大変（マイナーバージョンによってフォーマットが変わる件もあり）
→使われないからドキュメントも作られない


２．-Xlog
・Java9より「-Xlog」で統一される。

-Xlog[<what>][:[<output>][:[<decorators>][:<output-options>]]]

※仕様はJEP158を参照。
■JEP 158
http://openjdk.java.net/jeps/158

what…対象=レベル (例：gc=trace)
output…対象=出力先 (例：file=gctrace.txt)
decorators…フォーマット (例：uptimemillis,pids)
output-options…オプション(※現在はローテーションの指定のみ) (例：filecount=5,filesize=1024)

(1)what
・「*」「+」といった識別子が使える
→組み合わせることで細かな出力指定ができるようになるが、(JVMログにおける)ワイルドカードの使い方が一般的な考え方と異なっているので注意が必要。
・フォーマット自体も大きく変わる
→全てのGC方式に対して共通的なフォーマットとなる予定。


(2)output
・デフォルトは標準出力
・JVMログとjavaコマンドの応答は別扱い。
→JVMログをoffの設定にしてもjavaコマンドとしての応答結果は出力される。


(3)decolator
・一般的なwebアプリのオススメは「t,l,tg」※うろ覚え
→time,level,tags
→短命なプロセス(バッチアプリ等)は「uptime(millis|nanos)」もつけたほうが良い


■出力例：-Xmx512MBで起動してFULL GC発生したとき(※ParallelOldGC)
【指定オプション】-Xlog:all:file=gc%p.txt:t,l,tg

[2017-05-21T17:18:48.766+0900][info][gc,start                ] GC(32) Pause Full (Ergonomics)
[2017-05-21T17:18:48.766+0900][info][gc,phases,start         ] GC(32) Marking Phase
[2017-05-21T17:18:49.294+0900][info][gc,phases               ] GC(32) Marking Phase 527.637ms
[2017-05-21T17:18:49.294+0900][info][gc,phases,start         ] GC(32) Summary Phase
[2017-05-21T17:18:49.294+0900][info][gc,phases               ] GC(32) Summary Phase 0.044ms
[2017-05-21T17:18:49.294+0900][info][gc,phases,start         ] GC(32) Adjust Roots
[2017-05-21T17:18:49.295+0900][info][gc,phases               ] GC(32) Adjust Roots 0.596ms
[2017-05-21T17:18:49.295+0900][info][gc,phases,start         ] GC(32) Compaction Phase
[2017-05-21T17:18:49.473+0900][info][gc,phases               ] GC(32) Compaction Phase 178.576ms
[2017-05-21T17:18:49.473+0900][info][gc,phases,start         ] GC(32) Post Compact
[2017-05-21T17:18:49.475+0900][info][gc,phases               ] GC(32) Post Compact 1.979ms
[2017-05-21T17:18:49.479+0900][info][gc,heap                 ] GC(32) PSYoungGen: 131583K->131583K(153088K)
[2017-05-21T17:18:49.479+0900][info][gc,heap                 ] GC(32) ParOldGen: 349393K->349393K(349696K)
[2017-05-21T17:18:49.479+0900][info][gc,metaspace            ] GC(32) Metaspace: 4186K->4186K(1056768K)
[2017-05-21T17:18:49.479+0900][info][gc                      ] GC(32) Pause Full (Ergonomics) 469M->469M(491M) 713.021ms
[2017-05-21T17:18:49.479+0900][info][gc,cpu                  ] GC(32) User=2.31s Sys=0.00s Real=0.71s
[2017-05-21T17:18:49.480+0900][info][safepoint               ] Total time for which application threads were stopped: 0.7133178 seconds, Stopping threads took: 0.0000177 seconds
[2017-05-21T17:18:49.480+0900][info][safepoint               ] Application time: 0.0000583 seconds
[2017-05-21T17:18:49.480+0900][info][safepoint,cleanup       ] deflating idle monitors, 0.0000023 secs
[2017-05-21T17:18:49.480+0900][info][safepoint,cleanup       ] updating inline caches, 0.0000005 secs
[2017-05-21T17:18:49.480+0900][info][safepoint,cleanup       ] compilation policy safepoint handler, 0.0000005 secs
[2017-05-21T17:18:49.480+0900][info][safepoint,cleanup       ] mark nmethods, 0.0000112 secs
[2017-05-21T17:18:49.480+0900][info][safepoint,cleanup       ] purging class loader data graph, 0.0000000 secs

■出力例：-Xmx512MBで起動してFULL GC発生したとき(※CMS GC)
【指定オプション】-Xlog:all:file=gc%p.txt:t,uptimemillis,l,tg

[2017-05-21T16:22:16.645+0900][847ms][info][gc                      ] GC(9) Concurrent Cycle
[2017-05-21T16:22:16.645+0900][847ms][info][gc,marking              ] GC(9) Concurrent Clear Claimed Marks
[2017-05-21T16:22:16.645+0900][847ms][info][gc,marking              ] GC(9) Concurrent Clear Claimed Marks 0.034ms
[2017-05-21T16:22:16.645+0900][847ms][info][gc,marking              ] GC(9) Concurrent Scan Root Regions
[2017-05-21T16:22:16.652+0900][854ms][info][gc,marking              ] GC(9) Concurrent Scan Root Regions 6.629ms
[2017-05-21T16:22:16.652+0900][854ms][info][gc,marking              ] GC(9) Concurrent Mark (0.854s)
[2017-05-21T16:22:16.652+0900][854ms][info][gc,marking              ] GC(9) Concurrent Mark From Roots
[2017-05-21T16:22:16.652+0900][854ms][info][gc,task                 ] GC(9) Using 1 workers of 1 for marking
[2017-05-21T16:22:16.696+0900][898ms][info][safepoint               ] Application time: 0.0508277 seconds
[2017-05-21T16:22:16.696+0900][898ms][info][safepoint,cleanup       ] deflating idle monitors, 0.0000019 secs
[2017-05-21T16:22:16.696+0900][898ms][info][safepoint,cleanup       ] updating inline caches, 0.0000009 secs
[2017-05-21T16:22:16.696+0900][898ms][info][safepoint,cleanup       ] compilation policy safepoint handler, 0.0000005 secs
[2017-05-21T16:22:16.696+0900][898ms][info][safepoint,cleanup       ] mark nmethods, 0.0000089 secs
[2017-05-21T16:22:16.696+0900][898ms][info][safepoint,cleanup       ] purging class loader data graph, 0.0000000 secs
[2017-05-21T16:22:18.713+0900][2915ms][info][gc,marking              ] GC(9) Concurrent Mark From Roots 2061.666ms
[2017-05-21T16:22:18.714+0900][2916ms][info][gc,marking              ] GC(9) Concurrent Mark Abort
[2017-05-21T16:22:18.714+0900][2916ms][info][gc                      ] GC(9) Concurrent Cycle 2068.537ms

(4)output,output-option
・Java9よりjcmd経由でログを強制ローテートできるようになったので「filecount」は1以上を指定するべき。
・「filesize」はデフォルトで20MBなので、大抵のwebアプリの場合は増やすべき。


(5)tags
GC系…gc
エラー系…exceptions
スレッド系…os, thread
動作解析…class, vmoperation


３．そのほか
・STW(Stop The World)時間が出力されるようになった。
→今まではフォーマットによって計算が必要だったり出力されていなかったりした。

・OOME(Out Of Memory Error)起こした時の例外(exceptions)ログは下記
→実際はArrayListにHashMapを突っ込みまくってOOME起こしているが、そこまでは追えなさそうな印象
■出力例：-Xmx512MBで起動してOOME発生したとき(※CMS GC)
指定オプション：-Xlog:all:file=gc%p.txt:utc,l,tg

[2017-05-21T07:02:41.618+0000][info][exceptions              ] Exception <a 'java/lang/OutOfMemoryError'{0x00000000e1ba0958}> (0x00000000e1ba0958) 
[2017-05-21T07:02:41.618+0000][info][exceptions              ] Exception <a 'java/lang/OutOfMemoryError'{0x00000000e1ba0958}: Java heap space>
[2017-05-21T07:02:41.618+0000][info][exceptions              ] 1 [Exception (): a 'java/lang/OutOfMemoryError'{0x00000000e1ba0958} in {method} {0x0000022753c07b88} 'putVal' '(ILjava/lang/Object;Ljava/lang/Object;ZZ)Ljava/lang/Object;' in 'java/util/HashMap' at 0x00000227483fb160]
[2017-05-21T07:02:41.618+0000][info][exceptions              ] 2 [Exception (): a 'java/lang/OutOfMemoryError'{0x00000000e1ba0958} in {method} {0x0000022753ec0468} 'main' '([Ljava/lang/String;)V' in 'hoge/fuga/OOME' at 0x00000227483ffe88]