2. 程式人生 > >詳解CMS收集過程和日誌分析

詳解CMS收集過程和日誌分析

阿新 • • 發佈：2018-11-28

讓我們先簡單的看下整個堆年輕代和年老代的垃圾收集器組合（以下配合java8完美支援，其他版本可能稍有不同），其中標紅線的則是我們今天要著重講的內容：

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

  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: [CMS-concurrent-mark2: 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] – 同上    

相關推薦

詳解CMS收集過程和日誌分析

讓我們先簡單的看下整個堆年輕代和年老代的垃圾收集器組合（以下配合java8完美支援，其他版本可能稍有不同），其中標紅線的則是我們今天要著重講的內容： ParNew and CMS "Concurrent Mark and Sweep" 是CMS的全稱，官方給予的名稱是：“Mostly

GC之詳解CMS收集過程和日誌分析

話題引入 讓我們先簡單的看下整個堆年輕代和年老代的垃圾收集器組合（以下配合java8完美支援，其他版本可能稍有不同），其中標紅線的則是我們今天要著重講的內容： ParNew and CMS "Concurrent Mark and Sweep" 是CMS的全稱，官方給予的名稱是：“Mostly Co

syslog、日誌服務器安裝、卸載詳解、如何安裝和卸載EventLog Analyzer

技術 src 如何 RoCE analyze sys ESS watermark 詳解 syslog、日誌服務器安裝、卸載詳解、如何安裝和卸載EventLog Analyzer

TCP/IP詳解--ICMP 控制報文和差錯報文 Tracerouter 命令的過程

分享一下我老師大神的人工智慧教程！零基礎，通俗易懂！http://blog.csdn.net/jiangjunshow 也歡迎大家轉載本篇文章。分享知識，造福人民，實現我們中華民族偉大復興！        

二叉樹之一BST樹，AVL樹詳解及B樹和紅黑樹原理分析

BST樹，AVL樹詳解及B樹和紅黑樹原理分析 網際網路面試中樹尤其是BST，AVL是提問的重點也是難點，甚至B樹乃至高階資料結構紅黑樹都是提問的重點，像阿里雲面試就曾經問過map實現機制（紅黑樹）及其原理，這裡我們要做到對BST/AVL完全熟悉能給出全部程式碼實現，紅黑樹、

日誌系統ELK使用詳解(四)--kibana安裝和使用

##概述# 這是這個小系列的最後一篇了，我們將看到如何安裝kibana，以及對ELK中的日誌資訊進行快速查詢。 ##kibana安裝# 1.到官網下載kibana； 2.解壓縮； 3.修改配置檔案kibana-5.3.0-darwin-x86_64/confi

Hbase 查詢過程詳解(基於hbase0.98版本後分析的)

hbase0.96版本後刪除了root 表，因為覺的目的是根據rroot表獲取meta地址，過程是通過zookeeper獲取root表地址，在根據root表記錄meta表地址進行訪問，還不如和zookeeper通訊一次。新增了namespace，詳細見patch設計（https://issues.apac

JVM中垃圾回收機制如何判斷是否死亡？詳解引用計數法和可達性分析 ！

> 因為熱愛，所以堅持。 > 文章下方有本文參考電子書和視訊的**下載地址**哦~ 這節我們主要講垃圾收集的一些基本概念，先了解垃圾收集是什麼、然後觸發條件是什麼、最後虛擬機器如何判斷物件是否死亡。 ### 一、前言   我們都知道Java和C++有一個非常大的區別就是Java有自動的垃圾回收

POI操作Excel詳解，讀取xls和xlsx格式的文件

shee xss split 類型 後綴 .sh lan xls lin package org.ian.webutil; import java.io.File; import java.io.FileInputStream; import java.io.FileN

[轉載]AMOLED結構詳解，BOE專家給你分析驅動補償

晶體 即使 長時間 http 如何 電容 環境 抽取 分享 關鍵詞： AMOLED, 驅動補償 有機發光顯示二極管（OLED）作為一種電流型發光器件已越來越多地被應用於高性能顯示中。由於它自發光的特性，與LCD相比，AMOLED具有高對比度、超輕薄

跨域問題相關知識詳解（原生js和jquery兩種方法實現jsonp跨域）

syn con 加載 developer 兩種方法 ray exe 編寫 分組 1、同源策略 同源策略（Same origin policy），它是由Netscape提出的一個著名的安全策略。同源策略是一種約定，它是瀏覽器最核心也最基本的安全功能，如果缺少了同源策略，則瀏覽

(轉)Java 詳解 JVM 工作原理和流程

移植 獲得 代碼 適配 調用 tac 階段 main方法 等待 作為一名Java使用者，掌握JVM的體系結構也是必須的。說起Java，人們首先想到的是Java編程語言，然而事實上，Java是一種技術，它由四方面組成：Java編程語言、Java類文件格式、Java虛擬機和Ja

Java 詳解 JVM 工作原理和流程

str literal 狀態 應用 流程 href ctu 局部變量 自定義 作為一名Java使用者，掌握JVM的體系結構也是必須的。說起Java，人們首先想到的是Java編程語言，然而事實上，Java是一種技術，它由四方面組成：Java編程語言、Java類文件格式、Jav

詳解MySQL基準測試和sysbench工具

threads 組件 程序 原因 str 前言 全面 無法連接 不同 前言 作為一名後臺開發，對數據庫進行基準測試，以掌握數據庫的性能情況是非常必要的。本文介紹了MySQL基準測試的基本概念，以及使用sysbench對MySQL進行基準測試的詳細方法。 文章有疏漏之處，歡迎

詳解MySQL基準測試和sysbench工具(轉)

lua 增刪 後臺 simple ads 執行時間 bench 進行 響應 前言 作為一名後臺開發，對數據庫進行基準測試，以掌握數據庫的性能情況是非常必要的。本文介紹了MySQL基準測試的基本概念，以及使用sysbench對MySQL進行基準測試的詳細方法。 文章有疏漏

Python第七課----正則和日誌分析

python一、正則表達式：1、分類： 1、BRE基本正則，grep、sed，vi等軟件支持，vim有擴展 2、ERE擴展正則，egrep、grep-E，sed-r等 3、PCRE最重要的，高級語言中的2、基本語法： 1、元字符 metacharacter.匹配除了換行符外任意一字符，叠代

詳解 最大子段和

最大 負數 nbsp 端點 關於 一段 描述 計數器 曾經 題目名稱：最大子段和 題目描述：給出一段序列，選出其中連續且非空的一段使得這段和最大。 輸入格式： 第一行是一個正整數N，表示了序列的長度。 第2行包含N個絕對值不大於10000的整數A[i]，描述了這段序列。

java類型轉換詳解（自動轉換和強制轉換）

代碼 oid 高精 log 相加 println 類型轉換詳解 範圍 void 自動轉換 class Hello { public static void main(String[] args) { //自動轉換 int a = 5; byte b = 6

datetime 模塊詳解 -- 基本的日期和時間類型

日歷 cell max 5-0 .cn 賦值 RR 意義 struct 轉自：https://www.cnblogs.com/fclbky/articles/4098204.html datetime 模塊提供了各種類用於操作日期和時間，該模塊側重於高效率的格式化輸出在 P

Squid代理服務器的ACL訪問控制和日誌分析

無需 連接 amp 文件 over fig url路徑 install 字符集 系統環境： 代理服務器(192.168.100.135)： YUM默認安裝無需配置即為標準正向代理模式，但是需對客戶端瀏覽器代理服務器進行設置（port：3128） yum instal