JAVA應用性能監控之JVM層GC調優

1. JVM內存結構

1.1 運行時數據區

運行時數據區是規範，內存結構是具體實現。

官方運行時數據區定義

• 程序計數器PC Register：JVM支持多線程同時執行，每個線程都有本身的PC Register，線程正在執行的方法叫作當前方法，若是是java代碼，PC Register裏面存放的就是房錢正在執行的指令的地址，若是你是C代碼，則爲空。
• Java虛擬機棧（Java Virtual Machine Stacks）是線程私有的，它的生命週期與線程相同。虛擬機棧描述的是Java方法執行的內存模型：每一個方法在執行的同時都會建立一個棧幀，用於存儲局部變量表、操做數棧、動態連接、方法出口燈信息。每個方法從調用直至執行完成的過程，就對應着一個棧幀在虛擬機棧中入棧到出棧的過程。
• Java堆（Java Heap）是Java虛擬機所管理的內存中最大的一塊。堆是被全部線程共享的一塊內存區域，在虛擬機啓動時建立。此內存區域的惟一目的就是存放對象實例，幾乎全部的對象實例都在這裏分配內存。Java堆能夠處於物理上不連續的內存空間中，只要邏輯上是連續的便可。
• 方法區（Method Area）：方法區域java堆同樣，是各個線程共享的內存區域，它用於存儲已被虛擬機加載的類信息、常亮、靜態變量、即時編譯器編譯後的代碼等數據。雖然Java虛擬機規範把方法區描述爲堆的一個邏輯部分，可是它卻有一個別名叫作Non-Heap（非堆），目的是與Java堆區分開來。
• 運行時常量池（Runtime Constant Pool）是方法區的一部分。Class文件中除了有類的版本、字段、方法、接口等描述信息外，還有一項信息是常量池（Constant Pool Table），用於存放編譯器生成的各類字面量和符號引用，這部份內容將在類加載後進入方法區的常量池中存放。
• 本地方法棧（Native Method Stacks）與虛擬機棧所放回的做用是很是類似的，它們之間的區別不過是虛擬機棧爲虛擬機執行的Java方法（也就是字節碼）服務，而本地方法棧則爲虛擬機使用到的Native方法服務。

1.2 JVM的內存結構

CCS：壓縮類空間，這個空間只有當啓用了壓縮類短指針時候，這個空間纔會存在，在堆中分配的每個對象，都有一個指向本身的Class的一個指針，64位的虛擬機指針的長度是64位，若是考慮性能的緣由，咱們能夠把這個指針採用短指針方式引用，採用32位指針，所引用的class文件都存儲在壓縮類空間。若是不啓用短指針，那麼壓縮類空間就不存在。
CodeCache：存放的是JIT編譯後的源代碼，還有JVM執行的JNI Native代碼。若是沒有啓用JIT即時編譯，或者沒有引用JNI方法，這塊空間不存在。
Metaspace = Class、Package、Method、Method、Field、字節碼、常量池、符號引用等等。
CCS：32位指針的Class。
CodeCache：JIT編譯後的本地代碼、JNI使用的C代碼。

實例：
啓用壓縮類空間：

jstat -gc 13144

禁用壓縮類空間：

jstat -gc 13523

codecache也是同樣操做。
-xint

經常使用參數：

• -Xms-Xmx
• -XX:NewSize -XX:MaxNewSize
• -XX:NewRatio -XX:SurvivorRatio
• -XX:MetaspaceSize -XX:MaxMetaspaceSize
• -XX:+UseCompressedClassPointers
• -XX:CompressedClassSpaceSize
• -XX:InitialCodeCacheSize
• -XX:ReservedCodeCacheSize

2. 垃圾回收算法

C++和Java中內存泄露區別：在C++中New了一個對象，可是將該對象的指針丟失了，這就致使這個對象佔用的內存永遠得不到釋放，就形成了內存泄露。在JAVA中New一個對象後，這個對象的指針一直被應用程序所持有，這樣垃圾回收就不能將其釋放，這樣就致使內存泄露。

2.1 如何肯定垃圾

思想：枚舉根節點，作可達性分析
根節點：類加載器、Thread、虛擬機棧的本地變量表、static成員、常亮引用、本地方法棧的變量等等。

2.2 各種算法

標記清除：算法分爲「標記」和「清除」兩個階段，首先標記出全部須要回收的對象，在標記完成後統一回收全部。缺點是效率不高，標記和清除兩個過程的效率都不高；產生碎片，碎片太多會致使提早GC。
複製算法：它將可用內存按照容量劃分爲大小相等的兩塊，每次只使用其中的一塊。當這一塊的內存用完了，就將還存活的對象複製到另一塊上面，而後再把已使用過的內存空間一次清理掉。優缺點是實現簡單，運行高效，可是空間利用率低。
標記整理算法：標記過程仍然與「標記-清除」算法同樣，但後續步驟不是直接對可回收對象進行清理，而是讓全部存活的對象都向一端移動，而後直接清理掉端邊界之外的內存。優缺點是沒有了內存碎片，可是整理內存比較耗時。
分代垃圾回收：Young區採用複製算法，Old區採用標記清除或者標記整理算法。

對象分配：

• 對象優先分配在Eden區。
• 大對象直接進入老年代：-XX:PretenureSizeThreshold，該參數規定多大的對象會直接分配在老年代。
• 長期存活對象進入老年代：
  -XX:MaxTenuringThreshold 晉升閾值
  -XX:+PrintTenuringDistribution 發生Young GC時候，打印存活對象的年齡的分佈狀況
  -XX:TargetSurivorRatio 設置Surivor區，Young區垃圾回收後存活對象的比例，假設該值設置爲80%，意味着發生一次Young GC，Surivor區存活對象爲80%，這時候須要計算這些80%存活對象的平均年齡，用平均年齡和晉升閾值之間取一個最小值，若是有對象年齡大於該最小值，也會將該對象晉升到老年代。

3. 垃圾收集器

3.1 三種類型垃圾收集器

• 串行收集器Serial：Serial、Serial Old。單線程，適用於內存小的嵌入式設備。
• 並行收集器Parallel：Paralel Scavenge、Parallel Old，吞吐量優先。
• 併發收集器Concurrent：CMS、G1，停頓時間優先。

3.2 並行VS併發

• 並行是指多條垃圾收緊線程並行工做，但此時用戶線程仍然處於等待狀態。適合科學計算、後臺處理等弱交互場景。
• 併發指用戶線程與垃圾收集線程同時執行（但不必定是並行的，可能會交替執行），垃圾收集線程在執行的時候不會停頓用戶程序的運行。適合對響應時間有要求的場景，好比Web。

3.3 停頓時間VS吞吐量

• 停頓時間：垃圾收集器作垃圾回收中斷應用執行的時間，-XX:MaxGCPauseMillis
• 吞吐量：花在垃圾收集的時間和花在應用時間的佔比。-XXGCTimeRatio=<n>，來及收集時間佔：1/1+n。

3.4 如何評價一個垃圾回收器的好壞

最理想的狀況下，吞吐量最大的時候，停頓時間最小。現實中，這兩個指標是互斥的，GC調優時候，很大部分工做就是如何權衡這兩個變量。

3.5 三種類型垃圾收集器開啓與停用

串行收集器：

-XX:+UseSerialGC -XX:+UseSerialOldGC

並行收集器：

吞吐量優先，
 -XX:+UseParallelGC  -XX:+UseParallelOldGC
 Server模式下的默認收集器，JVM會根據當前系統內存狀況決定啓用Server模式仍是Client模式，內存大於2G，JVM就會認爲是Server模式。
 jinfo -flag UseParallelGC 21669

併發收集器：

在Java8中，有兩個併發垃圾收集器，一個是CMS，一個是G1。
 響應時間優先。
 CMS: XX:+UseConcMarkSweepGC -XX:UseParNewGC
 G1: -XX:UseG1GC

3.6 垃圾收集器搭配

• 有連線的是能夠相互搭配使用。
• JDK8推薦使用G1，性能比較好，在Yong區和Old區均可以使用。
• 虛線表示CMS可能退化成SerialOld，空間擔保分配失敗。

如何選擇垃圾收集器？官方指導垃圾收集器選取方法

• 優先調整堆的大小，讓JVM本身來選擇；
• 若是內存小於100M，使用串行收集器；
• 若是是單核，並無停頓時間的要求，串行或JVM本身選；
• 若是容許停頓時間超過1秒，選擇並行或JVM本身選；
• 若是響應時間很是重要，而且不能超過1秒，使用併發收集器；

3.7 兩種經常使用垃圾收集器

3.7.1 Parallel Collector

工做原理：當發現內存不夠時，暫停應用程序，啓動多個垃圾回收線程來回收垃圾，垃圾回收結束後，從新啓動應用程序。
-XX:+UseParallelGC 手動開啓，server模式默認開啓；
-XX:ParallelGCThreads=<n> 開啓多少個GC線程；

CPU > 8 ，N=5/8；
  CPU < 8 ，N=CPU；

並行收集器的自適應特性（Parallel Collector Ergonomics），會自動調整堆得大小，來自適應調整知足咱們設定的指標：

• -XX:MaxGCPauseMills=<n> 最大停頓時間；
• -XX:GCTimeRatio=<n> 吞吐量；
• -Xmx<n> 堆的大小；
  優先知足停頓時間要求，而後知足吞吐量要求，若是兩個都知足的話，它會減少堆得大小，來知足停頓時間的要求，直到這三個條件中有一個是知足不了的。自適應其實不是最優的，由於它須要動態調整堆得大小來知足這些條件。
  動態內存調整
  並行收集器在自適應的時候會動態調整內存；
• -XX:YongGenerationSizeIncrement=<Y> Yong區動態調整每次增長的大小，默認20%；
• -XX:TenuredGenerationSizeIncrement=<T> Old區動態調整每次增長的大小，默認20%；
• -XX:AdaptiveSizeDecrementScaleFactor=<D> 動態減少時每次減少的大小，默認4%；
  在生產環境下不多使用自適應功能，主要經過手動調整。

3.7.2 CMS Collector

併發收集
低停頓，低延遲
老年代收集器

（1）CMS垃圾收集過程

• CMS Initial Mark：初始標記Root，STW（Stop The World，會中止應用程序）；
• CMS Concurrent Mark：併發標記，從根節點日後標記，不須要中止應用程序；
• CMS-Concurrent-Preclean：併發預清理，標記出堆中全部存活對象；
• CMS Remark：從新標記，STW（Stop The World，會中止應用程序），在第2和3步的時候會產生新的垃圾，修正3的結果；
• CMS Concurrent Sweep：併發清除；

（2）CMS缺點

• CPU敏感，垃圾收集的時候會佔用CPU，致使應用程序性能降低；
• 浮動垃圾，在垃圾收集的時候應用程序還會進行內存分配；
• 空間碎片；

在G1垃圾收集器出現以前，CMS垃圾收集器使用很是普遍。

（3）CMS相關參數

• -XX:ConcGCThreads 併發的GC線程數，和應用程序同時執行的時候的線程數；
• -XX:+UseCMSCompactAtFullCollection FullGC以後作壓縮，減小內存碎片；
• -XX:CMSFullGCsBeforeCompaction 多少此FullGC以後壓縮一次，由於壓縮是比較消耗時間的；
• -XX:CMSInitiatingOccupancyFraction Old區佔有多少存活對象時觸發FullGC，默認大概是90%多；
• -XX:+UseCMSInitiatingOccupancyOnly 是否動態可調，若是啓用這個值，就變成動態可調的了；
• -XX:+CMSScavengeBeforeRemark FullGC以前先作YGC，由於YGC能夠將不少垃圾都回收掉，通常調優時都很會打開；
• -XX:+CMSClassUnloadingEnabled 啓用回收Perm區（JDK4~JDK7有Perm區）；

實戰：
查看Java應用使用哪種垃圾收集器：

觸發FullGC的時機：

默認設置的是92%

3.7.3 G1 Collector

（1）簡介

The first focus of G1 is to provide a solution for users running applications that require large heaps with limited GC latency. This means heap sizes of around 6GB or larger, and a stable and predictable pause time below 0.5 seconds.

目標：知足大堆和短暫的停頓時間的要求；
G1是新生代和老年代收集器。
在JDK9中，已經將G1設置爲默認的垃圾收集器。
（2）G1結構

G1是以Region爲單位的。G1不像以前介紹的新生代、老生代垃圾收集器，雖說G1裏面也有Young區和Old區這種概念，可是這只是邏輯上的概念。
G1將JVM內存分爲一個小塊一個小塊，一個小塊叫一個Region。一部分Region組成Young區，一部分Region組成Old區。
標記爲H的Region，表示單獨有一塊存放大對象的區，若是對象大小超過Region大小的通常，就會存儲在H Region中。
（3）G1的幾個概念

• Region：G1把Heap分紅一塊塊的region，每一個region大小相等；
• SATB：Snapshot-At-The-Beginning，它是經過Root Tracing獲得的，GC開始時存活對象的快照；
• RSet：記錄了其餘Region中的對象引用本地Region中對象的關係，屬於Points-into結構（誰引用了個人對象）；

（4）Yong GC

• 新對象進入Eden區；
• 發生Yong GC時把存活對象拷貝到Survivor裏；
• 存活時間到達年齡閾值時，對象晉升到Old區；

（5）Mixed GC

• 不是FullGC，回收全部的Yong和部分Old；
• 伴隨着Mixed GC，有一個概念Global Concurrent Marking，全局併發標記；

Global Concurrent Marking （全局併發標記）

1. Initial-marking phase：標記GC Root，STW；
2. Root-Region-Scanning Phase：標記存活Region；
3. Concurrent-Marking Phase：標記存活的對象；
4. Remark-Phase：從新標記，STW；
5. Cleanup-Phase：部分STW；
6. Concurrent-Cleanup Phase：併發清理；

Mixed GC的時機

• -XX:InitiatingHeapOccupancyPercent 當堆中垃圾佔有率達到這個數值觸發Global Concurrent Marking，默認45%；
• -XX:G1HeapWastePercent 在Global Concurrent Marking結束後，能夠知道有多少空間要被回收，在每次YGC以後和再次發生Mixed GC以前，會檢查垃圾佔比是否達到此參數，只有達到了，下次纔會發生Mixed GC，若是沒有達到，就不會發生Mixed GC；

（6）Mixed GC相關參數

• -XX:G1MixedGCLiveThresholdPercent Old區的region被回收時候的存活對象佔比；
• -XX:G1MixedGCCountTarget 一次Global Concurrent Marking以後，最多執行Mixed GC的次數，由於執行一次Mixed GC，並不能將對象都回收掉，使存貨對象佔比小於G1MixedGCLiveThresholdPercent；
• -XX:G1OldCSetRegionThresholdPercent 1次Mixed GC中能被選入CSet的最多Old區的region數量，也就是說1次Mixed GC，最多能夠回收多少個Old區的region，CSet中存放的就是須要回收的regions；

（7）G1相關參數

• -XX:+UseG1GC 開啓G1；
• -XX:G1HeapRegionSize=n region的大小，1-32M，最多不能超過2048個region；
• -XX:MaxGCPauseMills=200 最大停頓時間；
• -XX:G1NewSizePercent -XX:G1MaxNewSizePercent Yong區的佔比；
• -XX:G1ReservePercent=10 保留防止to space溢出，就是發生Yong GC的時候，將一個S區和Eden區的對象移到另外一個S區時發生的溢出；
• -XX:ParallelGCThreads=n STW線程數；
• -XX:ConcGCThreads=n 併發線程數=1/4*並行；

（8）G1最佳實踐G1官方調優指南

• 年輕代大小：避免使用-Xmn、-XX:NewRatio等顯式設置Yong區大小，會覆蓋暫停時間目標（XX:MaxGCPauseMills）；
• 暫停時間目標：暫停時間不要設置的太嚴格，其吞吐目標是90%的應用程序時間和10%垃圾回收時間，太嚴格會直接影響到吞吐量；

（9）是否考慮切換到到G1

• 50%以上的堆被存活對象佔用；
• 對象的分配和晉升的速度變化很是快；
• 垃圾回收時間特別長，超過了1秒；

3.8 GC日誌分析

前面章節咱們知道評價一個垃圾收集器的好壞主要依據吞吐量和響應時間這兩個指標，咱們在調優時，主要也是調整這兩個值。可是咱們如何獲得而且衡量這兩個指標呢？這裏咱們就須要進行GC日誌分析。

3.8.1 打印日誌相關參數

• -XX:+PrintGCDetails
• -XX:+PrintGCTimeStamps
• -XX:+PrintGCDateStamps
• -Xloggc:$CATALINA_HOME/logs/log.gc
• -XX:+PrintHeapAtGC 發生GC時，打印整個堆的使用狀況
• -XX:PrintTenuringDistribution 發生GC時候，打印Young區中對象的年齡狀況。

3.8.2 Parallel GC日誌格式

Java HotSpot(TM) 64-Bit Server VM (25.161-b12) for windows-amd64 JRE (1.8.0_161-b12), built on Dec 19 2017 17:52:25 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 16687384k(9195396k free), swap 19177752k(7040076k free)
CommandLine flags: -XX:-BytecodeVerificationLocal -XX:-BytecodeVerificationRemote -XX:InitialHeapSize=31457280 -XX:+ManagementServer -XX:MaxHeapSize=104857600 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:TieredStopAtLevel=1 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:-UseLargePagesIndividualAllocation -XX:+UseParallelGC 
2019-11-10T19:19:12.927+0800: 4.575: [GC (Allocation Failure) [PSYoungGen: 8192K->1016K(9216K)] 8192K->1749K(29696K), 0.0024135 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-11-10T19:19:13.097+0800: 4.744: [GC (Allocation Failure) [PSYoungGen: 9208K->1016K(9216K)] 9941K->3080K(29696K), 0.0035051 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-11-10T19:19:13.197+0800: 4.844: [GC (Allocation Failure) [PSYoungGen: 9208K->1000K(9216K)] 11272K->4099K(29696K), 0.0022592 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-11-10T19:19:13.309+0800: 4.957: [GC (Allocation Failure) [PSYoungGen: 9192K->1000K(17408K)] 12291K->5140K(37888K), 0.0049571 secs] [Times: user=0.03 sys=0.00, real=0.00 secs] 
2019-11-10T19:19:13.476+0800: 5.123: [GC (Allocation Failure) [PSYoungGen: 17384K->1016K(17408K)] 21524K->6996K(37888K), 0.0073199 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2019-11-10T19:19:13.582+0800: 5.230: [GC (Allocation Failure) [PSYoungGen: 17400K->2679K(30720K)] 23380K->8667K(51200K), 0.0042196 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-11-10T19:19:13.759+0800: 5.406: [GC (Allocation Failure) [PSYoungGen: 30327K->3064K(30720K)] 36315K->10745K(51200K), 0.0074231 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2019-11-10T19:19:13.901+0800: 5.548: [GC (Metadata GC Threshold) [PSYoungGen: 27276K->3067K(26624K)] 34956K->12612K(47104K), 0.0034870 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-11-10T19:19:13.905+0800: 5.552: [Full GC (Metadata GC Threshold) [PSYoungGen: 3067K->0K(26624K)] [ParOldGen: 9545K->9589K(22528K)] 12612K->9589K(49152K), [Metaspace: 20548K->20547K(1067008K)], 0.0407167 secs] [Times: user=0.17 sys=0.00, real=0.04 secs]

3.8.3 CMS GC日誌格式

Orale官網CMS日誌分析

Java HotSpot(TM) 64-Bit Server VM (25.161-b12) for windows-amd64 JRE (1.8.0_161-b12), built on Dec 19 2017 17:52:25 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 16687384k(9173344k free), swap 19177752k(7348192k free)
CommandLine flags: -XX:-BytecodeVerificationLocal -XX:-BytecodeVerificationRemote -XX:InitialHeapSize=31457280 -XX:+ManagementServer -XX:MaxHeapSize=104857600 -XX:MaxNewSize=34955264 -XX:MaxTenuringThreshold=6 -XX:OldPLABSize=16 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:TieredStopAtLevel=1 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:-UseLargePagesIndividualAllocation -XX:+UseParNewGC 
2019-11-10T19:24:18.779+0800: 3.947: [GC (Allocation Failure) 2019-11-10T19:24:18.780+0800: 3.947: [ParNew: 8192K->1024K(9216K), 0.0043711 secs] 8192K->1699K(29696K), 0.0045420 secs] [Times: user=0.05 sys=0.00, real=0.00 secs] 
2019-11-10T19:24:18.931+0800: 4.098: [GC (Allocation Failure) 2019-11-10T19:24:18.931+0800: 4.098: [ParNew: 9216K->1024K(9216K), 0.0034687 secs] 9891K->3286K(29696K), 0.0035272 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

...

2019-11-10T19:24:19.629+0800: 4.797: [GC (CMS Initial Mark) [1 CMS-initial-mark: 7563K(20480K)] 8744K(29696K), 0.0005333 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-11-10T19:24:19.629+0800: 4.797: [CMS-concurrent-mark-start]
2019-11-10T19:24:19.640+0800: 4.808: [CMS-concurrent-mark: 0.011/0.011 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2019-11-10T19:24:19.640+0800: 4.808: [CMS-concurrent-preclean-start]
2019-11-10T19:24:19.641+0800: 4.808: [CMS-concurrent-preclean: 0.000/0.000 secs] [Times: user=0.03 sys=0.01, real=0.00 secs] 
2019-11-10T19:24:19.641+0800: 4.809: [GC (CMS Final Remark) [YG occupancy: 2410 K (9216 K)]2019-11-10T19:24:19.641+0800: 4.809: [Rescan (parallel) , 0.0009765 secs]2019-11-10T19:24:19.642+0800: 4.810: [weak refs processing, 0.0000600 secs]2019-11-10T19:24:19.642+0800: 4.810: [class unloading, 0.0024940 secs]2019-11-10T19:24:19.644+0800: 4.812: [scrub symbol table, 0.0062027 secs]2019-11-10T19:24:19.651+0800: 4.819: [scrub string table, 0.0006104 secs][1 CMS-remark: 7563K(20480K)] 9974K(29696K), 0.0106835 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2019-11-10T19:24:19.652+0800: 4.819: [CMS-concurrent-sweep-start]
2019-11-10T19:24:19.655+0800: 4.823: [CMS-concurrent-sweep: 0.004/0.004 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-11-10T19:24:19.655+0800: 4.823: [CMS-concurrent-reset-start]
2019-11-10T19:24:19.656+0800: 4.824: [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

3.8.4 G1 GC日誌格式

Oracle官網G1日誌分析

Java HotSpot(TM) 64-Bit Server VM (25.161-b12) for windows-amd64 JRE (1.8.0_161-b12), built on Dec 19 2017 17:52:25 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 16687384k(9167812k free), swap 19177752k(7386372k free)
CommandLine flags: -XX:-BytecodeVerificationLocal -XX:-BytecodeVerificationRemote -XX:InitialHeapSize=31457280 -XX:+ManagementServer -XX:MaxHeapSize=104857600 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:TieredStopAtLevel=1 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC -XX:-UseLargePagesIndividualAllocation 
2019-11-10T19:27:49.318+0800: 4.071: [GC pause (G1 Evacuation Pause) (young), 0.0024797 secs]
   [Parallel Time: 1.8 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 4070.9, Avg: 4070.9, Max: 4070.9, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 0.2, Avg: 0.4, Max: 0.9, Diff: 0.8, Sum: 3.1]
      [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.3]
      [Object Copy (ms): Min: 0.7, Avg: 1.2, Max: 1.4, Diff: 0.6, Sum: 9.5]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Termination Attempts: Min: 1, Avg: 25.6, Max: 34, Diff: 33, Sum: 205]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.5]
      [GC Worker Total (ms): Min: 1.6, Avg: 1.7, Max: 1.7, Diff: 0.1, Sum: 13.4]
      [GC Worker End (ms): Min: 4072.6, Avg: 4072.6, Max: 4072.6, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.2 ms]
   [Other: 0.5 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.2 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 9216.0K(9216.0K)->0.0B(15.0M) Survivors: 0.0B->2048.0K Heap: 9216.0K(30.0M)->1900.0K(30.0M)]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
 
 ...
 
 2019-11-10T19:27:51.222+0800: 5.974: [GC pause (G1 Evacuation Pause) (young) (initial-mark), 0.0038325 secs]
   [Parallel Time: 2.9 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 5974.0, Avg: 5974.0, Max: 5974.3, Diff: 0.4]
      [Ext Root Scanning (ms): Min: 0.4, Avg: 0.7, Max: 0.9, Diff: 0.5, Sum: 5.3]
      [Update RS (ms): Min: 0.6, Avg: 0.6, Max: 0.8, Diff: 0.2, Sum: 5.1]
         [Processed Buffers: Min: 1, Avg: 2.3, Max: 4, Diff: 3, Sum: 18]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.4, Diff: 0.4, Sum: 0.7]
      [Object Copy (ms): Min: 1.1, Avg: 1.3, Max: 1.5, Diff: 0.4, Sum: 10.4]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 2.4, Avg: 2.7, Max: 2.8, Diff: 0.4, Sum: 21.7]
      [GC Worker End (ms): Min: 5976.7, Avg: 5976.7, Max: 5976.7, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.2 ms]
   [Other: 0.7 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.5 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.2 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 9216.0K(9216.0K)->0.0B(7168.0K) Survivors: 2048.0K->2048.0K Heap: 24.2M(30.0M)->17.1M(30.0M)]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-11-10T19:27:51.226+0800: 5.978: [GC concurrent-root-region-scan-start]
2019-11-10T19:27:51.229+0800: 5.981: [GC concurrent-root-region-scan-end, 0.0027122 secs]
2019-11-10T19:27:51.229+0800: 5.981: [GC concurrent-mark-start]
2019-11-10T19:27:51.245+0800: 5.997: [GC concurrent-mark-end, 0.0159182 secs]
2019-11-10T19:27:51.245+0800: 5.997: [GC remark 2019-11-10T19:27:51.245+0800: 5.997: [Finalize Marking, 0.0002420 secs] 2019-11-10T19:27:51.245+0800: 5.997: [GC ref-proc, 0.0002816 secs] 2019-11-10T19:27:51.245+0800: 5.997: [Unloading, 0.0026105 secs], 0.0034068 secs]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-11-10T19:27:51.248+0800: 6.000: [GC cleanup 18M->18M(30M), 0.0007599 secs]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-11-10T19:27:51.304+0800: 6.057: [GC pause (G1 Evacuation Pause) (young), 0.0030225 secs]
   [Parallel Time: 2.1 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 6057.1, Avg: 6057.1, Max: 6057.3, Diff: 0.2]
      [Ext Root Scanning (ms): Min: 0.1, Avg: 0.3, Max: 0.7, Diff: 0.6, Sum: 2.6]
      [Update RS (ms): Min: 0.3, Avg: 0.6, Max: 0.9, Diff: 0.6, Sum: 4.7]
         [Processed Buffers: Min: 1, Avg: 2.5, Max: 5, Diff: 4, Sum: 20]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1]
      [Object Copy (ms): Min: 0.8, Avg: 1.0, Max: 1.1, Diff: 0.3, Sum: 8.0]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.3]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 1.9, Avg: 2.0, Max: 2.0, Diff: 0.2, Sum: 15.7]
      [GC Worker End (ms): Min: 6059.1, Avg: 6059.1, Max: 6059.1, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.2 ms]
   [Other: 0.7 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.5 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.2 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 7168.0K(7168.0K)->0.0B(1024.0K) Survivors: 2048.0K->2048.0K Heap: 24.1M(30.0M)->18.9M(30.0M)]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-11-10T19:27:51.331+0800: 6.084: [GC pause (G1 Evacuation Pause) (mixed), 0.0038677 secs]
   [Parallel Time: 3.3 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 6084.3, Avg: 6084.5, Max: 6085.0, Diff: 0.6]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.3, Max: 0.7, Diff: 0.7, Sum: 2.7]
      [Update RS (ms): Min: 0.2, Avg: 1.1, Max: 2.9, Diff: 2.6, Sum: 8.4]
         [Processed Buffers: Min: 1, Avg: 1.8, Max: 4, Diff: 3, Sum: 14]
      [Scan RS (ms): Min: 0.0, Avg: 0.3, Max: 1.0, Diff: 1.0, Sum: 2.3]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.2]
      [Object Copy (ms): Min: 0.1, Avg: 1.2, Max: 1.9, Diff: 1.8, Sum: 9.6]
      [Termination (ms): Min: 0.0, Avg: 0.3, Max: 0.5, Diff: 0.5, Sum: 2.0]
         [Termination Attempts: Min: 1, Avg: 8.5, Max: 14, Diff: 13, Sum: 68]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 2.7, Avg: 3.2, Max: 3.3, Diff: 0.6, Sum: 25.3]
      [GC Worker End (ms): Min: 6087.6, Avg: 6087.6, Max: 6087.6, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 0.4 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.2 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 1024.0K(1024.0K)->0.0B(1024.0K) Survivors: 2048.0K->1024.0K Heap: 19.9M(30.0M)->17.3M(30.0M)]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-11-10T19:27:51.350+0800: 6.103: [GC pause (G1 Evacuation Pause) (mixed), 0.0032610 secs]
   [Parallel Time: 2.8 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 6102.7, Avg: 6102.7, Max: 6103.1, Diff: 0.4]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.3, Max: 0.6, Diff: 0.6, Sum: 2.4]
      [Update RS (ms): Min: 0.7, Avg: 1.0, Max: 1.1, Diff: 0.5, Sum: 7.9]
         [Processed Buffers: Min: 2, Avg: 3.1, Max: 7, Diff: 5, Sum: 25]
      [Scan RS (ms): Min: 0.3, Avg: 0.4, Max: 0.5, Diff: 0.3, Sum: 3.1]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.2]
      [Object Copy (ms): Min: 0.7, Avg: 0.9, Max: 1.0, Diff: 0.3, Sum: 7.1]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Termination Attempts: Min: 1, Avg: 4.1, Max: 7, Diff: 6, Sum: 33]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 2.2, Avg: 2.6, Max: 2.7, Diff: 0.4, Sum: 20.8]
      [GC Worker End (ms): Min: 6105.3, Avg: 6105.3, Max: 6105.3, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 0.3 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.1 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 1024.0K(1024.0K)->0.0B(1024.0K) Survivors: 1024.0K->1024.0K Heap: 18.3M(30.0M)->15.4M(30.0M)]
 [Times: user=0.00 sys=0.00, real=0.00 secs]

發生Global Concurrent Marking時機：
jinfo -flag InitiatingHeapOccupancyPercent 1559

根據日誌（[Eden: 11.0M(11.0M)->0.0B(9216.0K) Survivors: 2048.0K->2048.0K Heap: 24.8M(30.0M)->15.2M(30.0M)]），獲得17.1/30.0 > 0.45，因此發生一次全局併發標記。
全局標記完成後，是否發生Mixed GC，取決於G1HeapWastePercent，整個參數默認值是5%。
併發標記完成以後，就能夠知道可以回收多少內存，在YCG以後和再次發生Mixed GC以前，會檢查垃圾佔比是否達到此參數，若是達到了，就會發生Mixed GC。

3.8.5 GC日誌可視化分析工具

（1）gceasy
網站
日誌文件上傳到網站，能夠獲得GC日誌中各類信息項的分析狀況，經過圖表的方式展現，而且對發生GC的可能性因素都進行了分析。

（2）GCViewer
項目地址
下載項目zip包，解壓後，獲得一個maven項目，編譯後，能夠獲得可運行jar包--gcviewer-1.36-SNAPSHOT.jar，直接運行便可。
概況圖：

右側3個tab頁面，在第一個Summary tab頁中，能夠獲得吞吐量Throughput的值，第三個Pause tab頁中，能夠獲得最大最小停頓時間Min/Max Pause。

上側3個tab頁面，第二個Event details tab頁，能夠獲得什麼緣由引發的GC pauses。

根據圖中能夠得出，採用的是CMS垃圾收集器，YGC發生使應用停頓了84次，CMS Initial Mark停頓了26次，CMS Final remark停頓了4次，每次最大時間、最小時間和平均時間均可以獲得。
工具中每一個值表明什麼含義，都可以在GCViewer的Github網站找到。

3.9 GC調優步驟

• 打印GC日誌
• 根據日誌獲得關鍵性性能指標
• 分析GC緣由，調優JVM參數

3.9.1 實戰GC調優

（1）初始設置

• -XX:+DisableExplicitGC 禁用手動觸發GC，防止代碼中調用System.gc()致使發生GC，在生產環境下，該參數通常都須要禁用
• -XX:+HeapDumpOnOutOfMemoryError
• -XX:+HeapDumpPath=$CATALINA_HOME/logs/
• -XX:+PrintGCDetails
• -XX:+PrintGCTimeStamps
• -XX:+PrintGCDateStamps
• -Xloggc:$CATALINA_HOME/logs/log.gc
• -XX:+PrintHeapAtGC 發生GC時，打印整個堆的使用狀況
• -XX:PrintTenuringDistribution 發生GC時候，打印Young區中對象的年齡狀況。

（2）Parallel GC調優指導原則

• 除非肯定，不然不要設置最大堆內存
• 優先設置吞吐量目標
• 若是吞吐量目標達不到，調大最大內存，不能讓OS使用Swap內存，若是仍然達不到，下降目標。
• 若是吞吐量能達到，GC時間太長，設置停頓時間的目標。

Oracle官網調優指南

實例：
項目默認啓動：

吞吐量    最小停頓時間    最大停頓時間    平均停頓時間      YGC       FullGC
96.37%    0.00195s      0.03732s       0.00575s          13        1

得出由於Metadpace致使Full GC。

目前metaspace是20.1M，咱們初步調大到32M，在內存調優時候，咱們須要一個參數一個參數調，這樣才能肯定到底時哪一個參數起的做用。
日誌分析：

吞吐量    最小停頓時間    最大停頓時間    平均停頓時間      YGC       FullGC
96.37%    0.00195s      0.03732s       0.00575s          13        1         ----默認啓動
97.69%    0.00172s      0.00538s       0.00352s          13        0         ----Metaspace調大到32M

咱們能夠根據日誌，以及每一個垃圾收集器的特色，例如這個並行垃圾收集器，咱們就能夠試着設置吞吐量和最大停頓時間目標，讓垃圾回收期本身動態調整，-XX:MaxGCPauseMillis=100 -XX:GCTimweeRatio=99，而後再經過GCViewer分析GC日誌。

（3）G1 GC調優

最佳實踐：

• 年輕代大小：避免使用-Xmn、-XX:NewRatio等顯式設置Yong區大小，會覆蓋暫停時間目標（XX:MaxGCPauseMills）；
• 暫停時間目標：暫停時間不要設置的太嚴格，其吞吐目標是90%的應用程序時間和10%垃圾回收時間，太嚴格會直接影響到吞吐量；

調優
默認參數啓動：

吞吐量    最小停頓時間    最大停頓時間    平均停頓時間      GC       
98.03%    0.00083s       0.01906s        0.00746s       6

設置內存大小，再次測試，-Xms512M -Xmx512M：

吞吐量    最小停頓時間    最大停頓時間    平均停頓時間      GC       
98.03%   0.00083s       0.01906s       0.00746s         6    ----默認啓動
95.87%   0.00076s       0.01291s       0.00578s         5    -Xms512M -Xmx512M

設置最大停頓時間限制，-XX:MaxGCPauseMillis=100：

吞吐量    最小停頓時間    最大停頓時間    平均停頓時間      GC       
98.03%   0.00083s       0.01906s       0.00746s         6    ----默認啓動
95.87%   0.00076s       0.01291s       0.00578s         5    -Xms512M -Xmx512M
95.68%   0.00065s       0.00703s       0.00065s         6    -XX:MaxGCPauseMillis=100

此次調整的參數反而致使吞吐量降低和GC次數增長，因此此次參數不該該調整。