CMS日誌

廣訓發表於2019-01-19

1. GC引數配置

-XX:+PrintGC

輸出GC日誌。

-verbose:gc

可以認為 -verbose:gc-XX:+PrintGC 的別名。

-Xloggc:log/gc.log

輸出GC日誌的儲存路徑。

-XX:+PrintGCDetails

輸出GC的詳細日誌。

-XX:+PrintGCDateStamps

輸出GC的時間戳(以日期的形式)。

-XX:+ExplicitGCInvokesConcurrent

無論什麼時候呼叫系統GC,都執行CMS GC,而不是Full GC。

-XX:+PrintHeapAtGC

在進行GC的前後列印出堆的資訊。

-Xms512m

設定初始堆的大小。

-Xmx512m

堆分配的最大空間。

-Xmn1024m

設定年輕代大小。

整個JVM記憶體大小 = 年輕代大小 + 年老代大小 + 持久代大小,持久代一般固定大小為64m,所以增大年輕代後,將會減小年老代大小。此值對系統效能影響較大,Sun官方推薦配置為整個堆的3/8。

-Xss320K

設定每個執行緒的堆疊大小。

JDK5.0以後每個執行緒堆疊大小為1M,以前每個執行緒堆疊大小為256K。根據應用的執行緒所需記憶體大小進行調整。在相同實體記憶體下,減小這個值能生成更多的執行緒。但是作業系統對一個程式內的執行緒數還是有限制的,不能無限生成,經驗值在3000~5000左右。

-XX:+UseConcMarkSweepGC

使用CMS收集器,其它類似。

-XX:NewRatio=4

設定年輕代(包括Eden和兩個Survivor區)與年老代的比值(除去持久代)。設定為4,則年輕代與年老代所佔比值為1:4,年輕代佔整個堆疊的1/5,預設值是2即老年代是新生代記憶體的2倍

-XX:SurvivorRatio=4

設定年輕代中Eden區與Survivor區的大小比值。設定為4,則兩個Survivor區與一個Eden區的比值為2:4,一個Survivor區佔整個年輕代的1/6,預設值為8。

-XX:MaxPermSize=16m

設定持久代大小為16m。

-XX:MaxTenuringThreshold=0

設定垃圾最大年齡。如果設定為0的話,則年輕代物件不經過Survivor區,直接進入年老代。對於年老代比較多的應用,可以提高效率。如果將此值設定為一個較大值,則年輕代物件會在Survivor區進行多次複製,這樣可以增加物件再年輕代的存活時間,增加在年輕代即被回收的概論。

GC[Allocation Failure]表示向young generation(eden)給新物件申請空間,但是young generation(eden)剩餘的合適空間不夠所需的大小導致的minor gc。

2. Minor GC: UseParNewGC 回收日誌

2018-12-29T14:39:40.102+0800: 3.856: [GC (Allocation Failure) 2018-12-29T14:39:40.102+0800: 3.856: [ParNew: 681600K->72044K(766784K), 0.0977206 secs] 681600K->72044K(4109120K), 0.0978554 secs] [Times: user=0.39 
sys=0.06, real=0.10 secs]

2018-12-29T14:39:40.102+0800 本次gc觸發的時間;

3.856 jvm啟動後所經歷的秒數;

GC (Allocation Failure) 物件分配在新生代但空間不夠導致觸發一次新生代gc;

ParNew 表示這是新生代gc型別, 即ParNewGC;

681600K->72044K(766784K), 0.0977206 secs 觸發新生代gc時年輕代堆的大小,回收後的年輕代堆的大小,年輕代堆的總大小,該次gc回收所耗費的時間;

681600K->72044K(4109120K) 回收前堆的總大小,回收後堆的總大小,堆的總大小。

3. Major GC: UseConcMarkSweepGC 垃圾收集

CMS垃圾收集器總共分為7個階段,其中有2個階段,即是初始標記和最終標記階段,是需要暫停使用者執行緒的,其餘垃圾收集執行緒均與使用者執行緒併發執行。

CMS垃圾收集器在新版本的 Java 中被標記為棄用,後續的垃圾收集器預設使用G1GC。但目前很大一部分的垃圾收集器依然是CMS,故需要了解一下CMS垃圾收集的一些流程。

3.1 Phase 1: Initial Mark 初始標記

2018-12-29T14:46:45.247+0800: 429.000: [GC (CMS Initial Mark) [1 CMS-initial-mark: 17305K(3342336K)] 607785K(4109120K), 0.0704856 secs] [Times: user=0.32 sys=0.10, real=0.07 secs] 

這是CMS中兩次stop-the-world事件中的一次。它有兩個目標:一是標記老年代中所有的GC Roots;二是標記被年輕代中活著的物件引用的物件;

[1 CMS-initial-mark 收集階段,開始收集所有的GC Roots和直接引用到的物件;

17305K(3342336K) 當前老年代的使用情況,老年代可用容量;

607785K(4109120K) 當前整個堆的使用情況,整個堆的容量,即是整個堆 – 老年代 = 新生代(4109120 – 3342336 = 766784)。

3.2 Phase 2: Concurrent Mark 併發標記

2018-12-29T14:46:45.317+0800: 429.071: [CMS-concurrent-mark-start]
2018-12-29T14:46:45.326+0800: 429.080: [CMS-concurrent-mark: 0.009/0.009 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]

這個階段會遍歷整個老年代並且標記所有存活的物件,從“初始化標記”階段找到的GC Roots開始。併發標記的特點是和應用程式執行緒同時執行。並不是老年代的所有存活物件都會被標記,因為標記的同時應用程式會改變一些物件的引用等;

CMS-concurrent-mark 併發收集階段,這個階段會遍歷整個年老代並且標記活著的物件。

0.009/0.009 secs 展示該階段持續的時間和時鐘時間。

3.3 Phase 3: Concurrent Preclean 併發預清除

2018-12-29T14:46:45.326+0800: 429.080: [CMS-concurrent-preclean-start]
2018-12-29T14:46:45.338+0800: 429.092: [CMS-concurrent-preclean: 0.012/0.012 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]

這個階段又是一個併發階段,和應用執行緒並行執行,不會中斷他們。前一個階段在並行執行的時候,一些物件的引用已經發生了變化,當這些引用發生變化的時候,JVM會標記堆的這個區域為Dirty Card(包含被標記但是改變了的物件,被認為”dirty”),這就是 Card Marking;

在pre-clean階段,那些能夠從dirty card物件到達的物件也會被標記,這個標記做完之後,dirty card標記就會被清除了;

一些必要的清掃工作也會做,還會做一些final remark階段需要的準備工作;

CMS-concurrent-preclean 這個階段負責前一個階段標記了又發生改變的物件標記。

3.4 Phase 4: Concurrent Abortable Preclean 可終止的併發預清理

2018-12-29T14:46:45.338+0800: 429.092: [CMS-concurrent-abortable-preclean-start]
CMS: abort preclean due to time 2018-12-29T14:46:50.484+0800: 434.238: [CMS-concurrent-abortable-preclean: 4.232/5.146 secs] [Times: user=5.49 sys=0.10, real=5.15 secs] 

又一個併發階段不會停止應用程式執行緒。這個階段嘗試著去承擔STW的Final Remark階段足夠多的工作。這個階段持續的時間依賴好多的因素,由於這個階段是重複的做相同的事情直到發生aboart的條件(比如:重複的次數、多少量的工作、持續的時間等等)之一才會停止;

CMS-concurrent-abortable-preclean 可終止的併發預清理;

這個階段很大程度的影響著即將來臨的Final Remark的停頓,有相當一部分重要的 configuration options 和 失敗的模式。

3.5 Phase 5: Final Remark 最終標記

2018-12-29T14:46:50.485+0800: 434.239: [GC (CMS Final Remark) [YG occupancy: 632074 K (766784 K)]2018-12-29T14:46:50.485+0800: 434.239: [Rescan (parallel) , 0.0791637 secs]2018-12-29T14:46:50.564+0800: 434.318: 
[weak refs processing, 0.0001243 secs]2018-12-29T14:46:50.565+0800: 434.318: [class unloading, 0.0409380 secs]2018-12-29T14:46:50.605+0800: 434.359: [scrub symbol table, 0.0136356 secs]2018-12-29T14:46:50.619+08
00: 434.373: [scrub string table, 0.0015586 secs][1 CMS-remark: 17305K(3342336K)] 649380K(4109120K), 0.1370772 secs] [Times: user=0.46 sys=0.06, real=0.13 secs] 

這個階段是CMS中第二個並且是最後一個STW的階段。該階段的任務是完成標記整個年老代的所有的存活物件。由於之前的預處理是併發的,它可能跟不上應用程式改變的速度,這個時候,STW是非常需要的來完成這個嚴酷考驗的階段;

通常CMS儘量執行Final Remark階段在年輕代是足夠乾淨的時候,目的是消除緊接著的連續的幾個STW階段;

CMS Final Remark 收集階段,這個階段會標記老年代全部的存活物件,包括那些在併發標記階段更改的或者新建立的引用物件;

YG occupancy: 632074 K (766784 K) 年輕代當前佔用的情況和容量;

Rescan (parallel) 這個階段在應用停止的階段完成存活物件的標記工作;

weak refs processing 第一個子階段,隨著這個階段的進行處理弱引用;

class unloading 第二個子階段, 類的解除安裝;

scrub symbol table 最後一個子階段, 清理字元引用等;

1 CMS-remark: 17305K(3342336K) 在這個階段之後老年代佔有的記憶體大小和老年代的容量;

649380K(4109120K) 在這個階段之後整個堆的記憶體大小和整個堆的容量;

通過以上5個階段的標記,老年代所有存活的物件已經被標記並且現在要通過Garbage Collector採用清掃的方式回收那些不能用的物件了。

3.6 Phase 6: Concurrent Sweep 併發清除

2018-12-29T14:46:50.622+0800: 434.376: [CMS-concurrent-sweep-start]
2018-12-29T14:46:50.635+0800: 434.388: [CMS-concurrent-sweep: 0.012/0.012 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 

和應用執行緒同時進行,不需要STW。這個階段的目的就是移除那些不用的物件,回收他們佔用的空間並且為將來使用;

CMS-concurrent-sweep 這個階段主要是清除那些沒有標記的物件並且回收空間。

3.7 Phase 7: Concurrent Reset 併發重置

2018-12-29T14:46:50.635+0800: 434.388: [CMS-concurrent-reset-start]
2018-12-29T14:46:50.651+0800: 434.405: [CMS-concurrent-reset: 0.016/0.016 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 

這個階段併發執行,重新設定CMS演算法內部的資料結構,準備下一個CMS生命週期的使用;

CMS-concurrent-reset 這個階段重新設定CMS演算法內部的資料結構,為下一個收集階段做準備;

可參考JVM調優——之CMS GC日誌分析

相關文章