GC日志介绍

本节将会介绍一下JVM常用的GC日志相关的参数，然后会对各个收集器的GC日志的各个部分做个详细的介绍。

JVM的GC日志参数

在我的前面的博客《JVM常用参数选项介绍》中，已经介绍了很多的GC日志相关的JVM参数，我们这里就用了下面几个参数，设置JVM参数的方式里面也有介绍，如果想了解更多可以看下那篇博客。

• -XX:+PrintGCDetails 在发生垃圾回收时打印内存回收详细的日志，并在进程退出时输出当前内存各区域分配情况。
• -XX:+PrintGCTimeStamps  打印GC发生时相对于JVM启动时的时间。
• -XX:+PrintGCDateStamps  打印出GC发生的具体时间。
• -Xloggc:<file> 表示把GC日志写入到一个文件中去，而不是打印到标准输出中。
• -XX:+PrintHeapAtGC  每一次GC前和GC后，都打印堆信息。这个参数用的话，会打印的日志比较多：每次GC前后的各个区域（Eden，from、to、Old、Metaspace等区域）的容量、使用量、使用占比等

我使用的是JDK1.8，使用一个springboot程序打的jar包，每种收集器的GC日志都会有区别，可以修改JVM参数修改所使用的垃圾收集器，然后观察不同的垃圾收集器的GC日志。

GC日志格式介绍

GC日志一般都是看两种GC：Minor GC（young GC）和Full GC，下面是从网上找到的两张young GC和Full GC的日志格式详解，图中会跟我发的日志有些许出入，但是不影响理解。

通过图示，我们可以发现GC日志格式的规律一般都是：GC前内存占用—>GC后内存占用（该区域内存总大小）

另外，我们还发现GC日志中有三个时间：user，sys和real

• user – 进程执行用户态代码（核心之外）所使用的时间。这是执行此进程所使用的实际 CPU 时间，其他进程和此进程阻塞的时间并不包括在内。在垃圾收集的情况下，表示 GC 线程执行所使用的 CPU 总时间。
• sys – 进程在内核态消耗的 CPU 时间，即在内核执行系统调用或等待系统事件所使用的 CPU 时间
• real – 程序从开始到结束所用的时钟时间。这个时间包括其他进程使用的时间片和进程阻塞的时间（比如等待 I/O 完成）。对于并行gc，这个数字应该接近（用户时间+系统时间）除以垃圾收集器使用的线程数。

一般的GC事件中，real time是小于sys+user time的，因为一般是多个线程并发的去做GC，所以real time是要小于sys+user time的。如果real>sys+user的话，则你的应用可能存在下列问题：IO负载非常重或者是CPU不够用。

young GC日志：[GC (Allocation Failure) [PSYoungGen: 31744K->2192K(36864K)] 31744K->2200K(121856K), 0.0139308 secs] [Times: user=0.05 sys=0.01, real=0.01 secs] 

Full GC日志介绍：[Full GC (Metadata GC Threshold) [PSYoungGen: 5104K->0K(132096K)] [ParOldGen: 416K->5453K(50176K)] 5520K->5453K(182272K), [Metaspace: 20637K->20637K(1067008K)], 0.0245883 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 

 

Parallel收集器GC日志

启动命令如下：

java -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -Xloggc:./gc.log  -jar demo.jar  &

启动的时候如果不指定收集器默认使用的是并行收集器Parallel Scavenge+Parallel Old的组合，启动完成后GC日志如下：可以看到帮我们设置了一些默认的JVM参数，这种类型的GC日志格式上面已经介绍过了。

Java HotSpot(TM) 64-Bit Server VM (25.171-b11) for linux-amd64 JRE (1.8.0_171-b11), built on Mar 28 2018 17:07:08 by "java_re" with gcc 4.3.0 20080428 (Red Hat 4.3.0-8)
Memory: 4k page, physical 8009432k(5404404k free), swap 0k(0k free)
CommandLine flags: -XX:InitialHeapSize=128150912 -XX:MaxHeapSize=2050414592 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC 
2019-10-24T17:46:38.455+0800: 0.466: [GC (Allocation Failure) [PSYoungGen: 31744K->2192K(36864K)] 31744K->2200K(121856K), 0.0139308 secs] [Times: user=0.05 sys=0.01, real=0.01 secs] 
2019-10-24T17:46:38.611+0800: 0.622: [GC (Allocation Failure) [PSYoungGen: 33936K->2704K(68608K)] 33944K->2720K(153600K), 0.0055295 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
2019-10-24T17:46:38.805+0800: 0.816: [GC (Allocation Failure) [PSYoungGen: 66192K->3744K(68608K)] 66208K->3768K(153600K), 0.0078802 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
2019-10-24T17:46:38.985+0800: 0.996: [GC (Allocation Failure) [PSYoungGen: 67232K->4673K(132096K)] 67256K->4705K(217088K), 0.0060158 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
2019-10-24T17:46:39.187+0800: 1.198: [GC (Metadata GC Threshold) [PSYoungGen: 75443K->5104K(132096K)] 75475K->5520K(217088K), 0.0071404 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
2019-10-24T17:46:39.195+0800: 1.205: [Full GC (Metadata GC Threshold) [PSYoungGen: 5104K->0K(132096K)] [ParOldGen: 416K->5453K(50176K)] 5520K->5453K(182272K), [Metaspace: 20637K->20637K(1067008K)], 0.0245883 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 
2019-10-24T17:46:40.022+0800: 2.033: [GC (Allocation Failure) [PSYoungGen: 126976K->4692K(206336K)] 132429K->10217K(256512K), 0.0099817 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
2019-10-24T17:46:40.900+0800: 2.911: [GC (Allocation Failure) [PSYoungGen: 205908K->6628K(259072K)] 211433K->19268K(309248K), 0.0168431 secs] [Times: user=0.06 sys=0.01, real=0.02 secs] 

上面打印的日志比较简单，如果启用了-XX:+PrintHeapAtGC参数，则打印的日志就会比较多了，如下所示：每次GC前后的各个区域（Eden，from、to、Old、Metaspace等区域）的容量、使用量、使用占比等都会被打印出来。

{Heap before GC invocations=2 (full 0):
 PSYoungGen      total 36864K, used 33968K [0x00000000d7400000, 0x00000000d9d00000, 0x0000000100000000)
  eden space 31744K, 100% used [0x00000000d7400000,0x00000000d9300000,0x00000000d9300000)
  from space 5120K, 43% used [0x00000000d9300000,0x00000000d952c010,0x00000000d9800000)
  to   space 5120K, 0% used [0x00000000d9800000,0x00000000d9800000,0x00000000d9d00000)
 ParOldGen       total 84992K, used 8K [0x0000000085c00000, 0x000000008af00000, 0x00000000d7400000)
  object space 84992K, 0% used [0x0000000085c00000,0x0000000085c02000,0x000000008af00000)
 Metaspace       used 10224K, capacity 10514K, committed 10624K, reserved 1058816K
  class space    used 1214K, capacity 1323K, committed 1408K, reserved 1048576K
2019-10-23T17:54:25.803+0800: 0.610: [GC (Allocation Failure) 
[PSYoungGen: 33968K->2656K(36864K)] 33976K->2672K(121856K), 0.0035263 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
Heap after GC invocations=2 (full 0):
 PSYoungGen      total 36864K, used 2656K [0x00000000d7400000, 0x00000000dbc00000, 0x0000000100000000)
  eden space 31744K, 0% used [0x00000000d7400000,0x00000000d7400000,0x00000000d9300000)
  from space 5120K, 51% used [0x00000000d9800000,0x00000000d9a98020,0x00000000d9d00000)
  to   space 5120K, 0% used [0x00000000d9300000,0x00000000d9300000,0x00000000d9800000)
 ParOldGen       total 84992K, used 16K [0x0000000085c00000, 0x000000008af00000, 0x00000000d7400000)
  object space 84992K, 0% used [0x0000000085c00000,0x0000000085c04000,0x000000008af00000)
 Metaspace       used 10224K, capacity 10514K, committed 10624K, reserved 1058816K
  class space    used 1214K, capacity 1323K, committed 1408K, reserved 1048576K
}

CMS收集器日志

启动命令如下：使用-XX:+UseConcMarkSweepGC命令启用了CMS+ParNew的收集器组合。

java  -XX:+UseConcMarkSweepGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -Xloggc:./gc.log  -jar demo.jar  &

Java HotSpot(TM) 64-Bit Server VM (25.171-b11) for linux-amd64 JRE (1.8.0_171-b11), built on Mar 28 2018 17:07:08 by "java_re" with gcc 4.3.0 20080428 (Red Hat 4.3.0-8)
Memory: 4k page, physical 8009432k(5374436k free), swap 0k(0k free)
CommandLine flags: -XX:InitialHeapSize=128150912 -XX:MaxHeapSize=2050414592 -XX:MaxNewSize=348966912 -XX:MaxTenuringThreshold=6 -XX:OldPLABSize=16 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:+UseParNewGC 
2019-10-25T15:17:22.103+0800: 0.474: [GC (Allocation Failure) 2019-10-25T15:17:22.103+0800: 0.474: [ParNew: 33856K->2195K(38080K), 0.0046083 secs] 33856K->2195K(122752K), 0.0047429 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
2019-10-25T15:17:22.247+0800: 0.618: [GC (Allocation Failure) 2019-10-25T15:17:22.247+0800: 0.618: [ParNew: 36051K->1818K(38080K), 0.0115188 secs] 36051K->3679K(122752K), 0.0115990 secs] [Times: user=0.03 sys=0.01, real=0.01 secs] 
2019-10-25T15:17:22.370+0800: 0.741: [GC (GCLocker Initiated GC) 2019-10-25T15:17:22.370+0800: 0.741: [ParNew: 35675K->1754K(38080K), 0.0020893 secs] 37536K->3614K(122752K), 0.0021557 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-10-25T15:17:22.436+0800: 0.807: [GC (Allocation Failure) 2019-10-25T15:17:22.436+0800: 0.807: [ParNew: 35610K->2358K(38080K), 0.0031579 secs] 37470K->4219K(122752K), 0.0032263 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
2019-10-25T15:17:22.542+0800: 0.913: [GC (Allocation Failure) 2019-10-25T15:17:22.542+0800: 0.913: [ParNew: 36214K->2849K(38080K), 0.0038451 secs] 38075K->4709K(122752K), 0.0039135 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
2019-10-25T15:17:22.644+0800: 1.015: [GC (Allocation Failure) 2019-10-25T15:17:22.644+0800: 1.015: [ParNew: 36705K->2565K(38080K), 0.0065677 secs] 38565K->4976K(122752K), 0.0066423 secs] [Times: user=0.02 sys=0.01, real=0.00 secs] 
2019-10-25T15:17:22.763+0800: 1.134: [GC (Allocation Failure) 2019-10-25T15:17:22.763+0800: 1.134: [ParNew: 36421K->3713K(38080K), 0.0090066 secs] 38832K->6733K(122752K), 0.0090870 secs] [Times: user=0.03 sys=0.00, real=0.00 secs] 
2019-10-25T15:17:22.926+0800: 1.297: [GC (Allocation Failure) 2019-10-25T15:17:22.926+0800: 1.297: [ParNew: 37569K->2719K(38080K), 0.0067120 secs] 40589K->6168K(122752K), 0.0067936 secs] [Times: user=0.03 sys=0.00, real=0.00 secs] 
2019-10-25T15:17:22.940+0800: 1.310: [GC (CMS Initial Mark) [1 CMS-initial-mark: 3449K(84672K)] 7830K(122752K), 0.0044113 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
2019-10-25T15:17:22.944+0800: 1.315: [CMS-concurrent-mark-start]
2019-10-25T15:17:22.960+0800: 1.331: [CMS-concurrent-mark: 0.016/0.016 secs] [Times: user=0.06 sys=0.01, real=0.01 secs] 
2019-10-25T15:17:22.960+0800: 1.331: [CMS-concurrent-preclean-start]
2019-10-25T15:17:22.961+0800: 1.332: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2019-10-25T15:17:22.961+0800: 1.332: [CMS-concurrent-abortable-preclean-start]
2019-10-25T15:17:23.086+0800: 1.457: [CMS-concurrent-abortable-preclean: 0.062/0.125 secs] [Times: user=0.48 sys=0.00, real=0.13 secs] 
2019-10-25T15:17:23.088+0800: 1.459: [GC (CMS Final Remark) [YG occupancy: 20583 K (38080 K)]2019-10-25T15:17:23.088+0800: 1.459: [Rescan (parallel) , 0.0053038 secs]2019-10-25T15:17:23.094+0800: 1.464: [weak refs processing, 0.0000257 secs]2019-10-25T15:17:23.094+0800: 1.464: [class unloading, 0.0036873 secs]2019-10-25T15:17:23.097+0800: 1.468: [scrub symbol table, 0.0022628 secs]2019-10-25T15:17:23.100+0800: 1.470: [scrub string table, 0.0003715 secs][1 CMS-remark: 3449K(84672K)] 24032K(122752K), 0.0120789 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
2019-10-25T15:17:23.101+0800: 1.472: [CMS-concurrent-sweep-start]
2019-10-25T15:17:23.103+0800: 1.474: [CMS-concurrent-sweep: 0.002/0.002 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
2019-10-25T15:17:23.103+0800: 1.474: [CMS-concurrent-reset-start]
2019-10-25T15:17:23.174+0800: 1.544: [CMS-concurrent-reset: 0.070/0.070 secs] [Times: user=0.20 sys=0.05, real=0.07 secs] 

可以看到设置了-XX:MaxTenuringThreshold=6这个参数，表示Survivor区的对象晋升老年代的年龄阈值为6，这个值在JDK 1.8之前默认为15。

young GC日志跟上面类似，就不再重复介绍了：2019-10-25T15:17:22.644+0800: 1.015: [GC (Allocation Failure) 2019-10-25T15:17:22.644+0800: 1.015: [ParNew: 36705K->2565K(38080K), 0.0065677 secs] 38565K->4976K(122752K), 0.0066423 secs] [Times: user=0.02 sys=0.01, real=0.00 secs] 

结合我前面的博客《常用垃圾收集器介绍》对CMS收集器的工作过程介绍，可以看到六个步骤：

• 1、初始标记（CMS initial mark）——STW：这个阶段是标记从GCRoots直接可达的老年代对象、新生代引用的老年代对象，速度很快 。
• 2、并发标记（CMS concurrent mark）：并发标记阶段就是进行GC Roots Tracing的过程，由前阶段标记过的对象出发，所有可到达的对象都在本阶段中标记。
• 3、并发预清理（CMS concurrent preclean）：此阶段标记从新生代晋升的对象、新分配到老年代的对象以及在并发阶段被修改了的对象，因此，这个阶段也需要扫描新生代+老年代。此阶段做的事情跟重新标记类似，目的是为了让重新标记阶段的STW尽可能短。
• 4、重新标记（CMS remark）——STW：而重新标记阶段则是为了修正并发标记期间因用户程序继续运作而导致标记产生变动的那一部分对象的标记记录，这个阶段的停顿时间一般会比初始标记阶段稍长一些，但远比并发标记的时间短。
• 5、并发清除（CMS concurrent sweep）：用户线程被重新激活，同时清理那些无效的对象。
• 6、并发重置（CMS concurrent reset）：CMS清除内部状态，为下次回收做准备。

如果想对CMS收集器的GC日志有更多的了解，推荐两篇文章《GC之详解CMS收集过程和日志分析》和《理解CMS GC日志》。

G1收集器日志

启动命令如下：使用-XX:+UseG1GC 命令启用了G1收集器。

java  -XX:+UseG1GC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -Xloggc:./gc.log  -jar demo.jar  &

G1日志是最复杂的，推荐两篇文章：https://blog.csdn.net/fouy_yun/article/details/78376154，https://www.cnblogs.com/cuizhiquan/articles/11068752.html

参考资料
Java HotSpot Virtual Machine Garbage Collection Tuning Guide Release 8
Java垃圾收集必备手册。