JVM性能调优之GC日志分析

1.为什么需要GC日志

Java虚拟机GC日志是用于定位问题重要的日志信息，频繁的GC可能导致应用吞吐量下降，响应时间增加，甚至导致服务不可用。所以需要我们对GC日志进行分析并优化。

2. 如何开启GC日志

我们可以在JVM中设置参数-XX:+PrintGC或者-verbose:gc，默认GC日志是关闭的，但是如果想输出GC详细的日志，可以增加其他的辅助参数。可以根据自己的需求增加。

注意：GC的日志是以替换的方式(>)写入的，而不是追加(>>)，如果下次写入到同一个文件中的话，以前的GC内容会被清空。

参数	描述
-XX:+PrintGC	输出GC日志，默认是关闭的
-XX:+PrintGCDetails	输出GC的详细日志，默认是关闭的
-XX:+PrintGCTimeStamps	输出GC的时间戳，以基准时间的形式
-XX:+PrintGCDateStamps	输出GC的时间戳，以日期的形式(类似于2022-04-01T14:21:33.438+0800)
-XX:+PrintHeapAtGC	在进行GC的前后打印出堆的信息
-Xloggc:/usr/local/gc/gc.log	指定将GC日志输出到具体的文件，默认为标准输出

3. 查询GC日志

3.1 使用JVM参数开启GC日志

我们今天idea中使用JVM参数开启GC日志，如图：

-XX:+PrintGC    //输出GC日志，默认是关闭的
-XX:+PrintGCDetails  //输出GC的详细日志，默认是关闭
-XX:+PrintGCTimeStamps //输出GC的时间戳，以基准时间的形式
-XX:+PrintGCDateStamps // 输出GC的时间戳，以日期的形式(类似于2022-04-01T14:21:33.438+0800)
-XX:+UseConcMarkSweepGC  //打开此开关参数后，使用ParNew+CMS+Serial Old收集器组合进行垃圾收集。Serial Old作为CMS收集器出现Concurrent Mode Failure的备用垃圾收集器。
-Xloggc:C:\Users\DXH\Desktop\gc.txt//指定将GC日志输出到具体的文件，默认为标准输出

GC日志输出结果：

2022-04-01T14:36:23.631+0800: 0.213: [Full GC (System.gc()) 2022-04-01T14:36:23.631+0800: 0.213: [CMS: 0K->11914K(173440K), 0.0381510 secs] 31921K->11914K(251456K), [Metaspace: 5380K->5380K(1056768K)], 0.0383984 secs] [Times: user=0.05 sys=0.00, real=0.04 secs] 
2022-04-01T14:36:23.778+0800: 0.360: [GC (Allocation Failure) 2022-04-01T14:36:23.778+0800: 0.360: [ParNew: 69504K->80K(78144K), 0.0012867 secs] 81418K->11994K(251584K), 0.0013509 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
Heap
 par new generation   total 78144K, used 9174K [0x00000006c3000000, 0x00000006c84c0000, 0x00000006ec990000)
  eden space 69504K,  13% used [0x00000006c3000000, 0x00000006c38e1af0, 0x00000006c73e0000)
  from space 8640K,   0% used [0x00000006c7c50000, 0x00000006c7c64000, 0x00000006c84c0000)
  to   space 8640K,   0% used [0x00000006c73e0000, 0x00000006c73e0000, 0x00000006c7c50000)
 concurrent mark-sweep generation total 173440K, used 11914K [0x00000006ec990000, 0x00000006f72f0000, 0x00000007c0000000)
 Metaspace       used 5514K, capacity 5742K, committed 5760K, reserved 1056768K
  class space    used 596K, capacity 637K, committed 640K, reserved 1048576K

Minor GC日志分析：

//自JVM启动0.360秒时发生本次GC
2022-04-01T14:36:23.778+0800: 0.360: 
/**
* 对新生代进行GC，使用ParNew收集器
* 69504K是新生代回收前的大小，80K是新生代回收后的大小
* 78144K是当前新生代分配的内存总大小，
* 0.0012867 secs表示本次新生代回收耗时 0.0012867秒
*/
[ParNew: 69504K->80K(78144K), 0.0012867 secs] 

/**
* 81418K是整个堆内存回收之前的大小，11994K是整个堆内存回收之后的大小
* 251584K是当前整个堆内存大小。
* 0.0013509 secs表示本次新生代回收耗时 0.0013509 秒
*/
81418K->11994K(251584K), 0.0013509 secs] 
/**
* user：指的是CPU工作在用户态所花费的时间；
* sys：指的是CPu工作在内核态所花费的时间；
* real：指的是在此次GC事件中所花费的总时间，即STW时间
*/
[Times: user=0.00 sys=0.00, real=0.00 secs] 

Full GCr GC日志分析：

//老年代GC，System.gc()是GC的原因
[Full GC (System.gc()) 
//自JVM启动0.213秒时发生本次GC
2022-04-01T14:36:23.631+0800: 0.213: 
/**
* 对老年代进行GC，使用CMS收集器
* 0K是老年代回收前的大小，11914K是老年代回收后的大小
* 173440K是当前老年代分配的内存总大小，
* 0.0381510 secs表示本次老年代回收耗时 0.0381510 秒
*/
[CMS: 0K->11914K(173440K), 0.0381510 secs] 
/**
* 31921K是整个堆内存回收之前的大小，11914K是整个堆内存回收之后的大小
* 251456K是当前整个堆内存大小。
* 0.0383984 secs表示本次新生代回收耗时 0.0383984 秒
*/
31921K->11914K(251456K), 
[Metaspace: 5380K->5380K(1056768K)], 0.0383984 secs] 
/**
* user：指的是CPU工作在用户态所花费的时间；
* sys：指的是CPU工作在内核态所花费的时间；
* real：指的是在此次GC事件中所花费的总时间，即STW时间
*/
[Times: user=0.05 sys=0.00, real=0.04 secs] 

无论是 minor GC 或者是 Full GC, 我们主要关注 GC 回收实时耗时 , 如 real=0.02secs, 即 stop the world 时间，如果该时间过长，则严重影响应用性能。

3.2 CMS GC 日志分析

Concurrent Mark Sweep(CMS)是老年代回收器，从名字 (Mark Sweep) 可以看出，CMS 收集器就是 “标记-清除” 算法实现的，分为六个步骤：

1. 初始标记(STW initial mark)；
2. 并发标记 (Concurrent marking)；
3. 并发预清理(Concurrent precleaning)；
4. 重新标记(STW remark)；
5. 并发清理 (Concurrent sweeping)；
6. 并发重置 (Concurrent reset)。

其中初始标记 (STW initial mark) 和 重新标记 (STW remark) 需要”Stop the World”。

• 初始标记：在这个阶段需要虚拟机停顿正在执行的任务，官方的叫法STW（Stop The World），这个过程从垃圾回收的根对象开始，只扫描到能够和根对象直接关联的对象，并作标记，这个过程虽然暂停了JVM，但是很快完成了。
• 并发标记：这个阶段紧随初始标记阶段，在初始标记的基础上继续向下追溯标记，并发标记阶段，应用程序的线程和并发标记的线程并发执行，所以用户感受不到停顿。
• 并发预清理：该阶段仍是并发的，在这个阶段，虚拟机查找在执行并发标记阶段新进入老年代的对象（可能会有一些对象从新生代晋升到老年代，或者有一些对象直接被分配到老年代）。
  通过重新扫描，减少下一个阶段重新标记的工作，因为下一个阶段会 Stop The World。
• 重新标记：这个阶段会暂停虚拟机，收集线程扫描在CMS堆中剩余的对象，扫描从根对象开始向下追溯，并处理对象关联。
• 并发清理：清理垃圾对象，这个阶段应用程序线程和收集器线程并发执行。
• 并发重置：这个阶段重置CMS收集器的数据结构，等待下一次回收。

CMS使得在收集过程中只是很短的暂停应用的执行，我们可以在JVM 参数中设置 -XX:UseConcMarkSweepGC 来使用此收集器 , 不过此收集器仅用于 old （老年代）和 Perm(永生代) 的对象收集。

不过CMS减少了STW的次数，但是整体GC时间增加，因为 CMS Initial mark 和 remark 都会 stop the world，记做 2 次。所以一次 CMS 至少会让 Full GC 的次数 +2，而 CMS 可能失败再引发一次 Full GC。

此外 CMS 进行垃圾回收时也有可能会发生失败的情况，有以下几种

• 伴随prommotion failed，然后Full GC：
  prommotion failed代表存活区内存不足，对象进入老年代，而此时老年代也没有内存容纳对象，将导致一次Full GC。
• 伴随着Concurrent modelFailed，然后Full GC：
  CMS回收速度慢，CMS完成前，老年代被占满，将导致一次Full GC。
• 频繁 CMS GC：
  内存吃紧，老年代长时间处于较满的状态

4. JVM常用参数

4.1 设置堆大小

参数名称	含义	默认值	说明
-Xms2g	初始化堆大小为2G	物理内存的1/64(小于1GB)	当空余堆内存小于40%时，JVM就会增大堆直到-Xmx最大值限制，可以使用-XX：MaxHeapFreeRatio指定这个比例
-Xmx2g	最大堆大小为2G	物理内存的1/4(小于1GB)	当空余堆内存大于70%时，JVM就会减少堆直到-Xms最大值限制，可以使用-XX：MaxHeapFreeRatio指定这个比例
-XX：NewRatio	年轻代(包括eden和两个Survivor )与老年代（除去老年代）的比值	-XX：NewRati=4表示年轻代和老年代所占比值为1：4，年轻代占整个堆栈的1/5， Xms=Xmx并且设置了Xmn的情况下，该参数不需要进行设置
-XX：SurvivorRatio	eden和Survivor的比值	-XX：SurvivorRatio=8：2表示一个Survivor区占1/10

4.2 设置年轻代大小

参数名称	含义	默认值	说明
-Xmn2g	年轻代大小为2G		注意此处大小是（Eden+2个Survivor Space），与jmap-heap中显示的new gen是不同的，整个堆大小=年轻代+老年代+持久代(永久代)，增大年轻代后，将会减小年老代大小。此值对系统性能影响较大，Sun官方推荐配置为整个堆的3/8
-XX：NewSize=2G	设置年轻代大小为2G
-XX：MaxNewSize=2G	年轻代最大值大小为2G

4.2 设置持久代（方法区）大小

参数名称	含义	默认值	说明
-XX：PermSize=64M	设置持久代大小为64M	物理内存的1/64
-XX：MaxPermSize=2G	持久代最大值大小为2G	物理内存的1/4

4.3 设置线程的堆栈大小

参数名称	含义	默认值	说明
-Xss1024K	每个线程的堆栈大小1024k	JDK5.0以后每个线程堆栈大小为1M，以前每个线程堆栈大小为256K	根据应用的线程所需内存大小进行调整。在相同物理内存下，减小这个值能生成更多的线程。但是操作系统对一个进程内的线程数还是有限制的，不能无限生成，经验值在3000~5000左右。(例如：-Xss1024K)

4.4 设置GC收集器

参数名称	含义
-XX:+UseSerialGC	虚拟机运行在client模式下的默认值，打开此开关后，使用Serial+SerialOld的收集器组合进行内存回收。
-XX:+UseParNewGC	指定使用ParNew+SerialOld收集器组合回收内存
-XX:+UserConMarkSweepGC	使用ParNew+CMS+Serial Old的收集器组合进行内存回收。Serial Old收集器将作为CMC收集器出现Concurrent Mode Fail失败后的后被收集处理器使用
-XX:+UserParallelOldGC	使用ParallelScavenge+Parallel Old的收集器进行内存回收
-XX:+UseG1GC	使用G1的收集器进行内存回收

4.5 其他常用参数

参数名称	含义	默认值	说明
-XX：DisableExplicitGC	关闭System.gc()		这个参数需要严格的测试
-XX：MaxTenuringThreshold	晋升老年代的对象年龄，每个对象在坚持一次Minor GC之后，年龄就增加，当超过这个参数值时就进入老年代
-XX：PretenureSizeThreshold	直接晋升老年代对象的大小，设置这个参数后，大于这个参数的对象将直接在老年代分配	0
-XX：ParallelGCThread	并行收集器的线程数		配置与处理器数目相同，适用于CMS
-XX：MaxGCPauseMillis	设置GC的最大停顿时间，仅在使用Parallel Scavenge收集器时生效
-XX：HandlePromotionFailure	是否允许分配担保失败，即老年代的剩余空间不足以应付新生代的整个Eden和survivor区的所有对象都存活的极端情况
-XX:+CMSInitiatingOccupancyFraction	设置CMS收集器在老年代空间被使用多少后触发垃圾收集。默认值为百分之68，仅在使用CMS收集器时生效
-XX:+UseCMSCompactAtFullCollection	设置CMS收集器在完成垃圾收集后是否进行一次内存碎片整理，仅在使用CMS收集器时生效
-XX:+CMSFullGCsBeforeCompaction	设置CMS收集器在进行若干次垃圾收集后在启动一次内存碎片整理。仅在使用CMS收集器时生效
-XX:+HeapDumpOnOutOfMemory	当抛出OOM时，使用HPOF将堆的快照保存在当前目录
-XX:+HeapDumpPath	快照输出路径