GC日志文件格式（JVM调优）

柔情只为你懂 2022-10-19 05:34 25阅读 0赞

先通过一条《深入理解java虚拟机》一书中的一个例子gc日志来回顾一下gc日志的基本知识，下面是一条gc日志：

33.125：[GC[DefNew: 3324k->152k(3712k), 0.0025925 secs] 3324k>152k(11904k),0.0031680 secs]

从左至右，各个信息的意思为：

33.125： 自虚拟机启动以来经过的秒数，单位为秒；  
GC： 垃圾收集的停顿类型为不需要STW（Stop The World ）。如果是Full GC说明发生了STW。如果是Full GC (System)说明是调用System.gc()方法所触发的收集。  
DefNew：表示GC发生的区域在新生代。这个名称和所使用的收集器密切相关。可以有Tenured、Perm、ParNew、PSYoungGen等等。其中hotspot虚拟机使用的是PSYoungGen代表新生代  
3324k->152k(3712k)：GC前该区域（DefNew）已使用容量->GC后该区域已使用容量（该内存区域总容量）  
0.0025925 secs：该内存区域（DefNew）GC所占用的时间。  
3324k->152k(11904k)：GC前Java堆已使用容量->GC后Java堆已使用容量（Java堆总容量）

线上启动项目时，打印GC的参数配置：

java -Xloggc:/tmp/gc-%t.log -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=20M -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCCause -jar app.jar

GC日志会打印到`/tmp/gc-2021-03-28_17-35-01.log.0.current`文件中。

下面是线上日志打印的结果，我们分析几条。

### 第一条 ###

2021-03-28T18:02:49.809+0800: 3.175: [GC (Allocation Failure) [PSYoungGen: 65536K->7435K(76288K)] 65536K->7451K(251392K), 0.0132004 secs] [Times: user=0.00 sys=0.02, real=0.01 secs]

*  2019-03-28T18:02:49.809+0800 : gc日志记录时间
 *  3.175 ：gc发生时，虚拟机运行了多少秒
 *  GC (Allocation Failure) ： 发生了一次垃圾回收，若前面有Full则表明是Full GC，没有Full的修饰表明这是一次Minor GC 。注意它不表示只GC新生代，括号里的内容是gc发生的原因，这里的Allocation Failure的原因是年轻代中没有足够区域能够存放需要分配的数据而失败。
 *  PSYoungGen： 使用的垃圾收集器的名字。
 *  65536K->7435K(76288K) ：垃圾收集前后的年轻代内存使用情况，其中前面的65536kb为gc之前的使用量，7435kb为gc之后的内存使用量。括号里的76288k为该内存区域的总量。
 *  65536K->7451K(251392K) ： 垃圾收集前后整个堆内存的使用情况，括号里的为整个可以的堆内存的容量。  
    0.0132004 secs ：整个GC过程持续时间
 *  \[Times: user=0.00 sys=0.02, real=0.01 secs\] ：分别表示用户态耗时，内核态耗时和总耗时。也是对gc耗时的一个记录。

### 第二条 ###

019-21-28T18:02:52.097+0800: 5.463: [GC (Metadata GC Threshold) [PSYoungGen: 13589K->8536K(76288K)] 15555K->10511K(251392K), 0.0159315 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]

一次minor gc，但是与前两次的gc原因不一样，这次的gc原因是：Metadata GC Threshold。Metadata即元数据的意思。我们可以看出这是与虚拟机的元数据区有关系的一次gc。元数据区，在jdk1.8以前又叫永久代，从JDK8开始，永久代(PermGen)的概念被废弃掉了，取而代之的就是这里的称为Metaspace的存储空间。元空间和永久代是虚拟机对方法区这个概念的一个具体实现。对于元空间而言，这一块空间是存在本地内存当中的。因此，默认情况下，元空间的大小仅受本地内存限制，但我们可以通过参数来指定元空间的大小。

这里元空间发生gc，说明元空间的内存不够了，到达了阀值。对元空间进行了一次垃圾回收，回收之前是13489k，回收之后是8536k。

### 第三条 ###

2019-21-28T18:02:52.114+0800: 5.479: [Full GC (Metadata GC Threshold) [PSYoungGen: 8536K->0K(76288K)] [ParOldGen: 1974K->8439K(88064K)] 10511K->8439K(164352K), [Metaspace: 20723K->20723K(1067008K)], 0.0733626 secs] [Times: user=0.09 sys=0.03, real=0.07 secs]

发生了一次Full GC，且触发原因也是元空间不足。

*  \[PSYoungGen: 8536K->0K(76288K)\] ：年轻代进行了一次gc
 *  \[ParOldGen: 1974K->8439K(88064K)\] ：老年代进行了一次gc
 *  \[Metaspace: 20723K->20723K(1067008K)\] ： 元空间（方法区）发生了一次gc，但是值得注意的是，gc前后内存使用情况并没有发生任何改变。同时，元空间总的可使用的内存为：1gb。

### 第四条 ###

2019-21-28T18:07:36.876+0800: 290.243: [Full GC (Ergonomics) [PSYoungGen: 58860K->52656K(859648K)] [ParOldGen: 757683K->757303K(1154560K)] 816543K->809960K(2014208K), [Metaspace: 62060K->62053K(1105920K)], 4.0586369 secs] [Times: user=11.55 sys=0.16, real=4.06 secs]

注意，这次full gc的原因发生了变化，为Full GC (Ergonomics），它的意思是执行了一次全局gc。

且从执行效果\[ParOldGen: 757683K->757303K(1154560K)\]来看，本次full gc从内存使用情况来看几乎没有起到作用。这有两个可能的原因：1.gc本身没有回收多少对象;2.gc回收了很多对象，但同时又有更多的对象进入老年代  
同时，元数据区使用量继续变大。

### OOM出现前GC的表现 ###

#### 1.通过日志观察到的现象 ####

程序运行过程中使用的内存不断升高

FullGC出现的频率越来越高

每次FullGC能回收的内存越来越少，最后基本回收不到内存

最终出现OOM

#### 2.原因分析 ####

出现了内存泄露，一定是有的对象一直占着内存不释放，导致FullGC回收不了，最终OOM。

JVM调优可以参考我的另一篇文章：https://blog.csdn.net/wuxiaolongah/article/details/114461027