理解 GC 日志

落日映苍穹つ 2022-04-16 06:27 227阅读 0赞

使用的是 `java version "1.8.0_161"`进行测试的。  
设置 JVM 启动参数为：

-Xms10m -Xmx10m -XX:+PrintGCDetails -Xloggc:/data/log/gc.log 
    -XX:+PrintGCDateStamps -XX:+HeapDumpOnOutOfMemoryError 
    -XX:HeapDumpPath=/data/log

执行代码片段：

public class RuntimeConstantPoolOOM { 
        public static void main(String[] args) { 
            List<String> list = new ArrayList<>();
            int i = 0;
            while (true) { 
                list.add(String.valueOf(i++).intern());
            }
        }
    }

然后抛出异常

Exception in thread "main" java.lang.OutOfMemoryError: GC overhead limit exceeded

下面来看生成的 gc.log。

CommandLine flags:
     -XX:+HeapDumpOnOutOfMemoryError
     -XX:HeapDumpPath=/data/log
     -XX:InitialHeapSize=10485760 
     -XX:MaxHeapSize=10485760
     -XX:+PrintGC 
     -XX:+PrintGCDateStamps 
     -XX:+PrintGCDetails 
     -XX:+PrintGCTimeStamps 
     -XX:+UseCompressedClassPointers
     -XX:+UseCompressedOops 
     -XX:+UseParallelGC

这是 gc.log 中的虚拟机运行的参数，可知我们的垃圾收集器是 ParallelGC。

##### Minor GC #####

Minor GC：新生代 GC，指发生在新生代的 GC 事件，新生代的 Java 对象大多朝生夕灭，Minor GC 会很频繁，回收速度非常快。

2018-11-18T19:31:12.804-0800: 0.207: 
    [ GC (Allocation Failure) [PSYoungGen: 2048K->496K(2560K)] 
     2048K->588K(9728K), 0.0011270 secs ]
    [Times: user=0.00 sys=0.01, real=0.00 secs]

1.  `2018-11-18T19:31:12.804-0800`： 发生 GC 事件的开始时间点
2.  `0.207`：GC 事件的开始时间，相对于 JVM 的启动时间，单位是秒
3.  `GC`：用来区分是 Minor GC 还是 Full GC 的标志，这里表示发生的 Minor GC
4.  `Allocation Failure`：引起垃圾回收的原因，本次 GC 是因为年轻代中不能存放新分配的数据结构
5.  `PSYoungGen`：表示新生代，这个名称由 GC 收集器决定，这里的收集器是 Parallel Scavenge，新生代收集器，采用复制算法进行收集
6.  `2048K->496K(2560K)`：表示本次 GC 之前和之后年轻代内存的使用情况，圆括号里的 2560k 表示年轻代的总大小，年轻代细分为 Eden、From Survivor、To Survivor 空间。
7.  `2048K->588K(9728K)`：表示本次 GC 之前和之后堆内存的使用情况，括号里的内存大小表示可用的堆内存
8.  `0.0011270 secs`：GC 事件持续的时间，单位是秒
9.  `Times: user=0.00 sys=0.01, real=0.00 secs`：GC 事件的持续时间，通过多种分类来进行衡量：  
    `user` \- 此次垃圾回收，垃圾收集线程消耗的所有 CPU 时间，即用户态消耗的 CPU 时间  
    `sys` \- 内核态消耗的 CPU 时间  
    `real` \- 应用程序暂停的时间（clock time）,包括各种非运算的等待耗时，如等待磁盘 I/O 、线程阻塞，CPU时间不包括这些

堆大小 = 新生代（eden + from + to） + 老年代，  
年轻代从 2048K->496K 回收了1552 k，  
堆内存 从 2048K->588K 回收了 1460 k，  
可知有 1552 - 1460 = 92k 的对象从年轻代升级到了老年代

##### Full GC #####

发生在老年代的 GC（或称 Major GC），经常伴随至少一次的 Minor GC，Full GC 的速度一般会比 Minor GC 慢 10 倍以上。

2018-11-18T19:31:12.857-0800: 0.259:
     [Full GC (Ergonomics) [PSYoungGen: 480K->0K(2560K)] 
     [ParOldGen: 5706K->5764K(7168K)] 6186K->5764K(9728K),
     [Metaspace: 3317K->3317K(1056768K)], 0.0556835 secs] 
     [Times: user=0.09 sys=0.00, real=0.06 secs]

1.  `[Full GC (Ergonomics) [PSYoungGen: 480K->0K(2560K)]`： 老年代 GC 又称 Major GC，会伴随着一次年轻代的 GC（Minor GC），速度比较慢
2.  `[ParOldGen: 5706K->5764K(7168K)] 6186K->5764K(9728K)`：老年代 GC，Parallel Scavenge 的老年代版本，`5706K->5764K(7168K)]` 这个和年轻代的 GC 类似，表示 GC 前和 GC 后所占用的空间。`6186K->5764K(9728K)`表示 GC 前和 GC 后堆内存的占用，括号里是堆内存的大小
3.  `[Metaspace: 3317K->3317K(1056768K)]`：表示元空间 GC 前和 GC 后的内存占用，括号里表示 JVM 元空间的总大小  
    参考：[Understanding Garbage Collection Logs][]  
    [JVM(十三)理解GC日志][JVM_GC]  
    [《深入理解Java虚拟机》（六）堆内存使用分析，垃圾收集器 GC 日志解读][Java_ GC]

[Understanding Garbage Collection Logs]: https://dzone.com/articles/understanding-garbage
[JVM_GC]: https://blog.csdn.net/zhangjianjaEE/article/details/78656852
[Java_ GC]: https://segmentfault.com/a/1190000010648021