JVM調優——之CMS GC日誌分析

時間  2019-11-10
標籤 jvm cms 日誌 分析 欄目 Java 简体版
原文   原文鏈接

       最近在學習JVM和GC調優,今天總結下CMS的一些特色和要點,讓咱們先簡單的看下整個堆年輕代和年老代的垃圾收集器組合（如下配合java8完美支持，其餘版本可能稍有不一樣），其中標紅線的則是咱們今天要着重講的內容：html

垃圾回收器的可用組合:

 

 

ParNew and CMS

"Concurrent Mark and Sweep" 是CMS的全稱，官方給予的名稱是：「Mostly Concurrent Mark and Sweep Garbage Collector」;java

年輕代：採用 stop-the-world mark-copy 算法；node

年老代：採用 Mostly Concurrent mark-sweep 算法；算法

設計目標：年老代收集的時候避免長時間的暫停；服務器

可以達成該目標主要由於如下兩個緣由：數據結構

1  它不會花時間整理壓縮年老代，而是維護了一個叫作 free-lists 的數據結構，該數據結構用來管理那些回收再利用的內存空間；併發

2  mark-sweep分爲多個階段，其中一大部分階段GC的工做是和Application threads的工做同時進行的（固然，gc線程會和用戶線程競爭CPU的時間），默認的GC的工做線程爲你服務器物理CPU核數的1/4；oracle

補充：當你的服務器是多核同時你的目標是低延時，那該GC的搭配則是你的不二選擇。app

 

日誌

GC日誌初體驗

首先對整個GC日誌有一個大概的認知less

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

    1. 2016-08-23T02:23:07.219-0200 – GC發生的時間；
    2. 64.322 – GC開始，相對JVM啓動的相對時間，單位是秒；
    3. GC – 區別MinorGC和FullGC的標識，此次表明的是MinorGC;
    4. Allocation Failure – MinorGC的緣由，在這個case裏邊，因爲年輕代不知足申請的空間，所以觸發了MinorGC;
    5. ParNew – 收集器的名稱，它預示了年輕代使用一個並行的 mark-copy stop-the-world 垃圾收集器；
    6. 613404K->68068K – 收集先後年輕代的使用狀況；
    7. (613440K) – 整個年輕代的容量；
    8. 0.1020465 secs – 這個解釋用原滋原味的解釋：Duration for the collection w/o final cleanup.
    9. 10885349K->10880154K – 收集先後整個堆的使用狀況；
    10. (12514816K) – 整個堆的容量；
    11. 0.1021309 secs – ParNew收集器標記和複製年輕代活着的對象所花費的時間（包括和老年代通訊的開銷、對象晉升到老年代時間、垃圾收集週期結束一些最後的清理對象等的花銷）；
    12. [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的數據；

圖形分析：

          

 

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；二是標記被年輕代中活着的對象引用的對象。

標記結果以下：

分析：

2016-08-23T11:23:07.321-0200: 64.421: [GC (CMS Initial Mark2[1 CMS-initial-mark: 10812086K3(11901376K)4] 10887844K5(12514816K)6, 0.0001997 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]7

    1. 016-08-23T11:23:07.321-0200: 64.42 – GC事件開始，包括時鐘時間和相對JVM啓動時候的相對時間，下邊全部的階段改時間的含義相同；
    2. CMS Initial Mark – 收集階段，開始收集全部的GC Roots和直接引用到的對象；
    3. 10812086K – 當前老年代使用狀況；
    4. (11901376K) – 老年代可用容量；
    5. 10887844K – 當前整個堆的使用狀況；
    6. (12514816K) – 整個堆的容量；
    7. 0.0001997 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] – 時間計量；

Phase 2: Concurrent Mark

這個階段會遍歷整個老年代而且標記全部存活的對象，從「初始化標記」階段找到的GC Roots開始。併發標記的特色是和應用程序線程同時運行。並非老年代的全部存活對象都會被標記，由於標記的同時應用程序會改變一些對象的引用等。

標記結果以下：

在上邊的圖中，一個引用的箭頭已經遠離了當前對象（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-mark1: 035/0.035 secs2] [Times: user=0.07 sys=0.00, real=0.03 secs]3
    1. CMS-concurrent-mark – 併發收集階段，這個階段會遍歷整個年老代而且標記活着的對象；
    2. 035/0.035 secs – 展現該階段持續的時間和時鐘時間；
    3. [Times: user=0.07 sys=0.00, real=0.03 secs] – 同上

Phase 3: Concurrent Preclean

這個階段又是一個併發階段，和應用線程並行運行，不會中斷他們。前一個階段在並行運行的時候，一些對象的引用已經發生了變化，當這些引用發生變化的時候，JVM會標記堆的這個區域爲Dirty Card(包含被標記可是改變了的對象，被認爲"dirty")，這就是 Card Marking。

在pre-clean階段，那些可以從dirty card對象到達的對象也會被標記，這個標記作完以後，dirty card標記就會被清除了，以下：

另外，一些必要的清掃工做也會作，還會作一些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-preclean1: 0.016/0.016 secs2] [Times: user=0.02 sys=0.00, real=0.02 secs]3
    1. CMS-concurrent-preclean – 這個階段負責前一個階段標記了又發生改變的對象標記；
    2. 0.016/0.016 secs – 展現該階段持續的時間和時鐘時間；
    3. [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-preclean1: 0.167/1.074 secs2] [Times: user=0.20 sys=0.00, real=1.07 secs]3
    1. CMS-concurrent-abortable-preclean – 可終止的併發預清理；
    2. 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）；
    3. [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.5501: [GC (CMS Final Remark2) [YG occupancy: 387920 K (613440 K)3]65.550: [Rescan (parallel) , 0.0085125 secs]465.559: [weak refs processing, 0.0000243 secs]65.5595: [class unloading, 0.0013120 secs]65.5606: [scrub string table, 0.0001759 secs7][1 CMS-remark: 10812086K(11901376K)8] 11200006K(12514816K) 9, 0.0110730 secs10] [[Times: user=0.06 sys=0.00, real=0.01 secs]11

    1. 2016-08-23T11:23:08.447-0200: 65.550 – 同上；
    2. CMS Final Remark – 收集階段，這個階段會標記老年代所有的存活對象，包括那些在併發標記階段更改的或者新建立的引用對象；
    3. YG occupancy: 387920 K (613440 K) – 年輕代當前佔用狀況和容量；
    4. [Rescan (parallel) , 0.0085125 secs] – 這個階段在應用中止的階段完成存活對象的標記工做；
    5. weak refs processing, 0.0000243 secs]65.559 – 第一個子階段，隨着這個階段的進行處理弱引用；
    6. class unloading, 0.0013120 secs]65.560 – 第二個子階段(that is unloading the unused classes, with the duration and timestamp of the phase);
    7. scrub string table, 0.0001759 secs – 最後一個子階段（that is cleaning up symbol and string tables which hold class-level metadata and internalized string respectively）
    8. 10812086K(11901376K) – 在這個階段以後老年代佔有的內存大小和老年代的容量；
    9. 11200006K(12514816K) – 在這個階段以後整個堆的內存大小和整個堆的容量；
    10. 0.0110730 secs – 這個階段的持續時間；
    11. [Times: user=0.06 sys=0.00, real=0.01 secs] – 同上；

經過以上5個階段的標記，老年代全部存活的對象已經被標記而且如今要經過Garbage Collector採用清掃的方式回收那些不能用的對象了。

Phase 6: Concurrent Sweep

和應用線程同時進行，不須要STW。這個階段的目的就是移除那些不用的對象，回收他們佔用的空間而且爲未來使用。

如圖：

 

 

分析：

2016-08-23T11:23:08.458-0200: 65.561: [CMS-concurrent-sweep-start] 2016-08-23T11:23:08.485-0200: 65.588: [CMS-concurrent-sweep1: 0.027/0.027 secs2] [[Times: user=0.03 sys=0.00, real=0.03 secs] 3

    1. CMS-concurrent-sweep – 這個階段主要是清除那些沒有標記的對象而且回收空間；
    2. 0.027/0.027 secs – 展現該階段持續的時間和時鐘時間；
    3. [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-reset1: 0.012/0.012 secs2] [[Times: user=0.01 sys=0.00, real=0.01 secs]3

      1. CMS-concurrent-reset – 這個階段從新設置CMS算法內部的數據結構，爲下一個收集階段作準備；
      2. 0.012/0.012 secs – 展現該階段持續的時間和時鐘時間；
      3. [Times: user=0.01 sys=0.00, real=0.01 secs] – 同上

 

 

 

轉自:http://www.cnblogs.com/zhangxiaoguang/p/5792468.html

相關文章
相關標籤/搜索
每日一句
    每一个你不满意的现在，都有一个你没有努力的曾经。
本站公眾號
   歡迎關注本站公眾號,獲取更多信息
聯繫我們 最近搜索 最新文章 沪ICP备13005482号-10 MyBatis教程 SQL 教程 MySQL教程 Java 教程 Thymeleaf 教程 Hibernate教程 Spring教程 Redis教程