SlideShare a Scribd company logo
Garbage First GC
KUBOTA Yuji
@sugarlife
NTT OSSセンタ
Copyright©2015 NTT corp. All Rights Reserved.
2015/11/28
JJUG CCC 2015 Fall #ccc_cd6
@sugarlife
#ccc_cd6
#jjug
感想や質問はぜひ Twitter で!
Copyright©2015 NTT corp. All Rights Reserved. 2
はじめに
• 本セッションでは Garbage First
GC (G1 GC) について、ログから
動作状況を把握できる、主に開
発者・運用者向けの知識の土台
作りを目標としています
体系的な知識の土台作りが目標
Copyright©2015 NTT corp. All Rights Reserved. 3
おやくそく
• 本セッション (スライド) における
表現は全て個人の見解です
• 以下の JVM 実装に基づきます
–HotSpot VM (OpenJDK 8)
–repo jdk8u/jdk8u-dev/hotspot
•changeset 7664:831754f092fb(zip)
動作確認は jdk8u66 でやりました
Copyright©2015 NTT corp. All Rights Reserved. 4
KUBOTA Yuji @sugarlife
• OpenJDK テクニカルサポート
–コア解析からGCチューニング, etc…
• 解析支援ツール HeapStats 開発
–多数の商用で元気に稼働中 :)
• 難聴者
–資料的なスライドを多用します
過去にCMS GC, Jigsaw, HeapStats を発表
Copyright©2015 NTT corp. All Rights Reserved. 5
NTT OSSセンタ
• NTT グループの OSS 活用を支える部隊
*)OSSVERT®:OSs Suites VERified Technically(技術検証済みOSS組合せ)
事業会社
SI会社
問合せ対応、導
入支援、保守等
技術検証、
導入推進
プロダクト/
ツール類開発
技術者育成、
人材交流
各種
OSS コ
ミュニ
ティ
設計, 開
発, 運用
グループ各社
サポー
トベン
ダ、
NTT
研究所
等お
客
様
サポー
ト連携
開発
連携
①OSSトータル
サポート
NTT OSSセンタ
②OSS適用推進
(OSSVERT®*検証)
③技術開発
(DBMS,高可用ミドル等)
④ソフトウェア
基盤技術力向上
Kernel, PostgreSQL, Pacemaker, Tomcat, etc
Copyright©2015 NTT corp. All Rights Reserved. 6
OpenJDK Contributes
Copyright©2015 NTT corp. All Rights Reserved. 7
暗号化 zip 操作 API を提案中!
興味ある人は是非MLへ!
G1 GC 概要
なぜ Garbage First なのか?
Copyright©2015 NTT corp. All Rights Reserved. 8
Garbage Collection
1. 不要なメモリ領域(ゴミ)を判別し、
2. ゴミを処理して再利用可能にする
面倒なメモリ管理は JVM に任せたい
Copyright©2015 NTT corp. All Rights Reserved. 9
HotSpot VM の GC
• Serial GC, Parallel GC
–初期GC, JDK8 以前はデフォルト
• Concurrent Mark-Sweep GC
–JDK1.4.1 から導入 (出典:JDK-4758307)
• Garbage First GC
–JDK7 から導入, JDK9からデフォルト
細かく言えば他にもあるけど主流はこれら
Copyright©2015 NTT corp. All Rights Reserved. 10
Parallel と Concurrent
ケースバイケースで GC を選択しましょう
Copyright©2015 NTT corp. All Rights Reserved. 11
Parallel
(Serial =
Threadが1つ)
Concurrent
(実際は部分的に
停止するMostly)
Application
Thread
GC Thread
アプリケーション停止=Stop The World (STW)
メモリ管理
今回はPerm/Metaspace等は細かく見ません
Copyright©2015 NTT corp. All Rights Reserved. 12
Heap
Perm
/
Meta
space
Heap (ヒープ)
Copyright©2015 NTT corp. All Rights Reserved. 13
Heap
オブジェクトが配置される Heap を巨大な
一つのデータ構造として扱うのは非効率
ヒープ管理 (従来)
Copyright©2015 NTT corp. All Rights Reserved. 14
Eden Old
Survivor
0
Survivor
1
というわけで、Java (JVM)は世代別に分けて
それぞれ異なる GC で管理しています
Young
ヒープ管理 (従来)
Copyright©2015 NTT corp. All Rights Reserved. 15
Eden Old
Survivor
0
Survivor
1
ヒープが巨大化すると結局非効率になります
そこで G1 はヒープ構造を変更しました
Young
Heap Layout (G1)
Copyright©2015 NTT corp. All Rights Reserved. 16
G1 では Region と呼ばれる空間に
ヒープを等しく分割して管理してます
Heap Layout (G1)
Copyright©2015 NTT corp. All Rights Reserved. 17
Region のサイズは初期ヒープサイズに
依存しますが -XX:G1HeapRegionSize で
1~32MBの範囲で変更が可能です
Heap Layout (G1)
Copyright©2015 NTT corp. All Rights Reserved. 18
Region のサイズは初期ヒープサイズに
依存しますが -XX:G1HeapRegionSize で
1~32MBの範囲で変更が可能です
Regionサイズの半分以上の単体オブジェクトは
「Humongous Object」として扱われます
世代分け
Copyright©2015 NTT corp. All Rights Reserved. 19
E
O
S
O
O
S
S
E
O
E
O
O
E
S
O
O O
O
O
E
E
O
水:Eden 橙:Survivor 緑:Old 藍:未使用
G1 GC も他 GC と同じく世代別 GC です
Young (Eden, Survivor) 対象の Young GC
Young + Old (Tenure) 対象の Mixed GC
そして G1 GC が失敗した時の Full GC
Humongous Object
Copyright©2015 NTT corp. All Rights Reserved. 20
E
O
S
O
O
S
S
E
H
O
E
O
O
E
S
O
O O
O
H
O
E
E
O
Humongous Object が生成された場合は
専用の Region にアロケートされます
水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
Humongous Object
Copyright©2015 NTT corp. All Rights Reserved. 21
E
O
S
O
O
S
S
E
H
O
E
O
O
E
S
O
O O
O
H
O
E
E
O
Humongous Object が生成された場合は
専用の Region にアロケートされます
アロケート時に GC 発生の可能性がある上、
メモリ獲得コストも高いので極力生成は避ける
水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
Garbage First の所以
Copyright©2015 NTT corp. All Rights Reserved. 22
E
O
S
O
O
S
S
E
O
E
O
O
E
S
O
O O
O
O
E
E
O
H
H1. 各Regionの不要オブジェクト量は異なる
水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
Garbage First の所以
Copyright©2015 NTT corp. All Rights Reserved. 23
E
O
S
O
O
S
S
E
O
E
O
O
E
S
O
O O
O
O
E
E
O
H
H1. 各Regionの不要オブジェクト量は異なる
2. GC による回収はコスト(STW)が発生する
水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
Garbage First の所以
Copyright©2015 NTT corp. All Rights Reserved. 24
E
O
S
O
O
S
S
E
O
E
O
O
E
S
O
O O
O
O
E
E
O
H
H1. 各Regionの不要オブジェクト量は異なる
2. GC による回収はコスト(STW)が発生する
不要オブジェクト(ゴミ)が多いRegionだけ
GC して処理時間を(できるだけ)抑える=G1
水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
Garbage First の所以
Copyright©2015 NTT corp. All Rights Reserved. 25
E
O
S
O
O
S
S
E
T
E
O
O
T
E
S
T
O O
O
O
E
E
O
H
H1. 各Regionの不要オブジェクト量は異なる
2. GC による回収はコスト(STW)が発生する
不要オブジェクト(ゴミ)が多いRegionだけ
GC して処理時間を(できるだけ)抑える=G1
アプリケーションを止めないコンカレント
サイクルでマーキングを実施する
水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
Garbage First の所以
Copyright©2015 NTT corp. All Rights Reserved. 26
E
O
S
O
O
S
S
E
T
E
O
O
T
E
S
T
O O
O
O
E
E
O
H
H1. 各Regionの不要オブジェクト量は異なる
2. GC による回収はコスト(STW)が発生する
不要オブジェクト(ゴミ)が多いRegionだけ
GC して処理時間を(できるだけ)抑える=G1
アプリケーションを止めないコンカレント
サイクルでマーキングを実施する
-XX:MaxGCPauseMillis で指定した値を
目安に前向きに善処 (デフォルト 200ms)
水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
まとめ
Copyright©2015 NTT corp. All Rights Reserved. 27
• ヒープレイアウト
–従来と同じく世代別に領域を分ける。
ただし、巨大ヒープを効率的に処理
するため、Region に細分化
• G1 処理
–マーキングはコンカレントサイクル
–Young GC と Mixed GC の世代別GC
–失敗した場合は Full GC が発生する
ゴミの多い場所を優先してやるから G1 GC
G1 処理とログ
処理を具体的に追っていきましょう
Copyright©2015 NTT corp. All Rights Reserved. 28
Copyright©2015 NTT corp. All Rights Reserved. 29
以降のログ出力に利用したオプションです
G1 使用時の推奨値とは別なのに注意
ログについて
使用した Java 起動オプション
-XX:+UseG1GC
-XX:+PrintGCDetails
-XX:+PrintGCCause
-XX:+PrintGCDateStamps
見やすいようにタイムスタンプを除
外し、一部省略や改行をしています
水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
Copyright©2015 NTT corp. All Rights Reserved. 30
オブジェクトの生成
E E
生成オブジェクトは Eden に配置され、
Eden が一杯になると Young GC が発生
O
O
S
H
水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
Copyright©2015 NTT corp. All Rights Reserved. 31
オブジェクトの生成
E E
生成オブジェクトは Eden に配置され、
Eden が一杯になると Young GC が発生
O
O
E
S
H
水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
Copyright©2015 NTT corp. All Rights Reserved. 32
オブジェクトの生成
E E
生成オブジェクトは Eden に配置され、
Eden が一杯になると Young GC が発生
O
O
E E
S
H
水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
Copyright©2015 NTT corp. All Rights Reserved. 33
Young GC
E E
Young GC が発生した際はこの形式の
ログが出力。GC Causeは複数種類あります
O
O
E E
S
H
[GC pause (G1 Evacuation Pause) (young), 0.0650323 secs]
GC発生原因(GC Cause) young/mixed 識別箇所
水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
Copyright©2015 NTT corp. All Rights Reserved. 34
Young GC
E
E E
E
O
O
S
全 Eden / Survivor をスキャンし、生存オブ
ジェクトを新Survivorに退避 (Evacuation)
H
水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
Copyright©2015 NTT corp. All Rights Reserved. 35
Young GC
E
S
E S E
S
E
O
O
S
全 Eden / Survivor をスキャンし、生存オブ
ジェクトを新Survivorに退避 (Evacuation)
H
水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
Copyright©2015 NTT corp. All Rights Reserved. 36
Young GC
E
S
E S E
S
E
O
O
S
H
Survivor の一部のオブジェクトは
(年齢的に) Old に退避する場合もあります
水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
Copyright©2015 NTT corp. All Rights Reserved. 37
Young GC
E
S
E S
O
E
S
E
O
O
S
H
Survivor の一部のオブジェクトは
(年齢的に) Old に退避する場合もあります
水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
Copyright©2015 NTT corp. All Rights Reserved. 38
Young GC (Survivor Full)
E
S
E S E
S
E
O
O
S
H
もし退避先の Survivor に生存オブジェクト
を退避させるスペースがなかった場合は、
Eden から直接 Old 領域に退避することも
水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
Copyright©2015 NTT corp. All Rights Reserved. 39
Young GC (Survivor Full)
E
S
E S E
S
E
O
O
S
H
もし退避先の Survivor に生存オブジェクト
を退避させるスペースがなかった場合は、
Eden から直接 Old 領域に退避することも
水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
Copyright©2015 NTT corp. All Rights Reserved. 40
Young GC (Survivor Full)
E
S
E S E
S
E
O
O
S
H
もし退避先の Survivor に生存オブジェクト
を退避させるスペースがなかった場合は、
Eden から直接 Old 領域に退避することも
O
水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
Copyright©2015 NTT corp. All Rights Reserved. 41
Young GC 後
O
Eden / Survivor元 (from) に割り当てていた
Region を解放して不要オブジェクトを回収
S
S
S O
O H
水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
Copyright©2015 NTT corp. All Rights Reserved. 42
ログと大まかな処理の流れ[GC pause (G1 Evacuation Pause) (young), 0.0650323 secs]
[Parallel Time: 38.6 ms, GC Workers: 10]
[GC Worker Start (ms): Min: 27181.9, Avg: 27182.2, Max: 27184.0, Diff: 2.1]
[Ext Root Scanning (ms): Min: 0.0, Avg: 0.9, Max: 1.9, Diff: 1.9, Sum: 8.8]
[Update RS (ms): Min: 0.0, Avg: 0.1, Max: 0.5, Diff: 0.5, Sum: 1.1]
[Processed Buffers: Min: 0, Avg: 0.8, Max: 3, Diff: 3, Sum: 8]
[Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.3]
[Code Root Scanning (ms): Min: 0.5, Avg: 1.0, Max: 1.8, Diff: 1.2, Sum: 9.7]
[Object Copy (ms): Min: 15.2, Avg: 16.6, Max: 17.4, Diff: 2.3, Sum: 166.0]
[Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 2.4]
[Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.3]
[GC Worker Total (ms): Min: 17.0, Avg: 18.9, Max: 19.1, Diff: 2.1, Sum: 188.6]
[GC Worker End (ms): Min: 27201.0, Avg: 27201.0, Max: 27201.0, Diff: 0.0]
[Code Root Fixup: 1.0 ms]
[Code Root Purge: 0.1 ms]
[Clear CT: 1.4 ms]
[Other: 23.9 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 21.4 ms]
[Ref Enq: 0.2 ms]
[Redirty Cards: 1.2 ms]
[Humongous Register: 0.0 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.4 ms]
[Eden: 224.0M(224.0M)->0.0B(196.0M) Survivors: 0.0B->28.0M Heap: 228.9M(4500.0M)->48.5M(4500.0M)]
[Times: user=0.26 sys=0.08, real=0.06 secs]
一連のログを全部表示すると、このように
インデントでグルーピングされています
[GC pause (G1 Evacuation Pause) (young), 0.0650323 secs]
[Parallel Time: 38.6 ms, GC Workers: 10]
[GC Worker Start (ms): Min: 27181.9, Avg: 27182.2, Max: 27184.0, Diff: 2.1]
[Ext Root Scanning (ms): Min: 0.0, Avg: 0.9, Max: 1.9, Diff: 1.9, Sum: 8.8]
[Update RS (ms): Min: 0.0, Avg: 0.1, Max: 0.5, Diff: 0.5, Sum: 1.1]
[Processed Buffers: Min: 0, Avg: 0.8, Max: 3, Diff: 3, Sum: 8]
[Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.3]
[Code Root Scanning (ms): Min: 0.5, Avg: 1.0, Max: 1.8, Diff: 1.2, Sum: 9.7]
[Object Copy (ms): Min: 15.2, Avg: 16.6, Max: 17.4, Diff: 2.3, Sum: 166.0]
[Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 2.4]
[Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.3]
[GC Worker Total (ms): Min: 17.0, Avg: 18.9, Max: 19.1, Diff: 2.1, Sum: 188.6]
[GC Worker End (ms): Min: 27201.0, Avg: 27201.0, Max: 27201.0, Diff: 0.0]
[Code Root Fixup: 1.0 ms]
[Code Root Purge: 0.1 ms]
[Clear CT: 1.4 ms]
[Other: 23.9 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 21.4 ms]
[Ref Enq: 0.2 ms]
[Redirty Cards: 1.2 ms]
[Humongous Register: 0.0 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.4 ms]
[Eden: 224.0M(224.0M)->0.0B(196.0M) Survivors: 0.0B->28.0M Heap: 228.9M(4500.0M)->48.5M(4500.0M)]
[Times: user=0.26 sys=0.08, real=0.06 secs]
Copyright©2015 NTT corp. All Rights Reserved. 43
ログと大まかな処理の流れ
特に重要なのは先頭と末尾
[GC pause (G1 Evacuation Pause) (young), 0.0650323 secs]
[Parallel Time: 38.6 ms, GC Workers: 10]
[GC Worker Start (ms): Min: 27181.9, Avg: 27182.2, Max: 27184.0, Diff: 2.1]
[Ext Root Scanning (ms): Min: 0.0, Avg: 0.9, Max: 1.9, Diff: 1.9, Sum: 8.8]
[Update RS (ms): Min: 0.0, Avg: 0.1, Max: 0.5, Diff: 0.5, Sum: 1.1]
[Processed Buffers: Min: 0, Avg: 0.8, Max: 3, Diff: 3, Sum: 8]
[Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.3]
[Code Root Scanning (ms): Min: 0.5, Avg: 1.0, Max: 1.8, Diff: 1.2, Sum: 9.7]
[Object Copy (ms): Min: 15.2, Avg: 16.6, Max: 17.4, Diff: 2.3, Sum: 166.0]
[Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 2.4]
[Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.3]
[GC Worker Total (ms): Min: 17.0, Avg: 18.9, Max: 19.1, Diff: 2.1, Sum: 188.6]
[GC Worker End (ms): Min: 27201.0, Avg: 27201.0, Max: 27201.0, Diff: 0.0]
[Code Root Fixup: 1.0 ms]
[Code Root Purge: 0.1 ms]
[Clear CT: 1.4 ms]
[Other: 23.9 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 21.4 ms]
[Ref Enq: 0.2 ms]
[Redirty Cards: 1.2 ms]
[Humongous Register: 0.0 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.4 ms]
[Eden: 224.0M(224.0M)->0.0B(196.0M) Survivors: 0.0B->28.0M Heap: 228.9M(4500.0M)->48.5M(4500.0M)]
[Times: user=0.26 sys=0.08, real=0.06 secs]
Copyright©2015 NTT corp. All Rights Reserved. 44
ログと大まかな処理の流れ
[GC pause (<GCCause>) (young), 0.0650323 secs]
:
:
[Eden: 224.0M(224.0M)->0.0B(196.0M)
Survivors: 0.0B->28.0M
Heap: 228.9M(4500.0M)->48.5M(4500.0M)]
[Times: user=0.26 sys=0.08, real=0.06 secs]
各領域のサイズと停止(STW)時間が解ります
Young GC 確認
[GC pause (G1 Evacuation Pause) (young), 0.0650323 secs]
[Parallel Time: 38.6 ms, GC Workers: 10]
[GC Worker Start (ms): Min: 27181.9, Avg: 27182.2, Max: 27184.0, Diff: 2.1]
[Ext Root Scanning (ms): Min: 0.0, Avg: 0.9, Max: 1.9, Diff: 1.9, Sum: 8.8]
[Update RS (ms): Min: 0.0, Avg: 0.1, Max: 0.5, Diff: 0.5, Sum: 1.1]
[Processed Buffers: Min: 0, Avg: 0.8, Max: 3, Diff: 3, Sum: 8]
[Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.3]
[Code Root Scanning (ms): Min: 0.5, Avg: 1.0, Max: 1.8, Diff: 1.2, Sum: 9.7]
[Object Copy (ms): Min: 15.2, Avg: 16.6, Max: 17.4, Diff: 2.3, Sum: 166.0]
[Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 2.4]
[Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.3]
[GC Worker Total (ms): Min: 17.0, Avg: 18.9, Max: 19.1, Diff: 2.1, Sum: 188.6]
[GC Worker End (ms): Min: 27201.0, Avg: 27201.0, Max: 27201.0, Diff: 0.0]
[Code Root Fixup: 1.0 ms]
[Code Root Purge: 0.1 ms]
[Clear CT: 1.4 ms]
[Other: 23.9 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 21.4 ms]
[Ref Enq: 0.2 ms]
[Redirty Cards: 1.2 ms]
[Humongous Register: 0.0 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.4 ms]
[Eden: 224.0M(224.0M)->0.0B(196.0M) Survivors: 0.0B->28.0M Heap: 228.9M(4500.0M)->48.5M(4500.0M)]
[Times: user=0.26 sys=0.08, real=0.06 secs]
Copyright©2015 NTT corp. All Rights Reserved. 45
ログと大まかな処理の流れ
[GC pause (<GCCause>) (young), 0.0650323 secs]
:
:
[Eden: 224.0M(224.0M)->0.0B(196.0M)
Survivors: 0.0B->28.0M
Heap: 228.9M(4500.0M)->48.5M(4500.0M)]
[Times: user=0.26 sys=0.08, real=0.06 secs]
GC前 使用量(容量) -> GC後 使用量(容量)
実 STW 時間
各領域のサイズと停止(STW)時間が解ります
Young GC 確認
Copyright©2015 NTT corp. All Rights Reserved. 46
ログと大まかな処理の流れ[GC pause (G1 Evacuation Pause) (young), 0.0650323 secs]
[Parallel Time: 38.6 ms, GC Workers: 10]
[GC Worker Start (ms): Min: 27181.9, Avg: 27182.2, Max: 27184.0, Diff: 2.1]
[Ext Root Scanning (ms): Min: 0.0, Avg: 0.9, Max: 1.9, Diff: 1.9, Sum: 8.8]
[Update RS (ms): Min: 0.0, Avg: 0.1, Max: 0.5, Diff: 0.5, Sum: 1.1]
[Processed Buffers: Min: 0, Avg: 0.8, Max: 3, Diff: 3, Sum: 8]
[Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.3]
[Code Root Scanning (ms): Min: 0.5, Avg: 1.0, Max: 1.8, Diff: 1.2, Sum: 9.7]
[Object Copy (ms): Min: 15.2, Avg: 16.6, Max: 17.4, Diff: 2.3, Sum: 166.0]
[Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 2.4]
[Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.3]
[GC Worker Total (ms): Min: 17.0, Avg: 18.9, Max: 19.1, Diff: 2.1, Sum: 188.6]
[GC Worker End (ms): Min: 27201.0, Avg: 27201.0, Max: 27201.0, Diff: 0.0]
[Code Root Fixup: 1.0 ms]
[Code Root Purge: 0.1 ms]
[Clear CT: 1.4 ms]
[Other: 23.9 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 21.4 ms]
[Ref Enq: 0.2 ms]
[Redirty Cards: 1.2 ms]
[Humongous Register: 0.0 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.4 ms]
[Eden: 224.0M(224.0M)->0.0B(196.0M) Survivors: 0.0B->28.0M Heap: 228.9M(4500.0M)->48.5M(4500.0M)]
[Times: user=0.26 sys=0.08, real=0.06 secs]
このグループは GC Worker による生存オブ
ジェクトのスキャンと退避処理のログです
[GC pause (G1 Evacuation Pause) (young), 0.0650323 secs]
[Parallel Time: 38.6 ms, GC Workers: 10]
[GC Worker Start (ms): Min: 27181.9, Avg: 27182.2, Max: 27184.0, Diff: 2.1]
[Ext Root Scanning (ms): Min: 0.0, Avg: 0.9, Max: 1.9, Diff: 1.9, Sum: 8.8]
[Update RS (ms): Min: 0.0, Avg: 0.1, Max: 0.5, Diff: 0.5, Sum: 1.1]
[Processed Buffers: Min: 0, Avg: 0.8, Max: 3, Diff: 3, Sum: 8]
[Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.3]
[Code Root Scanning (ms): Min: 0.5, Avg: 1.0, Max: 1.8, Diff: 1.2, Sum: 9.7]
[Object Copy (ms): Min: 15.2, Avg: 16.6, Max: 17.4, Diff: 2.3, Sum: 166.0]
[Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 2.4]
[Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.3]
[GC Worker Total (ms): Min: 17.0, Avg: 18.9, Max: 19.1, Diff: 2.1, Sum: 188.6]
[GC Worker End (ms): Min: 27201.0, Avg: 27201.0, Max: 27201.0, Diff: 0.0]
[Code Root Fixup: 1.0 ms]
[Code Root Purge: 0.1 ms]
[Clear CT: 1.4 ms]
[Other: 23.9 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 21.4 ms]
[Ref Enq: 0.2 ms]
[Redirty Cards: 1.2 ms]
[Humongous Register: 0.0 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.4 ms]
[Eden: 224.0M(224.0M)->0.0B(196.0M) Survivors: 0.0B->28.0M Heap: 228.9M(4500.0M)->48.5M(4500.0M)]
[Times: user=0.26 sys=0.08, real=0.06 secs]
Copyright©2015 NTT corp. All Rights Reserved. 47
ログと大まかな処理の流れ
[Parallel Time: 38.6 ms, GC Workers: 10]
[<ラベル>: Min:<最小>, Avg:<平均>, Max:<最大>,
Diff:<最大-最少>, Sum:<全 Worker の合計値>]
Worker
数
この様な形式で各ラベルごとに
並列処理に懸った時間が出力されます
[GC pause (G1 Evacuation Pause) (young), 0.0650323 secs]
[Parallel Time: 38.6 ms, GC Workers: 10]
[GC Worker Start (ms): Min: 27181.9, Avg: 27182.2, Max: 27184.0, Diff: 2.1]
[Ext Root Scanning (ms): Min: 0.0, Avg: 0.9, Max: 1.9, Diff: 1.9, Sum: 8.8]
[Update RS (ms): Min: 0.0, Avg: 0.1, Max: 0.5, Diff: 0.5, Sum: 1.1]
[Processed Buffers: Min: 0, Avg: 0.8, Max: 3, Diff: 3, Sum: 8]
[Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.3]
[Code Root Scanning (ms): Min: 0.5, Avg: 1.0, Max: 1.8, Diff: 1.2, Sum: 9.7]
[Object Copy (ms): Min: 15.2, Avg: 16.6, Max: 17.4, Diff: 2.3, Sum: 166.0]
[Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 2.4]
[Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.3]
[GC Worker Total (ms): Min: 17.0, Avg: 18.9, Max: 19.1, Diff: 2.1, Sum: 188.6]
[GC Worker End (ms): Min: 27201.0, Avg: 27201.0, Max: 27201.0, Diff: 0.0]
[Code Root Fixup: 1.0 ms]
[Code Root Purge: 0.1 ms]
[Clear CT: 1.4 ms]
[Other: 23.9 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 21.4 ms]
[Ref Enq: 0.2 ms]
[Redirty Cards: 1.2 ms]
[Humongous Register: 0.0 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.4 ms]
[Eden: 224.0M(224.0M)->0.0B(196.0M) Survivors: 0.0B->28.0M Heap: 228.9M(4500.0M)->48.5M(4500.0M)]
[Times: user=0.26 sys=0.08, real=0.06 secs]
Copyright©2015 NTT corp. All Rights Reserved. 48
ログと大まかな処理の流れ
[Parallel Time: X ms, GC Workers: Y]
[<ラベル>: Min:<最小>, Avg:<平均>, Max:<最大>,
Diff:<最大-最少>, Sum:<全 Worker の合計値>]
Worker
数
GC Worker処理のラベルとその内容はこちら
[GC Worker Start]:開始タイムスタンプ (VM起動時間)
[Ext Root Scanning]:Heapの Root Region のスキャン
[Update RS],[Scan RS]:RS(Remember Set, 新規オブジェ
クトが配置されたリージョンのコレクション)のスキャン
[Code Root Scanning]:Code Cache のスキャン
[Object Copy]:Evacuation、退避処理
[Termination]:他スレッド処理を steal して処理した時間
[GC Worker Other]:処理時間に計上されない内部処理
[GC Worker Total]:Start から End までの時間
[GC Worker End]:終了タイムスタンプ (VM起動時間)
[GC pause (G1 Evacuation Pause) (young), 0.0650323 secs]
[Parallel Time: 38.6 ms, GC Workers: 10]
[GC Worker Start (ms): Min: 27181.9, Avg: 27182.2, Max: 27184.0, Diff: 2.1]
[Ext Root Scanning (ms): Min: 0.0, Avg: 0.9, Max: 1.9, Diff: 1.9, Sum: 8.8]
[Update RS (ms): Min: 0.0, Avg: 0.1, Max: 0.5, Diff: 0.5, Sum: 1.1]
[Processed Buffers: Min: 0, Avg: 0.8, Max: 3, Diff: 3, Sum: 8]
[Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.3]
[Code Root Scanning (ms): Min: 0.5, Avg: 1.0, Max: 1.8, Diff: 1.2, Sum: 9.7]
[Object Copy (ms): Min: 15.2, Avg: 16.6, Max: 17.4, Diff: 2.3, Sum: 166.0]
[Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 2.4]
[Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.3]
[GC Worker Total (ms): Min: 17.0, Avg: 18.9, Max: 19.1, Diff: 2.1, Sum: 188.6]
[GC Worker End (ms): Min: 27201.0, Avg: 27201.0, Max: 27201.0, Diff: 0.0]
[Code Root Fixup: 1.0 ms]
[Code Root Purge: 0.1 ms]
[Clear CT: 1.4 ms]
[Other: 23.9 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 21.4 ms]
[Ref Enq: 0.2 ms]
[Redirty Cards: 1.2 ms]
[Humongous Register: 0.0 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.4 ms]
[Eden: 224.0M(224.0M)->0.0B(196.0M) Survivors: 0.0B->28.0M Heap: 228.9M(4500.0M)->48.5M(4500.0M)]
[Times: user=0.26 sys=0.08, real=0.06 secs]
Copyright©2015 NTT corp. All Rights Reserved. 49
ログと大まかな処理の流れ
オブジェクト情報を保持する構造の掃除など
[Code Root Fixup: X ms]
[Code Root Purge: X ms]
[Clear CT: X ms]
Copyright©2015 NTT corp. All Rights Reserved. 50
ログと大まかな処理の流れ[GC pause (G1 Evacuation Pause) (young), 0.0650323 secs]
[Parallel Time: 38.6 ms, GC Workers: 10]
[GC Worker Start (ms): Min: 27181.9, Avg: 27182.2, Max: 27184.0, Diff: 2.1]
[Ext Root Scanning (ms): Min: 0.0, Avg: 0.9, Max: 1.9, Diff: 1.9, Sum: 8.8]
[Update RS (ms): Min: 0.0, Avg: 0.1, Max: 0.5, Diff: 0.5, Sum: 1.1]
[Processed Buffers: Min: 0, Avg: 0.8, Max: 3, Diff: 3, Sum: 8]
[Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.3]
[Code Root Scanning (ms): Min: 0.5, Avg: 1.0, Max: 1.8, Diff: 1.2, Sum: 9.7]
[Object Copy (ms): Min: 15.2, Avg: 16.6, Max: 17.4, Diff: 2.3, Sum: 166.0]
[Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 2.4]
[Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.3]
[GC Worker Total (ms): Min: 17.0, Avg: 18.9, Max: 19.1, Diff: 2.1, Sum: 188.6]
[GC Worker End (ms): Min: 27201.0, Avg: 27201.0, Max: 27201.0, Diff: 0.0]
[Code Root Fixup: 1.0 ms]
[Code Root Purge: 0.1 ms]
[Clear CT: 1.4 ms]
[Other: 23.9 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 21.4 ms]
[Ref Enq: 0.2 ms]
[Redirty Cards: 1.2 ms]
[Humongous Register: 0.0 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.4 ms]
[Eden: 224.0M(224.0M)->0.0B(196.0M) Survivors: 0.0B->28.0M Heap: 228.9M(4500.0M)->48.5M(4500.0M)]
[Times: user=0.26 sys=0.08, real=0.06 secs]
[Other: 23.9 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 21.4 ms]
[Ref Enq: 0.2 ms]
[Redirty Cards: 1.2 ms]
[Humongous Register: 0.0 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.4 ms]
それ以外の処理
GC対象Regionセット収集
強参照以外の処理と収集
Dirty Card の再処理
Humongousの
処理と解放
GC対象Regionセットの解放
Copyright©2015 NTT corp. All Rights Reserved. 51
Young GC 後
O
S
S
S O
O H
Young GC 編おしまい
水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
Copyright©2015 NTT corp. All Rights Reserved. 52
複数回の Young GC 後
O
S
O
O
O O
S
S
Heap の使用率が閾値を超えると
Marking Cycle が発生
O
O
O
O
O
O
E
E
E
E
H
O
水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
Copyright©2015 NTT corp. All Rights Reserved. 53
Marking Cycle
O
O S
O
O
O O
S
S
Heap の使用率が閾値を超えると
Marking Cycle が発生
O
O
O
O
O
O
E
E
E
E
HYoung GC or Humongous 配置後のヒープ
使用率がデフォルトで 45% 超えると発生
-XX:InitiatingHeapOccupancyPercent で設定可
水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
Copyright©2015 NTT corp. All Rights Reserved. 54
Marking Cycle ログ
[GC pause (<GCCause>) (young) (initial-mark), 0.00554820 secs]
:(Young GC のログ)
[GC concurrent-root-region-scan-start]
[GC concurrent-root-region-scan-end, 0.0566056 secs]
[GC concurrent-mark-start]
:(0 以上の Young GC が発生する)
[GC concurrent-mark-end, 1.6776461 secs]
[GC remark [Finalize Marking, 0.0000801 secs]
[GC ref-proc, 0.0000749 secs]
[Unloading, 0.0007663 secs], 0.0010696 secs]
[Times: user=0.00 sys=0.00, real=0.00 secs]
[GC cleanup 16G->14G(32G), 0.0557430 secs]
[Times: user=0.01 sys=0.00, real=0.00 secs]
[GC concurrent-cleanup-start]
[GC concurrent-cleanup-end, 0.0222541 secs]
Marking Cycle のログ全容 (ラベルで判断)
Copyright©2015 NTT corp. All Rights Reserved. 55
Marking Cycle ログ
[GC pause (<GCCause>) (young) (initial-mark), 0.00554820 secs]
:(Young GC のログ)
[GC concurrent-root-region-scan-start]
[GC concurrent-root-region-scan-end, 0.0566056 secs]
[GC concurrent-mark-start]
:(0 以上の Young GC が発生する)
[GC concurrent-mark-end, 1.6776461 secs]
[GC remark [Finalize Marking, 0.0000801 secs]
[GC ref-proc, 0.0000749 secs]
[Unloading, 0.0007663 secs], 0.0010696 secs]
[Times: user=0.00 sys=0.00, real=0.00 secs]
[GC cleanup 16G->14G(32G), 0.0557430 secs]
[Times: user=0.01 sys=0.00, real=0.00 secs]
[GC concurrent-cleanup-start]
[GC concurrent-cleanup-end, 0.0222541 secs]
マーキングサイクルの開始
Copyright©2015 NTT corp. All Rights Reserved. 56
Marking Cycle ログ
[GC pause (<GCCause>) (young) (initial-mark), 0.00554820 secs]
:(Young GC のログ)
[GC concurrent-root-region-scan-start]
[GC concurrent-root-region-scan-end, 0.0566056 secs]
[GC concurrent-mark-start]
:(0 以上の Young GC が発生する)
[GC concurrent-mark-end, 1.6776461 secs]
[GC remark [Finalize Marking, 0.0000801 secs]
[GC ref-proc, 0.0000749 secs]
[Unloading, 0.0007663 secs], 0.0010696 secs]
[Times: user=0.00 sys=0.00, real=0.00 secs]
[GC cleanup 16G->14G(32G), 0.0557430 secs]
[Times: user=0.01 sys=0.00, real=0.00 secs]
[GC concurrent-cleanup-start]
[GC concurrent-cleanup-end, 0.0222541 secs]
Root Region を決定 (initial-mark)
Copyright©2015 NTT corp. All Rights Reserved. 57
Marking Cycle ログ
[GC pause (<GCCause>) (young) (initial-mark), 0.00554820 secs]
:(Young GC のログ)
[GC concurrent-root-region-scan-start]
[GC concurrent-root-region-scan-end, 0.0566056 secs]
[GC concurrent-mark-start]
:(0 以上の Young GC が発生する)
[GC concurrent-mark-end, 1.6776461 secs]
[GC remark [Finalize Marking, 0.0000801 secs]
[GC ref-proc, 0.0000749 secs]
[Unloading, 0.0007663 secs], 0.0010696 secs]
[Times: user=0.00 sys=0.00, real=0.00 secs]
[GC cleanup 16G->14G(32G), 0.0557430 secs]
[Times: user=0.01 sys=0.00, real=0.00 secs]
[GC concurrent-cleanup-start]
[GC concurrent-cleanup-end, 0.0222541 secs]
Root Region をスキャン
(concurrent-root-region-scan)
Copyright©2015 NTT corp. All Rights Reserved. 58
Marking Cycle ログ
[GC pause (<GCCause>) (young) (initial-mark), 0.00554820 secs]
:(Young GC のログ)
[GC concurrent-root-region-scan-start]
[GC concurrent-root-region-scan-end, 0.0566056 secs]
[GC concurrent-mark-start]
:(0 以上の Young GC が発生する)
[GC concurrent-mark-end, 1.6776461 secs]
[GC remark [Finalize Marking, 0.0000801 secs]
[GC ref-proc, 0.0000749 secs]
[Unloading, 0.0007663 secs], 0.0010696 secs]
[Times: user=0.00 sys=0.00, real=0.00 secs]
[GC cleanup 16G->14G(32G), 0.0557430 secs]
[Times: user=0.01 sys=0.00, real=0.00 secs]
[GC concurrent-cleanup-start]
[GC concurrent-cleanup-end, 0.0222541 secs]
参照を辿ってマーク (concurrent-mark)
Copyright©2015 NTT corp. All Rights Reserved. 59
Marking Cycle ログ
[GC pause (<GCCause>) (young) (initial-mark), 0.00554820 secs]
:(Young GC のログ)
[GC concurrent-root-region-scan-start]
[GC concurrent-root-region-scan-end, 0.0566056 secs]
[GC concurrent-mark-start]
:(0 以上の Young GC が発生する)
[GC concurrent-mark-end, 1.6776461 secs]
[GC remark [Finalize Marking, 0.0000801 secs]
[GC ref-proc, 0.0000749 secs]
[Unloading, 0.0007663 secs], 0.0010696 secs]
[Times: user=0.00 sys=0.00, real=0.00 secs]
[GC cleanup 16G->14G(32G), 0.0557430 secs]
[Times: user=0.01 sys=0.00, real=0.00 secs]
[GC concurrent-cleanup-start]
[GC concurrent-cleanup-end, 0.0222541 secs]
漏れを防ぐために全スレッド止めて再マーク
Copyright©2015 NTT corp. All Rights Reserved. 60
Marking Cycle ログ
[GC pause (<GCCause>) (young) (initial-mark), 0.00554820 secs]
:(Young GC のログ)
[GC concurrent-root-region-scan-start]
[GC concurrent-root-region-scan-end, 0.0566056 secs]
[GC concurrent-mark-start]
:(0 以上の Young GC のログがここに入るケースが多い)
[GC concurrent-mark-end, 1.6776461 secs]
[GC remark [Finalize Marking, 0.0000801 secs]
[GC ref-proc, 0.0000749 secs]
[Unloading, 0.0007663 secs], 0.0010696 secs]
[Times: user=0.00 sys=0.00, real=0.00 secs]
[GC cleanup 16G->14G(32G), 0.0557430 secs]
[Times: user=0.01 sys=0.00, real=0.00 secs]
[GC concurrent-cleanup-start]
[GC concurrent-cleanup-end, 0.0222541 secs]
漏れを防ぐために全スレッド止めて再マーク
Finalize Marking: 強参照の再マーク
GC ref-proc: 強参照「以外」のマーク
Unloading: クラスアンロード処理
Copyright©2015 NTT corp. All Rights Reserved. 61
Marking Cycle ログ
[GC pause (<GCCause>) (young) (initial-mark), 0.00554820 secs]
:(Young GC のログ)
[GC concurrent-root-region-scan-start]
[GC concurrent-root-region-scan-end, 0.0566056 secs]
[GC concurrent-mark-start]
:(0 以上の Young GC が発生する)
[GC concurrent-mark-end, 1.6776461 secs]
[GC remark [Finalize Marking, 0.0000801 secs]
[GC ref-proc, 0.0000749 secs]
[Unloading, 0.0007663 secs], 0.0010696 secs]
[Times: user=0.00 sys=0.00, real=0.00 secs]
[GC cleanup 16G->14G(32G), 0.0557430 secs]
[Times: user=0.01 sys=0.00, real=0.00 secs]
[GC concurrent-cleanup-start]
[GC concurrent-cleanup-end, 0.0222541 secs]
生存オブジェクトのない Region 回収など
Copyright©2015 NTT corp. All Rights Reserved. 62
Marking Cycle ログ
[GC pause (<GCCause>) (young) (initial-mark), 0.00554820 secs]
:(Young GC のログ) → 最後に [Times:… real=X.XX secs]
[GC concurrent-root-region-scan-start]
[GC concurrent-root-region-scan-end, 0.0566056 secs]
[GC concurrent-mark-start]
:(0 以上の Young GC が発生する)
[GC concurrent-mark-end, 1.6776461 secs]
[GC remark [Finalize Marking, 0.0000801 secs]
[GC ref-proc, 0.0000749 secs]
[Unloading, 0.0007663 secs], 0.0010696 secs]
[Times: user=0.00 sys=0.00, real=0.00 secs]
[GC cleanup 16G->14G(32G), 0.0557430 secs]
[Times: user=0.01 sys=0.00, real=0.00 secs]
[GC concurrent-cleanup-start]
[GC concurrent-cleanup-end, 0.0222541 secs]
Concurrent ではない処理は STW が発生する
Copyright©2015 NTT corp. All Rights Reserved. 63
Marking Cycle 後
参照追跡を完了し、各 Region ごとの生存オ
ブジェクト情報を得て Mixed GC を起動
O
O S
O
O
O O
S
S
O
O
O
O
O
O
E
E
E
E
H
水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
Copyright©2015 NTT corp. All Rights Reserved. 64
Mixed GC
O
O S
O
O
O O
S
S
O
O
O
O
O
O
E
E
E
E
H
アルゴリズム(とログ)は Young GC と一緒
[GC pause (G1 Evacuation Pause) (mixed), 0.0640122 secs]
GC発生原因(GC Cause) ここが mixed になるだけ
水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
Copyright©2015 NTT corp. All Rights Reserved. 65
Mixed GC と Young GC の違い
O
O S
O
O
O O
S
S
O
O
O
O
O
O
E
E
E
E
H
JDK-8059452 でデフォルト値が変更
ゴミが多い Region を対象に GC する
・全ての Eden, Survivor と、生存オブジェクトが閾値
(デフォルト 85%) を下回る Old Region が GC 対象。
-XX:G1MixedGCLiveThresholdPercent で設定可能
条件達成まで複数回起動する
・回収可能な Old Regionの不要オブジェクトが、ヒー
プ全体の閾値(デフォルト 5%)以下になるまで繰り返
す。-XX:G1HeapWastePercent で設定可能
水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
Copyright©2015 NTT corp. All Rights Reserved. 66
Mixed GC
O
O S
O
O
O O
S
S
O
O
O
O
O
O
E
E
E
E
H
全ての Eden, Survivor から新たな Survivor、
選択された Old から新たな Old へ退避する
水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
Copyright©2015 NTT corp. All Rights Reserved. 67
Mixed GC
全ての Eden, Survivor から新たな Survivor、
選択された Old から新たな Old へ退避する
O
O S
O
O
O O
S
S
O
O
O
O
O
O
E
E
E
E
H
O
水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
Copyright©2015 NTT corp. All Rights Reserved. 68
Mixed GC
全ての Eden, Survivor から新たな Survivor、
選択された Old から新たな Old へ退避する
O
O
S
O S
S
S
O
O
O O
S
S
O
O
O
O
O
O
E
E
E
E
H
O
水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
Copyright©2015 NTT corp. All Rights Reserved. 69
Mixed GC 後
O S
O
S
S
O
O
O O
O
O
O
O
O
O
H
退避元 Eden, Survivor, Old の Region を回収
条件達成してなければ次の Mixed GC へ
水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
Copyright©2015 NTT corp. All Rights Reserved. 70
Mixed GC 停止後
S
S
O
O
O
S
O
O
O
O
O
O
H
最終的にゴミが多かった Old Region が
全て回収されて Mixed GC が停止する
水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
まとめ
Copyright©2015 NTT corp. All Rights Reserved. 71
• Young GC と Mixed GC
–アルゴリズム(とログ)は一緒
–大きな違いは GC 対象の Region
–Regionごとの退避と解放の繰り返し
• Marking Cycle
–対象 Region を決めるのに必要な処
理を一部コンカレントに行っている
ログもインデントのおかげで慣れると楽です
注意すべき
パターン
汎用的なチューニング指南
Copyright©2015 NTT corp. All Rights Reserved. 72
Copyright©2015 NTT corp. All Rights Reserved. 73
Evacuation Failure
E
S
E S E
S
E
O
O
S
H
O
退避 (Evacuation) 先の Survivor or Old に
退避させるスペースがなく失敗したパターン
Full GC が起動する場合もある
水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
Copyright©2015 NTT corp. All Rights Reserved. 74
Evacuation Failure
E
S
E S E
S
E
O
O
S
H
O
ログには (to-space exhausted) と出ます
水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用[GC pause (G1 Evacuation Pause) (mixed)
(to-space exhausted), 0.0083907 secs]
[Parallel Time: 11.7 ms, GC Workers: 10]
:
Copyright©2015 NTT corp. All Rights Reserved. 75
Evacuation Failure
E
S
E S E
S
E
O
O
S
H
O
Full GC が起動した場合でも同じです
水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用[GC pause (G1 Evacuation Pause) (mixed)
(to-space exhausted), 0.0083907 secs]
[Parallel Time: 11.7 ms, GC Workers: 10]
:
[GC pause (G1 Evacuation Pause) (young) (initial-mark)
(to-space exhausted), 0.0045139 secs]
:
[GC concurrent-mark-start]
[Full GC (Allocation Failure) 4429M->113M(4500M), 0.7380897 secs]
[Eden: 0.0B(224.0M)->0.0B(2004.0M)
Survivors: 0.0B->0.0B
Heap: 4429.1M(4500.0M)->113.1M(4500.0M)],
[Metaspace: 12003K->12003K(1060864K)]
[Times: user=0.78 sys=0.00, real=0.73 secs]
[GC concurrent-mark-abort]
:
水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
Copyright©2015 NTT corp. All Rights Reserved. 76
Evacuation Failure
E
S
E S E
S
E
O
O
S
H
O
[GC pause (G1 Evacuation Pause) (mixed)
(to-space exhausted), 0.0083907 secs]
[Parallel Time: 11.7 ms, GC Workers: 10]
:
[GC pause (G1 Evacuation Pause) (young) (initial-mark)
(to-space exhausted), 0.0045139 secs]
:
[GC concurrent-mark-start]
[Full GC (Allocation Failure) 4429M->113M(4500M), 0.7380897 secs]
[Eden: 0.0B(224.0M)->0.0B(2004.0M)
Survivors: 0.0B->0.0B
Heap: 4429.1M(4500.0M)->113.1M(4500.0M)],
[Metaspace: 12003K->12003K(1060864K)]
[Times: user=0.78 sys=0.00, real=0.73 secs]
[GC concurrent-mark-abort]
:
実 STW 時間
Full GC のログもこれまでと同じ形式です
各空間の
GC前後の
使用量(容量)
GC Cause
水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
Copyright©2015 NTT corp. All Rights Reserved. 77
Evacuation Failure
E
S
E S E
S
E
O
O
S
H
O
[GC pause (G1 Evacuation Pause) (mixed)
(to-space exhausted), 0.0083907 secs]
[Parallel Time: 11.7 ms, GC Workers: 10]
:
[GC pause (G1 Evacuation Pause) (young) (initial-mark)
(to-space exhausted), 0.0045139 secs]
:
[GC concurrent-mark-start]
[Full GC (Allocation Failure) 4429M->113M(4500M), 0.7380897 secs]
[Eden: 0.0B(224.0M)->0.0B(2004.0M)
Survivors: 0.0B->0.0B
Heap: 4429.1M(4500.0M)->113.1M(4500.0M)],
[Metaspace: 12003K->12003K(1060864K)]
[Times: user=0.78 sys=0.00, real=0.73 secs]
[GC concurrent-mark-abort]
:
実 STW 時間
各空間の
GC前後の
使用量(容量)
GC Cause対策案
1. Heap を増やす (Region の個数を増やす)
2. -XX:InitiatingHeapOccupancyPercent を
下げてサイクル頻度を上げる
3. -Xms, -Xmx, -XX:MaxGCPauseMillis 以外を
削除し、over-tuning を回避する
Region 管理の改善が代表的な対策です
Copyright©2015 NTT corp. All Rights Reserved. 78
Humongous Allocation 頻発
E
S
H
H
E S E
H
S
H
E
O
O
S
H
O
H
Humongous Object が大量に生成され、
GC 頻発や処理に時間が懸かるパターン
水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
Copyright©2015 NTT corp. All Rights Reserved. 79
Humongous Allocation 頻発
E
S
H
H
E S E
H
S
H
E
O
O
S
H
O
H
[GC pause (G1 Humongous Allocation) (mixed), 0.4331340 secs]
:
[Other: 0.7 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.2 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.2 ms]
[Humongous Register: 260.1 ms]
[Humongous Reclaim: 480.7 ms]
[Free CSet: 0.1 ms]
:
GC Cause が G1 Humongous Allocation の
GC Pause や、Humongous 関連処理の
処理時間から確認します
水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
Copyright©2015 NTT corp. All Rights Reserved. 80
Humongous Allocation 頻発
E
S
H
H
E S E
H
S
H
E
O
O
S
H
O
H
[GC pause (G1 Humongous Allocation) (mixed), 0.4331340 secs]
:
[Other: 0.7 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.2 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.2 ms]
[Humongous Register: 260.1 ms]
[Humongous Reclaim: 480.7 ms]
[Free CSet: 0.1 ms]
:
対策案
1. -XX:G1HeapRegionSize で Region サイズ
を Heap と一緒に増やす。Heap を増やさ
ない場合は Region 数が減り Evacuation
Failure の可能性が増すので注意
2. 巨大なオブジェクトを極力生成しない
(長大な配列、文字列、フィールド数が極
端にクラスなど)
Humongous を減らすのが抜本対策
水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
Copyright©2015 NTT corp. All Rights Reserved. 81
CPU 処理時間が長い
Java プロセス以外にも疑うべき範囲が
広がりますが、GC 処理時間が長いパターン
[GC pause (G1 Evacuation Pause) (mixed), 0.8332274 secs]
:
[Ref Proc: 103.4 ms]
:
[Times: user=1.25 sys=0.60, real=0.83 secs]
Copyright©2015 NTT corp. All Rights Reserved. 82
CPU 処理時間が長い
[GC pause (G1 Evacuation Pause) (mixed), 0.8332274 secs]
:
[Ref Proc: 103.4 ms]
:
[Times: user=1.25 sys=0.60, real=0.83 secs]
対策案
1. 物理 CPU コアが余裕なら -XX:ConcGCThreads を増や
して並列度を上げる。逆にコア数が少ない、メモリが
小さい場合は、従来GCを検討する
2. Reference Processing([Ref Proc]) の時間が長い場合は、
-XX:+ParallelRefProcEnabled を指定して並列処理する。
WeakReference や SoftReference の抑制も検討する
3. -XX:InitiatingHeapOccupancyPercent を上げてサイク
ル頻度を下げる (副作用もあるので注意)
特にケースバイケースなパターンなので注意
まとめ
Copyright©2015 NTT corp. All Rights Reserved. 83
• Evacuation Failure
–ヒープを増やそう
• Humongous Allocation
–ヒープを増やそう
• CPU 処理時間が長い
–CPUを増やそう(NUMA環境は注意)
ジョークですが G1 が生まれた経緯はこれ
おわりに
Copyright©2015 NTT corp. All Rights Reserved. 84
• 自分のアプリケーションがどの
ようにメモリを使っているかは
意識しましょう
• まずは動かして性能を測定して
みてください
• GC に任せるのはそれから
現場に神宿る
References
Copyright©2015 NTT corp. All Rights Reserved. 85
• Detlefs, D., Flood, C., Heller, S., and
Printezis, T. “Garbage-first garbage
collection” (ISMM 2004)
• http://hg.openjdk.java.net/jdk8u/
• jdk8u-dev/hotspot (7664:831754f092fb)
• Getting Started with G1 Garbage
Collector (Oracle Documents)
HeapStats チームや同僚達の支えに感謝
End
おつかれさまでした
Copyright©2015 NTT corp. All Rights Reserved. 86

More Related Content

Garbage First Garbage Collection (G1 GC) #jjug_ccc #ccc_cd6

  • 1. Garbage First GC KUBOTA Yuji @sugarlife NTT OSSセンタ Copyright©2015 NTT corp. All Rights Reserved. 2015/11/28 JJUG CCC 2015 Fall #ccc_cd6
  • 3. はじめに • 本セッションでは Garbage First GC (G1 GC) について、ログから 動作状況を把握できる、主に開 発者・運用者向けの知識の土台 作りを目標としています 体系的な知識の土台作りが目標 Copyright©2015 NTT corp. All Rights Reserved. 3
  • 4. おやくそく • 本セッション (スライド) における 表現は全て個人の見解です • 以下の JVM 実装に基づきます –HotSpot VM (OpenJDK 8) –repo jdk8u/jdk8u-dev/hotspot •changeset 7664:831754f092fb(zip) 動作確認は jdk8u66 でやりました Copyright©2015 NTT corp. All Rights Reserved. 4
  • 5. KUBOTA Yuji @sugarlife • OpenJDK テクニカルサポート –コア解析からGCチューニング, etc… • 解析支援ツール HeapStats 開発 –多数の商用で元気に稼働中 :) • 難聴者 –資料的なスライドを多用します 過去にCMS GC, Jigsaw, HeapStats を発表 Copyright©2015 NTT corp. All Rights Reserved. 5
  • 6. NTT OSSセンタ • NTT グループの OSS 活用を支える部隊 *)OSSVERT®:OSs Suites VERified Technically(技術検証済みOSS組合せ) 事業会社 SI会社 問合せ対応、導 入支援、保守等 技術検証、 導入推進 プロダクト/ ツール類開発 技術者育成、 人材交流 各種 OSS コ ミュニ ティ 設計, 開 発, 運用 グループ各社 サポー トベン ダ、 NTT 研究所 等お 客 様 サポー ト連携 開発 連携 ①OSSトータル サポート NTT OSSセンタ ②OSS適用推進 (OSSVERT®*検証) ③技術開発 (DBMS,高可用ミドル等) ④ソフトウェア 基盤技術力向上 Kernel, PostgreSQL, Pacemaker, Tomcat, etc Copyright©2015 NTT corp. All Rights Reserved. 6
  • 7. OpenJDK Contributes Copyright©2015 NTT corp. All Rights Reserved. 7 暗号化 zip 操作 API を提案中! 興味ある人は是非MLへ!
  • 8. G1 GC 概要 なぜ Garbage First なのか? Copyright©2015 NTT corp. All Rights Reserved. 8
  • 9. Garbage Collection 1. 不要なメモリ領域(ゴミ)を判別し、 2. ゴミを処理して再利用可能にする 面倒なメモリ管理は JVM に任せたい Copyright©2015 NTT corp. All Rights Reserved. 9
  • 10. HotSpot VM の GC • Serial GC, Parallel GC –初期GC, JDK8 以前はデフォルト • Concurrent Mark-Sweep GC –JDK1.4.1 から導入 (出典:JDK-4758307) • Garbage First GC –JDK7 から導入, JDK9からデフォルト 細かく言えば他にもあるけど主流はこれら Copyright©2015 NTT corp. All Rights Reserved. 10
  • 11. Parallel と Concurrent ケースバイケースで GC を選択しましょう Copyright©2015 NTT corp. All Rights Reserved. 11 Parallel (Serial = Threadが1つ) Concurrent (実際は部分的に 停止するMostly) Application Thread GC Thread アプリケーション停止=Stop The World (STW)
  • 13. Heap (ヒープ) Copyright©2015 NTT corp. All Rights Reserved. 13 Heap オブジェクトが配置される Heap を巨大な 一つのデータ構造として扱うのは非効率
  • 14. ヒープ管理 (従来) Copyright©2015 NTT corp. All Rights Reserved. 14 Eden Old Survivor 0 Survivor 1 というわけで、Java (JVM)は世代別に分けて それぞれ異なる GC で管理しています Young
  • 15. ヒープ管理 (従来) Copyright©2015 NTT corp. All Rights Reserved. 15 Eden Old Survivor 0 Survivor 1 ヒープが巨大化すると結局非効率になります そこで G1 はヒープ構造を変更しました Young
  • 16. Heap Layout (G1) Copyright©2015 NTT corp. All Rights Reserved. 16 G1 では Region と呼ばれる空間に ヒープを等しく分割して管理してます
  • 17. Heap Layout (G1) Copyright©2015 NTT corp. All Rights Reserved. 17 Region のサイズは初期ヒープサイズに 依存しますが -XX:G1HeapRegionSize で 1~32MBの範囲で変更が可能です
  • 18. Heap Layout (G1) Copyright©2015 NTT corp. All Rights Reserved. 18 Region のサイズは初期ヒープサイズに 依存しますが -XX:G1HeapRegionSize で 1~32MBの範囲で変更が可能です Regionサイズの半分以上の単体オブジェクトは 「Humongous Object」として扱われます
  • 19. 世代分け Copyright©2015 NTT corp. All Rights Reserved. 19 E O S O O S S E O E O O E S O O O O O E E O 水:Eden 橙:Survivor 緑:Old 藍:未使用 G1 GC も他 GC と同じく世代別 GC です Young (Eden, Survivor) 対象の Young GC Young + Old (Tenure) 対象の Mixed GC そして G1 GC が失敗した時の Full GC
  • 20. Humongous Object Copyright©2015 NTT corp. All Rights Reserved. 20 E O S O O S S E H O E O O E S O O O O H O E E O Humongous Object が生成された場合は 専用の Region にアロケートされます 水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
  • 21. Humongous Object Copyright©2015 NTT corp. All Rights Reserved. 21 E O S O O S S E H O E O O E S O O O O H O E E O Humongous Object が生成された場合は 専用の Region にアロケートされます アロケート時に GC 発生の可能性がある上、 メモリ獲得コストも高いので極力生成は避ける 水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
  • 22. Garbage First の所以 Copyright©2015 NTT corp. All Rights Reserved. 22 E O S O O S S E O E O O E S O O O O O E E O H H1. 各Regionの不要オブジェクト量は異なる 水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
  • 23. Garbage First の所以 Copyright©2015 NTT corp. All Rights Reserved. 23 E O S O O S S E O E O O E S O O O O O E E O H H1. 各Regionの不要オブジェクト量は異なる 2. GC による回収はコスト(STW)が発生する 水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
  • 24. Garbage First の所以 Copyright©2015 NTT corp. All Rights Reserved. 24 E O S O O S S E O E O O E S O O O O O E E O H H1. 各Regionの不要オブジェクト量は異なる 2. GC による回収はコスト(STW)が発生する 不要オブジェクト(ゴミ)が多いRegionだけ GC して処理時間を(できるだけ)抑える=G1 水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
  • 25. Garbage First の所以 Copyright©2015 NTT corp. All Rights Reserved. 25 E O S O O S S E T E O O T E S T O O O O E E O H H1. 各Regionの不要オブジェクト量は異なる 2. GC による回収はコスト(STW)が発生する 不要オブジェクト(ゴミ)が多いRegionだけ GC して処理時間を(できるだけ)抑える=G1 アプリケーションを止めないコンカレント サイクルでマーキングを実施する 水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
  • 26. Garbage First の所以 Copyright©2015 NTT corp. All Rights Reserved. 26 E O S O O S S E T E O O T E S T O O O O E E O H H1. 各Regionの不要オブジェクト量は異なる 2. GC による回収はコスト(STW)が発生する 不要オブジェクト(ゴミ)が多いRegionだけ GC して処理時間を(できるだけ)抑える=G1 アプリケーションを止めないコンカレント サイクルでマーキングを実施する -XX:MaxGCPauseMillis で指定した値を 目安に前向きに善処 (デフォルト 200ms) 水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
  • 27. まとめ Copyright©2015 NTT corp. All Rights Reserved. 27 • ヒープレイアウト –従来と同じく世代別に領域を分ける。 ただし、巨大ヒープを効率的に処理 するため、Region に細分化 • G1 処理 –マーキングはコンカレントサイクル –Young GC と Mixed GC の世代別GC –失敗した場合は Full GC が発生する ゴミの多い場所を優先してやるから G1 GC
  • 29. Copyright©2015 NTT corp. All Rights Reserved. 29 以降のログ出力に利用したオプションです G1 使用時の推奨値とは別なのに注意 ログについて 使用した Java 起動オプション -XX:+UseG1GC -XX:+PrintGCDetails -XX:+PrintGCCause -XX:+PrintGCDateStamps 見やすいようにタイムスタンプを除 外し、一部省略や改行をしています 水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
  • 30. Copyright©2015 NTT corp. All Rights Reserved. 30 オブジェクトの生成 E E 生成オブジェクトは Eden に配置され、 Eden が一杯になると Young GC が発生 O O S H 水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
  • 31. Copyright©2015 NTT corp. All Rights Reserved. 31 オブジェクトの生成 E E 生成オブジェクトは Eden に配置され、 Eden が一杯になると Young GC が発生 O O E S H 水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
  • 32. Copyright©2015 NTT corp. All Rights Reserved. 32 オブジェクトの生成 E E 生成オブジェクトは Eden に配置され、 Eden が一杯になると Young GC が発生 O O E E S H 水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
  • 33. Copyright©2015 NTT corp. All Rights Reserved. 33 Young GC E E Young GC が発生した際はこの形式の ログが出力。GC Causeは複数種類あります O O E E S H [GC pause (G1 Evacuation Pause) (young), 0.0650323 secs] GC発生原因(GC Cause) young/mixed 識別箇所 水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
  • 34. Copyright©2015 NTT corp. All Rights Reserved. 34 Young GC E E E E O O S 全 Eden / Survivor をスキャンし、生存オブ ジェクトを新Survivorに退避 (Evacuation) H 水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
  • 35. Copyright©2015 NTT corp. All Rights Reserved. 35 Young GC E S E S E S E O O S 全 Eden / Survivor をスキャンし、生存オブ ジェクトを新Survivorに退避 (Evacuation) H 水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
  • 36. Copyright©2015 NTT corp. All Rights Reserved. 36 Young GC E S E S E S E O O S H Survivor の一部のオブジェクトは (年齢的に) Old に退避する場合もあります 水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
  • 37. Copyright©2015 NTT corp. All Rights Reserved. 37 Young GC E S E S O E S E O O S H Survivor の一部のオブジェクトは (年齢的に) Old に退避する場合もあります 水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
  • 38. Copyright©2015 NTT corp. All Rights Reserved. 38 Young GC (Survivor Full) E S E S E S E O O S H もし退避先の Survivor に生存オブジェクト を退避させるスペースがなかった場合は、 Eden から直接 Old 領域に退避することも 水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
  • 39. Copyright©2015 NTT corp. All Rights Reserved. 39 Young GC (Survivor Full) E S E S E S E O O S H もし退避先の Survivor に生存オブジェクト を退避させるスペースがなかった場合は、 Eden から直接 Old 領域に退避することも 水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
  • 40. Copyright©2015 NTT corp. All Rights Reserved. 40 Young GC (Survivor Full) E S E S E S E O O S H もし退避先の Survivor に生存オブジェクト を退避させるスペースがなかった場合は、 Eden から直接 Old 領域に退避することも O 水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
  • 41. Copyright©2015 NTT corp. All Rights Reserved. 41 Young GC 後 O Eden / Survivor元 (from) に割り当てていた Region を解放して不要オブジェクトを回収 S S S O O H 水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
  • 42. Copyright©2015 NTT corp. All Rights Reserved. 42 ログと大まかな処理の流れ[GC pause (G1 Evacuation Pause) (young), 0.0650323 secs] [Parallel Time: 38.6 ms, GC Workers: 10] [GC Worker Start (ms): Min: 27181.9, Avg: 27182.2, Max: 27184.0, Diff: 2.1] [Ext Root Scanning (ms): Min: 0.0, Avg: 0.9, Max: 1.9, Diff: 1.9, Sum: 8.8] [Update RS (ms): Min: 0.0, Avg: 0.1, Max: 0.5, Diff: 0.5, Sum: 1.1] [Processed Buffers: Min: 0, Avg: 0.8, Max: 3, Diff: 3, Sum: 8] [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.3] [Code Root Scanning (ms): Min: 0.5, Avg: 1.0, Max: 1.8, Diff: 1.2, Sum: 9.7] [Object Copy (ms): Min: 15.2, Avg: 16.6, Max: 17.4, Diff: 2.3, Sum: 166.0] [Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 2.4] [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4] [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.3] [GC Worker Total (ms): Min: 17.0, Avg: 18.9, Max: 19.1, Diff: 2.1, Sum: 188.6] [GC Worker End (ms): Min: 27201.0, Avg: 27201.0, Max: 27201.0, Diff: 0.0] [Code Root Fixup: 1.0 ms] [Code Root Purge: 0.1 ms] [Clear CT: 1.4 ms] [Other: 23.9 ms] [Choose CSet: 0.0 ms] [Ref Proc: 21.4 ms] [Ref Enq: 0.2 ms] [Redirty Cards: 1.2 ms] [Humongous Register: 0.0 ms] [Humongous Reclaim: 0.0 ms] [Free CSet: 0.4 ms] [Eden: 224.0M(224.0M)->0.0B(196.0M) Survivors: 0.0B->28.0M Heap: 228.9M(4500.0M)->48.5M(4500.0M)] [Times: user=0.26 sys=0.08, real=0.06 secs] 一連のログを全部表示すると、このように インデントでグルーピングされています
  • 43. [GC pause (G1 Evacuation Pause) (young), 0.0650323 secs] [Parallel Time: 38.6 ms, GC Workers: 10] [GC Worker Start (ms): Min: 27181.9, Avg: 27182.2, Max: 27184.0, Diff: 2.1] [Ext Root Scanning (ms): Min: 0.0, Avg: 0.9, Max: 1.9, Diff: 1.9, Sum: 8.8] [Update RS (ms): Min: 0.0, Avg: 0.1, Max: 0.5, Diff: 0.5, Sum: 1.1] [Processed Buffers: Min: 0, Avg: 0.8, Max: 3, Diff: 3, Sum: 8] [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.3] [Code Root Scanning (ms): Min: 0.5, Avg: 1.0, Max: 1.8, Diff: 1.2, Sum: 9.7] [Object Copy (ms): Min: 15.2, Avg: 16.6, Max: 17.4, Diff: 2.3, Sum: 166.0] [Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 2.4] [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4] [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.3] [GC Worker Total (ms): Min: 17.0, Avg: 18.9, Max: 19.1, Diff: 2.1, Sum: 188.6] [GC Worker End (ms): Min: 27201.0, Avg: 27201.0, Max: 27201.0, Diff: 0.0] [Code Root Fixup: 1.0 ms] [Code Root Purge: 0.1 ms] [Clear CT: 1.4 ms] [Other: 23.9 ms] [Choose CSet: 0.0 ms] [Ref Proc: 21.4 ms] [Ref Enq: 0.2 ms] [Redirty Cards: 1.2 ms] [Humongous Register: 0.0 ms] [Humongous Reclaim: 0.0 ms] [Free CSet: 0.4 ms] [Eden: 224.0M(224.0M)->0.0B(196.0M) Survivors: 0.0B->28.0M Heap: 228.9M(4500.0M)->48.5M(4500.0M)] [Times: user=0.26 sys=0.08, real=0.06 secs] Copyright©2015 NTT corp. All Rights Reserved. 43 ログと大まかな処理の流れ 特に重要なのは先頭と末尾
  • 44. [GC pause (G1 Evacuation Pause) (young), 0.0650323 secs] [Parallel Time: 38.6 ms, GC Workers: 10] [GC Worker Start (ms): Min: 27181.9, Avg: 27182.2, Max: 27184.0, Diff: 2.1] [Ext Root Scanning (ms): Min: 0.0, Avg: 0.9, Max: 1.9, Diff: 1.9, Sum: 8.8] [Update RS (ms): Min: 0.0, Avg: 0.1, Max: 0.5, Diff: 0.5, Sum: 1.1] [Processed Buffers: Min: 0, Avg: 0.8, Max: 3, Diff: 3, Sum: 8] [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.3] [Code Root Scanning (ms): Min: 0.5, Avg: 1.0, Max: 1.8, Diff: 1.2, Sum: 9.7] [Object Copy (ms): Min: 15.2, Avg: 16.6, Max: 17.4, Diff: 2.3, Sum: 166.0] [Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 2.4] [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4] [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.3] [GC Worker Total (ms): Min: 17.0, Avg: 18.9, Max: 19.1, Diff: 2.1, Sum: 188.6] [GC Worker End (ms): Min: 27201.0, Avg: 27201.0, Max: 27201.0, Diff: 0.0] [Code Root Fixup: 1.0 ms] [Code Root Purge: 0.1 ms] [Clear CT: 1.4 ms] [Other: 23.9 ms] [Choose CSet: 0.0 ms] [Ref Proc: 21.4 ms] [Ref Enq: 0.2 ms] [Redirty Cards: 1.2 ms] [Humongous Register: 0.0 ms] [Humongous Reclaim: 0.0 ms] [Free CSet: 0.4 ms] [Eden: 224.0M(224.0M)->0.0B(196.0M) Survivors: 0.0B->28.0M Heap: 228.9M(4500.0M)->48.5M(4500.0M)] [Times: user=0.26 sys=0.08, real=0.06 secs] Copyright©2015 NTT corp. All Rights Reserved. 44 ログと大まかな処理の流れ [GC pause (<GCCause>) (young), 0.0650323 secs] : : [Eden: 224.0M(224.0M)->0.0B(196.0M) Survivors: 0.0B->28.0M Heap: 228.9M(4500.0M)->48.5M(4500.0M)] [Times: user=0.26 sys=0.08, real=0.06 secs] 各領域のサイズと停止(STW)時間が解ります Young GC 確認
  • 45. [GC pause (G1 Evacuation Pause) (young), 0.0650323 secs] [Parallel Time: 38.6 ms, GC Workers: 10] [GC Worker Start (ms): Min: 27181.9, Avg: 27182.2, Max: 27184.0, Diff: 2.1] [Ext Root Scanning (ms): Min: 0.0, Avg: 0.9, Max: 1.9, Diff: 1.9, Sum: 8.8] [Update RS (ms): Min: 0.0, Avg: 0.1, Max: 0.5, Diff: 0.5, Sum: 1.1] [Processed Buffers: Min: 0, Avg: 0.8, Max: 3, Diff: 3, Sum: 8] [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.3] [Code Root Scanning (ms): Min: 0.5, Avg: 1.0, Max: 1.8, Diff: 1.2, Sum: 9.7] [Object Copy (ms): Min: 15.2, Avg: 16.6, Max: 17.4, Diff: 2.3, Sum: 166.0] [Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 2.4] [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4] [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.3] [GC Worker Total (ms): Min: 17.0, Avg: 18.9, Max: 19.1, Diff: 2.1, Sum: 188.6] [GC Worker End (ms): Min: 27201.0, Avg: 27201.0, Max: 27201.0, Diff: 0.0] [Code Root Fixup: 1.0 ms] [Code Root Purge: 0.1 ms] [Clear CT: 1.4 ms] [Other: 23.9 ms] [Choose CSet: 0.0 ms] [Ref Proc: 21.4 ms] [Ref Enq: 0.2 ms] [Redirty Cards: 1.2 ms] [Humongous Register: 0.0 ms] [Humongous Reclaim: 0.0 ms] [Free CSet: 0.4 ms] [Eden: 224.0M(224.0M)->0.0B(196.0M) Survivors: 0.0B->28.0M Heap: 228.9M(4500.0M)->48.5M(4500.0M)] [Times: user=0.26 sys=0.08, real=0.06 secs] Copyright©2015 NTT corp. All Rights Reserved. 45 ログと大まかな処理の流れ [GC pause (<GCCause>) (young), 0.0650323 secs] : : [Eden: 224.0M(224.0M)->0.0B(196.0M) Survivors: 0.0B->28.0M Heap: 228.9M(4500.0M)->48.5M(4500.0M)] [Times: user=0.26 sys=0.08, real=0.06 secs] GC前 使用量(容量) -> GC後 使用量(容量) 実 STW 時間 各領域のサイズと停止(STW)時間が解ります Young GC 確認
  • 46. Copyright©2015 NTT corp. All Rights Reserved. 46 ログと大まかな処理の流れ[GC pause (G1 Evacuation Pause) (young), 0.0650323 secs] [Parallel Time: 38.6 ms, GC Workers: 10] [GC Worker Start (ms): Min: 27181.9, Avg: 27182.2, Max: 27184.0, Diff: 2.1] [Ext Root Scanning (ms): Min: 0.0, Avg: 0.9, Max: 1.9, Diff: 1.9, Sum: 8.8] [Update RS (ms): Min: 0.0, Avg: 0.1, Max: 0.5, Diff: 0.5, Sum: 1.1] [Processed Buffers: Min: 0, Avg: 0.8, Max: 3, Diff: 3, Sum: 8] [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.3] [Code Root Scanning (ms): Min: 0.5, Avg: 1.0, Max: 1.8, Diff: 1.2, Sum: 9.7] [Object Copy (ms): Min: 15.2, Avg: 16.6, Max: 17.4, Diff: 2.3, Sum: 166.0] [Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 2.4] [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4] [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.3] [GC Worker Total (ms): Min: 17.0, Avg: 18.9, Max: 19.1, Diff: 2.1, Sum: 188.6] [GC Worker End (ms): Min: 27201.0, Avg: 27201.0, Max: 27201.0, Diff: 0.0] [Code Root Fixup: 1.0 ms] [Code Root Purge: 0.1 ms] [Clear CT: 1.4 ms] [Other: 23.9 ms] [Choose CSet: 0.0 ms] [Ref Proc: 21.4 ms] [Ref Enq: 0.2 ms] [Redirty Cards: 1.2 ms] [Humongous Register: 0.0 ms] [Humongous Reclaim: 0.0 ms] [Free CSet: 0.4 ms] [Eden: 224.0M(224.0M)->0.0B(196.0M) Survivors: 0.0B->28.0M Heap: 228.9M(4500.0M)->48.5M(4500.0M)] [Times: user=0.26 sys=0.08, real=0.06 secs] このグループは GC Worker による生存オブ ジェクトのスキャンと退避処理のログです
  • 47. [GC pause (G1 Evacuation Pause) (young), 0.0650323 secs] [Parallel Time: 38.6 ms, GC Workers: 10] [GC Worker Start (ms): Min: 27181.9, Avg: 27182.2, Max: 27184.0, Diff: 2.1] [Ext Root Scanning (ms): Min: 0.0, Avg: 0.9, Max: 1.9, Diff: 1.9, Sum: 8.8] [Update RS (ms): Min: 0.0, Avg: 0.1, Max: 0.5, Diff: 0.5, Sum: 1.1] [Processed Buffers: Min: 0, Avg: 0.8, Max: 3, Diff: 3, Sum: 8] [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.3] [Code Root Scanning (ms): Min: 0.5, Avg: 1.0, Max: 1.8, Diff: 1.2, Sum: 9.7] [Object Copy (ms): Min: 15.2, Avg: 16.6, Max: 17.4, Diff: 2.3, Sum: 166.0] [Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 2.4] [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4] [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.3] [GC Worker Total (ms): Min: 17.0, Avg: 18.9, Max: 19.1, Diff: 2.1, Sum: 188.6] [GC Worker End (ms): Min: 27201.0, Avg: 27201.0, Max: 27201.0, Diff: 0.0] [Code Root Fixup: 1.0 ms] [Code Root Purge: 0.1 ms] [Clear CT: 1.4 ms] [Other: 23.9 ms] [Choose CSet: 0.0 ms] [Ref Proc: 21.4 ms] [Ref Enq: 0.2 ms] [Redirty Cards: 1.2 ms] [Humongous Register: 0.0 ms] [Humongous Reclaim: 0.0 ms] [Free CSet: 0.4 ms] [Eden: 224.0M(224.0M)->0.0B(196.0M) Survivors: 0.0B->28.0M Heap: 228.9M(4500.0M)->48.5M(4500.0M)] [Times: user=0.26 sys=0.08, real=0.06 secs] Copyright©2015 NTT corp. All Rights Reserved. 47 ログと大まかな処理の流れ [Parallel Time: 38.6 ms, GC Workers: 10] [<ラベル>: Min:<最小>, Avg:<平均>, Max:<最大>, Diff:<最大-最少>, Sum:<全 Worker の合計値>] Worker 数 この様な形式で各ラベルごとに 並列処理に懸った時間が出力されます
  • 48. [GC pause (G1 Evacuation Pause) (young), 0.0650323 secs] [Parallel Time: 38.6 ms, GC Workers: 10] [GC Worker Start (ms): Min: 27181.9, Avg: 27182.2, Max: 27184.0, Diff: 2.1] [Ext Root Scanning (ms): Min: 0.0, Avg: 0.9, Max: 1.9, Diff: 1.9, Sum: 8.8] [Update RS (ms): Min: 0.0, Avg: 0.1, Max: 0.5, Diff: 0.5, Sum: 1.1] [Processed Buffers: Min: 0, Avg: 0.8, Max: 3, Diff: 3, Sum: 8] [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.3] [Code Root Scanning (ms): Min: 0.5, Avg: 1.0, Max: 1.8, Diff: 1.2, Sum: 9.7] [Object Copy (ms): Min: 15.2, Avg: 16.6, Max: 17.4, Diff: 2.3, Sum: 166.0] [Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 2.4] [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4] [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.3] [GC Worker Total (ms): Min: 17.0, Avg: 18.9, Max: 19.1, Diff: 2.1, Sum: 188.6] [GC Worker End (ms): Min: 27201.0, Avg: 27201.0, Max: 27201.0, Diff: 0.0] [Code Root Fixup: 1.0 ms] [Code Root Purge: 0.1 ms] [Clear CT: 1.4 ms] [Other: 23.9 ms] [Choose CSet: 0.0 ms] [Ref Proc: 21.4 ms] [Ref Enq: 0.2 ms] [Redirty Cards: 1.2 ms] [Humongous Register: 0.0 ms] [Humongous Reclaim: 0.0 ms] [Free CSet: 0.4 ms] [Eden: 224.0M(224.0M)->0.0B(196.0M) Survivors: 0.0B->28.0M Heap: 228.9M(4500.0M)->48.5M(4500.0M)] [Times: user=0.26 sys=0.08, real=0.06 secs] Copyright©2015 NTT corp. All Rights Reserved. 48 ログと大まかな処理の流れ [Parallel Time: X ms, GC Workers: Y] [<ラベル>: Min:<最小>, Avg:<平均>, Max:<最大>, Diff:<最大-最少>, Sum:<全 Worker の合計値>] Worker 数 GC Worker処理のラベルとその内容はこちら [GC Worker Start]:開始タイムスタンプ (VM起動時間) [Ext Root Scanning]:Heapの Root Region のスキャン [Update RS],[Scan RS]:RS(Remember Set, 新規オブジェ クトが配置されたリージョンのコレクション)のスキャン [Code Root Scanning]:Code Cache のスキャン [Object Copy]:Evacuation、退避処理 [Termination]:他スレッド処理を steal して処理した時間 [GC Worker Other]:処理時間に計上されない内部処理 [GC Worker Total]:Start から End までの時間 [GC Worker End]:終了タイムスタンプ (VM起動時間)
  • 49. [GC pause (G1 Evacuation Pause) (young), 0.0650323 secs] [Parallel Time: 38.6 ms, GC Workers: 10] [GC Worker Start (ms): Min: 27181.9, Avg: 27182.2, Max: 27184.0, Diff: 2.1] [Ext Root Scanning (ms): Min: 0.0, Avg: 0.9, Max: 1.9, Diff: 1.9, Sum: 8.8] [Update RS (ms): Min: 0.0, Avg: 0.1, Max: 0.5, Diff: 0.5, Sum: 1.1] [Processed Buffers: Min: 0, Avg: 0.8, Max: 3, Diff: 3, Sum: 8] [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.3] [Code Root Scanning (ms): Min: 0.5, Avg: 1.0, Max: 1.8, Diff: 1.2, Sum: 9.7] [Object Copy (ms): Min: 15.2, Avg: 16.6, Max: 17.4, Diff: 2.3, Sum: 166.0] [Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 2.4] [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4] [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.3] [GC Worker Total (ms): Min: 17.0, Avg: 18.9, Max: 19.1, Diff: 2.1, Sum: 188.6] [GC Worker End (ms): Min: 27201.0, Avg: 27201.0, Max: 27201.0, Diff: 0.0] [Code Root Fixup: 1.0 ms] [Code Root Purge: 0.1 ms] [Clear CT: 1.4 ms] [Other: 23.9 ms] [Choose CSet: 0.0 ms] [Ref Proc: 21.4 ms] [Ref Enq: 0.2 ms] [Redirty Cards: 1.2 ms] [Humongous Register: 0.0 ms] [Humongous Reclaim: 0.0 ms] [Free CSet: 0.4 ms] [Eden: 224.0M(224.0M)->0.0B(196.0M) Survivors: 0.0B->28.0M Heap: 228.9M(4500.0M)->48.5M(4500.0M)] [Times: user=0.26 sys=0.08, real=0.06 secs] Copyright©2015 NTT corp. All Rights Reserved. 49 ログと大まかな処理の流れ オブジェクト情報を保持する構造の掃除など [Code Root Fixup: X ms] [Code Root Purge: X ms] [Clear CT: X ms]
  • 50. Copyright©2015 NTT corp. All Rights Reserved. 50 ログと大まかな処理の流れ[GC pause (G1 Evacuation Pause) (young), 0.0650323 secs] [Parallel Time: 38.6 ms, GC Workers: 10] [GC Worker Start (ms): Min: 27181.9, Avg: 27182.2, Max: 27184.0, Diff: 2.1] [Ext Root Scanning (ms): Min: 0.0, Avg: 0.9, Max: 1.9, Diff: 1.9, Sum: 8.8] [Update RS (ms): Min: 0.0, Avg: 0.1, Max: 0.5, Diff: 0.5, Sum: 1.1] [Processed Buffers: Min: 0, Avg: 0.8, Max: 3, Diff: 3, Sum: 8] [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.3] [Code Root Scanning (ms): Min: 0.5, Avg: 1.0, Max: 1.8, Diff: 1.2, Sum: 9.7] [Object Copy (ms): Min: 15.2, Avg: 16.6, Max: 17.4, Diff: 2.3, Sum: 166.0] [Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 2.4] [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4] [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.3] [GC Worker Total (ms): Min: 17.0, Avg: 18.9, Max: 19.1, Diff: 2.1, Sum: 188.6] [GC Worker End (ms): Min: 27201.0, Avg: 27201.0, Max: 27201.0, Diff: 0.0] [Code Root Fixup: 1.0 ms] [Code Root Purge: 0.1 ms] [Clear CT: 1.4 ms] [Other: 23.9 ms] [Choose CSet: 0.0 ms] [Ref Proc: 21.4 ms] [Ref Enq: 0.2 ms] [Redirty Cards: 1.2 ms] [Humongous Register: 0.0 ms] [Humongous Reclaim: 0.0 ms] [Free CSet: 0.4 ms] [Eden: 224.0M(224.0M)->0.0B(196.0M) Survivors: 0.0B->28.0M Heap: 228.9M(4500.0M)->48.5M(4500.0M)] [Times: user=0.26 sys=0.08, real=0.06 secs] [Other: 23.9 ms] [Choose CSet: 0.0 ms] [Ref Proc: 21.4 ms] [Ref Enq: 0.2 ms] [Redirty Cards: 1.2 ms] [Humongous Register: 0.0 ms] [Humongous Reclaim: 0.0 ms] [Free CSet: 0.4 ms] それ以外の処理 GC対象Regionセット収集 強参照以外の処理と収集 Dirty Card の再処理 Humongousの 処理と解放 GC対象Regionセットの解放
  • 51. Copyright©2015 NTT corp. All Rights Reserved. 51 Young GC 後 O S S S O O H Young GC 編おしまい 水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
  • 52. Copyright©2015 NTT corp. All Rights Reserved. 52 複数回の Young GC 後 O S O O O O S S Heap の使用率が閾値を超えると Marking Cycle が発生 O O O O O O E E E E H O 水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
  • 53. Copyright©2015 NTT corp. All Rights Reserved. 53 Marking Cycle O O S O O O O S S Heap の使用率が閾値を超えると Marking Cycle が発生 O O O O O O E E E E HYoung GC or Humongous 配置後のヒープ 使用率がデフォルトで 45% 超えると発生 -XX:InitiatingHeapOccupancyPercent で設定可 水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
  • 54. Copyright©2015 NTT corp. All Rights Reserved. 54 Marking Cycle ログ [GC pause (<GCCause>) (young) (initial-mark), 0.00554820 secs] :(Young GC のログ) [GC concurrent-root-region-scan-start] [GC concurrent-root-region-scan-end, 0.0566056 secs] [GC concurrent-mark-start] :(0 以上の Young GC が発生する) [GC concurrent-mark-end, 1.6776461 secs] [GC remark [Finalize Marking, 0.0000801 secs] [GC ref-proc, 0.0000749 secs] [Unloading, 0.0007663 secs], 0.0010696 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] [GC cleanup 16G->14G(32G), 0.0557430 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] [GC concurrent-cleanup-start] [GC concurrent-cleanup-end, 0.0222541 secs] Marking Cycle のログ全容 (ラベルで判断)
  • 55. Copyright©2015 NTT corp. All Rights Reserved. 55 Marking Cycle ログ [GC pause (<GCCause>) (young) (initial-mark), 0.00554820 secs] :(Young GC のログ) [GC concurrent-root-region-scan-start] [GC concurrent-root-region-scan-end, 0.0566056 secs] [GC concurrent-mark-start] :(0 以上の Young GC が発生する) [GC concurrent-mark-end, 1.6776461 secs] [GC remark [Finalize Marking, 0.0000801 secs] [GC ref-proc, 0.0000749 secs] [Unloading, 0.0007663 secs], 0.0010696 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] [GC cleanup 16G->14G(32G), 0.0557430 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] [GC concurrent-cleanup-start] [GC concurrent-cleanup-end, 0.0222541 secs] マーキングサイクルの開始
  • 56. Copyright©2015 NTT corp. All Rights Reserved. 56 Marking Cycle ログ [GC pause (<GCCause>) (young) (initial-mark), 0.00554820 secs] :(Young GC のログ) [GC concurrent-root-region-scan-start] [GC concurrent-root-region-scan-end, 0.0566056 secs] [GC concurrent-mark-start] :(0 以上の Young GC が発生する) [GC concurrent-mark-end, 1.6776461 secs] [GC remark [Finalize Marking, 0.0000801 secs] [GC ref-proc, 0.0000749 secs] [Unloading, 0.0007663 secs], 0.0010696 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] [GC cleanup 16G->14G(32G), 0.0557430 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] [GC concurrent-cleanup-start] [GC concurrent-cleanup-end, 0.0222541 secs] Root Region を決定 (initial-mark)
  • 57. Copyright©2015 NTT corp. All Rights Reserved. 57 Marking Cycle ログ [GC pause (<GCCause>) (young) (initial-mark), 0.00554820 secs] :(Young GC のログ) [GC concurrent-root-region-scan-start] [GC concurrent-root-region-scan-end, 0.0566056 secs] [GC concurrent-mark-start] :(0 以上の Young GC が発生する) [GC concurrent-mark-end, 1.6776461 secs] [GC remark [Finalize Marking, 0.0000801 secs] [GC ref-proc, 0.0000749 secs] [Unloading, 0.0007663 secs], 0.0010696 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] [GC cleanup 16G->14G(32G), 0.0557430 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] [GC concurrent-cleanup-start] [GC concurrent-cleanup-end, 0.0222541 secs] Root Region をスキャン (concurrent-root-region-scan)
  • 58. Copyright©2015 NTT corp. All Rights Reserved. 58 Marking Cycle ログ [GC pause (<GCCause>) (young) (initial-mark), 0.00554820 secs] :(Young GC のログ) [GC concurrent-root-region-scan-start] [GC concurrent-root-region-scan-end, 0.0566056 secs] [GC concurrent-mark-start] :(0 以上の Young GC が発生する) [GC concurrent-mark-end, 1.6776461 secs] [GC remark [Finalize Marking, 0.0000801 secs] [GC ref-proc, 0.0000749 secs] [Unloading, 0.0007663 secs], 0.0010696 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] [GC cleanup 16G->14G(32G), 0.0557430 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] [GC concurrent-cleanup-start] [GC concurrent-cleanup-end, 0.0222541 secs] 参照を辿ってマーク (concurrent-mark)
  • 59. Copyright©2015 NTT corp. All Rights Reserved. 59 Marking Cycle ログ [GC pause (<GCCause>) (young) (initial-mark), 0.00554820 secs] :(Young GC のログ) [GC concurrent-root-region-scan-start] [GC concurrent-root-region-scan-end, 0.0566056 secs] [GC concurrent-mark-start] :(0 以上の Young GC が発生する) [GC concurrent-mark-end, 1.6776461 secs] [GC remark [Finalize Marking, 0.0000801 secs] [GC ref-proc, 0.0000749 secs] [Unloading, 0.0007663 secs], 0.0010696 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] [GC cleanup 16G->14G(32G), 0.0557430 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] [GC concurrent-cleanup-start] [GC concurrent-cleanup-end, 0.0222541 secs] 漏れを防ぐために全スレッド止めて再マーク
  • 60. Copyright©2015 NTT corp. All Rights Reserved. 60 Marking Cycle ログ [GC pause (<GCCause>) (young) (initial-mark), 0.00554820 secs] :(Young GC のログ) [GC concurrent-root-region-scan-start] [GC concurrent-root-region-scan-end, 0.0566056 secs] [GC concurrent-mark-start] :(0 以上の Young GC のログがここに入るケースが多い) [GC concurrent-mark-end, 1.6776461 secs] [GC remark [Finalize Marking, 0.0000801 secs] [GC ref-proc, 0.0000749 secs] [Unloading, 0.0007663 secs], 0.0010696 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] [GC cleanup 16G->14G(32G), 0.0557430 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] [GC concurrent-cleanup-start] [GC concurrent-cleanup-end, 0.0222541 secs] 漏れを防ぐために全スレッド止めて再マーク Finalize Marking: 強参照の再マーク GC ref-proc: 強参照「以外」のマーク Unloading: クラスアンロード処理
  • 61. Copyright©2015 NTT corp. All Rights Reserved. 61 Marking Cycle ログ [GC pause (<GCCause>) (young) (initial-mark), 0.00554820 secs] :(Young GC のログ) [GC concurrent-root-region-scan-start] [GC concurrent-root-region-scan-end, 0.0566056 secs] [GC concurrent-mark-start] :(0 以上の Young GC が発生する) [GC concurrent-mark-end, 1.6776461 secs] [GC remark [Finalize Marking, 0.0000801 secs] [GC ref-proc, 0.0000749 secs] [Unloading, 0.0007663 secs], 0.0010696 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] [GC cleanup 16G->14G(32G), 0.0557430 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] [GC concurrent-cleanup-start] [GC concurrent-cleanup-end, 0.0222541 secs] 生存オブジェクトのない Region 回収など
  • 62. Copyright©2015 NTT corp. All Rights Reserved. 62 Marking Cycle ログ [GC pause (<GCCause>) (young) (initial-mark), 0.00554820 secs] :(Young GC のログ) → 最後に [Times:… real=X.XX secs] [GC concurrent-root-region-scan-start] [GC concurrent-root-region-scan-end, 0.0566056 secs] [GC concurrent-mark-start] :(0 以上の Young GC が発生する) [GC concurrent-mark-end, 1.6776461 secs] [GC remark [Finalize Marking, 0.0000801 secs] [GC ref-proc, 0.0000749 secs] [Unloading, 0.0007663 secs], 0.0010696 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] [GC cleanup 16G->14G(32G), 0.0557430 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] [GC concurrent-cleanup-start] [GC concurrent-cleanup-end, 0.0222541 secs] Concurrent ではない処理は STW が発生する
  • 63. Copyright©2015 NTT corp. All Rights Reserved. 63 Marking Cycle 後 参照追跡を完了し、各 Region ごとの生存オ ブジェクト情報を得て Mixed GC を起動 O O S O O O O S S O O O O O O E E E E H 水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
  • 64. Copyright©2015 NTT corp. All Rights Reserved. 64 Mixed GC O O S O O O O S S O O O O O O E E E E H アルゴリズム(とログ)は Young GC と一緒 [GC pause (G1 Evacuation Pause) (mixed), 0.0640122 secs] GC発生原因(GC Cause) ここが mixed になるだけ 水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
  • 65. Copyright©2015 NTT corp. All Rights Reserved. 65 Mixed GC と Young GC の違い O O S O O O O S S O O O O O O E E E E H JDK-8059452 でデフォルト値が変更 ゴミが多い Region を対象に GC する ・全ての Eden, Survivor と、生存オブジェクトが閾値 (デフォルト 85%) を下回る Old Region が GC 対象。 -XX:G1MixedGCLiveThresholdPercent で設定可能 条件達成まで複数回起動する ・回収可能な Old Regionの不要オブジェクトが、ヒー プ全体の閾値(デフォルト 5%)以下になるまで繰り返 す。-XX:G1HeapWastePercent で設定可能 水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
  • 66. Copyright©2015 NTT corp. All Rights Reserved. 66 Mixed GC O O S O O O O S S O O O O O O E E E E H 全ての Eden, Survivor から新たな Survivor、 選択された Old から新たな Old へ退避する 水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
  • 67. Copyright©2015 NTT corp. All Rights Reserved. 67 Mixed GC 全ての Eden, Survivor から新たな Survivor、 選択された Old から新たな Old へ退避する O O S O O O O S S O O O O O O E E E E H O 水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
  • 68. Copyright©2015 NTT corp. All Rights Reserved. 68 Mixed GC 全ての Eden, Survivor から新たな Survivor、 選択された Old から新たな Old へ退避する O O S O S S S O O O O S S O O O O O O E E E E H O 水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
  • 69. Copyright©2015 NTT corp. All Rights Reserved. 69 Mixed GC 後 O S O S S O O O O O O O O O O H 退避元 Eden, Survivor, Old の Region を回収 条件達成してなければ次の Mixed GC へ 水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
  • 70. Copyright©2015 NTT corp. All Rights Reserved. 70 Mixed GC 停止後 S S O O O S O O O O O O H 最終的にゴミが多かった Old Region が 全て回収されて Mixed GC が停止する 水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
  • 71. まとめ Copyright©2015 NTT corp. All Rights Reserved. 71 • Young GC と Mixed GC –アルゴリズム(とログ)は一緒 –大きな違いは GC 対象の Region –Regionごとの退避と解放の繰り返し • Marking Cycle –対象 Region を決めるのに必要な処 理を一部コンカレントに行っている ログもインデントのおかげで慣れると楽です
  • 73. Copyright©2015 NTT corp. All Rights Reserved. 73 Evacuation Failure E S E S E S E O O S H O 退避 (Evacuation) 先の Survivor or Old に 退避させるスペースがなく失敗したパターン Full GC が起動する場合もある 水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
  • 74. Copyright©2015 NTT corp. All Rights Reserved. 74 Evacuation Failure E S E S E S E O O S H O ログには (to-space exhausted) と出ます 水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用[GC pause (G1 Evacuation Pause) (mixed) (to-space exhausted), 0.0083907 secs] [Parallel Time: 11.7 ms, GC Workers: 10] :
  • 75. Copyright©2015 NTT corp. All Rights Reserved. 75 Evacuation Failure E S E S E S E O O S H O Full GC が起動した場合でも同じです 水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用[GC pause (G1 Evacuation Pause) (mixed) (to-space exhausted), 0.0083907 secs] [Parallel Time: 11.7 ms, GC Workers: 10] : [GC pause (G1 Evacuation Pause) (young) (initial-mark) (to-space exhausted), 0.0045139 secs] : [GC concurrent-mark-start] [Full GC (Allocation Failure) 4429M->113M(4500M), 0.7380897 secs] [Eden: 0.0B(224.0M)->0.0B(2004.0M) Survivors: 0.0B->0.0B Heap: 4429.1M(4500.0M)->113.1M(4500.0M)], [Metaspace: 12003K->12003K(1060864K)] [Times: user=0.78 sys=0.00, real=0.73 secs] [GC concurrent-mark-abort] :
  • 76. 水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用 Copyright©2015 NTT corp. All Rights Reserved. 76 Evacuation Failure E S E S E S E O O S H O [GC pause (G1 Evacuation Pause) (mixed) (to-space exhausted), 0.0083907 secs] [Parallel Time: 11.7 ms, GC Workers: 10] : [GC pause (G1 Evacuation Pause) (young) (initial-mark) (to-space exhausted), 0.0045139 secs] : [GC concurrent-mark-start] [Full GC (Allocation Failure) 4429M->113M(4500M), 0.7380897 secs] [Eden: 0.0B(224.0M)->0.0B(2004.0M) Survivors: 0.0B->0.0B Heap: 4429.1M(4500.0M)->113.1M(4500.0M)], [Metaspace: 12003K->12003K(1060864K)] [Times: user=0.78 sys=0.00, real=0.73 secs] [GC concurrent-mark-abort] : 実 STW 時間 Full GC のログもこれまでと同じ形式です 各空間の GC前後の 使用量(容量) GC Cause
  • 77. 水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用 Copyright©2015 NTT corp. All Rights Reserved. 77 Evacuation Failure E S E S E S E O O S H O [GC pause (G1 Evacuation Pause) (mixed) (to-space exhausted), 0.0083907 secs] [Parallel Time: 11.7 ms, GC Workers: 10] : [GC pause (G1 Evacuation Pause) (young) (initial-mark) (to-space exhausted), 0.0045139 secs] : [GC concurrent-mark-start] [Full GC (Allocation Failure) 4429M->113M(4500M), 0.7380897 secs] [Eden: 0.0B(224.0M)->0.0B(2004.0M) Survivors: 0.0B->0.0B Heap: 4429.1M(4500.0M)->113.1M(4500.0M)], [Metaspace: 12003K->12003K(1060864K)] [Times: user=0.78 sys=0.00, real=0.73 secs] [GC concurrent-mark-abort] : 実 STW 時間 各空間の GC前後の 使用量(容量) GC Cause対策案 1. Heap を増やす (Region の個数を増やす) 2. -XX:InitiatingHeapOccupancyPercent を 下げてサイクル頻度を上げる 3. -Xms, -Xmx, -XX:MaxGCPauseMillis 以外を 削除し、over-tuning を回避する Region 管理の改善が代表的な対策です
  • 78. Copyright©2015 NTT corp. All Rights Reserved. 78 Humongous Allocation 頻発 E S H H E S E H S H E O O S H O H Humongous Object が大量に生成され、 GC 頻発や処理に時間が懸かるパターン 水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
  • 79. Copyright©2015 NTT corp. All Rights Reserved. 79 Humongous Allocation 頻発 E S H H E S E H S H E O O S H O H [GC pause (G1 Humongous Allocation) (mixed), 0.4331340 secs] : [Other: 0.7 ms] [Choose CSet: 0.0 ms] [Ref Proc: 0.2 ms] [Ref Enq: 0.0 ms] [Redirty Cards: 0.2 ms] [Humongous Register: 260.1 ms] [Humongous Reclaim: 480.7 ms] [Free CSet: 0.1 ms] : GC Cause が G1 Humongous Allocation の GC Pause や、Humongous 関連処理の 処理時間から確認します 水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
  • 80. Copyright©2015 NTT corp. All Rights Reserved. 80 Humongous Allocation 頻発 E S H H E S E H S H E O O S H O H [GC pause (G1 Humongous Allocation) (mixed), 0.4331340 secs] : [Other: 0.7 ms] [Choose CSet: 0.0 ms] [Ref Proc: 0.2 ms] [Ref Enq: 0.0 ms] [Redirty Cards: 0.2 ms] [Humongous Register: 260.1 ms] [Humongous Reclaim: 480.7 ms] [Free CSet: 0.1 ms] : 対策案 1. -XX:G1HeapRegionSize で Region サイズ を Heap と一緒に増やす。Heap を増やさ ない場合は Region 数が減り Evacuation Failure の可能性が増すので注意 2. 巨大なオブジェクトを極力生成しない (長大な配列、文字列、フィールド数が極 端にクラスなど) Humongous を減らすのが抜本対策 水:Eden 橙:Survivor 緑:Old 紫:Humongous 藍:未使用
  • 81. Copyright©2015 NTT corp. All Rights Reserved. 81 CPU 処理時間が長い Java プロセス以外にも疑うべき範囲が 広がりますが、GC 処理時間が長いパターン [GC pause (G1 Evacuation Pause) (mixed), 0.8332274 secs] : [Ref Proc: 103.4 ms] : [Times: user=1.25 sys=0.60, real=0.83 secs]
  • 82. Copyright©2015 NTT corp. All Rights Reserved. 82 CPU 処理時間が長い [GC pause (G1 Evacuation Pause) (mixed), 0.8332274 secs] : [Ref Proc: 103.4 ms] : [Times: user=1.25 sys=0.60, real=0.83 secs] 対策案 1. 物理 CPU コアが余裕なら -XX:ConcGCThreads を増や して並列度を上げる。逆にコア数が少ない、メモリが 小さい場合は、従来GCを検討する 2. Reference Processing([Ref Proc]) の時間が長い場合は、 -XX:+ParallelRefProcEnabled を指定して並列処理する。 WeakReference や SoftReference の抑制も検討する 3. -XX:InitiatingHeapOccupancyPercent を上げてサイク ル頻度を下げる (副作用もあるので注意) 特にケースバイケースなパターンなので注意
  • 83. まとめ Copyright©2015 NTT corp. All Rights Reserved. 83 • Evacuation Failure –ヒープを増やそう • Humongous Allocation –ヒープを増やそう • CPU 処理時間が長い –CPUを増やそう(NUMA環境は注意) ジョークですが G1 が生まれた経緯はこれ
  • 84. おわりに Copyright©2015 NTT corp. All Rights Reserved. 84 • 自分のアプリケーションがどの ようにメモリを使っているかは 意識しましょう • まずは動かして性能を測定して みてください • GC に任せるのはそれから 現場に神宿る
  • 85. References Copyright©2015 NTT corp. All Rights Reserved. 85 • Detlefs, D., Flood, C., Heller, S., and Printezis, T. “Garbage-first garbage collection” (ISMM 2004) • http://hg.openjdk.java.net/jdk8u/ • jdk8u-dev/hotspot (7664:831754f092fb) • Getting Started with G1 Garbage Collector (Oracle Documents) HeapStats チームや同僚達の支えに感謝