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次数增长，因此此次参数不该该调整。