SlideShare a Scribd company logo

Concurrent Mark-Sweep Garbage Collection #jjug_ccc

•
•
Yuji Kubota
Yuji Kubota

Re-Introduction: Concurrent Mark-Sweep Garbage Collection @ Japan JUG Conference.

1 of 93
Downloaded 197 times
Concurrent Mark-Sweep Garbage Collection 再入門 KUBOTA Yuji @sugarlife kubota.yuji@gmail.com JJUG CCC 2014 Fall #ccc_r16
はじめに •本セッションでは Concurrent Mark- Sweep GC (CMS GC)について、動作 の概要の復習から GC ログの読み方 を解説し、問題の把握や調査の糸口 として役立てられることを目的とし ています。 2
はじめに •本セッションでは Concurrent Mark- Sweep GC (CMS GC)について、動作 の概要の復習から GC ログの読み方 を解説し、問題の把握や調査の糸口 として役立てられることを目的とし ています。 CMS GC を思い出すためのセッション 3
おやくそく •本セッションにおける表現は全て私 個人の見解です。 •以下の JVM 実装に基づいています •HotSpot VM (OpenJDK 7) •http://hg.openjdk.java.net/jdk7u/jdk7u •changeset 1085:4093bbbc9000 4
KUBOTA Yuji (@sugarlife) •OpenJDK Technical Support Engineer •IcedTea Committer (HeapStats) •JavaOne 2014 Speaker 5
おしながき •CMS GC 概要 •Concurrent Mark-Sweep GC •HotSpot VM の CMS GC •GC ログの読み方 •注意すべきパターン 6
ここで質問 •CMS GC をどの程度知っていますか？ •名前は聞いたことある •GC ログを読んだことがある •チューニングしたことがある •OpenJDKのソースを読んだことがある •HeapStats 知ってる？ 7
CMS GC 概要 CMS GC 概要 Concurrent Mark-Sweep GC HotSpot VM の CMS GC GC ログの読み方 注意すべきパターン 8
Garbage Collection 1. 不要なメモリ領域(ゴミ)を判別し、 2. ゴミを処理して再利用可能にする 9
Concurrent GC •アプリケーションと同時に動く Parallel Concurrent Application Thread GC Thread 10
Concurrent Mark-Sweep GC 1. ゴミじゃない領域を Mark し、 2. Sweep して再利用可能にする ヒープ領域 FreeList ✔ ✔ ✔ ✔ ←再利用時に辿る(コンパクションなし) Thread stack JNI Reference … Root 11
CMS GC 概要 CMS GC 概要 Concurrent Mark-Sweep GC HotSpot VM の CMS GC GC ログの読み方 注意すべきパターン 12
HotSpot VM のメモリ領域(ヒープ) Heap Perm / Meta space 13
ヒープ領域の世代別管理 New Generation Old Generation Perm / Meta spaceMinor GC Major GC 14 Heapは生成されたばかりのオブジェクトを管理するNew世代と、 長命なオブジェクトを管理するOld世代で分割して管理している。
世代別 GC (CMS GC利用時) •Minor GC: Parallel Copy GC •アプリケーションを止める (別名 Stop-The-World, STW) •早い・メモリが断片化しない •Major GC: CMS GC •一部アプリケーションを止める •コンパクションしないので断片化する 15
ヒープ領域の構造 Eden Survivor 1 Survivor 0 Tenured Perm / Meta space 16 New領域 Old領域 各世代の構造
オブジェクト割り当て要求 Eden Survivor 1 Survivor 0 Tenured Perm / Meta space 17 New領域 Old領域 新規オブジェクトは Eden 領域に割り当てられる
Minor GC Eden Survivor 1 Survivor 0 Tenured Perm / Meta space 18 New領域 Old領域
Minor GC 後 Eden Survivor 1 Survivor 0 Tenured Perm / Meta space 19 New領域 Old領域
再びオブジェクト割り当て要求 Eden Survivor 1 Survivor 0 Tenured Perm / Meta space 20 New領域 Old領域
Minor GC + Promotion Eden Survivor 1 Survivor 0 Tenured Perm / Meta space 21 New領域 Old領域 age++
Minor GC + Promotion Eden Survivor 1 Survivor 0 Tenured Perm / Meta space 22 New領域 Old領域 age++ promotion
Minor GC + Promotion Eden Survivor 1 Survivor 0 Tenured Perm / Meta space age++ promotion 23 • 最大で -XX:+MaxTenuringThreshold 以上 Survivor 間を移動 • Eden から Survivor へ移動ができない promotion 条件
Minor GC + Promotion Eden Survivor 1 Survivor 0 Tenured Perm / Meta space age++ promotion 24 • 最大で -XX:+MaxTenuringThreshold 以上 Survivor 間を移動 • Eden から Survivor へ移動ができない promotion 条件 -XX:+AlwaysTenureで Survivor スルー
Minor GC + Promotion 後 Eden Survivor 1 Survivor 0 Tenured Perm / Meta space 25 New領域 Old領域
Several xxx after. Eden Survivor 1 Survivor 0 Tenured Perm / Meta space 26 New領域 Old領域
Major GC (CMS GC) Eden Survivor 1 Survivor 0 Tenured Perm / Meta space 27 GC 対象
Major GC (CMS GC) Eden Survivor 1 Survivor 0 Tenured Perm / Meta space • -XX:CMSInitiatingOccupancyFraction (92%) • その他、ヒープ占有速度の統計判断など 発生条件 28 GC 対象
Major GC (CMS GC) Eden Survivor 1 Survivor 0 Tenured Perm / Meta space • -XX:CMSInitiatingOccupancyFraction (92%) • その他、ヒープ占有速度の統計判断など 発生条件 29 -XX:+UseCMSInitiatingOccupancyOnly を設定するとこの条件のみで判断する GC 対象
Major GC (CMS フェーズ) 1. Initial mark 2. Concurrent mark 3. Concurrent preclean 4. Concurrent abortable preclean 5. Remark (Final mark) 6. Concurrent sweep 7. Concurrent reset Mark Sweep 後始末 30
Major GC (CMS フェーズ) 1. Initial mark 2. Concurrent mark 3. Concurrent preclean 4. Concurrent abortable preclean 5. Remark (Final mark) 6. Concurrent sweep 7. Concurrent reset Mark Sweep 後始末 31 STW STW Concurrent が付いている フェーズはアプリと同時に 動作するが、付いてない フェーズは STW が発生する
Major GC (CMS GC) 後 Eden Survivor 1 Survivor 0 Tenured Perm / Meta space 32 New領域 Old領域
Major GC (CMS GC) 後 Eden Survivor 1 Survivor 0 Tenured Perm / Meta space CMS GC は安定している？ いいえ、失敗して STW を伴う Full GC が発生する場合もあります 33 New領域 Old領域 CMS GC とは別アルゴリズム (Mark-Sweep-Compact, 断片化しない)
Full GC (with STW) Eden Survivor 1 Survivor 0 Tenured Perm / Meta space GC 対象 34
Full GC (with STW) Eden Survivor 1 Survivor 0 Tenured Perm / Meta space GC 対象 35 • 断片化で割り当てられない (promotion failed) • 回収が間に合わない (concurrent mode failure) 発生条件
まとめ •Concurrent Mark-Sweep GC •レスポンスタイム重視なシステム向け •コンパクションがなく断片化が生じる •HotSpot VM の CMS GC •世代別ヒープ管理 •STW を伴う GC やフェーズがある •CMS で回収を失敗すると Full GC 36
GC ログの読み方 CMS GC 概要 Concurrent Mark-Sweep GC HotSpot VM の CMS GC GC ログの読み方 注意すべきパターン 37
Java 起動オプション •CMS GC を使う、 •-XX:+UseConcMarkSweepGC •-XX:+CMSClassUnloadingEnabled (推奨) •ログ (GC, ヒープダンプ) •-Xloggc:gc.log •-XX:+PrintGCDetails •-XX:+PrintGCDateStamps •-XX:+HeapDumpOnOutOfMemoryError GC時にクラスを アンロードする OOME発生時 38 JDK8 からデフォルト true
タイムスタンプ •2014-09-01T12:39:09.293+0900: 617423.912: [GC… •以降の GC ログでは省略する。 39 ‐XX:+PrintGCDateStamps Java process の uptime (second)
Minor GC •617423.912: [GC617423.912: [ParNew: 230016K->4553K(306688K), 0.0159800 secs] 2993210K->2774025K(4160256K), 0.0161510 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 40
Minor GC •617423.912: [GC 617423.912: [ParNew: 230016K->4553K(306688K), 0.0159800 secs] 2993210K->2774025K(4160256K), 0.0161510 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 41 見やすく整形
Minor GC •617423.912: [GC 617423.912: [ParNew: 230016K->4553K(306688K), 0.0159800 secs] 2993210K->2774025K(4160256K), 0.0161510 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 42 GC共通部分 Minor GC time(1)相当 (全体の処理時間は real の値を見るのが良い) 処理時間(STW)
Minor GC (Minor GC) •617423.912: [GC 617423.912: [ParNew: 230016K->4553K(306688K), 0.0159800 secs] 2993210K->2774025K(4160256K), 0.0161510 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 43 Minor GC
Minor GC (Minor GC) •617423.912: [GC 617423.912: [ParNew: 230016K->4553K(306688K), 0.0159800 secs] 2993210K->2774025K(4160256K), 0.0161510 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 44 開始時刻 処理時間 New領域のサイズ GC前 GC後 総容量
Minor GC (GC共通部分) •617423.912: [GC 617423.912: [ParNew: 230016K->4553K(306688K), 0.0159800 secs] 2993210K->2774025K(4160256K), 0.0161510 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 45 GC共通部分
Minor GC (GC共通部分) •617423.912: [GC 617423.912: [ParNew: 230016K->4553K(306688K), 0.0159800 secs] 2993210K->2774025K(4160256K), 0.0161510 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 46 開始時刻 処理時間 GC前 GC後 総容量 ヒープ全体のサイズ
Minor GC (promotion) •617423.912: [GC 617423.912: [ParNew: 230016K->4553K(306688K), 0.0159800 secs] 2993210K->2774025K(4160256K), 0.0161510 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 47 Old領域に移った サイズの求め方
Minor GC (promotion) •617423.912: [GC 617423.912: [ParNew: 230016K->4553K(306688K), 0.0159800 secs] 2993210K->2774025K(4160256K), 0.0161510 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 48 New領域の差分 全体の差分 promoted = (230016-4553) - (2993210-2774025) = 6278K Old領域へ promote Old領域に移った サイズの求め方
CMS GC • 2014-09-01T12:39:09.310+0900: 617423.929: [GC [1 CMS-initial-mark: 2925342K(3853568K)] 2937899K(4160256K), 0.0098890 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] • 2014-09-01T12:39:09.320+0900: 617423.939: [CMS-concurrent-mark-start] • 2014-09-01T12:39:09.772+0900: 617424.391: [CMS-concurrent-mark: 0.454/0.454 secs] [Times: user=1.38 sys=0.00, real=0.45 secs] • 2014-09-01T12:39:09.772+0900: 617424.391: [CMS-concurrent-preclean-start] • 2014-09-01T12:39:09.789+0900: 617424.408: [CMS-concurrent-preclean: 0.016/0.017 secs] [Times: user=0.05 sys=0.00, real=0.01 secs] • 2014-09-01T12:39:09.789+0900: 617424.408: [CMS-concurrent-abortable-preclean-start] • CMS: abort preclean due to time 2014-09-01T12:39:14.863+0900: 617429.482: [CMS-concurrent-abortable-preclean: 1.807/5.074 secs] [Times: user=3.82 sys=0.03, real=5.08 secs] • 2014-09-01T12:39:14.864+0900: 617429.484: [GC[YG occupancy: 54721 K (306688 K)]2014-09-01T12:39:14.864+0900: 617429.484: [Rescan (parallel) , 0.0256580 secs]2014-09-01T12:39:14.890+0900: 617429.509: [weak refs processing, 0.0245990 secs]2014-09-01T12:39:14.915+0900: 617429.534: [class unloading, 0.0403370 secs]2014-09-01T12:39:14.955+0900: 617429.574: [scrub symbol table, 0.0197600 secs]2014-09-01T12:39:14.975+0900: 617429.594: [scrub string table, 0.0044930 secs] [1 CMS-remark: 2925342K(3853568K)] 2980064K(4160256K), 0.1238550 secs] [Times: user=0.20 sys=0.00, real=0.12 secs] • 2014-09-01T12:39:14.990+0900: 617429.609: [CMS-concurrent-sweep-start] • 2014-09-01T12:39:17.724+0900: 617432.343: [CMS-concurrent-sweep: 2.734/2.734 secs] [Times: user=3.02 sys=0.03, real=2.74 secs] • 2014-09-01T12:39:17.724+0900: 617432.343: [CMS-concurrent-reset-start] • 2014-09-01T12:39:17.732+0900: 617432.352: [CMS-concurrent-reset: 0.008/0.008 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 49
CMS GC • 2014-09-01T12:39:09.310+0900: 617423.929: [GC [1 CMS-initial-mark: 2925342K(3853568K)] 2937899K(4160256K), 0.0098890 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] • 2014-09-01T12:39:09.320+0900: 617423.939: [CMS-concurrent-mark-start] • 2014-09-01T12:39:09.772+0900: 617424.391: [CMS-concurrent-mark: 0.454/0.454 secs] [Times: user=1.38 sys=0.00, real=0.45 secs] • 2014-09-01T12:39:09.772+0900: 617424.391: [CMS-concurrent-preclean-start] • 2014-09-01T12:39:09.789+0900: 617424.408: [CMS-concurrent-preclean: 0.016/0.017 secs] [Times: user=0.05 sys=0.00, real=0.01 secs] • 2014-09-01T12:39:09.789+0900: 617424.408: [CMS-concurrent-abortable-preclean-start] • CMS: abort preclean due to time 2014-09-01T12:39:14.863+0900: 617429.482: [CMS-concurrent-abortable-preclean: 1.807/5.074 secs] [Times: user=3.82 sys=0.03, real=5.08 secs] • 2014-09-01T12:39:14.864+0900: 617429.484: [GC[YG occupancy: 54721 K (306688 K)]2014-09-01T12:39:14.864+0900: 617429.484: [Rescan (parallel) , 0.0256580 secs]2014-09-01T12:39:14.890+0900: 617429.509: [weak refs processing, 0.0245990 secs]2014-09-01T12:39:14.915+0900: 617429.534: [class unloading, 0.0403370 secs]2014-09-01T12:39:14.955+0900: 617429.574: [scrub symbol table, 0.0197600 secs]2014-09-01T12:39:14.975+0900: 617429.594: [scrub string table, 0.0044930 secs] [1 CMS-remark: 2925342K(3853568K)] 2980064K(4160256K), 0.1238550 secs] [Times: user=0.20 sys=0.00, real=0.12 secs] • 2014-09-01T12:39:14.990+0900: 617429.609: [CMS-concurrent-sweep-start] • 2014-09-01T12:39:17.724+0900: 617432.343: [CMS-concurrent-sweep: 2.734/2.734 secs] [Times: user=3.02 sys=0.03, real=2.74 secs] • 2014-09-01T12:39:17.724+0900: 617432.343: [CMS-concurrent-reset-start] • 2014-09-01T12:39:17.732+0900: 617432.352: [CMS-concurrent-reset: 0.008/0.008 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 50 冗長なので、以降はタ イムスタンプを省略
CMS フェーズ 1. Initial mark 2. Concurrent mark 3. Concurrent preclean 4. Concurrent abortable preclean 5. Remark (Final mark) 6. Concurrent sweep 7. Concurrent reset Mark Sweep 後始末 51 Initial mark Concurrent mark Concurrent preclean Remark Concurrent sweep Concurrent reset 再掲
Initial mark •[GC [1 CMS-initial-mark: 2925342K(3853568K)] 2937899K(4160256K), 0.0098890 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] •Root から直接辿れるオブジェクトをマーキ ング。処理中は Stop The World が発生する •マーキング情報はビットマップ (CMSBitMap) と呼ばれるデータ構造で管理される 52 Initial mark Concurrent mark Concurrent preclean Remark Concurrent sweep Concurrent reset
Initial mark •[GC [1 CMS-initial-mark: 2925342K(3853568K)] 2937899K(4160256K), 0.0098890 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] •Root から直接辿れるオブジェクトをマーキ ング。処理中は Stop The World が発生する •マーキング情報はビットマップ (CMSBitMap) と呼ばれるデータ構造で管理される フェーズ Old 領域 ヒープ全体 処理時間(STW) 53 処理時間 Initial mark Concurrent mark Concurrent preclean Remark Concurrent sweep Concurrent reset
Initial mark • VM_Operation::evaluate() • VM_CMS_Initial_Mark::doit() • CMSCollector::do_CMS_operation() • checkpointRootsInitial() • GenCollectedHeapSharedHeap::gen_process_strong_roots() SharedHeap::process_strong_roots() • Universe::oops_do() • MarkRefsIntoClosure::do_oop() • : • CMSBitMap::mark() 54Inside OpenJDK Initial mark Concurrent mark Concurrent preclean Remark Concurrent sweep Concurrent reset
Concurrent mark •[CMS-concurrent-mark-start] •[CMS-concurrent-mark: 0.454/0.454 secs] [Times: user=1.38 sys=0.00, real=0.45 secs] •全スレッドを再開しつつ、Initial mark でマーク したオブジェクトから辿れる全てのオブジェク トをマーキング •Minor GC が発生した場合、作成・更新したオブ ジェクトはCard Table (Dirty Card)で管理される 55 Initial mark Concurrent mark Concurrent preclean Remark Concurrent sweep Concurrent reset
Concurrent mark •[CMS-concurrent-mark-start] •[CMS-concurrent-mark: 0.454/0.454 secs] [Times: user=1.38 sys=0.00, real=0.45 secs] •全スレッドを再開しつつ、Initial mark でマーク したオブジェクトから辿れる全てのオブジェク トをマーキング •Minor GC が発生した場合、作成・更新したオブ ジェクトはCard Table (Dirty Card)で管理される 56 処理時間 他スレッドへの処理 (yield等)を含む wall timeフェーズ開始 フェーズ完了 Initial mark Concurrent mark Concurrent preclean Remark Concurrent sweep Concurrent reset
Concurrent mark • CMSCollector::markFromRoots() • : • CMSBitMap::iterate() • MarkFromRootsClosure::do_bit() • : • oopDesc::oop_iterate() • instanceRefKlass::oop_oop_iterate_nv() … (mark対象クラスに依る) • PushOrMarkClosure::do_oop_nv() • : • CMSBitMap::mark() 57Inside OpenJDK Initial mark Concurrent mark Concurrent preclean Remark Concurrent sweep Concurrent reset
Concurrent preclean •[CMS-concurrent-preclean-start] •[CMS-concurrent-preclean: 0.016/0.017 secs] [Times: user=0.05 sys=0.00, real=0.01 secs] •STW が発生する Remark を短縮するため、 Concurrent mark 中に Minor GC で Dirty Card に入ったオブジェクトをマーキングし、 Remark のマーキング処理量を減らす。 58 Initial mark Concurrent mark Concurrent preclean Remark Concurrent sweep Concurrent reset
Concurrent abortable preclean •[CMS-concurrent-abortable-preclean-start] •[CMS-concurrent-abortable-preclean: 1.807/5.074 secs] [Times: user=3.82 sys=0.03, real=5.08 secs] •Remark では New 領域もスキャンして Old 領域 のライブオブジェクトを漏らさずマーキングする •Minor GC が実行されて New 領域の使用量が減 り Remark の負荷が下がるのを可能な限り待つ 59 Initial mark Concurrent mark Concurrent preclean Remark Concurrent sweep Concurrent reset
Concurrent abortable preclean •Eden 使用量が 2MB 以下になるまで最大 5秒 待つ •CMSScheduleRemarkEdenSizeThreshould •CMSMaxAbortablePrecleanTime で設定 •最大まで待ったら「CMS: abort preclean due to time」を出力してフェーズ終了 •「abortable」の所以。エラーではない • 例: Minor GC が一度も起きなかった 60 Initial mark Concurrent mark Concurrent preclean Remark Concurrent sweep Concurrent reset
Concurrent preclean • CMSCollector::preclean() • : • ReferenceProcessor::preclean_discoverd_references() • CMSDrainMarkingStackClosure::do_void() • oopDesc::oop_iterate() … (スタックされたmark済みoop) • : • CMSBitMap::mark() 61Inside OpenJDK Initial mark Concurrent mark Concurrent preclean Remark Concurrent sweep Concurrent reset
Remark (Final mark) • [GC [YG occupancy: 54721 K (306688 K)] [Rescan (parallel) , 0.0256580 secs] [weak refs processing, 0.0245990 secs] [class unloading, 0.0403370 secs] [scrub symbol table, 0.0197600 secs] [scrub string table, 0.0044930 secs] [1 CMS-remark: 2925342K(3853568K)] 2980064K(4160256K), 0.1238550 secs] [Times: user=0.20 sys=0.00, real=0.12 secs] 62 処理時間(STW) 漏れがないよう に全スレッドを 止めてスキャン、 マーキング。 Initial mark Concurrent mark Concurrent preclean Remark Concurrent sweep Concurrent reset
Remark (Final mark) • [GC [YG occupancy: 54721 K (306688 K)] [Rescan (parallel) , 0.0256580 secs] [weak refs processing, 0.0245990 secs] [class unloading, 0.0403370 secs] [scrub symbol table, 0.0197600 secs] [scrub string table, 0.0044930 secs] [1 CMS-remark: 2925342K(3853568K)] 2980064K(4160256K), 0.1238550 secs] [Times: user=0.20 sys=0.00, real=0.12 secs] New領域のサイズ(処理はなし) Remark (二世代 スキャン。Dirty Cardをマーキング) ソフト参照・弱参照オブジェクトの開放 Old領域のサイズ 63 ヒープ全体サイズ Initial mark Concurrent mark Concurrent preclean Remark Concurrent sweep Concurrent reset
Remark (Final mark) • [GC [YG occupancy: 54721 K (306688 K)] [Rescan (parallel) , 0.0256580 secs] [weak refs processing, 0.0245990 secs] [class unloading, 0.0403370 secs] [scrub symbol table, 0.0197600 secs] [scrub string table, 0.0044930 secs] [1 CMS-remark: 2925342K(3853568K)] 2980064K(4160256K), 0.1238550 secs] [Times: user=0.20 sys=0.00, real=0.12 secs] CMSClassUnloadingEnabledが有効な時に実行 クラスアンロード シンボルテーブル のゴミ回収 interned string 回収 64 Initial mark Concurrent mark Concurrent preclean Remark Concurrent sweep Concurrent reset
Remark (Final mark) • CMSCollector::do_CMS_operation() • checkpointRootsFinal() • do_remark_parallel() / do_remark_non_parallel() • : • CMSParRemarkTask::work() • CMSParRemarkTask::do_dirty_card_rescan_tasks() • CardTableModRefBS::dirty_card_iterate() • CMSBitMap::mark_range() 65Inside OpenJDK Initial mark Concurrent mark Concurrent preclean Remark Concurrent sweep Concurrent reset
Concurrent sweep •[CMS-concurrent-sweep-start] •[CMS-concurrent-sweep: 2.734/2.734 secs] [Times: user=3.02 sys=0.03, real=2.74 secs] •未マークのオブジェクトを回収し、FreeList を再構築、統計情報の計算や空間のサイズ 調整を行う 66 Initial mark Concurrent mark Concurrent preclean Remark Concurrent sweep Concurrent reset
Concurrent sweep •CMSCollector::sweep() •sweepWork() •CompactibleFreeListSpace::blk_iterate_careful() •SweepClosure::do_blk_careful() •SweepClosure::do_yield_check() •SweepClosure::do_yield_work() 67Inside OpenJDK Initial mark Concurrent mark Concurrent preclean Remark Concurrent sweep Concurrent reset
Concurrent reset •[CMS-concurrent-reset-start] •[CMS-concurrent-reset: 0.008/0.008 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] •ビットマップなど次の CMS GC に備えて関 連データをクリア・初期化する。 68 Initial mark Concurrent mark Concurrent preclean Remark Concurrent sweep Concurrent reset
Concurrent reset •CMSCollector::reset() •: •CMSBitMap::clear_large_range() •ConcurrentMarkSweepThread::desynchronize() •ConcurrentMarkSweepThread::acknowledge_yield_r equest() •: 69Inside OpenJDK Initial mark Concurrent mark Concurrent preclean Remark Concurrent sweep Concurrent reset
まとめ •GC ログの読み方 •STW 時間 ([Times: 以降の real 値) •ParNew, CMS-initial-mark, CMS-remark •ヒープ使用量の推移 •GC前K -> GC後K (総容量) •基本的には GUI Tool を使いましょう •細かく調査する時はログを見る 70
注意すべきパターン CMS GC 概要 Concurrent Mark-Sweep GC HotSpot VM の CMS GC GC ログの読み方 注意すべきパターン 71
Full GC (with STW) Eden Survivor 1 Survivor 0 Tenured Perm / Meta space GC 対象 72 • 断片化で割り当てられない (promotion failed) • 回収が間に合わない (concurrent mode failure) 発生条件 再掲
promotion failed •3.586: [GC3.586: [ParNew (promotion failed): 232923K->283768K(306688K), 0.1500250 secs] 3.736: [CMS: 3102003K->240898K(3853568K), 1.8438740 secs] 3334926K->259898K(4160256K), [CMS Perm : 125100K->116602K(262144K)], 1.9941370 secs] [Times: user=2.05 sys=0.00, real=1.99 secs] 1. Old 領域で断片化が進む/不足する 2. Minor GC 中の promotion に失敗 3. 断片化解消のため、FullGC を実行 73
promotion failed •3.586: [GC3.586: [ParNew (promotion failed): 232923K->283768K(306688K), 0.1500250 secs] 3.736: [CMS: 3102003K->240898K(3853568K), 1.8438740 secs] 3334926K->259898K(4160256K), [CMS Perm : 125100K->115103K(262144K)], 1.9941370 secs] [Times: user=2.05 sys=0.00, real=1.99 secs] 1. Old 領域で断片化が進む/不足する 2. Minor GC 中の promotion に失敗 3. 断片化解消のため、FullGC を実行 74 ヒープ全体 New領域 Old領域 Perm領域 処理時間 (STW)
promotion failed 対策 •短命オブジェクトはNew領域で回収する •サイズが大きくて短命なオブジェクトは早 めに捨てる(参照を切る)ように実装する •New 領域のサイズを調整する •Minor GC (≒STW)時間とのトレードオフ •promotion させず New 領域で粘る •-XX:+MaxTenuringThreshold を上げる •最新の JDK はデフォルトで最大(15) 75
promotion failed 対策 •見落としがちな兆候 •Minor GC 後のOld領域より、次の Minor GC の GC 前の Old 領域の方が大きい •New 領域に割り当てず Old 領域に直接オ ブジェクトを割り当てている •Old 領域 ＞ New 領域だが promotion failed •断片化が深刻なレベルで発生している。 短い期間で発生していたら要注意 76
concurrent mode failure •62.696: [Full GC62.696: [CMS64.460: [CMS-concurrent- sweep: 2.319/2.386 secs] [Times: user=3.75 sys=0.13, real=2.39 secs] (concurrent mode failure): 3315076K- >398110K(3853568K), 5.4293100 secs] 3320358K- >398110K(4160256K), [CMS Perm : 125738K- >125738K(262144K)], 5.4294290 secs] [Times: user=5.43 sys=0.00, real=5.43 secs] •CMS GC 実行中に更に CMS GC が要求された。 CMS サイクルは同時処理が行えないため、 FullGC を呼び出して空きメモリを確保する 77 処理時間(STW)
concurrent mode failure 対策 •CMS GCの回収が間に合わない •CMS GCの開始タイミングを早める •-XX:+CMSInitiatingOccupancyFraction を 下げる •サーバのスペックアップ •スレッド単体の処理速度を上げる •並列度(スレッド数)を上げる •メモリだけ増やすと処理量が増えて逆効果 78
Minor GC と CMS GC の競合は？ •競合しない •データ競合 •CMS GC はマーキングに専用のビットマッ プを利用しているので競合しない •スレッド競合 •Minor GCが動く → CMS GCスレッドが一時 停止する (STW なので全スレッド一時停止) 79
GC Locker •18.412: [GC18.412: [ParNew (promotion failed): 307246K->305703K(306688K), 0.1039500 secs] 3695539K->3798331K(4160256K), 0.1041210 secs] [Times: user=0.20 sys=0.00, real=0.10 secs] •GC locker: Trying a full collection because scavenge failed •18.516: [Full GC18.516: [CMS: 3112627K- >662510K(3853568K), 3.5806870 secs] 3418331K- >662510K(4160256K), [CMS Perm : 115836K- >115846K(262144K)], 3.5808080 secs] [Times: user=3.58 sys=0.01, real=3.58 secs] 80
81 •GC locker: GC を止める機構 •HotSpot 初期化中 •JNI API 呼び出し (Get*Critical(),(画像処理等)) •Trying a full collection because scavenge failed •GC 停止中にばんばんオブジェクト作成 → New領域満杯 → OLD領域に直接割り当て → 深刻な断片化 －(最終的に)→ promotion 失敗 •CMS GC と相性がかなり悪い GC Locker: 何が起きたのか
GC Locker: 最悪なケース • 1085.695: [CMS-concurrent-sweep-start] • 1086.736: [GC1086.736: [ParNew (promotion failed): 300234K- >297058K(306688K), 0.1784670 secs] 3833880K- >3893624K(4160256K), 0.2084860 secs] [Times: user=0.26 sys=0.00, real=0.20 secs] • GC locker: Trying a full collection because scavenge failed • 1087.214: [Full GC1087.215: [CMS1104.749: [CMS-concurrent-sweep: 18.564/19.051 secs] [Times: user=28.84 sys=0.25, real=19.05 secs] (concurrent mode failure): 2986166K->357385K(3853568K), 16.8898790 secs] 3894624K->358385K(4160256K), [CMS Perm : 128222K->128215K(262144K)], 20.8900340 secs] [Times: user=27.84 sys=0.00, real=20.99 secs] 82 やばい
GC Locker + Sweep • 1085.695: [CMS-concurrent-sweep-start] • 1086.736: [GC1086.736: [ParNew (promotion failed): 300234K- >297058K(306688K), 0.1784670 secs] 3833880K- >3893624K(4160256K), 0.2084860 secs] [Times: user=0.26 sys=0.00, real=0.20 secs] • GC locker: Trying a full collection because scavenge failed • 1087.214: [Full GC1087.215: [CMS1104.749: [CMS-concurrent-sweep: 18.564/19.051 secs] [Times: user=28.84 sys=0.25, real=19.05 secs] (concurrent mode failure): 2986166K->357385K(3853568K), 16.8898790 secs] 3894624K->358385K(4160256K), [CMS Perm : 128222K->128215K(262144K)], 20.8900340 secs] [Times: user=27.84 sys=0.00, real=20.99 secs] 83 Full GC (STW) 開始 Concurrent Sweep 開始 Concurrent Sweep 完了 Sweep(一部) + FullGC の間 STW FreeList
GC Locker 対策 •GC Locker の頻度を下げる •-XX:+PrintGCCause •[GC(GCLocker Initiated GC) … •断片化しない GC を使う •短命 JVM で対処する 84
まとめ •注意すべきパターン •promotion failed •concurrent mode failure •断片化が発生しやすい状況は避ける 85
おわりに •自分のアプリケーションがどのよう にメモリを使っているかは意識しま しょう •GCに任せるのはそれから 86
Reference •Tony Printezis, David Detlefs. A Generational Mostly-concurrent Garbage Collection (ISMM 2000) •中村成洋, 相川光.ガベージコレクションのアルゴリ ズムと実装 •中村成洋. 徹底解剖「G1GC」アルゴリズム編 •中村成洋. 徹底解剖「G1GC」実装編 •http://hg.openjdk.java.net/jdk7u/jdk7u 87
Thanks ! •Yasumasa Suenaga (@YaSuenag ) •Shinji Takao •and, thank you for your attention! 88
おまけ CMS GC 概要 Concurrent Mark-Sweep GC HotSpot VM の CMS GC GC ログの読み方 注意すべきパターン おまけ 89
ヒープの確保 • JNI_CreateJavaVM() … JVM 作成＆初期化 • Threads::create_vm() • Universe::initialize_heap() … GC に応じた各メモリ管理の初期化 • GC に基づいて CollectedHeap(ヒープ領域の定義クラス), CollectorPolicy (メ モリ管理方針の定義クラス) を作成。 • CMS の場合はそれぞれ以下。 • (AS)ConcurrentMarkSweepPolicy(), GenCollectedHeap() • CollectHeap::initialize() … GC アルゴリズム応じたヒープ領域確保 • CMSの場合は、GenCollectedHeap::initialize() • ConcurrentMarkSweepPolicy(), GenCollectorPolicy::initialize_all() • ヒープ空間の各世代に対応する Generation オブジェクトを作成 • CMS GC Thread の作成 90Inside OpenJDK
GC 着火 • メモリ確保 • 4 つの bytecode (new, newarray, anewarray, multianewarray) • TemplateTable 起動 • 各 Runtime クラスからメモリ確保関数が呼ばれる • instanceKlass::allocate_instance(), oopFactory::new_typeArray(), oopFactory::new_objArray(), arrayKlass::multi_allocate() • 最終的に CollectedHeap::common_mem_allocate_init() を呼ぶ • TLAB からの確保 (UseTLAB使用時, CollectedHeap::allocate_from_tlab()) • CollectedHeap::mem_allocate() … GCに応じたメモリ確保 • この二つの両方で失敗したら OufOfMemoryError 91Inside OpenJDK
GC 着火 • GenCollectedHeap::mem_allocate() … CMS のメモリ確保 • GenCollectorPolicy::mem_allocate_work() • Generation::par_allocate() … New領域からの獲得 • GenCollectedHeap::attempt_allocation() … 各世代からの獲得 • Generation::allocate() … 各世代定義オブジェクトの処理 • GenCollectorPolicy::expand_heap_and_allocate() … ヒープ拡張 • VM_GenCollectForAllocation::doit() … GC の起動 • GenCollectedHeap::do_collection() • GenCollectorPolicy::satisfy_failed_allocation() • GC後、上のmem_allocate_work()が行われる 92Inside OpenJDK
ほんとにおしまい •質問は @sugarlife か #ccc_r16 へ •懇親会でも受付中！ 93 KUBOTA Yuji @sugarlife kubota.yuji@gmail.com

More Related Content

Concurrent Mark-Sweep Garbage Collection #jjug_ccc

  • 1. Concurrent Mark-Sweep Garbage Collection 再入門 KUBOTA Yuji @sugarlife kubota.yuji@gmail.com JJUG CCC 2014 Fall #ccc_r16
  • 2. はじめに •本セッションでは Concurrent Mark- Sweep GC (CMS GC)について、動作 の概要の復習から GC ログの読み方 を解説し、問題の把握や調査の糸口 として役立てられることを目的とし ています。 2
  • 3. はじめに •本セッションでは Concurrent Mark- Sweep GC (CMS GC)について、動作 の概要の復習から GC ログの読み方 を解説し、問題の把握や調査の糸口 として役立てられることを目的とし ています。 CMS GC を思い出すためのセッション 3
  • 5. KUBOTA Yuji (@sugarlife) •OpenJDK Technical Support Engineer •IcedTea Committer (HeapStats) •JavaOne 2014 Speaker 5
  • 6. おしながき •CMS GC 概要 •Concurrent Mark-Sweep GC •HotSpot VM の CMS GC •GC ログの読み方 •注意すべきパターン 6
  • 7. ここで質問 •CMS GC をどの程度知っていますか？ •名前は聞いたことある •GC ログを読んだことがある •チューニングしたことがある •OpenJDKのソースを読んだことがある •HeapStats 知ってる？ 7
  • 8. CMS GC 概要 CMS GC 概要 Concurrent Mark-Sweep GC HotSpot VM の CMS GC GC ログの読み方 注意すべきパターン 8
  • 9. Garbage Collection 1. 不要なメモリ領域(ゴミ)を判別し、 2. ゴミを処理して再利用可能にする 9
  • 11. Concurrent Mark-Sweep GC 1. ゴミじゃない領域を Mark し、 2. Sweep して再利用可能にする ヒープ領域 FreeList ✔ ✔ ✔ ✔ ←再利用時に辿る(コンパクションなし) Thread stack JNI Reference … Root 11
  • 12. CMS GC 概要 CMS GC 概要 Concurrent Mark-Sweep GC HotSpot VM の CMS GC GC ログの読み方 注意すべきパターン 12
  • 14. ヒープ領域の世代別管理 New Generation Old Generation Perm / Meta spaceMinor GC Major GC 14 Heapは生成されたばかりのオブジェクトを管理するNew世代と、 長命なオブジェクトを管理するOld世代で分割して管理している。
  • 15. 世代別 GC (CMS GC利用時) •Minor GC: Parallel Copy GC •アプリケーションを止める (別名 Stop-The-World, STW) •早い・メモリが断片化しない •Major GC: CMS GC •一部アプリケーションを止める •コンパクションしないので断片化する 15
  • 21. Minor GC + Promotion Eden Survivor 1 Survivor 0 Tenured Perm / Meta space 21 New領域 Old領域 age++
  • 22. Minor GC + Promotion Eden Survivor 1 Survivor 0 Tenured Perm / Meta space 22 New領域 Old領域 age++ promotion
  • 23. Minor GC + Promotion Eden Survivor 1 Survivor 0 Tenured Perm / Meta space age++ promotion 23 • 最大で -XX:+MaxTenuringThreshold 以上 Survivor 間を移動 • Eden から Survivor へ移動ができない promotion 条件
  • 24. Minor GC + Promotion Eden Survivor 1 Survivor 0 Tenured Perm / Meta space age++ promotion 24 • 最大で -XX:+MaxTenuringThreshold 以上 Survivor 間を移動 • Eden から Survivor へ移動ができない promotion 条件 -XX:+AlwaysTenureで Survivor スルー
  • 25. Minor GC + Promotion 後 Eden Survivor 1 Survivor 0 Tenured Perm / Meta space 25 New領域 Old領域
  • 27. Major GC (CMS GC) Eden Survivor 1 Survivor 0 Tenured Perm / Meta space 27 GC 対象
  • 28. Major GC (CMS GC) Eden Survivor 1 Survivor 0 Tenured Perm / Meta space • -XX:CMSInitiatingOccupancyFraction (92%) • その他、ヒープ占有速度の統計判断など 発生条件 28 GC 対象
  • 29. Major GC (CMS GC) Eden Survivor 1 Survivor 0 Tenured Perm / Meta space • -XX:CMSInitiatingOccupancyFraction (92%) • その他、ヒープ占有速度の統計判断など 発生条件 29 -XX:+UseCMSInitiatingOccupancyOnly を設定するとこの条件のみで判断する GC 対象
  • 30. Major GC (CMS フェーズ) 1. Initial mark 2. Concurrent mark 3. Concurrent preclean 4. Concurrent abortable preclean 5. Remark (Final mark) 6. Concurrent sweep 7. Concurrent reset Mark Sweep 後始末 30
  • 31. Major GC (CMS フェーズ) 1. Initial mark 2. Concurrent mark 3. Concurrent preclean 4. Concurrent abortable preclean 5. Remark (Final mark) 6. Concurrent sweep 7. Concurrent reset Mark Sweep 後始末 31 STW STW Concurrent が付いている フェーズはアプリと同時に 動作するが、付いてない フェーズは STW が発生する
  • 32. Major GC (CMS GC) 後 Eden Survivor 1 Survivor 0 Tenured Perm / Meta space 32 New領域 Old領域
  • 33. Major GC (CMS GC) 後 Eden Survivor 1 Survivor 0 Tenured Perm / Meta space CMS GC は安定している？ いいえ、失敗して STW を伴う Full GC が発生する場合もあります 33 New領域 Old領域 CMS GC とは別アルゴリズム (Mark-Sweep-Compact, 断片化しない)
  • 34. Full GC (with STW) Eden Survivor 1 Survivor 0 Tenured Perm / Meta space GC 対象 34
  • 35. Full GC (with STW) Eden Survivor 1 Survivor 0 Tenured Perm / Meta space GC 対象 35 • 断片化で割り当てられない (promotion failed) • 回収が間に合わない (concurrent mode failure) 発生条件
  • 36. まとめ •Concurrent Mark-Sweep GC •レスポンスタイム重視なシステム向け •コンパクションがなく断片化が生じる •HotSpot VM の CMS GC •世代別ヒープ管理 •STW を伴う GC やフェーズがある •CMS で回収を失敗すると Full GC 36
  • 37. GC ログの読み方 CMS GC 概要 Concurrent Mark-Sweep GC HotSpot VM の CMS GC GC ログの読み方 注意すべきパターン 37
  • 38. Java 起動オプション •CMS GC を使う、 •-XX:+UseConcMarkSweepGC •-XX:+CMSClassUnloadingEnabled (推奨) •ログ (GC, ヒープダンプ) •-Xloggc:gc.log •-XX:+PrintGCDetails •-XX:+PrintGCDateStamps •-XX:+HeapDumpOnOutOfMemoryError GC時にクラスを アンロードする OOME発生時 38 JDK8 からデフォルト true
  • 39. タイムスタンプ •2014-09-01T12:39:09.293+0900: 617423.912: [GC… •以降の GC ログでは省略する。 39 ‐XX:+PrintGCDateStamps Java process の uptime (second)
  • 40. Minor GC •617423.912: [GC617423.912: [ParNew: 230016K->4553K(306688K), 0.0159800 secs] 2993210K->2774025K(4160256K), 0.0161510 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 40
  • 41. Minor GC •617423.912: [GC 617423.912: [ParNew: 230016K->4553K(306688K), 0.0159800 secs] 2993210K->2774025K(4160256K), 0.0161510 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 41 見やすく整形
  • 42. Minor GC •617423.912: [GC 617423.912: [ParNew: 230016K->4553K(306688K), 0.0159800 secs] 2993210K->2774025K(4160256K), 0.0161510 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 42 GC共通部分 Minor GC time(1)相当 (全体の処理時間は real の値を見るのが良い) 処理時間(STW)
  • 43. Minor GC (Minor GC) •617423.912: [GC 617423.912: [ParNew: 230016K->4553K(306688K), 0.0159800 secs] 2993210K->2774025K(4160256K), 0.0161510 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 43 Minor GC
  • 44. Minor GC (Minor GC) •617423.912: [GC 617423.912: [ParNew: 230016K->4553K(306688K), 0.0159800 secs] 2993210K->2774025K(4160256K), 0.0161510 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 44 開始時刻 処理時間 New領域のサイズ GC前 GC後 総容量
  • 45. Minor GC (GC共通部分) •617423.912: [GC 617423.912: [ParNew: 230016K->4553K(306688K), 0.0159800 secs] 2993210K->2774025K(4160256K), 0.0161510 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 45 GC共通部分
  • 46. Minor GC (GC共通部分) •617423.912: [GC 617423.912: [ParNew: 230016K->4553K(306688K), 0.0159800 secs] 2993210K->2774025K(4160256K), 0.0161510 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 46 開始時刻 処理時間 GC前 GC後 総容量 ヒープ全体のサイズ
  • 47. Minor GC (promotion) •617423.912: [GC 617423.912: [ParNew: 230016K->4553K(306688K), 0.0159800 secs] 2993210K->2774025K(4160256K), 0.0161510 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 47 Old領域に移った サイズの求め方
  • 48. Minor GC (promotion) •617423.912: [GC 617423.912: [ParNew: 230016K->4553K(306688K), 0.0159800 secs] 2993210K->2774025K(4160256K), 0.0161510 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 48 New領域の差分 全体の差分 promoted = (230016-4553) - (2993210-2774025) = 6278K Old領域へ promote Old領域に移った サイズの求め方
  • 49. CMS GC • 2014-09-01T12:39:09.310+0900: 617423.929: [GC [1 CMS-initial-mark: 2925342K(3853568K)] 2937899K(4160256K), 0.0098890 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] • 2014-09-01T12:39:09.320+0900: 617423.939: [CMS-concurrent-mark-start] • 2014-09-01T12:39:09.772+0900: 617424.391: [CMS-concurrent-mark: 0.454/0.454 secs] [Times: user=1.38 sys=0.00, real=0.45 secs] • 2014-09-01T12:39:09.772+0900: 617424.391: [CMS-concurrent-preclean-start] • 2014-09-01T12:39:09.789+0900: 617424.408: [CMS-concurrent-preclean: 0.016/0.017 secs] [Times: user=0.05 sys=0.00, real=0.01 secs] • 2014-09-01T12:39:09.789+0900: 617424.408: [CMS-concurrent-abortable-preclean-start] • CMS: abort preclean due to time 2014-09-01T12:39:14.863+0900: 617429.482: [CMS-concurrent-abortable-preclean: 1.807/5.074 secs] [Times: user=3.82 sys=0.03, real=5.08 secs] • 2014-09-01T12:39:14.864+0900: 617429.484: [GC[YG occupancy: 54721 K (306688 K)]2014-09-01T12:39:14.864+0900: 617429.484: [Rescan (parallel) , 0.0256580 secs]2014-09-01T12:39:14.890+0900: 617429.509: [weak refs processing, 0.0245990 secs]2014-09-01T12:39:14.915+0900: 617429.534: [class unloading, 0.0403370 secs]2014-09-01T12:39:14.955+0900: 617429.574: [scrub symbol table, 0.0197600 secs]2014-09-01T12:39:14.975+0900: 617429.594: [scrub string table, 0.0044930 secs] [1 CMS-remark: 2925342K(3853568K)] 2980064K(4160256K), 0.1238550 secs] [Times: user=0.20 sys=0.00, real=0.12 secs] • 2014-09-01T12:39:14.990+0900: 617429.609: [CMS-concurrent-sweep-start] • 2014-09-01T12:39:17.724+0900: 617432.343: [CMS-concurrent-sweep: 2.734/2.734 secs] [Times: user=3.02 sys=0.03, real=2.74 secs] • 2014-09-01T12:39:17.724+0900: 617432.343: [CMS-concurrent-reset-start] • 2014-09-01T12:39:17.732+0900: 617432.352: [CMS-concurrent-reset: 0.008/0.008 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 49
  • 50. CMS GC • 2014-09-01T12:39:09.310+0900: 617423.929: [GC [1 CMS-initial-mark: 2925342K(3853568K)] 2937899K(4160256K), 0.0098890 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] • 2014-09-01T12:39:09.320+0900: 617423.939: [CMS-concurrent-mark-start] • 2014-09-01T12:39:09.772+0900: 617424.391: [CMS-concurrent-mark: 0.454/0.454 secs] [Times: user=1.38 sys=0.00, real=0.45 secs] • 2014-09-01T12:39:09.772+0900: 617424.391: [CMS-concurrent-preclean-start] • 2014-09-01T12:39:09.789+0900: 617424.408: [CMS-concurrent-preclean: 0.016/0.017 secs] [Times: user=0.05 sys=0.00, real=0.01 secs] • 2014-09-01T12:39:09.789+0900: 617424.408: [CMS-concurrent-abortable-preclean-start] • CMS: abort preclean due to time 2014-09-01T12:39:14.863+0900: 617429.482: [CMS-concurrent-abortable-preclean: 1.807/5.074 secs] [Times: user=3.82 sys=0.03, real=5.08 secs] • 2014-09-01T12:39:14.864+0900: 617429.484: [GC[YG occupancy: 54721 K (306688 K)]2014-09-01T12:39:14.864+0900: 617429.484: [Rescan (parallel) , 0.0256580 secs]2014-09-01T12:39:14.890+0900: 617429.509: [weak refs processing, 0.0245990 secs]2014-09-01T12:39:14.915+0900: 617429.534: [class unloading, 0.0403370 secs]2014-09-01T12:39:14.955+0900: 617429.574: [scrub symbol table, 0.0197600 secs]2014-09-01T12:39:14.975+0900: 617429.594: [scrub string table, 0.0044930 secs] [1 CMS-remark: 2925342K(3853568K)] 2980064K(4160256K), 0.1238550 secs] [Times: user=0.20 sys=0.00, real=0.12 secs] • 2014-09-01T12:39:14.990+0900: 617429.609: [CMS-concurrent-sweep-start] • 2014-09-01T12:39:17.724+0900: 617432.343: [CMS-concurrent-sweep: 2.734/2.734 secs] [Times: user=3.02 sys=0.03, real=2.74 secs] • 2014-09-01T12:39:17.724+0900: 617432.343: [CMS-concurrent-reset-start] • 2014-09-01T12:39:17.732+0900: 617432.352: [CMS-concurrent-reset: 0.008/0.008 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 50 冗長なので、以降はタ イムスタンプを省略
  • 51. CMS フェーズ 1. Initial mark 2. Concurrent mark 3. Concurrent preclean 4. Concurrent abortable preclean 5. Remark (Final mark) 6. Concurrent sweep 7. Concurrent reset Mark Sweep 後始末 51 Initial mark Concurrent mark Concurrent preclean Remark Concurrent sweep Concurrent reset 再掲
  • 52. Initial mark •[GC [1 CMS-initial-mark: 2925342K(3853568K)] 2937899K(4160256K), 0.0098890 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] •Root から直接辿れるオブジェクトをマーキ ング。処理中は Stop The World が発生する •マーキング情報はビットマップ (CMSBitMap) と呼ばれるデータ構造で管理される 52 Initial mark Concurrent mark Concurrent preclean Remark Concurrent sweep Concurrent reset
  • 53. Initial mark •[GC [1 CMS-initial-mark: 2925342K(3853568K)] 2937899K(4160256K), 0.0098890 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] •Root から直接辿れるオブジェクトをマーキ ング。処理中は Stop The World が発生する •マーキング情報はビットマップ (CMSBitMap) と呼ばれるデータ構造で管理される フェーズ Old 領域 ヒープ全体 処理時間(STW) 53 処理時間 Initial mark Concurrent mark Concurrent preclean Remark Concurrent sweep Concurrent reset
  • 54. Initial mark • VM_Operation::evaluate() • VM_CMS_Initial_Mark::doit() • CMSCollector::do_CMS_operation() • checkpointRootsInitial() • GenCollectedHeapSharedHeap::gen_process_strong_roots() SharedHeap::process_strong_roots() • Universe::oops_do() • MarkRefsIntoClosure::do_oop() • : • CMSBitMap::mark() 54Inside OpenJDK Initial mark Concurrent mark Concurrent preclean Remark Concurrent sweep Concurrent reset
  • 55. Concurrent mark •[CMS-concurrent-mark-start] •[CMS-concurrent-mark: 0.454/0.454 secs] [Times: user=1.38 sys=0.00, real=0.45 secs] •全スレッドを再開しつつ、Initial mark でマーク したオブジェクトから辿れる全てのオブジェク トをマーキング •Minor GC が発生した場合、作成・更新したオブ ジェクトはCard Table (Dirty Card)で管理される 55 Initial mark Concurrent mark Concurrent preclean Remark Concurrent sweep Concurrent reset
  • 56. Concurrent mark •[CMS-concurrent-mark-start] •[CMS-concurrent-mark: 0.454/0.454 secs] [Times: user=1.38 sys=0.00, real=0.45 secs] •全スレッドを再開しつつ、Initial mark でマーク したオブジェクトから辿れる全てのオブジェク トをマーキング •Minor GC が発生した場合、作成・更新したオブ ジェクトはCard Table (Dirty Card)で管理される 56 処理時間 他スレッドへの処理 (yield等)を含む wall timeフェーズ開始 フェーズ完了 Initial mark Concurrent mark Concurrent preclean Remark Concurrent sweep Concurrent reset
  • 57. Concurrent mark • CMSCollector::markFromRoots() • : • CMSBitMap::iterate() • MarkFromRootsClosure::do_bit() • : • oopDesc::oop_iterate() • instanceRefKlass::oop_oop_iterate_nv() … (mark対象クラスに依る) • PushOrMarkClosure::do_oop_nv() • : • CMSBitMap::mark() 57Inside OpenJDK Initial mark Concurrent mark Concurrent preclean Remark Concurrent sweep Concurrent reset
  • 58. Concurrent preclean •[CMS-concurrent-preclean-start] •[CMS-concurrent-preclean: 0.016/0.017 secs] [Times: user=0.05 sys=0.00, real=0.01 secs] •STW が発生する Remark を短縮するため、 Concurrent mark 中に Minor GC で Dirty Card に入ったオブジェクトをマーキングし、 Remark のマーキング処理量を減らす。 58 Initial mark Concurrent mark Concurrent preclean Remark Concurrent sweep Concurrent reset
  • 59. Concurrent abortable preclean •[CMS-concurrent-abortable-preclean-start] •[CMS-concurrent-abortable-preclean: 1.807/5.074 secs] [Times: user=3.82 sys=0.03, real=5.08 secs] •Remark では New 領域もスキャンして Old 領域 のライブオブジェクトを漏らさずマーキングする •Minor GC が実行されて New 領域の使用量が減 り Remark の負荷が下がるのを可能な限り待つ 59 Initial mark Concurrent mark Concurrent preclean Remark Concurrent sweep Concurrent reset
  • 60. Concurrent abortable preclean •Eden 使用量が 2MB 以下になるまで最大 5秒 待つ •CMSScheduleRemarkEdenSizeThreshould •CMSMaxAbortablePrecleanTime で設定 •最大まで待ったら「CMS: abort preclean due to time」を出力してフェーズ終了 •「abortable」の所以。エラーではない • 例: Minor GC が一度も起きなかった 60 Initial mark Concurrent mark Concurrent preclean Remark Concurrent sweep Concurrent reset
  • 61. Concurrent preclean • CMSCollector::preclean() • : • ReferenceProcessor::preclean_discoverd_references() • CMSDrainMarkingStackClosure::do_void() • oopDesc::oop_iterate() … (スタックされたmark済みoop) • : • CMSBitMap::mark() 61Inside OpenJDK Initial mark Concurrent mark Concurrent preclean Remark Concurrent sweep Concurrent reset
  • 62. Remark (Final mark) • [GC [YG occupancy: 54721 K (306688 K)] [Rescan (parallel) , 0.0256580 secs] [weak refs processing, 0.0245990 secs] [class unloading, 0.0403370 secs] [scrub symbol table, 0.0197600 secs] [scrub string table, 0.0044930 secs] [1 CMS-remark: 2925342K(3853568K)] 2980064K(4160256K), 0.1238550 secs] [Times: user=0.20 sys=0.00, real=0.12 secs] 62 処理時間(STW) 漏れがないよう に全スレッドを 止めてスキャン、 マーキング。 Initial mark Concurrent mark Concurrent preclean Remark Concurrent sweep Concurrent reset
  • 63. Remark (Final mark) • [GC [YG occupancy: 54721 K (306688 K)] [Rescan (parallel) , 0.0256580 secs] [weak refs processing, 0.0245990 secs] [class unloading, 0.0403370 secs] [scrub symbol table, 0.0197600 secs] [scrub string table, 0.0044930 secs] [1 CMS-remark: 2925342K(3853568K)] 2980064K(4160256K), 0.1238550 secs] [Times: user=0.20 sys=0.00, real=0.12 secs] New領域のサイズ(処理はなし) Remark (二世代 スキャン。Dirty Cardをマーキング) ソフト参照・弱参照オブジェクトの開放 Old領域のサイズ 63 ヒープ全体サイズ Initial mark Concurrent mark Concurrent preclean Remark Concurrent sweep Concurrent reset
  • 64. Remark (Final mark) • [GC [YG occupancy: 54721 K (306688 K)] [Rescan (parallel) , 0.0256580 secs] [weak refs processing, 0.0245990 secs] [class unloading, 0.0403370 secs] [scrub symbol table, 0.0197600 secs] [scrub string table, 0.0044930 secs] [1 CMS-remark: 2925342K(3853568K)] 2980064K(4160256K), 0.1238550 secs] [Times: user=0.20 sys=0.00, real=0.12 secs] CMSClassUnloadingEnabledが有効な時に実行 クラスアンロード シンボルテーブル のゴミ回収 interned string 回収 64 Initial mark Concurrent mark Concurrent preclean Remark Concurrent sweep Concurrent reset
  • 65. Remark (Final mark) • CMSCollector::do_CMS_operation() • checkpointRootsFinal() • do_remark_parallel() / do_remark_non_parallel() • : • CMSParRemarkTask::work() • CMSParRemarkTask::do_dirty_card_rescan_tasks() • CardTableModRefBS::dirty_card_iterate() • CMSBitMap::mark_range() 65Inside OpenJDK Initial mark Concurrent mark Concurrent preclean Remark Concurrent sweep Concurrent reset
  • 66. Concurrent sweep •[CMS-concurrent-sweep-start] •[CMS-concurrent-sweep: 2.734/2.734 secs] [Times: user=3.02 sys=0.03, real=2.74 secs] •未マークのオブジェクトを回収し、FreeList を再構築、統計情報の計算や空間のサイズ 調整を行う 66 Initial mark Concurrent mark Concurrent preclean Remark Concurrent sweep Concurrent reset
  • 68. Concurrent reset •[CMS-concurrent-reset-start] •[CMS-concurrent-reset: 0.008/0.008 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] •ビットマップなど次の CMS GC に備えて関 連データをクリア・初期化する。 68 Initial mark Concurrent mark Concurrent preclean Remark Concurrent sweep Concurrent reset
  • 70. まとめ •GC ログの読み方 •STW 時間 ([Times: 以降の real 値) •ParNew, CMS-initial-mark, CMS-remark •ヒープ使用量の推移 •GC前K -> GC後K (総容量) •基本的には GUI Tool を使いましょう •細かく調査する時はログを見る 70
  • 71. 注意すべきパターン CMS GC 概要 Concurrent Mark-Sweep GC HotSpot VM の CMS GC GC ログの読み方 注意すべきパターン 71
  • 72. Full GC (with STW) Eden Survivor 1 Survivor 0 Tenured Perm / Meta space GC 対象 72 • 断片化で割り当てられない (promotion failed) • 回収が間に合わない (concurrent mode failure) 発生条件 再掲
  • 73. promotion failed •3.586: [GC3.586: [ParNew (promotion failed): 232923K->283768K(306688K), 0.1500250 secs] 3.736: [CMS: 3102003K->240898K(3853568K), 1.8438740 secs] 3334926K->259898K(4160256K), [CMS Perm : 125100K->116602K(262144K)], 1.9941370 secs] [Times: user=2.05 sys=0.00, real=1.99 secs] 1. Old 領域で断片化が進む/不足する 2. Minor GC 中の promotion に失敗 3. 断片化解消のため、FullGC を実行 73
  • 74. promotion failed •3.586: [GC3.586: [ParNew (promotion failed): 232923K->283768K(306688K), 0.1500250 secs] 3.736: [CMS: 3102003K->240898K(3853568K), 1.8438740 secs] 3334926K->259898K(4160256K), [CMS Perm : 125100K->115103K(262144K)], 1.9941370 secs] [Times: user=2.05 sys=0.00, real=1.99 secs] 1. Old 領域で断片化が進む/不足する 2. Minor GC 中の promotion に失敗 3. 断片化解消のため、FullGC を実行 74 ヒープ全体 New領域 Old領域 Perm領域 処理時間 (STW)
  • 75. promotion failed 対策 •短命オブジェクトはNew領域で回収する •サイズが大きくて短命なオブジェクトは早 めに捨てる(参照を切る)ように実装する •New 領域のサイズを調整する •Minor GC (≒STW)時間とのトレードオフ •promotion させず New 領域で粘る •-XX:+MaxTenuringThreshold を上げる •最新の JDK はデフォルトで最大(15) 75
  • 76. promotion failed 対策 •見落としがちな兆候 •Minor GC 後のOld領域より、次の Minor GC の GC 前の Old 領域の方が大きい •New 領域に割り当てず Old 領域に直接オ ブジェクトを割り当てている •Old 領域 ＞ New 領域だが promotion failed •断片化が深刻なレベルで発生している。 短い期間で発生していたら要注意 76
  • 77. concurrent mode failure •62.696: [Full GC62.696: [CMS64.460: [CMS-concurrent- sweep: 2.319/2.386 secs] [Times: user=3.75 sys=0.13, real=2.39 secs] (concurrent mode failure): 3315076K- >398110K(3853568K), 5.4293100 secs] 3320358K- >398110K(4160256K), [CMS Perm : 125738K- >125738K(262144K)], 5.4294290 secs] [Times: user=5.43 sys=0.00, real=5.43 secs] •CMS GC 実行中に更に CMS GC が要求された。 CMS サイクルは同時処理が行えないため、 FullGC を呼び出して空きメモリを確保する 77 処理時間(STW)
  • 78. concurrent mode failure 対策 •CMS GCの回収が間に合わない •CMS GCの開始タイミングを早める •-XX:+CMSInitiatingOccupancyFraction を 下げる •サーバのスペックアップ •スレッド単体の処理速度を上げる •並列度(スレッド数)を上げる •メモリだけ増やすと処理量が増えて逆効果 78
  • 79. Minor GC と CMS GC の競合は？ •競合しない •データ競合 •CMS GC はマーキングに専用のビットマッ プを利用しているので競合しない •スレッド競合 •Minor GCが動く → CMS GCスレッドが一時 停止する (STW なので全スレッド一時停止) 79
  • 80. GC Locker •18.412: [GC18.412: [ParNew (promotion failed): 307246K->305703K(306688K), 0.1039500 secs] 3695539K->3798331K(4160256K), 0.1041210 secs] [Times: user=0.20 sys=0.00, real=0.10 secs] •GC locker: Trying a full collection because scavenge failed •18.516: [Full GC18.516: [CMS: 3112627K- >662510K(3853568K), 3.5806870 secs] 3418331K- >662510K(4160256K), [CMS Perm : 115836K- >115846K(262144K)], 3.5808080 secs] [Times: user=3.58 sys=0.01, real=3.58 secs] 80
  • 81. 81 •GC locker: GC を止める機構 •HotSpot 初期化中 •JNI API 呼び出し (Get*Critical(),(画像処理等)) •Trying a full collection because scavenge failed •GC 停止中にばんばんオブジェクト作成 → New領域満杯 → OLD領域に直接割り当て → 深刻な断片化 －(最終的に)→ promotion 失敗 •CMS GC と相性がかなり悪い GC Locker: 何が起きたのか
  • 82. GC Locker: 最悪なケース • 1085.695: [CMS-concurrent-sweep-start] • 1086.736: [GC1086.736: [ParNew (promotion failed): 300234K- >297058K(306688K), 0.1784670 secs] 3833880K- >3893624K(4160256K), 0.2084860 secs] [Times: user=0.26 sys=0.00, real=0.20 secs] • GC locker: Trying a full collection because scavenge failed • 1087.214: [Full GC1087.215: [CMS1104.749: [CMS-concurrent-sweep: 18.564/19.051 secs] [Times: user=28.84 sys=0.25, real=19.05 secs] (concurrent mode failure): 2986166K->357385K(3853568K), 16.8898790 secs] 3894624K->358385K(4160256K), [CMS Perm : 128222K->128215K(262144K)], 20.8900340 secs] [Times: user=27.84 sys=0.00, real=20.99 secs] 82 やばい
  • 83. GC Locker + Sweep • 1085.695: [CMS-concurrent-sweep-start] • 1086.736: [GC1086.736: [ParNew (promotion failed): 300234K- >297058K(306688K), 0.1784670 secs] 3833880K- >3893624K(4160256K), 0.2084860 secs] [Times: user=0.26 sys=0.00, real=0.20 secs] • GC locker: Trying a full collection because scavenge failed • 1087.214: [Full GC1087.215: [CMS1104.749: [CMS-concurrent-sweep: 18.564/19.051 secs] [Times: user=28.84 sys=0.25, real=19.05 secs] (concurrent mode failure): 2986166K->357385K(3853568K), 16.8898790 secs] 3894624K->358385K(4160256K), [CMS Perm : 128222K->128215K(262144K)], 20.8900340 secs] [Times: user=27.84 sys=0.00, real=20.99 secs] 83 Full GC (STW) 開始 Concurrent Sweep 開始 Concurrent Sweep 完了 Sweep(一部) + FullGC の間 STW FreeList
  • 84. GC Locker 対策 •GC Locker の頻度を下げる •-XX:+PrintGCCause •[GC(GCLocker Initiated GC) … •断片化しない GC を使う •短命 JVM で対処する 84
  • 85. まとめ •注意すべきパターン •promotion failed •concurrent mode failure •断片化が発生しやすい状況は避ける 85
  • 87. Reference •Tony Printezis, David Detlefs. A Generational Mostly-concurrent Garbage Collection (ISMM 2000) •中村成洋, 相川光.ガベージコレクションのアルゴリ ズムと実装 •中村成洋. 徹底解剖「G1GC」アルゴリズム編 •中村成洋. 徹底解剖「G1GC」実装編 •http://hg.openjdk.java.net/jdk7u/jdk7u 87
  • 88. Thanks ! •Yasumasa Suenaga (@YaSuenag ) •Shinji Takao •and, thank you for your attention! 88
  • 89. おまけ CMS GC 概要 Concurrent Mark-Sweep GC HotSpot VM の CMS GC GC ログの読み方 注意すべきパターン おまけ 89
  • 90. ヒープの確保 • JNI_CreateJavaVM() … JVM 作成＆初期化 • Threads::create_vm() • Universe::initialize_heap() … GC に応じた各メモリ管理の初期化 • GC に基づいて CollectedHeap(ヒープ領域の定義クラス), CollectorPolicy (メ モリ管理方針の定義クラス) を作成。 • CMS の場合はそれぞれ以下。 • (AS)ConcurrentMarkSweepPolicy(), GenCollectedHeap() • CollectHeap::initialize() … GC アルゴリズム応じたヒープ領域確保 • CMSの場合は、GenCollectedHeap::initialize() • ConcurrentMarkSweepPolicy(), GenCollectorPolicy::initialize_all() • ヒープ空間の各世代に対応する Generation オブジェクトを作成 • CMS GC Thread の作成 90Inside OpenJDK
  • 91. GC 着火 • メモリ確保 • 4 つの bytecode (new, newarray, anewarray, multianewarray) • TemplateTable 起動 • 各 Runtime クラスからメモリ確保関数が呼ばれる • instanceKlass::allocate_instance(), oopFactory::new_typeArray(), oopFactory::new_objArray(), arrayKlass::multi_allocate() • 最終的に CollectedHeap::common_mem_allocate_init() を呼ぶ • TLAB からの確保 (UseTLAB使用時, CollectedHeap::allocate_from_tlab()) • CollectedHeap::mem_allocate() … GCに応じたメモリ確保 • この二つの両方で失敗したら OufOfMemoryError 91Inside OpenJDK
  • 92. GC 着火 • GenCollectedHeap::mem_allocate() … CMS のメモリ確保 • GenCollectorPolicy::mem_allocate_work() • Generation::par_allocate() … New領域からの獲得 • GenCollectedHeap::attempt_allocation() … 各世代からの獲得 • Generation::allocate() … 各世代定義オブジェクトの処理 • GenCollectorPolicy::expand_heap_and_allocate() … ヒープ拡張 • VM_GenCollectForAllocation::doit() … GC の起動 • GenCollectedHeap::do_collection() • GenCollectorPolicy::satisfy_failed_allocation() • GC後、上のmem_allocate_work()が行われる 92Inside OpenJDK
  • 93. ほんとにおしまい •質問は @sugarlife か #ccc_r16 へ •懇親会でも受付中！ 93 KUBOTA Yuji @sugarlife kubota.yuji@gmail.com