likes
comments
collection
share

GC 日志和借助 Easy GC 分析

作者站长头像
站长
· 阅读数 5

Easy GC 是一个不错的 GC 日志分析平台（虽然商业化），但是提供了部分免费功能。

如何分析 GC 日志

测试代码：

/**
 *
 * CMS GC LOG 场景：
 * VM Args: -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
 *
 * G1 GC LOG 场景：
 * VM Args: -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
 *
 * @author zhengsh
 * @date 2021-8-13
 */
public class HeapOOM {

    public static void main(String[] args) {
        List<byte[]> list = new ArrayList<>();
        while (true) {
            list.add(new byte[2048]);
        }
    }
}

执行之后回频繁打印 GC 日志，下面是一个详细的 GC 日志 VM Args: -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

CMS 垃圾收集器 GC 日志分析

下面是一段完整的 GC 日志：

2022-04-17T23:29:40.688-0800: 0.427: [GC (Allocation Failure) To enable GC log rotation, use -Xloggc:<filename> -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=<num_of_files>
where num_of_file > 0
GC log rotation is turned off
2022-04-17T23:29:40.689-0800: 0.427: [ParNew: 2752K->319K(3072K), 0.0055017 secs] 2752K->2425K(9920K), 0.0056525 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
2022-04-17T23:29:40.702-0800: 0.440: [GC (Allocation Failure) 2022-04-17T23:29:40.702-0800: 0.440: [ParNew: 3071K->320K(3072K), 0.0159887 secs] 5177K->5138K(9920K), 0.0160631 secs] [Times: user=0.01 sys=0.01, real=0.01 secs] 
2022-04-17T23:29:40.719-0800: 0.457: [GC (CMS Initial Mark) [1 CMS-initial-mark: 4818K(6848K)] 5196K(9920K), 0.0002686 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2022-04-17T23:29:40.719-0800: 0.458: [CMS-concurrent-mark-start]
2022-04-17T23:29:40.720-0800: 0.459: [CMS-concurrent-mark: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2022-04-17T23:29:40.720-0800: 0.459: [CMS-concurrent-preclean-start]
2022-04-17T23:29:40.720-0800: 0.459: [CMS-concurrent-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2022-04-17T23:29:40.721-0800: 0.459: [GC (CMS Final Remark) [YG occupancy: 377 K (3072 K)]2022-04-17T23:29:40.721-0800: 0.459: [Rescan (parallel) , 0.0001184 secs]2022-04-17T23:29:40.721-0800: 0.459: [weak refs processing, 0.0000738 secs]2022-04-17T23:29:40.721-0800: 0.459: [class unloading, 0.0003178 secs]2022-04-17T23:29:40.721-0800: 0.460: [scrub symbol table, 0.0004800 secs]2022-04-17T23:29:40.722-0800: 0.460: [scrub string table, 0.0001745 secs][1 CMS-remark: 4818K(6848K)] 5196K(9920K), 0.0012455 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2022-04-17T23:29:40.722-0800: 0.460: [CMS-concurrent-sweep-start]
2022-04-17T23:29:40.722-0800: 0.461: [CMS-concurrent-sweep: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2022-04-17T23:29:40.723-0800: 0.461: [CMS-concurrent-reset-start]
2022-04-17T23:29:40.723-0800: 0.461: [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2022-04-17T23:29:40.729-0800: 0.468: [GC (Allocation Failure) 2022-04-17T23:29:40.729-0800: 0.468: [ParNew: 3071K->3071K(3072K), 0.0000425 secs]2022-04-17T23:29:40.729-0800: 0.468: [CMS: 4817K->6847K(6848K), 0.0070084 secs] 7888K->7809K(9920K), [Metaspace: 2715K->2715K(1056768K)], 0.0071286 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
2022-04-17T23:29:40.738-0800: 0.477: [GC (CMS Initial Mark) [1 CMS-initial-mark: 6847K(6848K)] 7811K(9920K), 0.0008446 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2022-04-17T23:29:40.739-0800: 0.478: [CMS-concurrent-mark-start]
2022-04-17T23:29:40.741-0800: 0.479: [CMS-concurrent-mark: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2022-04-17T23:29:40.741-0800: 0.479: [CMS-concurrent-preclean-start]
2022-04-17T23:29:40.742-0800: 0.480: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2022-04-17T23:29:40.742-0800: 0.480: [GC (CMS Final Remark) [YG occupancy: 1018 K (3072 K)]2022-04-17T23:29:40.742-0800: 0.480: [Rescan (parallel) , 0.0105555 secs]2022-04-17T23:29:40.753-0800: 0.491: [weak refs processing, 0.0002020 secs]2022-04-17T23:29:40.753-0800: 0.491: [class unloading, 0.0007003 secs]2022-04-17T23:29:40.754-0800: 0.492: [scrub symbol table, 0.0004289 secs]2022-04-17T23:29:40.754-0800: 0.492: [scrub string table, 0.0001928 secs][1 CMS-remark: 6847K(6848K)] 7866K(9920K), 0.0122433 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2022-04-17T23:29:40.754-0800: 0.493: [CMS-concurrent-sweep-start]
2022-04-17T23:29:40.755-0800: 0.493: [CMS-concurrent-sweep: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2022-04-17T23:29:40.755-0800: 0.493: [CMS-concurrent-reset-start]
2022-04-17T23:29:40.755-0800: 0.493: [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2022-04-17T23:29:40.779-0800: 0.517: [GC (Allocation Failure) 2022-04-17T23:29:40.779-0800: 0.517: [ParNew: 3068K->3068K(3072K), 0.0000359 secs]2022-04-17T23:29:40.779-0800: 0.517: [CMS: 6847K->6847K(6848K), 0.0057479 secs] 9916K->9818K(9920K), [Metaspace: 2715K->2715K(1056768K)], 0.0058647 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
2022-04-17T23:29:40.800-0800: 0.539: [GC (CMS Initial Mark) [1 CMS-initial-mark: 6847K(6848K)] 9820K(9920K), 0.0003379 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2022-04-17T23:29:40.801-0800: 0.539: [CMS-concurrent-mark-start]
2022-04-17T23:29:40.802-0800: 0.540: [CMS-concurrent-mark: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2022-04-17T23:29:40.802-0800: 0.540: [CMS-concurrent-preclean-start]
2022-04-17T23:29:40.803-0800: 0.541: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2022-04-17T23:29:40.803-0800: 0.541: [CMS-concurrent-abortable-preclean-start]
2022-04-17T23:29:40.803-0800: 0.541: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2022-04-17T23:29:40.803-0800: 0.541: [GC (CMS Final Remark) [YG occupancy: 2973 K (3072 K)]2022-04-17T23:29:40.803-0800: 0.541: [Rescan (parallel) , 0.0103808 secs]2022-04-17T23:29:40.813-0800: 0.552: [weak refs processing, 0.0000788 secs]2022-04-17T23:29:40.813-0800: 0.552: [class unloading, 0.0002551 secs]2022-04-17T23:29:40.814-0800: 0.552: [scrub symbol table, 0.0006772 secs]2022-04-17T23:29:40.814-0800: 0.553: [scrub string table, 0.0001837 secs][1 CMS-remark: 6847K(6848K)] 9820K(9920K), 0.0116955 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2022-04-17T23:29:40.815-0800: 0.553: [CMS-concurrent-sweep-start]
2022-04-17T23:29:40.815-0800: 0.553: [CMS-concurrent-sweep: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2022-04-17T23:29:40.815-0800: 0.554: [CMS-concurrent-reset-start]
2022-04-17T23:29:40.815-0800: 0.554: [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2022-04-17T23:29:40.819-0800: 0.558: [GC (Allocation Failure) 2022-04-17T23:29:40.820-0800: 0.558: [ParNew: 3070K->3070K(3072K), 0.0000444 secs]2022-04-17T23:29:40.820-0800: 0.558: [CMS: 6847K->6847K(6848K), 0.0061107 secs] 9917K->9905K(9920K), [Metaspace: 2715K->2715K(1056768K)], 0.0062647 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
2022-04-17T23:29:40.853-0800: 0.592: [GC (CMS Initial Mark) [1 CMS-initial-mark: 6847K(6848K)] 9907K(9920K), 0.0003864 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2022-04-17T23:29:40.854-0800: 0.592: [CMS-concurrent-mark-start]
2022-04-17T23:29:40.856-0800: 0.594: [CMS-concurrent-mark: 0.002/0.002 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2022-04-17T23:29:40.856-0800: 0.594: [CMS-concurrent-preclean-start]
2022-04-17T23:29:40.857-0800: 0.596: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2022-04-17T23:29:40.857-0800: 0.596: [CMS-concurrent-abortable-preclean-start]
2022-04-17T23:29:40.857-0800: 0.596: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2022-04-17T23:29:40.858-0800: 0.596: [GC (CMS Final Remark) [YG occupancy: 3059 K (3072 K)]2022-04-17T23:29:40.860-0800: 0.598: [Rescan (parallel) , 0.0104075 secs]2022-04-17T23:29:40.870-0800: 0.609: [weak refs processing, 0.0001138 secs]2022-04-17T23:29:40.870-0800: 0.609: [class unloading, 0.0003060 secs]2022-04-17T23:29:40.871-0800: 0.609: [scrub symbol table, 0.0008453 secs]2022-04-17T23:29:40.872-0800: 0.610: [scrub string table, 0.0003887 secs][1 CMS-remark: 6847K(6848K)] 9907K(9920K), 0.0139785 secs] [Times: user=0.00 sys=0.00, real=0.02 secs] 
2022-04-17T23:29:40.872-0800: 0.610: [CMS-concurrent-sweep-start]
2022-04-17T23:29:40.872-0800: 0.611: [Full GC (Allocation Failure) 2022-04-17T23:29:40.873-0800: 0.611: [CMS2022-04-17T23:29:40.873-0800: 0.611: [CMS-concurrent-sweep: 0.001/0.001 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
 (concurrent mode failure): 6847K->6847K(6848K), 0.0056779 secs] 9917K->9917K(9920K), [Metaspace: 2715K->2715K(1056768K)], 0.0057284 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
2022-04-17T23:29:40.878-0800: 0.617: [Full GC (Allocation Failure) 2022-04-17T23:29:40.878-0800: 0.617: [CMS: 6847K->6847K(6848K), 0.0050873 secs] 9917K->9917K(9920K), [Metaspace: 2715K->2715K(1056768K)], 0.0051308 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2022-04-17T23:29:40.886-0800: 0.624: [Full GC (Allocation Failure) 2022-04-17T23:29:40.886-0800: 0.624: [CMS: 6847K->278K(6848K), 0.0044491 secs] 9919K->278K(9920K), [Metaspace: 2740K->2740K(1056768K)], 0.0045030 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
Heap
 par new generation   total 3072K, used 87K [0x00000007fbe00000, 0x00000007fc150000, 0x00000007fc150000)
  eden space 2752K,   3% used [0x00000007fbe00000, 0x00000007fbe15e80, 0x00000007fc0b0000)
  from space 320K,   0% used [0x00000007fc0b0000, 0x00000007fc0b0000, 0x00000007fc100000)
  to   space 320K,   0% used [0x00000007fc100000, 0x00000007fc100000, 0x00000007fc150000)
 concurrent mark-sweep generation total 6848K, used 278K [0x00000007fc150000, 0x00000007fc800000, 0x00000007fc800000)
 Metaspace       used 2747K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 292K, capacity 386K, committed 512K, reserved 1048576K

借助商业工具 Easy GC

官网地址 gceasy.ycrash.cn/ GC 日志和借助 Easy GC 分析

上传文件分析 gc_h.log.0.current.log 生成建议： GC 日志和借助 Easy GC 分析 堆空间 GC 日志和借助 Easy GC 分析 停顿时间 GC 日志和借助 Easy GC 分析 回收统计 GC 日志和借助 Easy GC 分析

其他信息 GCeasy-report-gc_h.pdf