GCLog分析

# GC日志详解

对于java应用我们可以通过一些配置把程序运行过程中的gc日志全部打印出来，然后分析gc日志得到关键性指标，分析GC原因，调优JVM参数。

打印GC日志方法，在JVM参数里增加参数，%t 代表时间

-Xloggc:./gc-%t.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps -XX:+PrintGCCause  
-XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=10 -XX:GCLogFileSize=100M

1
2

Tomcat则直接加在JAVA_OPTS变量里。

# 如何分析GC日志

运行程序加上对应gc日志

java -jar -Xloggc:./gc-%t.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps  -XX:+PrintGCTimeStamps -XX:+PrintGCCause  -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=10 -XX:GCLogFileSize=100M microservice-eureka-server.jar

我们可以看到图中第一行红框，是项目的配置参数。这里不仅配置了打印GC日志，还有相关的VM内存参数。

第二行红框中的是在这个GC时间点发生GC之后相关GC情况。

1、对于2.909： 这是从jvm启动开始计算到这次GC经过的时间，前面还有具体的发生时间日期。

2、Full GC(Metadata GC Threshold)指这是一次full gc，括号里是gc的原因， PSYoungGen是年轻代的GC，ParOldGen是老年代的GC，Metaspace是元空间的GC

3、 6160K->0K(141824K)，这三个数字分别对应GC之前占用年轻代的大小，GC之后年轻代占用，以及整个年轻代的大小。

4、112K->6056K(95744K)，这三个数字分别对应GC之前占用老年代的大小，GC之后老年代占用，以及整个老年代的大小。

5、6272K->6056K(237568K)，这三个数字分别对应GC之前占用堆内存的大小，GC之后堆内存占用，以及整个堆内存的大小。

6、20516K->20516K(1069056K)，这三个数字分别对应GC之前占用元空间内存的大小，GC之后元空间内存占用，以及整个元空间内存的大小。

7、0.0209707是该时间点GC总耗费时间。

从日志可以发现几次fullgc都是由于元空间不够导致的，所以我们可以将元空间调大点

java -jar -Xloggc:./gc-adjust-%t.log -XX:MetaspaceSize=256M -XX:MaxMetaspaceSize=256M -XX:+PrintGCDetails -XX:+PrintGCDateStamps  -XX:+PrintGCTimeStamps -XX:+PrintGCCause  -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=10 -XX:GCLogFileSize=100M microservice-eureka-server.jar

调整完我们再看下gc日志发现已经没有因为元空间不够导致的fullgc了

对于CMS和G1收集器的日志会有一点不一样，也可以试着打印下对应的gc日志分析下，可以发现gc日志里面的gc步骤跟我们之前讲过的步骤是类似的

public class HeapTest {
    byte[] a = new byte[1024 * 100];  //100KB
    public static void main(String[] args) throws InterruptedException {
        ArrayList<HeapTest> heapTests = new ArrayList<>();
        while (true) {
            heapTests.add(new HeapTest());
            Thread.sleep(10);
        }
    }
}

1
2
3
4
5
6
7
8
9
10

-Xloggc:d:/gc-cms-%t.log -Xms50M -Xmx50M -XX:MetaspaceSize=256M -XX:MaxMetaspaceSize=256M -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps -XX:+PrintGCCause  -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=10 -XX:GCLogFileSize=100M -XX:+UseParNewGC -XX:+UseConcMarkSweepGC

-Xloggc:d:/gc-g1-%t.log -Xms50M -Xmx50M -XX:MetaspaceSize=256M -XX:MaxMetaspaceSize=256M -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps -XX:+PrintGCCause  -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=10 -XX:GCLogFileSize=100M -XX:+UseG1GC

上面的这些参数，能够帮我们查看分析GC的垃圾收集情况。但是如果GC日志很多很多，成千上万行。就算你一目十行，看完了，脑子也是一片空白。所以我们可以借助一些功能来帮助我们分析，这里推荐一个**gceasy**(https://gceasy.io (opens new window))，可以上传gc文件，然后他会利用可视化的界面来展现GC情况。具体下图所示

上图我们可以看到年轻代，老年代，以及永久代的内存分配，和最大使用情况。

上图我们可以看到堆内存在GC之前和之后的变化，以及其他信息。这个工具还提供基于机器学习的JVM智能优化建议，当然现在这个功能需要付费

# GCLog 分析例子

Java HotSpot(TM) 64-Bit Server VM (25.281-b09) for bsd-amd64 JRE (1.8.0_281-b09), built on Dec  9 2020 12:44:49 by "java_re" with gcc 4.2.1 Compatible Apple LLVM 10.0.0 (clang-1000.11.45.5)
Memory: 4k page, physical 16777216k(53404k free)

/proc/meminfo:

CommandLine flags: -XX:InitialHeapSize=62914560 -XX:MaxHeapSize=62914560 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:SurvivorRatio=8 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC 
14.508: [GC (Allocation Failure) [PSYoungGen: 16384K->2016K(18432K)] 16384K->14294K(59392K), 0.0081521 secs] [Times: user=0.01 sys=0.03, real=0.01 secs] 
21.304: [GC (Allocation Failure) [PSYoungGen: 18309K->2040K(18432K)] 30587K->22211K(59392K), 0.0132841 secs] [Times: user=0.04 sys=0.03, real=0.01 secs] 
35.813: [GC (Allocation Failure) [PSYoungGen: 18345K->2044K(18432K)] 38517K->36177K(59392K), 0.0130356 secs] [Times: user=0.03 sys=0.03, real=0.02 secs] 
35.826: [Full GC (Ergonomics) [PSYoungGen: 2044K->0K(18432K)] [ParOldGen: 34133K->36039K(40960K)] 36177K->36039K(59392K), [Metaspace: 9104K->9104K(1058816K)], 0.0181604 secs] [Times: user=0.06 sys=0.01, real=0.02 secs] 
50.565: [Full GC (Ergonomics) [PSYoungGen: 16322K->9306K(18432K)] [ParOldGen: 36039K->40814K(40960K)] 52361K->50121K(59392K), [Metaspace: 9201K->9201K(1058816K)], 0.0169998 secs] [Times: user=0.06 sys=0.01, real=0.01 secs] 
Heap
 PSYoungGen      total 18432K, used 11613K [0x00000007bec00000, 0x00000007c0000000, 0x00000007c0000000)
  eden space 16384K, 70% used [0x00000007bec00000,0x00000007bf757690,0x00000007bfc00000)
  from space 2048K, 0% used [0x00000007bfc00000,0x00000007bfc00000,0x00000007bfe00000)
  to   space 2048K, 0% used [0x00000007bfe00000,0x00000007bfe00000,0x00000007c0000000)
 ParOldGen       total 40960K, used 40814K [0x00000007bc400000, 0x00000007bec00000, 0x00000007bec00000)
  object space 40960K, 99% used [0x00000007bc400000,0x00000007bebdb988,0x00000007bec00000)
 Metaspace       used 9219K, capacity 9634K, committed 9984K, reserved 1058816K
  class space    used 1072K, capacity 1168K, committed 1280K, reserved 1048576K

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20

# 解析

年轻代变化：16384K->2016K 表明年轻代在GC之前是满的（16384K），GC完成后，存活的对象占用了2016K。
整个堆的变化：16384K->14294K 指的是整个堆（包括年轻代和老年代）在GC前后的变化。GC前整个堆的使用量为16384K，而GC后整个堆的使用量变成了14294K。

如果我们来计算这两者之间的差异：

年轻代清理了：16384K - 2016K = 14368K
整个堆内存释放了：16384K - 14294K = 2090K

这里看似有矛盾，实际上是因为在GC过程中，一部分对象从年轻代晋升到了老年代。这个晋升过程导致老年代的使用增加，从而使整个堆的释放空间看起来不如年轻代清理的空间大。换句话说，虽然年轻代清理了较多空间，但晋升到老年代的对象占用了一部分，这部分在整个堆的计算中表现为较少的空间释放。

因此，整个堆的减少量（2090K）并不等于年轻代清理掉的内存量（14368K），因为晋升机制的作用导致老年代的占用增加，减少了可见的“空间释放”。这种情况常见于那些生成许多短暂对象但同时有一定数量对象持续存活（并晋升到老年代）的应用场景。

# GC过程中多少新生代进入老年代?

从给定的GC日志数据中，我们可以估算进入老年代的数据量。以下是如何计算：

年轻代的减少：如前所述，年轻代从16384K减少到2016K，即清理了14368K。
整个堆的减少：整个堆从16384K减少到14294K，即清理了2090K。

年轻代清理掉的内存与整个堆清理掉的内存之间的差额就是晋升到老年代的内存量，这是因为被清理的内存部分转移到了老年代。我们可以用以下公式计算晋升到老年代的内存量：

晋升到老年代的内存量=(年轻代清理的内存量)−(整个堆清理的内存量)

晋升到老年代的内存量=14368K−2090K=12278K

因此，根据这个计算，约有12278K的内存从年轻代晋升到了老年代。这表示GC过程中，这部分内存由于在年轻代中存活了足够长的时间或者由于其他原因（如对象大小、存活年龄等）被转移到了老年代。

上次更新: 2025/10/14, 20:08:40

← 字节码与操作数栈 jdk17新特性→