GC日志分析

垃圾收集器在进行垃圾收集的过程中，可以输出日志，我们通过日志，可以看到当前垃圾收集器的运行情况。通过gc日志，我们可以观察垃圾收集器的行为，以及当前应用程序的GC情况和内存使用情况。学会查看和分析垃圾收集日志，一方面可以帮助我们学习垃圾收集器；另一方面，在必要的时候，可以帮助我们定位问题，解决问题，对JVM进行优化。

　　默认，JVM不会打印出GC日志信息，可以通过参数-XX:+PrintGC或-verbose:gc来设置JVM输出gc日志到终端中。

　　JVM参数：-XX:+PrintGC -XX:+UseSerialGC -Xms10m -Xmx10m

[GC (Allocation Failure)  1922K->1394K(9920K), 0.0021245 secs]
[Full GC (Allocation Failure)  7585K->7538K(9920K), 0.0023668 secs]

　　当设置了"-XX:+PrintGC"或者"-verbose:gc"以后就会输出类似输出上面的GC日志。这是最简单的GC日志，包含了垃圾收集过程中的信息。其中红色部分的"GC"和"Full GC"表示这次GC的类型，而绿色部分的"Allocation Failure"表示表示发生这次GC的原因，从上面的日志可以看出，是由于内存分配失败导致的GC。后面的黄色部分"1922K->1394K(9920K)"表示这次GC导致JVM中堆内存的使用量从1922K降低到了1394K，其中括号中表示当前整个JVM堆的大小。最后蓝色部分的"0.0021245 secs"表示这次GC持续的时间。

　　上面输出的是简单格式的GC日志，虽然提供了一些信息，但是通过这些信息，我们没法知道这次GC发生的时候，这次GC是发生在老年代还是在年轻代，是否有对象从年轻代被移动到了老年代等信息，所以我们希望可以看到更加详尽的信息。这个时候，我们需要设置-XX:+PrintGCDetails参数来输出更加详细的GC日志，下面我们结合不同的收集器组合，来分析下它们的输出日志。

Serial GC + Serial Old

　　Serial GC和Serial Old收集器是比较早的单线程收集器，工作原理我们在上面已经介绍过了。这里，我们来看下使用这两款收集器进行垃圾收集的时候，输出的日志格式是怎么样的。首先我们需要设置JVM参数：

　　JVM参数：-XX:+PrintGC -XX:+PrintGCDetails -XX:+UseSerialGC -Xms10m -Xmx10m

[GC (Allocation Failure) 
[DefNew: 1922K->319K(3072K), 0.0027356 secs] 1922K->1394K(9920K), 0.0027698 secs] 
[Times: user=0.00 sys=0.00, real=0.00 secs] 

[Full GC (Allocation Failure) 
[Tenured: 6514K->6484K(6848K), 0.0025899 secs] 8562K->8532K(9920K), [Metaspace: 2984K->2984K(1056768K)], 0.0026153 secs] 
[Times: user=0.00 sys=0.00, real=0.00 secs] 

 　　可以发现，通过设置了"-XX:+PrintGCDetails"以后，输出的GC日志信息多了很多。我们先来看第一条，红色部分"GC"表示这次发生的是Minor GC，绿色部分"Allocation Failure"表示导致这次GC的原因是内存分配失败。接下来，黄色部分的内容，则和前面的日志有些区别了，这里输出的内容相对比较详细。"DefNew: 1922K->319K(3072K), 0.0027356 secs] 1922K->1394K(9920K), 0.0027698 secs"，其中DefNew表示这次GC发生在年轻代（不同的收集器，日志的格式不一定相同）,接下来"1922K->319K"表示这次GC导致年轻代使用的内存从1922K降到319K，括号中的"3072K"表示年轻代中的堆内存大小为3072K。"0.0027356 secs"表示这次年轻代GC耗时0.0027356s。后面的"1922K->1393K"表示总的堆内存（年轻代 + 老年代）的使用情况的变化，从1922K降低到1394K, 括号中的"9920K"表示总的堆内存的大小。最后的"0.0027698 secs"表示这次GC总的消耗的时间。最后是这次GC消耗的时间的统计，其中user表示用户态CPU执行的时间，sys表示内核态CPU执行的时间，这两个时间不包括被挂起消耗的时间，而real表示的是实际的时间，可以认为是墙上时钟走过的时间。

　　下面的这条日志，"Full GC"表示这次GC是一次Major GC，后面的原因和上面一样。我们来看下黄色部分，"Tenured"表示这次GC发生在老年代，其中"6524K->6484K"表示老年代内存从6524K降低到6484K。后面的时间"0.0025899 secs"表示这次老年代GC耗时0.0025899s。接下来的"8562K -> 8532K"和上面提到的一样，表示整个堆内存的变化。最后的时间表示这次GC的总耗时为"0.0026153s"。

Parallel Scanvage + Parallel Old

　　不同的垃圾收集器，输出的日志信息也不是完全相同的，上面我们看到的日志，是使用Serial GC和Serial Old收集器输出的gc日志，而下面的日志信息，则是使用Parallel Scavenge收集器和Parallel Old收集器输出的日志。

　　JVM参数：-XX:+PrintGC -XX:+UseParallelOldGC -XX:+PrintGCDetails -Xms10m -Xmx10m

[GC (Allocation Failure) --
[PSYoungGen: 1391K->1391K(2560K)] 7537K->7537K(9728K), 0.0007436 secs] 
[Times: user=0.00 sys=0.00, real=0.00 secs] 

[Full GC (Allocation Failure) 
[PSYoungGen: 1391K->1374K(2560K)] 
[ParOldGen: 6145K->6145K(7168K)] 7537K->7520K(9728K), [Metaspace: 2984K->2984K(1056768K)], 0.0037697 secs] 
[Times: user=0.01 sys=0.00, real=0.01 secs] 

　　可以看到，使用Parallel Scavenge 和 Parallel Old收集器输出的日志，会有一些不同，不过日志内容大体上差不多。最后，我们来看下CMS垃圾收集器的日志是怎么样的，相对上面几款收集器，CMS相对更加复杂，从它输出的日志也可以看出来。

ParNew + Concurrent Mark Sweep（CMS）

　　下面，我们来看下ParNew配合CMS收集器在进行垃圾收集的时候，输出的GC 日志信息。

　　JVM参数：-XX:+PrintGC -XX:+UseConcMarkSweepGC -XX:+PrintGCDetails -Xms10m -Xmx10m

[GC (Allocation Failure) [ParNew: 2418K->0K(3072K), 0.0032236 secs] 3508K->3455K(9920K), 0.0032520 secs] 
[Times: user=0.01 sys=0.00, real=0.00 secs] 

[GC (CMS Initial Mark) [1 CMS-initial-mark: 3455K(6848K)] 4479K(9920K), 0.0005566 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[CMS-concurrent-mark-start]
[CMS-concurrent-mark: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[CMS-concurrent-preclean-start]
[CMS-concurrent-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC (CMS Final Remark) [YG occupancy: 1024 K (3072 K)]
[Rescan (parallel) , 0.0001118 secs][weak refs processing, 0.0000191 secs][class unloading, 0.0002858 secs]
[scrub symbol table, 0.0003506 secs][scrub string table, 0.0001305 secs]
[1 CMS-remark: 3455K(6848K)] 4479K(9920K), 0.0009500 secs] 
[Times: user=0.00 sys=0.00, real=0.01 secs] 
[CMS-concurrent-sweep-start]
[CMS-concurrent-sweep: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[CMS-concurrent-reset-start]
[CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

　　通过第一条日志，可以看出我们使用"-XX:+UseConcMarkSweepGC"指定CMS垃圾收集器的时候，使用的是ParNew + CMS收集器组合。下面输出的一堆日志，就是CMS收集器在进行垃圾收集过程中输出的信息。可以明显的看到，CMS在进行垃圾收集的过程中，经历了4个阶段，在日志中我用4中颜色标记出来了。需要注意的是黄色部分，这是CMS的重新标记的阶段，在上面我们介绍CMS收集器的时候说过，在这个阶段，是会出现Stop The World的，所以如果这个阶段消耗的时间比较长，则会影响应用的响应时间。

其他日志参数

　　有时候，我们需要在GC日志中输出时间值，这样我们就可以知道这次GC发生的具体时间点。我们可以通过JVM参数"-XX:+PrintGCTimeStamps" 和"-XX:+PrintGCDateStamps"来设置日志输出的时间。使用"-XX:+PrintGCTimeStamps"参数，可以在输出的日志前加上产生日志的时间戳：

7.327: [GC (Allocation Failure) 7.327: [DefNew: 2095K->2095K(3072K), 0.0000209 secs]

　　可以看到，输出的日志中，在头部包含了一个时间戳，表示从JVM启动以来经过的秒数。而"-XX:+PrintGCDateStamps"则表示输出日志时的当前时间，相对来说更加直观：

2017-02-24T00:14:38.611-0800: [GC (Allocation Failure) 
2017-02-24T00:14:38.611-0800: [DefNew: 1922K->319K(3072K), 0.0025676 secs] 1922K->1394K(9920K), 0.0026134 secs] 

　　除了将日志输出到控制台，我们还可以将日志输出到日志文件中，这样就可以通过分析日志文件来分析系统的GC情况了，一般在服务器运行过程中，我们都会将GC日志输出到指定的文件中，供需要的时候分析。可以通过JVM参数"-Xloggc:<file>"来指定日志输出的目录。