一笑而过

JVM参数及gc日志详解

2020/05/22

​ 发现因探活失败而导致项目频繁重启，通过查看gc日志和dump文件定位到是由于项目频繁gc导致的。就此记录一下JVM参数和gc日志的含义。本文适合对jvm内存结构有一定了解的读者，如对jvm不了解请参看Java 基础之详解 Jvm

一、使用的JVM相关参数

本文只是列举了本文相关的JVM参数，更多JVM参数详见

-XX:+PrintGC #打印GC信息      
-XX:+PrintGCDetails    #打印GC的详细信息 和-XX:+PrintGC同时存在时-XX:+PrintGC不生效   
-Duser.timezone=Asia/Shanghai #设置时区 
-XX:+PrintGCTimeStamps  #GC时，打印进程启动到现在经历的时间 （持续时间）    
-XX:+PrintGCDateStamps    #输出GC的时间戳(以日期的形式）
-XX:+PrintHeapAtGC #每次GC前后打印堆信息        
-XX:+PrintTenuringDistribution #输出显示在survivor空间里面有效的对象的岁数情况。     
-Xloggc:/data/gc/logs/gc.log #gc日志输出地址

二、gc日志截图img

三、gc日志详解

​ 上图gc日志包含三部分信息：gc前堆信息，gc信息和gc后堆信息，gc前后堆信息包含PSYoungGen（年轻代）、ParOldGen（老年代）、Metaspace（元空间）的使用情况，年轻代包含eden space、 from space、to space的空间使用情况，可以看到这次gc是因为eden已经没有空间了。

1、gc前堆信息

{Heap before GC invocations=87 (full 1):   #invocationsgc次数; full (full 1)gc执行次数
 PSYoungGen      total 893440K, used 780520K [0x00000007b0800000, 0x00000007f0800000, 0x00000007f0800000)  #堆内存总空间是3G，新生代：老年代=1:2 所以新生代总空间大约为1G
  eden space 747520K, 100% used  #导致本次gc的直接原因，Eden : from : to = 8 : 1 : 1
  [0x00000007b0800000,0x00000007de200000,0x00000007de200000)
  from space 145920K, 22% used [0x00000007de200000,0x00000007e023a1b8,0x00000007e7080000)
  to   space 137728K, 0% used [0x00000007e8180000,0x00000007e8180000,0x00000007f0800000)
 ParOldGen       total 2097152K, used 622054K [0x0000000730800000, 0x00000007b0800000, 0x00000007b0800000) #堆内存总空间是3G，新生代：老年代=1:2 所以老生代总空间大约为2G
  object space 2097152K, 29% used [0x0000000730800000,0x0000000756779b18,0x00000007b0800000)
 Metaspace       used 107165K, capacity 109274K, committed 110464K, reserved 1146880K
  class space    used 12598K, capacity 13217K, committed 13440K, reserved 1048576K

2、gc信息

2020-05-15T14:47:36.576+0800: 9679.920: [GC (Allocation Failure) #分配空间失败导致gc，9679.920表示进程启动到现在经历的时间
Desired survivor size 133169152 bytes, new threshold 1 (max 15) #参见https://blog.csdn.net/z69183787/article/details/104975579/
[PSYoungGen: 780520K->1815K(918528K)] 1402575K->623957K(3015680K), 0.0075856 secs] 
#PSYoungGen （Parallel PSYoungGen 并行回收器） 780520K->1815K(918528K)表示GC前已使用->GC后已使用（年轻代总容量），[]之外表示堆GC前已使用->GC后已使用（堆总容量），最后为 GC 耗时。
[Times: user=0.02 sys=0.00, real=0.00 secs] #user表示用户态CPU耗时，sys表示系统CPU耗时，real表示GC实际耗时

3、gc后堆信息

​ 可以看到因为本次gc是Minor GC 所以新生代垃圾回收效果显著，老年代没有进行垃圾回收。

Heap after GC invocations=87 (full 1):
 PSYoungGen      total 918528K, used 1815K [0x00000007b0800000, 0x00000007f0800000, 0x00000007f0800000) 
  eden space 780800K, 0% used [0x00000007b0800000,0x00000007b0800000,0x00000007e0280000)
  from space 137728K, 1% used [0x00000007e8180000,0x00000007e8345c78,0x00000007f0800000)
  to   space 130048K, 0% used [0x00000007e0280000,0x00000007e0280000,0x00000007e8180000)
 ParOldGen       total 2097152K, used 622142K [0x0000000730800000, 0x00000007b0800000, 0x00000007b0800000)
  object space 2097152K, 29% used [0x0000000730800000,0x000000075678fb18,0x00000007b0800000)
 Metaspace       used 107165K, capacity 109274K, committed 110464K, reserved 1146880K
  class space    used 12598K, capacity 13217K, committed 13440K, reserved 1048576K
}

四、后续

​ 由gc日志可知频繁gc是由于eden没空间了，导致分配新空间失败所致，但是为什么新生代满了？是有大对象还是什么原因？这就需要分析dump文件，dump的分析需要使用一些工具，详情请看使用MAT(MemoryAnalyzer)分析dump文件排查内存泄漏，最后找到问题，一次性查“文章”记录过多导致（15000条）。

Post Directory