title: 理解GC日志
comments: false
date: 2019-07-16 10:25:52
description: 理解 GC 打印的回收日志內容
categories: GC
概述
每一種收集器的日志形式都是由它們自身的實現決定的，換而言之，每個收集器的日志格式都可以不一樣，但是虛擬機的設計者為了方便用戶閱讀，將每個收集器的日志都維持一定的共性。
使用 -XX:+PrintGC
使用 -XX:+PrintGC 開啟簡單的 GC 日志。
以啟動 SpringBoot 為例：
[GC (Allocation Failure) 262144K->24800K(1005056K), 0.0182439 secs]
[GC (Metadata GC Threshold) 45740K->14793K(1005056K), 0.0099653 secs]
[Full GC (Metadata GC Threshold) 14793K->14558K(1005056K), 0.0803518 secs]
開頭是 GC 或者 FULL GC，然后是 GC 前和 GC 后使用的堆空間的大小，括號中是堆的大小，最后是 GC 執行耗費的時間。
簡單模式的 GC 日志是與收集器無關的，也沒有提供其它信息。
使用 -XX:+PrintGCDetails
使用 -XX:+PrintGCDetails 開啟詳細的 GC 日志，我們再加上一個參數 -XX:+PrintGCTimeStamps 用來打印發生 GC 時距離 Java 虛擬機啟動所經過的秒數。
以啟動 SpringBoot 為例：
[GC (Allocation Failure) [PSYoungGen: 262144K->24659K(305664K)] 262144K->24747K(1005056K), 0.0190895 secs] [Times: user=0.06 sys=0.01, real=0.02 secs]
[GC (Metadata GC Threshold) [PSYoungGen: 56032K->15248K(305664K)] 56120K->15344K(1005056K), 0.0114648 secs] [Times: user=0.07 sys=0.01, real=0.01 secs]
[Full GC (Metadata GC Threshold) [PSYoungGen: 15248K->0K(305664K)] [ParOldGen: 96K->15116K(699392K)] 15344K->15116K(1005056K), [Metaspace: 21279K->21279K(1069056K)], 0.0832569 secs] [Times: user=0.38 sys=0.01, real=0.08 secs]
我的 JDK 版本是 1.8.0_212，默認的垃圾處理器是 Parallel Scavenge（新生代） 和 Parallel Old（老年代）。
[GC 和 [FULL GC
表示這次垃圾收集的停頓類型，而不是用來區分是新生代 GC 還是老年代 GC，如果有“FULL”，說明這次垃圾收集是發生了“Stop The World”的。如果是調用了 System.gc(); 方法所觸發的收集，那么這將顯示 [GC (System.gc()) 或 [Full GC (System.gc()) 。
[PSYoungGen 和 [PSOldGen
這里表示 GC 發生的區域。這里的命名是根據收集器的改變而改變的，默認使用 Parallel Scavenge/Old 收集器，所以顯示 PSYoungGen 和 PSOldGen；如果使用 Serial + CMS 收集器的話，這里就顯示 ParNew（新生代）和 CMS（老年代）由於 CMS 的日志類別比較多，后面再詳細說明；如果使用 Serial + Serial Old 收集器的話，這就顯示 ParNew（新生代）和 Tenured（老年代）。
262144K->24659K(305664K)]
這里表示的含義是 “GC 前該內存區域已使用的容量 -> GC 后該內存區域已使用的容量（該內存區域的總容量）”。而在方括號之外的 “262144K->24747K(1005056K)” 則表示 “GC 前堆已使用容量 -> GC 后堆已使用容量（Java 堆的總容量）”。
0.0190895 secs]
在 Java 堆的總容量之后，是一個時間，表示內存區域 GC 所占用的時間，單位是秒。
**[Times: user=0.06 sys=0.01, real=0.02 secs] **
這里是收集器給出的 GC 所占用時間的更具體的數據。user：用戶態消耗的 CPU 時間；sys：內核態消耗的 CPU 時間；real：操作從開始到結束所經過的牆鍾時間。
牆鍾時間：牆鍾時間包括各種非運算的等待耗時，例如等待磁盤 I/O、等待線程堵塞，而 CPU 時間不包括這些耗時，但當系統有多 CPU 或者多核的話，多線程操作會疊加這些 CPU 時間，所以看到 user 或 sys 時間超過 real 時間完全是正常的。
CMS 日志講解
在 JDK1.8.0_212下在運行時。
加入 -XX:+PrintGCDetails -XX:+UseConcMarkSweepGC -XX:-UseAdaptiveSizePolicy 參數。
[GC (Allocation Failure) [ParNew: 167808K->20287K(188736K), 0.0174186 secs] 167808K->20287K(1027648K), 0.0174666 secs] [Times: user=0.08 sys=0.01, real=0.01 secs]
[GC (CMS Initial Mark) [1 CMS-initial-mark: 13213K(838912K)] 35700K(1027648K), 0.0018935 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
[CMS-concurrent-mark-start]
[CMS-concurrent-mark: 0.023/0.024 secs] [Times: user=0.07 sys=0.00, real=0.02 secs]
[CMS-concurrent-preclean-start]
[CMS-concurrent-preclean: 0.002/0.002 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[CMS-concurrent-abortable-preclean-start]
[CMS-concurrent-abortable-preclean: 0.241/0.328 secs] [Times: user=0.68 sys=0.02, real=0.33 secs]
[GC (CMS Final Remark) [YG occupancy: 108205 K (188736 K)][Rescan (parallel) , 0.0160882 secs][weak refs processing, 0.0000512 secs][class unloading, 0.0026681 secs][scrub symbol table, 0.0039342 secs][scrub string table, 0.0004904 secs][1 CMS-remark: 13213K(838912K)] 121419K(1027648K), 0.0238344 secs] [Times: user=0.13 sys=0.00, real=0.03 secs]
[CMS-concurrent-sweep-start]
[CMS-concurrent-sweep: 0.006/0.006 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
[CMS-concurrent-reset-start]
[CMS-concurrent-reset: 0.007/0.007 secs] [Times: user=0.01 sys=0.01, real=0.01 secs]
回收新生代
[GC (Allocation Failure) [ParNew: 167808K->20287K(188736K), 0.0174186 secs] 167808K->20287K(1027648K), 0.0174666 secs] [Times: user=0.08 sys=0.01, real=0.01 secs]
- GC (Allocation Failure)：新生代分配內存失敗，發生 GC。
- ParNew：說明新生代的垃圾收集器是 ParNew。（使用
-XX:+UseConcMarkSweepGC指定老年代收集器為 CMS 時，新生代默認收集器是 ParNew）。 - 167808K->20287K(188736K)：167808K 表示回收之前新生代的使用容量，20287K 表示回收之后新生代的使用容量，188736K 表示新生代的總容量。
- 0.0174186 secs：表示收集新生代時的耗時。
- 167808K->20287K(1027648K)：167808K 表示回收之前整個堆的使用量，20287K 表示回收之后整個堆的使用量，1027648K 表示整個堆的總容量。
- 0.0174666 secs：表示整個堆回收的耗時。
初始化標記
[GC (CMS Initial Mark) [1 CMS-initial-mark: 13213K(838912K)] 35700K(1027648K), 0.0018935 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
- GC (CMS Initial Mark) ：初始化標記，開始進行老年代的回收。
- 13213K(838912K)：表示在老年代使用了 13213K 時進行回收，838912K 表示老年代的總容量。
- 35700K(1027648K)：35700K 表示整個堆的使用情況，1027648K 表示整個堆的容量。
- 0.0018935 secs：初始化標記的耗時。
這個階段會從跟對象開始掃描，會標記由根可以直接到達的對象（直接，不是間接），標記期間會暫停整個應用程序。
並發標記
[CMS-concurrent-mark-start]
[CMS-concurrent-mark: 0.023/0.024 secs] [Times: user=0.07 sys=0.00, real=0.02 secs]
並發標記階段。在初始化標記階段被暫停的線程重新運行，從初始化標記階段標記過的對象出發，所有可到達的對象都在本階段中標記，也就是遍歷整個老年代。
0.023：表示並發標記時間。
0.024：表示並發標記的牆鍾時間。
由於該階段的過程中用戶線程也在運行，這就可能會發生這樣的情況，已經被遍歷過的對象的引用被用戶線程改變，如果發生了這樣的情況，JVM 就會標記這個區域為 Dirty Card。
預清理
[CMS-concurrent-preclean-start]
[CMS-concurrent-preclean: 0.002/0.002 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
這個階段會把上一個階段被標記為 Dirty Card 的對象以及可達的對象重新遍歷標記，完成后清除 Dirty Card 標記，另外，還會做一些必要的清掃工作，還會做一些 final remark 階段需要的准備工作。
這個階段也是並發執行的，與用戶線程同時工作。
說實話，這個是我參考網絡上的解釋，我也不太懂。
可中止的預清理
[CMS-concurrent-abortable-preclean-start]
[CMS-concurrent-abortable-preclean: 0.241/0.328 secs] [Times: user=0.68 sys=0.02, real=0.33 secs]
這個階段嘗試着去承擔接下來 "Stop The World" 的 final remark 階段足夠多的工作，由於這個階段是重復的做相同的事情直到發生 aboart 的條件（比如：重復的次數、多少量的工作、持續的時間等等）之一才會停止。這個階段很大程度的影響着即將來臨的 final remark 的停頓。
這個階段也是並發執行的，與用戶線程同時工作。
說實話，這個是我參考網絡上的解釋，我也不太懂。
重新標記階段
[GC (CMS Final Remark) [YG occupancy: 108205 K (188736 K)][Rescan (parallel) , 0.0160882 secs][weak refs processing, 0.0000512 secs][class unloading, 0.0026681 secs][scrub symbol table, 0.0039342 secs][scrub string table, 0.0004904 secs][1 CMS-remark: 13213K(838912K)] 121419K(1027648K), 0.0238344 secs] [Times: user=0.13 sys=0.00, real=0.03 secs]
- [GC (CMS Final Remark)：表示這是CMS的重新標記階段，會 STW，該階段的任務是完成標記整個年老代的所有的存活對象，盡管先前的 pre clean 階段盡量應對處理了並發運行時用戶線程改變的對象應用的標記，但是不可能跟上對象改變的速度，只是為 final remark 階段盡量減少了負擔。
- [YG occupancy: 108205 K (188736 K)]：表示年輕代當前的內存占用情況，通常 final remark 階段要盡量運行在年輕代是足夠干凈的時候，這樣可以消除緊接着的連續的幾個 STW 階段。
- [Rescan (parallel) , 0.0160882 secs]：這是整個 final remark 階段掃描對象的用時總計，該階段會重新掃描 CMS 堆中剩余的對象，重新從“根對象”開始掃描，並且也會處理對象關聯。本次掃描共耗時 0.0160882。
- [weak refs processing, 0.0000512 secs]：第一個子階段，表示對弱引用的處理耗時為 0.0000512。
- [class unloading, 0.0026681 secs]：第二個子階段，表示卸載無用的類的耗時為 0.0026681。
- [scrub symbol table, 0.0039342 secs]：最后一個子階段，表示清理分別包含類級元數據和內部化字符串的符號和字符串表的耗時。
- [1 CMS-remark: 13213K(838912K)]：表示經歷了上面的階段后老年代的內存使用情況。再后面的
121419K(1027648K), 0.0238344 secs表示 final remark 后整個堆的內存使用情況和整個final remark的耗時。
並發清除階段
[CMS-concurrent-sweep-start]
[CMS-concurrent-sweep: 0.006/0.006 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
[CMS-concurrent-reset-start]
[CMS-concurrent-reset: 0.007/0.007 secs] [Times: user=0.01 sys=0.01, real=0.01 secs]
該階段和用戶線程並發執行，不會STW，作用是清除之前標記階段沒有被標記的無用對象並回收內存。整個過程分為兩個子階段。
- CMS-concurrent-sweep：第一個子階段，任務是清除那些沒有標記的無用對象並回收內存。后面的參數是耗時，不再多提。
- CMS-concurrent-reset：第二個子階段，作用是重新設置CMS算法內部的數據結構，准備下一個CMS生命周期的使用。
知識點
我們上面提到CMS收集器會在老年代內存使用到一定程度時就觸發垃圾回收，這是因為CMS收集器的一個缺陷導致的這種設定，也就是無法處理“浮動垃圾”，“浮動垃圾”就是指標記清除階段用戶線程運行產生的垃圾，而這部分對象由於沒有做標記處理所以在本次CMS收集中是無法處理的。如果CMS是在老年代空間快用完時才啟動垃圾回收，那很可能會導致在並發階段由於用戶線程持續產生垃圾而導致老年代內存不夠用而導致“Concurrent Mode Failure”失敗，那這時候虛擬機就會啟用后備預案，臨時啟用Serial Old收集器來重新進行老年代的垃圾收集，Serial Old是基於“標記-整理”算法的單線程收集器，這樣停頓時間就會很長。
這個CMS啟動的內存使用閾值可以通過參數-XX:CMSInitiatiingOccupancyFranction來設置。我通過在命令行輸入java -XX:+PrintFlagsInitial命令查看到該參數的值是 -1，那么 -1 是什么意思呢？
看 JVM 源碼可知：
product(intx, CMSInitiatingOccupancyFraction, -1,
"Percentage CMS generation occupancy to start a CMS collection "
"cycle. A negative value means that CMSTriggerRatio is used")
注釋里也說了，如果CMSInitiatingOccupancyFraction是個負值，那么CMSTriggerRatio將被用到。
那么具體是如何用到的呢？
_cmsGen ->init_initiating_occupancy(CMSInitiatingOccupancyFraction, CMSTriggerRatio);
void ConcurrentMarkSweepGeneration::init_initiating_occupancy(intx io, uintx tr) {
assert(io <= 100 && tr <= 100, "Check the arguments");
if (io >= 0) {
_initiating_occupancy = (double)io / 100.0;
} else {
_initiating_occupancy = ((100 - MinHeapFreeRatio) +
(double)(tr * MinHeapFreeRatio) / 100.0)
/ 100.0;
}
}
如果CMSInitiatingOccupancyFraction在0~100之間，那么由CMSInitiatingOccupancyFraction決定。
否則由按 ((100 - MinHeapFreeRatio) + (double)( CMSTriggerRatio * MinHeapFreeRatio) / 100.0) / 100.0 決定。
那么MinHeapFreeRatio，CMSTriggerRatio的初始值是多少？
uintx MinHeapFreeRatio = 40
uintx CMSTriggerRatio = 80
即最終當老年代達到 ((100 - 40) + (double) 80 * 40 / 100 ) / 100 = 92 %時，會觸發CMS回收。
參考：