2. 程式人生 > >JVM系列4-GC log

JVM系列4-GC log

阿新 • • 發佈：2019-02-04

1、JVM引數

-XX:+PrintGC

引數-XX:+PrintGC開啟了簡單GC日誌模式，為每一次新生代（young generation）的GC和每一次的Full GC列印一行資訊。日誌預設輸出到終端。下面舉例說明：

[GC 1843K->632K(116736K), 0.0112928 secs]
[Full GC 632K->558K(116736K), 0.0157125 secs]

每行開始首先是GC的型別（可以是“GC”或者“Full GC”），然後是在GC之前和GC之後已使用的堆空間，再然後是當前的堆容量，最後是GC持續的時間（以秒計）。

第一行的意思就是GC將已使用的堆空間從1843K減少到632K，當前的堆容量（譯者注：GC發生時）是116736K，GC持續的時間是0.0112928 秒。

簡單模式的GC日誌格式是與GC演算法無關的，日誌也沒有提供太多的資訊。在上面的例子中，我們甚至無法從日誌中判斷是否GC將一些物件從young generation移到了old generation。所以詳細模式的GC日誌更有用一些。

-XX:PrintGCDetails

如果不是使用-XX:+PrintGC，而是-XX:PrintGCDetails，就開啟了詳細GC日誌模式。在這種模式下，日誌格式和所使用的GC演算法有關。我們首先看一下使用PS垃圾收集器在young generation中生成的日誌。為了便於閱讀這裡將一行日誌分為多行並使用縮排。備註：共同使用PrintGC和PrintGCDetails，只會顯示PrintGCDetails。

[GC
 [PSYoungGen: 1843K->632K(35840K)] 1843K->632K(116736K), 0.0149062 secs] 
 [Times: user=0.03 sys=0.00, real=0.02 secs] 

[Full GC 
 [PSYoungGen: 632K->0K(35840K)] 
 [ParOldGen: 0K->558K(80896K)] 632K->558K(116736K) 
 [PSPermGen: 2930K->2930K(21504K)], 0.0220857 secs]
 [Times: user=0.02 sys=0.00, real=0.02
 
 secs]

我們可以很容易發現：這是一次在young generation中的GC，它將已使用的堆空間從1843K減少到了632K，用時0.0149062秒。此外我們還可以得到更多的資訊：所使用的垃圾收集器（即Parallel Scavenge GC）、young generation的大小和使用情況（在這個例子中PS垃圾收集器將young generation所使用的堆空間從1843K減少到632K）。

既然我們已經知道了young generation的大小，所以很容易判定發生了GC，因為young generation無法分配更多的物件空間：已經使用了35840K中的1843K。我們可以進一步得出結論，多數從young generation移除的物件仍然在堆空間中，只是被移到了old generation。

接下來看一下Full GC的輸出日誌：
除了關於young generation的詳細資訊，日誌也提供了old generation和permanent generation的詳細資訊。對於這三個generations，一樣也可以看到所使用的垃圾收集器、堆空間的大小、GC前後的堆使用情況。需要注意的是顯示堆空間的大小等於young generation和old generation各自堆空間的和。以上面為例，堆空間總共佔用了558K，其中0K在young generation，558K在old generation。Full GC持續了0.02秒，使用者空間的CPU執行時間為0.02秒，說明GC使用了多執行緒。

對不同generation詳細的日誌可以讓我們分析GC的原因，如果某個generation的日誌顯示在GC之前，堆空間幾乎被佔滿，那麼很有可能就是這個generation觸發了GC。但是在上面的例子中，三個generation中的任何一個都不是這樣的，在這種情況下是什麼原因觸發了GC呢。對於Throughput垃圾收集器，在某一個generation被過度使用之前，GC ergonomics決定要啟動GC。

Full GC也可以通過顯式的請求而觸發，可以是通過應用程式，或者是一個外部的JVM介面。這樣觸發的GC可以很容易在日誌裡分辨出來，因為輸出的日誌是以“Full GC(System)”開頭的，而不是“Full GC”。

對於Serial垃圾收集器，詳細的GC日誌和Throughput垃圾收集器是非常相似的。唯一的區別是不同的generation日誌可能使用了不同的GC演算法。使用垃圾收集器作為一行日誌的開頭可以方便我們從日誌就判斷出JVM的GC設定。

對於CMS垃圾收集器，young generation的詳細日誌也和Throughput垃圾收集器非常相似，但是old generation的日誌卻不是這樣。對於CMS垃圾收集器，在old generation中的GC是在不同的時間片內與應用程式同時執行的。GC日誌自然也和Full GC的日誌不同。而且在不同時間片的日誌夾雜著在此期間young generation的GC日誌。但是瞭解了上面介紹的GC日誌的基本元素，也不難理解在不同時間片內的日誌。只是在解釋GC執行時間時要特別注意，由於大多數時間片內的GC都是和應用程式同時執行的，所以和那種獨佔式的GC相比，GC的持續時間更長一些並不說明一定有問題。

即使CMS垃圾收集器沒有完成一個CMS週期，Full GC也可能會發生。如果發生了GC，在日誌中會包含觸發Full GC的原因，例如眾所周知的”concurrent mode failure“。

-XX:+PrintGCTimeStamps和-XX:+PrintGCDateStamps

使用-XX:+PrintGCTimeStamps可以將時間和日期也加到GC日誌中。表示自JVM啟動至今的時間戳會被新增到每一行中。例子如下：

0.148: [GC
 [PSYoungGen: 1843K->632K(35840K)] 1843K->632K(116736K), 0.0147505 secs]
 [Times: user=0.05 sys=0.00, real=0.01 secs] 
0.163: [Full GC
 [PSYoungGen: 632K->0K(35840K)]
 [ParOldGen: 0K->557K(80896K)] 632K->557K(116736K)
 [PSPermGen: 2844K->2843K(21504K)], 0.0149489 secs]
 [Times: user=0.02 sys=0.00, real=0.02 secs]

如果同時指定了-XX:+PrintGCDateStamps，每一行就新增上了絕對的日期和時間：

2017-02-01T19:43:51.405+0800: 0.111: [GC
 [PSYoungGen: 1843K->632K(35840K)] 1843K->632K(116736K), 0.0019876 secs]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 

2017-02-01T19:43:51.407+0800: 0.113: [Full GC
 [PSYoungGen: 632K->0K(35840K)]
 [ParOldGen: 0K->557K(80896K)] 632K->557K(116736K)
 [PSPermGen: 2844K->2843K(21504K)], 0.0378132 secs]
 [Times: user=0.08 sys=0.00, real=0.04 secs]

-Xloggc

預設的GC日誌時輸出到終端的，使用-Xloggc:也可以輸出到指定的檔案。需要注意這個引數隱式的設定了引數-XX:+PrintGC和-XX:+PrintGCTimeStamps，但為了以防在新版本的JVM中有任何變化，我仍建議顯示的設定這些引數。

2、可管理的JVM引數

一個常常被討論的問題是在生產環境中GC日誌是否應該開啟。因為它所產生的開銷通常都非常有限，因此我的答案是需要開啟。但並不一定在啟動JVM時就必須指定GC日誌引數。

HotSpot JVM有一類特別的引數叫做可管理的引數。對於這些引數，可以在執行時修改他們的值。我們這裡所討論的所有引數以及以“PrintGC”開頭的引數都是可管理的引數。這樣在任何時候我們都可以開啟或是關閉GC日誌。比如我們可以使用JDK自帶的jinfo工具來設定這些引數，或者是通過JMX客戶端呼叫HotSpotDiagnostic MXBean的setVMOption方法來設定這些引數。

3、GC日誌分析工具 - GCviewer

4、CMS日誌分析

4.1 JVM引數設定

-XX:+PrintGC            // 輸出GC日誌
-XX:+PrintGCDetails     // 輸出GC的詳細日誌
-XX:+PrintGCTimeStamps  // 輸出GC的時間戳（以基準時間的形式）
-XX:+PrintGCDateStamps  // 輸出GC的時間戳（以日期的形式，如 2013-05-04T21:53:59.234+0800）
-Xloggc:./log/gc.log    // 日誌檔案的輸出路徑

-XX:+UseParNewGC        // 新生代使用ParNew回收器
-XX:+UseConcMarkSweepGC // 老年代使用CMS回收器

4.2 ParNew and CMS

年輕代：採用 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的搭配則是你的不二選擇。

4.3 日誌形式

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]

4.4 Minor GC

從年輕代空間（包括 Eden 和 Survivor 區域）回收記憶體被稱為 Minor GC。這一定義既清晰又易於理解。但是，當發生Minor GC事件的時候，有一些有趣的地方需要注意到：

  • 當 JVM 無法為一個新的物件分配空間時會觸發 Minor GC，比如當 Eden 區滿了。所以分配率越高，越頻繁執行 Minor GC。
  • 記憶體池被填滿的時候，其中的內容全部會被複制，指標會從0開始跟蹤空閒記憶體。Eden 和 Survivor 區進行了標記和複製操作，取代了經典的標記、掃描、壓縮、清理操作。所以 Eden 和 Survivor 區不存在記憶體碎片。寫指標總是停留在所使用記憶體池的頂部。
  • 執行 Minor GC 操作時，不會影響到永久代。從永久代到年輕代的引用被當成 GC roots，從年輕代到永久代的引用在標記階段被直接忽略掉。
  • 質疑常規的認知，所有的 Minor GC 都會觸發“stop-the-world”，停止應用程式的執行緒。對於大部分應用程式，停頓導致的延遲都是可以忽略不計的。其中的真相就是，大部分 Eden 區中的物件都能被認為是垃圾，永遠也不會被複制到 Survivor 區或者老年代空間。如果正好相反，Eden 區大部分新生物件不符合 GC 條件，Minor GC 執行時暫停的時間將會長很多。
    所以 Minor GC 的情況就相當清楚了 — 每次 Minor GC 會清理年輕代的記憶體。

2016-08-23T02:23:07.219-0200*1: 64.3222*:
[GC*3(Allocation Failure4*) 64.322:
　 [ParNew*5: 613404K->68068K6(613440K)7, 0.1020465 secs8*]
　　10885349K->10880154K*9(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的資料；

圖形分析：

4.5 Full/Major GC

大家應該注意到，目前，這些術語無論是在 JVM 規範還是在垃圾收集研究論文中都沒有正式的定義。但是我們一看就知道這些在我們已經知道的基礎之上做出的定義是正確的，Minor GC 清理年輕帶記憶體應該被設計得簡單：

  • Major GC 是清理老年代。
  • Full GC 是清理整個堆空間—包括年輕代和老年代。

很不幸，實際上它還有點複雜且令人困惑。首先，許多 Major GC 是由 Minor GC 觸發的，所以很多情況下將這兩種 GC 分離是不太可能的。另一方面，許多現代垃圾收集機制會清理部分永久代空間，所以使用“cleaning”一詞只是部分正確。

這使得我們不用去關心到底是叫 Major GC 還是 Full GC，大家應該關注當前的 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]

從上面的日誌中可以看到，這和上節（GC演算法 垃圾收集器概述）中介紹的CMS垃圾回收器的工作步驟是一致的，如下圖，
CMS垃圾回收器

從上圖可以看出，CMS回收時有兩個階段會發生“STW”，分別是：初始標記和重新標記。

Phase 1: Initial Mark
這是CMS中兩次stop-the-world事件中的一次。它有兩個目標：一是標記老年代中所有的GC Roots；二是標記被年輕代中活著的物件引用的物件。
標記結果如下：
Initial Mark

分析：
2016-08-23T11:23:07.321-0200: 64.42**1: [GC (**CMS Initial Mark2
[1 CMS-initial-mark: 10812086K**3(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開始。併發標記的特點是和應用程式執行緒同時執行，不會發生STW。並不是老年代的所有存活物件都會被標記，因為標記的同時應用程式會改變一些物件的引用等。

標記結果如下：

Concurrent Mark
在上邊的圖中，一個引用的箭頭已經遠離了當前物件（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 secs**2] [Times: user=0.07 sys=0.00, real=0.03 secs]2**
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
這個階段又是一個併發階段，和應用執行緒並行執行，不會中斷他們，不會發生STW。前一個階段在並行執行的時候，一些物件的引用已經發生了變化，當這些引用發生變化的時候，JVM會標記堆的這個區域為Dirty Card(包含被標記但是改變了的物件，被認為”dirty”)，這就是 Card Marking。
如下圖：


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

分析：
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 secs**2**]
[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 secs**2**]
[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.550**1: [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. lass 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。這個階段的目的就是移除那些不用的物件，回收他們佔用的空間並且為將來使用。
如圖：

Concurrent Sweep

分析：
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 secs**2**]
[[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 secs**2] [[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] – 同上

5、G1日誌分析

相關推薦

JVM系列4-GC log

1、JVM引數 -XX:+PrintGC 引數-XX:+PrintGC開啟了簡單GC日誌模式，為每一次新生代（young generation）的GC和每一次的Full GC列印一行資訊。日誌預設輸出到終端。下面舉例說明： [GC 1843K->

jvm系列:Java GC 分析

maxperm 日期 格式 ogg nth 意思 his cat 比較 Java GC就是JVM記錄儀，書畫了JVM各個分區的表演。 什麽是 Java GC Java GC（Garbage Collection，垃圾收集，垃圾回收）機制，是Java與C++/C的主要區別

【轉載】JVM系列二:GC策略&記憶體申請、物件衰老

  JVM裡的GC(Garbage Collection)的演算法有很多種，如標記清除收集器，壓縮收集器，分代收集器等等,詳見HotSpot VM GC 的種類        現在比較常用的是分代收集（generational colle

jvm系列之-gc日誌檢視

在上一篇中我們介紹的有引數的設定，那我們要了解不同的引數對於程式的影響和對於調優的影響，這個時候我們就需要檢視gc日誌來看我們設定的引數是否合理，這一章節中我們就來檢視gc日誌 一、新生代和老年代的比值對效能的影響 Map map = new HashMap<&

JVM系列：GC引數分析和調優

不管是YGC還是Full GC,GC過程中都會對導致程式執行中中斷,正確的選擇不同的GC策略,調整JVM、GC的引數，可以極大的減少由於GC工作，而導致的程式執行中斷方面的問題，進而適當的提高Java程式的工作效率。但是調整GC是以個極為複雜的過程，由於各個程式具備不同的特點

(拿來主義-4) JVM系列(四) - JVM GC回收算法

年輕代和老年代 變量 jdk major gc 高效 image 隊列 you 頻率 JVM系列(四) - JVM GC回收算法 轉載自https://juejin.im/post/5b4dea755188251ac1098e98 前言 第二篇介紹了Java內存運行時區域

jvm系列(三):java GC算法 垃圾收集器

應對 sca 互聯 都是 生命 改進 壓縮 速度 垃圾收集器 原文鏈接：http://www.cnblogs.com/ityouknow/p/5614961.html 概述 垃圾收集 Garbage Collection 通常被稱為“GC”，它誕生於1960年 MIT 的

JVM系列第4講：從原始碼到機器碼，發生了什麼？

在上篇文章我們聊到，無論什麼語言寫的程式碼，其到最後都是通過機器碼執行的，無一例外。那麼對於 Java 語言來說，其從原始碼到機器碼，這中間到底發生了什麼呢？這就是今天我們要聊的。 如下圖所示，編譯器可以分為：前端編譯器、JIT 編譯器和AOT編譯器。下面我們逐個講解。 前端編譯器：原始碼到位元組碼

JVM系列第14講：JVM引數之GC日誌配置

說到 Java 虛擬機器，不得不提的就是 Java 虛擬機器的 GC（Garbage Collection）日誌。而對於 GC 日誌，我們不僅要學會看懂，而且要學會如何設定對應的 GC 日誌引數。今天就讓我們來學習一下 Java 虛擬機器中所有與 GC 日誌有關的引數。相信掌握了這些引數之後，對於大家線上列印

jvm系列(十):如何優化Java GC「譯」

Sangmin Lee發表在Cubrid上的"Become a Java GC Expert"系列文章的第三篇《How to Tune Java Garbage Collection》,本文的作者是韓國人，寫在JDK 1.8釋出之前，雖然有些地方有些許過時，但整體內容還是

jvm系列(六):Java服務GC引數調優案例

本文介紹了一次生產環境的JVM GC相關引數的調優過程，通過引數的調整避免了GC卡頓對JAVA服務成功率的影響。 這段時間在整理jvm系列的文章，無意中發現本文，作者思路清晰通過步步分析最終解決問題。我個人特別喜歡這種實戰類的內容，經原作者的授權同意，將文章分

深入JVM系列（二）之GC機制、收集器與GC調優

一、回顧JVM記憶體分配 1.1、記憶體分配： 1、物件優先在EDEN分配 2、大物件直接進入老年代  3、長期存活的物件將進入老年代  4、適齡物件也可能進入老年代：動態物件年齡判斷 動態物件年齡判斷： 虛擬機器並不總是要求物件的年齡必須達到MaxTenuring

jvm系列(九):Java GC 分析

Java GC就是JVM記錄儀，書畫了JVM各個分割槽的表演。 什麼是 Java GC Java GC（Garbage Collection，垃圾收集，垃圾回收）機制，是Java與C++/C的主要區別之一，作為Java開發者，一般不需要專門編寫記憶體回收和垃圾清理程式碼，對記憶體洩露和溢位的問題，也

jvm系列(三):java GC演算法 垃圾收集器

GC演算法 垃圾收集器 概述 垃圾收集 Garbage Collection 通常被稱為“GC”，它誕生於1960年 MIT 的 Lisp 語言，經過半個多世紀，目前已經十分成熟了。 jvm 中，程式計數器、虛擬機器棧、本地方法棧都是隨執行緒而生隨執行緒而滅，棧幀隨著方法的進入和退出做入棧和出棧

3.深入jvm核心-原理、診斷與優化-4. GC演算法和種類

一、GC演算法和種類 GC的概念 GC演算法 引用計數法 標記清除 標記壓縮 複製演算法 可觸及性 Stop-The-World

JVM效能優化系列-(4) 編寫高效Java程式

4. 編寫高效Java程式 4.1 面向物件 構造器引數太多怎麼辦？ 正常情況下，如果構造器引數過多，可能會考慮重寫多個不同引數的建構函式，如下面的例子所示： public class FoodNormal { //required private final String foodNa

JVM系列（2）-GC

1.什麼是GC？ 大白話說就是垃圾回收機制，記憶體空間是有限的，你建立的每個物件和變數都會佔據記憶體，gc做的就是物件清除將記憶體釋放出來，這就是GC要做的事。 2.需要GC的區域 說起垃圾回收的場所，瞭解過JVM（Java Virtual Machine Model）記憶體模型的朋友應該會很清楚，堆是Jav

JVM系列【4】記憶體模型

## JVM系列筆記目錄 > - 虛擬機器的基礎概念 > - class檔案結構 > - class檔案載入過程 > - jvm記憶體模型 > - JVM常用指令 > - GC與調優 ### 硬體層資料一致性 #### - 儲存器層次結構 ![file](ht

JVM系列【6】GC與調優1

### JVM系列筆記目錄 > - 虛擬機器的基礎概念 > - class檔案結構 > - class檔案載入過程 > - jvm記憶體模型 > - JVM常用指令 > - GC與調優 ### GC基礎知識 - #### 什麼是垃圾 ​ 沒有任何引用指向的一個

JVM系列【6】GC與調優2.md

### JVM系列筆記目錄 > - 虛擬機器的基礎概念 > - class檔案結構 > - class檔案載入過程 > - jvm記憶體模型 > - JVM常用指令 > - GC與調優 #### 瞭解HotSpot常用命令列引數 JVM的命令列引數參考: http