面试题集中营—GC日志简析及频繁GC的调优

如何查看GC日志

        有两种方式查看GC日志，一种是动态命令行查看

        jstat  -gc <pid> 300 5

        第二种就是在JVM参数中增加打印的参数，如下：

       -XX:+PrintGCDetails -XX:+PrintGCTimeStamps   表示打印每次GC的日志以及GC发生的时间

        -Xloggc:gc.log 可以把gc日志写入文件中

JVM配置的堆结构

        -XX:NewSize=5M -XX:MaxNewSize=5M -XX:InitialHeapSize=10M -XX:MaxHeapSize=10M

 -XX:SurvivorRatio=8 -XX:PretenureSizeThreshold=10M -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps

        新生代：5M、老年代：5M、Eden区：4M、FromSurvivor和ToSurvivor都是0.5M

GC日志说明

我们来看一个GC日志的打印结果：

0.144: [GC (Allocation Failure) 0.144: [ParNew: 3699K->510K(4608K), 0.0030788 secs] 3699K->1641K(9728K), 0.0031282 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
Heap
 par new generation   total 4608K, used 3745K [0x00000000ff600000, 0x00000000ffb00000, 0x00000000ffb00000)
  eden space 4096K,  78% used [0x00000000ff600000, 0x00000000ff928980, 0x00000000ffa00000)
  from space 512K,  99% used [0x00000000ffa80000, 0x00000000ffaffb40, 0x00000000ffb00000)
  to   space 512K,   0% used [0x00000000ffa00000, 0x00000000ffa00000, 0x00000000ffa80000)
 concurrent mark-sweep generation total 5120K, used 1130K [0x00000000ffb00000, 0x0000000100000000, 0x0000000100000000)
 Metaspace       used 3151K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 344K, capacity 388K, committed 512K, reserved 1048576K

        第一行是运行时的打印，后面是程序退出时的堆内存结果打印。

        第一行的0.144表示程序运行开始后0.144秒发生了一个GC。这是一次年轻代的GC，年轻代的GC算法是ParNew，3699K->510K表示本次GC清理的空间，4608K表示年轻代的总的可用空间，最后的时间0.0030788s 表示本次GC的时间。后面紧跟着的是年轻代GC前后堆的占用情况，后面9728K是堆内存的总大小。user、sys、real表示用户耗时，系统耗时和实际耗时。

       JVM退出时打印的结果分析：分成了三个部分

       1、年轻代管理，从这里我们能够看出年轻代、Eden区和Survivor区的空间及使用比例。

       2、老年代管理，老年代的GC算法和空间使用情况。

       3、元数据区, 元数据区域及class空间的使用情况。

     JDK1.8默认垃圾处理器

       我们把 -XX:+UseParNewGC -XX:+UseConcMarkSweepGC去掉，来查看一下默认情况下的GC日志。

0.177: [GC (Allocation Failure) [PSYoungGen: 3706K->488K(4608K)] 3706K->1700K(9728K), 0.0068803 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
Heap
 PSYoungGen      total 4608K, used 3711K [0x00000000ffb00000, 0x0000000100000000, 0x0000000100000000)
  eden space 4096K, 78% used [0x00000000ffb00000,0x00000000ffe25c30,0x00000000fff00000)
  from space 512K, 95% used [0x00000000fff00000,0x00000000fff7a020,0x00000000fff80000)
  to   space 512K, 0% used [0x00000000fff80000,0x00000000fff80000,0x0000000100000000)
 ParOldGen       total 5120K, used 1212K [0x00000000ff600000, 0x00000000ffb00000, 0x00000000ffb00000)
  object space 5120K, 23% used [0x00000000ff600000,0x00000000ff72f020,0x00000000ffb00000)
 Metaspace       used 3154K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 345K, capacity 388K, committed 512K, reserved 1048576K

        上述我们可以看到JDK1.8默认的年轻代垃圾处理器是PSYoungGen,默认的老年代垃圾回收器是ParOldGen。我们后面会单开一章来详细说明一下有关垃圾收集器的概念。

频繁GC调优

       GC分成Minor GC、Major GC 和 Full GC

       Minor GC：从年轻代空间回收内容，也成为Young GC

       Major GC：从老年代空间回收内存

       Full GC：清理整个内容堆 - 既包括年轻代也包括老年代

     Minor GC与Major GC过多

       Minor GC：就是年轻代空间太少不足以分配新的对象，就需要GC。Minor GC过多自然会导致Major GC变多，因为对于无法释放的对象，在多次复制移动后根据复制次数就会转移到老年代。        

      注： Major GC只有CMS这个垃圾回收器才有。

       解决方法：

       1、优化代码逻辑：这里可以多学习一下阿里的java手册

       2、如果应用存在大量的短期对象，就适当的增加年轻代的大小；如果应用存在较多的持久对象就适当的增加老年代的大小；

     Full GC

        Full GC（Full Garbage Collection）是对整个堆内存（包括年轻代、老年代、永久代或Metaspace等）进行清理的一种垃圾回收操作。触发Full GC的条件可能包括老年代空间不足、永久代/Metaspace空间不足、显式调用System.gc()等。Full GC的执行会导致相对较长的停顿时间，因为它需要对整个堆内存进行回收。

        CMS垃圾收集器的Full GC日志如下:

38.342: [GC (Allocation Failure) 38.342: [ParNew: 6144K->640K(6144K), 0.0027651 secs] 11491K->8130K(19840K), 0.0028367 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
38.345: [GC (CMS Initial Mark) [1 CMS-initial-mark: 7490K(13696K)] 8146K(19840K), 0.0004821 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
38.345: [CMS-concurrent-mark-start]
38.351: [CMS-concurrent-mark: 0.006/0.006 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
38.351: [CMS-concurrent-preclean-start]
38.351: [CMS-concurrent-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
38.351: [GC (CMS Final Remark) [YG occupancy: 1073 K (6144 K)]38.351: [Rescan (parallel) , 0.0002674 secs]38.352: [weak refs processing, 0.0000457 secs]38.352: [class unloading, 0.0006265 secs]38.352: [scrub symbol table, 0.0004225 secs]38.353: [scrub string table, 0.0001100 secs][1 CMS-remark: 7490K(13696K)] 8564K(19840K), 0.0015694 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 
38.353: [CMS-concurrent-sweep-start]
38.355: [CMS-concurrent-sweep: 0.002/0.002 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
38.355: [CMS-concurrent-reset-start]
38.355: [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

        解析：FullGC也会包括一次年轻代的GC，我们主要还是从第二行开始看

        第一个阶段（CMS Initial Mark）：initial-mark-初始标记节点，后面跟着的7490K是老年代的使用情况，13696K表示整个老年代的大小。8146K表示的是堆内存的使用情况，19840K是整个堆的大小。后面跟着的时间就是初始标记阶段的使用时间。这个阶段主要标记GC ROOTS，这个阶段为STW。

        第二个阶段（CMS-concurrent-mark）：并发标记阶段，这个阶段是从第一阶段标记的ROOTS来找存活的对象。和应用程序是并发执行的，并不会停止应用程序。

        第三个阶段（CMS-concurrent-preclean）：由于上一个阶段是并发的，那么一些对象的引用会发生变化，如果发生了变化，JVM会标记这个区域为DirtyCard。这个阶段就是重新标记。

        第四个阶段（CMS Final Remark）：最终标记阶段，这个阶段会老年代全部的存活对象，包括在并发标记阶段更改或者新创建的引用对象。后面跟着的一些统计数据，比如堆内存的使用情况，扫描花费的时间等。

        第五个阶段（CMS-concurrent-sweep）：并发清理阶段，不需要STW，主要是移除不需要的对象释放内存空间。

        第六个阶段（CMS-concurrent-reset）：并发重置阶段，主要是为了下一次GC做准备

        Parallel垃圾收集器的Full GC日志如下:

72.884: [GC (Allocation Failure) [PSYoungGen: 6125K->500K(6144K)] 16090K->13017K(19968K), 0.0042736 secs] [Times: user=0.11 sys=0.00, real=0.00 secs] 
72.888: [Full GC (Ergonomics) [PSYoungGen: 500K->0K(6144K)] [ParOldGen: 12517K->12671K(13824K)] 13017K->12671K(19968K), [Metaspace: 5545K->5535K(1056768K)], 0.0794034 secs] [Times: user=0.38 sys=0.00, real=0.08 secs] 
89.479: [Full GC (Ergonomics) [PSYoungGen: 5632K->1599K(6144K)] [ParOldGen: 12671K->13700K(13824K)] 18303K->15299K(19968K), [Metaspace: 5536K->5536K(1056768K)], 0.0526621 secs] [Times: user=0.16 sys=0.00, real=0.05 secs] 
101.378: [Full GC (Ergonomics) [PSYoungGen: 5632K->3391K(6144K)] [ParOldGen: 13700K->13699K(13824K)] 19332K->17090K(19968K), [Metaspace: 5536K->5536K(1056768K)], 0.0493102 secs] [Times: user=0.24 sys=0.00, real=0.05 secs] 

       解析：同样的也是年轻代和老年代同时进行了一次GC。PSYoungGen：使用了Parallel Scavenge并行垃圾收集器的新生代GC前后大小的变化；ParOldGen：使用了Parallel Old并行垃圾收集器的老年代GC前后大小的变化；Metaspace： 元数据区GC前后大小的变化，JDK1.8中引入了元数据区以替代永久代；xxx secs：指GC花费的时间

     触发GC的情况

       1、代码中调用system.gc()；

       2、老年代空间不足；

       3、堆中分配了大对象；

      解决方法 

        首先通过分析Full GC的过程，新生代和老年代的占用情况，还有每个阶段的时间。定位到具体的原因，比如我们发现老年代每次Full GC回收的内存很少，或者越来越少，FullGC的频率越来越快，那么就表示在堆中出现了无法释放的对象，每次回收都被标记成存活对象。此时就要配合堆分析工具查看占用内存的对象是哪些，并定位到代码中。

        其次在代码中创建了大对象，在新生代中无法分配就会直接进入老年代，这时也需要优化代码。

        原则上基本不需要怎么进行JVM调优，JVM的本身的设计是低延时高并发大吞吐量的，对于日常的服务来说基本上都可以满足了，只需要调整堆空间的大小即可。

        JVM调优的主要调整的部分：

        1、在内存大小不变的情况下，合理的内容空间分配可以提高系统的吞吐量；

        2、根据业务需要调整垃圾回收器；

        3、重点关注的区域是堆区，里面主要存放对象实例。

JDK工具

        jinfo：查看JVM配置参数信息

        jmap：查看当前程序JVM堆使用情况

        jstat：查看JVM GC统计信息