CMS GC日志分析 · 日常學習

## 引入讓我們先簡單的看下整個堆年輕代和年老代的垃圾收集器組合（以下配合java8完美支持，其他版本可能稍有不同），其中標紅線的則是我們今天要著重講的內容： ### 垃圾回收器的可用組合 ![](https://box.kancloud.cn/48e96090c730a1e10b14b0d2dd9a91f1_620x365.png) ### ParNew and CMS "Concurrent Mark and Sweep" 是CMS的全稱，官方給予的名稱是：“Mostly Concurrent Mark and Sweep Garbage Collector”; * 年輕代：采用 stop-the-world mark-copy 算法； * 年老代：采用 Mostly Concurrent mark-sweep 算法； * 設計目標：年老代收集的時候避免長時間的暫停；能夠達成該目標主要因為以下兩個原因： * 1 它不會花時間整理壓縮年老代，而是維護了一個叫做 free-lists 的數據結構，該數據結構用來管理那些回收再利用的內存空間； * 2 mark-sweep分為多個階段，其中一大部分階段GC的工作是和Application threads的工作同時進行的（當然，gc線程會和用戶線程競爭CPU的時間），默認的GC的工作線程為你服務器物理CPU核數的1/4；補充：**當你的服務器是多核同時你的目標是低延時，那該GC的搭配則是你的不二選擇**。 ## 日志 ### GC日志初體驗首先對整個GC日志有一個大概的認知 ``` 2016-08-23T02:23:07.219-0200: 64.322: [GC (Allocation Failure) 64.322: [ParNew: 613404K->68068K(613440K), 0.1020465 secs] 10885349K->10880154K(12514816K), 0.1021309 secs] [Times: user=0.78 sys=0.01, real=0.11 secs]2016-08-23T02:23:07.321-0200: 64.425: [GC (CMS Initial Mark) [1 CMS-initial-mark: 10812086K(11901376K)] 10887844K(12514816K), 0.0001997 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 2016-08-23T02:23:07.321-0200: 64.425: [CMS-concurrent-mark-start] 2016-08-23T02:23:07.357-0200: 64.460: [CMS-concurrent-mark: 0.035/0.035 secs] [Times: user=0.07 sys=0.00, real=0.03 secs] 2016-08-23T02:23:07.357-0200: 64.460: [CMS-concurrent-preclean-start] 2016-08-23T02:23:07.373-0200: 64.476: [CMS-concurrent-preclean: 0.016/0.016 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 2016-08-23T02:23:07.373-0200: 64.476: [CMS-concurrent-abortable-preclean-start] 2016-08-23T02:23:08.446-0200: 65.550: [CMS-concurrent-abortable-preclean: 0.167/1.074 secs] [Times: user=0.20 sys=0.00, real=1.07 secs] 2016-08-23T02:23:08.447-0200: 65.550: [GC (CMS Final Remark) [YG occupancy: 387920 K (613440 K)]65.550: [Rescan (parallel) , 0.0085125 secs]65.559: [weak refs processing, 0.0000243 secs]65.559: [class unloading, 0.0013120 secs]65.560: [scrub symbol table, 0.0008345 secs]65.561: [scrub string table, 0.0001759 secs][1 CMS-remark: 10812086K(11901376K)] 11200006K(12514816K), 0.0110730 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 2016-08-23T02:23:08.458-0200: 65.561: [CMS-concurrent-sweep-start] 2016-08-23T02:23:08.485-0200: 65.588: [CMS-concurrent-sweep: 0.027/0.027 secs] [Times: user=0.03 sys=0.00, real=0.03 secs] 2016-08-23T02:23:08.485-0200: 65.589: [CMS-concurrent-reset-start] 2016-08-23T02:23:08.497-0200: 65.601: [CMS-concurrent-reset: 0.012/0.012 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] Minor GC 2016-08-23T02:23:07.219-02001: 64.3222:[GC3(Allocation Failure4) 64.322: [ParNew5: 613404K->68068K6(613440K)7, 0.1020465 secs8] 10885349K->10880154K9(12514816K)10, 0.1021309 secs11][Times: user=0.78 sys=0.01, real=0.11 secs]12 ``` > 2016-08-23T02:23:07.219-0200 – GC發生的時間； > 64.322 – GC開始，相對JVM啟動的相對時間，單位是秒； > GC – 區別MinorGC和FullGC的標識，這次代表的是MinorGC; > Allocation Failure – MinorGC的原因，在這個case里邊，由于年輕代不滿足申請的空間，因此觸發了MinorGC; > ParNew – 收集器的名稱，它預示了年輕代使用一個并行的 mark-copy stop-the-world 垃圾收集器； > 613404K->68068K – 收集前后年輕代的使用情況； > (613440K) – 整個年輕代的容量； > 0.1020465 secs – 這個解釋用原滋原味的解釋：Duration for the collection w/o final cleanup. > 10885349K->10880154K – 收集前后整個堆的使用情況； > (12514816K) – 整個堆的容量； > 0.1021309 secs – ParNew收集器標記和復制年輕代活著的對象所花費的時間（包括和老年代通信的開銷、對象晉升到老年代時間、垃圾收集周期結束一些最后的清理對象等的花銷）； > [Times: user=0.78 sys=0.01, real=0.11 secs] – GC事件在不同維度的耗時，具體的用英文解釋起來更加合理: > user – Total CPU time that was consumed by Garbage Collector threads during this collection > sys – Time spent in OS calls or waiting for system event > real – Clock time for which your application was stopped. With Parallel GC this number should be close to (user time + system time) divided by the number of threads used by the Garbage Collector. In this particular case 8 threads were used. Note that due to some activities not being parallelizable, it always exceeds the ratio by a certain amount. 我們來分析下對象晉升問題（原文中的計算方式有問題）： > 開始的時候：整個堆的大小是 10885349K，年輕代大小是613404K，這說明老年代大小是 10885349-613404=10271945K， > 收集完成之后：整個堆的大小是 10880154K，年輕代大小是68068K，這說明老年代大小是 10880154-68068=10812086K， > 老年代的大小增加了：10812086-10271945=608209K，也就是說年輕代到年老代promot了608209K的數據；圖形分析： ![](https://box.kancloud.cn/8abaafe3b5ef8d3ce76cb53fb2782530_443x121.png) ## Full/Major GC ``` 2016-08-23T11:23:07.321-0200: 64.425: [GC (CMS Initial Mark)1 [1 CMS-initial-mark: 10812086K(11901376K)] 10887844K(12514816K), 0.0001997 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 2016-08-23T11:23:07.321-0200: 64.425: [CMS-concurrent-mark-start] 2016-08-23T11:23:07.357-0200: 64.460: [: 0.035/0.035 secs] [Times: user=0.07 sys=0.00, real=0.03 secs] 2016-08-23T11:23:07.357-0200: 64.460: [CMS-concurrent-preclean-start] 2016-08-23T11:23:07.373-0200: 64.476: [CMS-concurrent-preclean3: 0.016/0.016 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 2016-08-23T11:23:07.373-0200: 64.476: [CMS-concurrent-abortable-preclean-start] 2016-08-23T11:23:08.446-0200: 65.550: [CMS-concurrent-abortable-preclean4: 0.167/1.074 secs] [Times: user=0.20 sys=0.00, real=1.07 secs] 2016-08-23T11:23:08.447-0200: 65.550: [GC (CMS Final Remark5) [YG occupancy: 387920 K (613440 K)]65.550: [Rescan (parallel) , 0.0085125 secs]65.559: [weak refs processing, 0.0000243 secs]65.559: [class unloading, 0.0013120 secs]65.560: [scrub symbol table, 0.0008345 secs]65.561: [scrub string table, 0.0001759 secs][1 CMS-remark: 10812086K(11901376K)] 11200006K(12514816K), 0.0110730 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 2016-08-23T11:23:08.458-0200: 65.561: [CMS-concurrent-sweep-start] 2016-08-23T11:23:08.485-0200: 65.588: [CMS-concurrent-sweep6: 0.027/0.027 secs] [Times: user=0.03 sys=0.00, real=0.03 secs] 2016-08-23T11:23:08.485-0200: 65.589: [CMS-concurrent-reset-start] 2016-08-23T11:23:08.497-0200: 65.601: [CMS-concurrent-reset7: 0.012/0.012 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] ``` ### Phase 1: Initial Mark **這是CMS中兩次stop-the-world事件中的一次**。它有兩個目標：**一是標記老年代中所有的GC Roots；二是標記被年輕代中活著的對象引用的對象**。標記結果如下： ![](https://box.kancloud.cn/a5ab93224108f7ebc6882f850bef8fcc_344x124.png) 分析： ``` 2016-08-23T11:23:07.321-0200: 64.42: [GC (CMS Initial Mark[1 CMS-initial-mark: 10812086K(11901376K)] 10887844K(12514816K), 0.0001997 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] ``` > 016-08-23T11:23:07.321-0200: 64.42 – GC事件開始，包括時鐘時間和相對JVM啟動時候的相對時間，下邊所有的階段改時間的含義相同； > CMS Initial Mark – 收集階段，開始收集所有的GC Roots和直接引用到的對象； > 10812086K – 當前老年代使用情況； > (11901376K) – 老年代可用容量； > 10887844K – 當前整個堆的使用情況； > (12514816K) – 整個堆的容量； > 0.0001997 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] – 時間計量； ### Phase 2: Concurrent Mark 這個階段會**遍歷整個老年代并且標記所有存活的對象**，從“初始化標記”階段找到的GC Roots開始。并發標記的特點是和應用程序線程同時運行。并不是老年代的所有存活對象都會被標記，因為標記的同時應用程序會改變一些對象的引用等。標記結果如下： ![](https://box.kancloud.cn/1644ef693ac59d06f22b75d320301c2e_399x151.png) 在上邊的圖中，一個引用的箭頭已經遠離了當前對象（current obj）分析： ``` 2016-08-23T11:23:07.321-0200: 64.425: [CMS-concurrent-mark-start] 2016-08-23T11:23:07.357-0200: 64.460: [CMS-concurrent-mark: 035/0.035 secs] [Times: user=0.07 sys=0.00, real=0.03 secs] ``` > CMS-concurrent-mark – 并發收集階段，這個階段會遍歷整個年老代并且標記活著的對象； > 035/0.035 secs – 展示該階段持續的時間和時鐘時間； > [Times: user=0.07 sys=0.00, real=0.03 secs] – 同上 ### Phase 3: Concurrent Preclean 這個階段又是一個并發階段，和應用線程并行運行，不會中斷他們。前一個階段在并行運行的時候，一些對象的引用已經發生了變化，當這些引用發生變化的時候，JVM會標記堆的這個區域為Dirty Card(包含被標記但是改變了的對象，被認為"dirty")，這就是 Card Marking。 ![](https://box.kancloud.cn/c7673c759b382216da258cecc61c86d6_508x185.png) 在pre-clean階段，那些能夠從dirty card對象到達的對象也會被標記，這個標記做完之后，**dirty card標記就會被清除**了，如下： ![](https://box.kancloud.cn/7b4c9549db9e49b67e323eb20722477b_567x204.png) 另外，一些必要的清掃工作也會做，還會做一些final remark階段需要的準備工作；分析 ``` 2016-08-23T11:23:07.357-0200: 64.460: [CMS-concurrent-preclean-start] 2016-08-23T11:23:07.373-0200: 64.476: [CMS-concurrent-preclean: 0.016/0.016 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] ``` > CMS-concurrent-preclean – 這個階段負責前一個階段標記了又發生改變的對象標記； > 0.016/0.016 secs – 展示該階段持續的時間和時鐘時間； > [Times: user=0.02 sys=0.00, real=0.02 secs] – 同上 ### Phase 4: Concurrent Abortable Preclean 又一個并發階段不會停止應用程序線程。這個階段嘗試著去承擔STW的Final Remark階段足夠多的工作。這個階段持續的時間依賴好多的因素，由于這個階段是**重復的做相同的事情直到發生aboart的條件**（比如：重復的次數、多少量的工作、持續的時間等等）之一才會停止。 ``` 2016-08-23T11:23:07.373-0200: 64.476: [CMS-concurrent-abortable-preclean-start] 2016-08-23T11:23:08.446-0200: 65.550: [CMS-concurrent-abortable-preclean: 0.167/1.074 secs] [Times: user=0.20 sys=0.00, real=1.07 secs] ``` > CMS-concurrent-abortable-preclean – 可終止的并發預清理； > 0.167/1.074 secs – 展示該階段持續的時間和時鐘時間（It is interesting to note that the user time reported is a lot smaller than clock time. Usually we have seen that real time is less than user time, meaning that some work was done in parallel and so elapsed clock time is less than used CPU time. Here we have a little amount of work – for 0.167 seconds of CPU time, and garbage collector threads were doing a lot of waiting. Essentially, they were trying to stave off for as long as possible before having to do an STW pause. By default, this phase may last for up to 5 seconds）； > [Times: user=0.20 sys=0.00, real=1.07 secs] – 同上 **這個階段很大程度的影響著即將來臨的Final Remark的停頓**，有相當一部分重要的 configuration options 和失敗的模式； ### Phase 5: Final Remark 這個階段是CMS中第二個并且是最后一個STW的階段。該階段的任務是**完成標記整個年老代的所有的存活對象**。由于之前的預處理是并發的，它可能跟不上應用程序改變的速度，這個時候，STW是非常需要的來完成這個嚴酷考驗的階段。通常CMS盡量運行Final Remark階段在年輕代是足夠干凈的時候，目的是消除緊接著的連續的幾個STW階段。分析： ``` 2016-08-23T11:23:08.447-0200: 65.550: [GC (CMS Final Remark) [YG occupancy: 387920 K (613440 K)]65.550: [Rescan (parallel) , 0.0085125 secs]465.559: [weak refs processing, 0.0000243 secs]65.559: [class unloading, 0.0013120 secs]65.560: [scrub string table, 0.0001759 secs][1 CMS-remark: 10812086K(11901376K)] 11200006K(12514816K) , 0.0110730 secs] [[Times: user=0.06 sys=0.00, real=0.01 secs] 2016-08-23T11:23:08.447-0200: 65.550 – 同上； ``` CMS Final Remark – 收集階段，**這個階段會標記老年代全部的存活對象，包括那些在并發標記階段更改的或者新創建的引用對象**； > YG occupancy: 387920 K (613440 K) – 年輕代當前占用情況和容量； > [Rescan (parallel) , 0.0085125 secs] – 這個階段在應用停止的階段完成存活對象的標記工作； > weak refs processing, 0.0000243 secs]65.559 – 第一個子階段，隨著這個階段的進行處理弱引用； > class unloading, 0.0013120 secs]65.560 – 第二個子階段(that is unloading the unused classes, with the duration and timestamp of the phase); > scrub string table, 0.0001759 secs – 最后一個子階段（that is cleaning up symbol and string tables which hold class-level metadata and internalized string respectively） > 10812086K(11901376K) – 在這個階段之后老年代占有的內存大小和老年代的容量； > 11200006K(12514816K) – 在這個階段之后整個堆的內存大小和整個堆的容量； > 0.0110730 secs – 這個階段的持續時間； > [Times: user=0.06 sys=0.00, real=0.01 secs] – 同上；通過以上5個階段的標記，老年代所有存活的對象已經被標記并且現在要通過Garbage Collector采用清掃的方式回收那些不能用的對象了。 ### Phase 6: Concurrent Sweep **和應用線程同時進行，不需要STW**。這個階段的目的就是**移除那些不用的對象**，回收他們占用的空間并且為將來使用。如圖： ![](https://box.kancloud.cn/1499e31f7baba8f9c09541eb11e5ad0d_443x166.png) 分析： ``` 2016-08-23T11:23:08.458-0200: 65.561: [CMS-concurrent-sweep-start] 2016-08-23T11:23:08.485-0200: 65.588: [CMS-concurrent-sweep: 0.027/0.027 secs] [[Times: user=0.03 sys=0.00, real=0.03 secs] ``` > CMS-concurrent-sweep – 這個階段主要是清除那些沒有標記的對象并且回收空間； > 0.027/0.027 secs – 展示該階段持續的時間和時鐘時間； > [Times: user=0.03 sys=0.00, real=0.03 secs] – 同上 ### Phase 7: Concurrent Reset 這個階段并發執行，**重新設置CMS算法內部的數據結構**，準備下一個CMS生命周期的使用。 ``` 2016-08-23T11:23:08.485-0200: 65.589: [CMS-concurrent-reset-start] 2016-08-23T11:23:08.497-0200: 65.601: [CMS-concurrent-reset: 0.012/0.012 secs] [[Times: user=0.01 sys=0.00, real=0.01 secs] ``` > CMS-concurrent-reset – 這個階段重新設置CMS算法內部的數據結構，為下一個收集階段做準備； > 0.012/0.012 secs – 展示該階段持續的時間和時鐘時間； > [Times: user=0.01 sys=0.00, real=0.01 secs] – 同上