关于ManagementFactory.getGarbageCollectorMXBeans统计FullGC次数异常的问题

问题描述 #

我想统计FullGC次数，编写了如下监控代码：

Thread t = new Thread(new Runnable() {
    @Override
    public void run() {
        long fullGcCount = 0;
        for(GarbageCollectorMXBean bean: ManagementFactory.getGarbageCollectorMXBeans()) {
            System.out.println(bean.getName());
            if(bean.getName().equals("ConcurrentMarkSweep")) {
                logger.info("init fullgc count:{}", bean.getCollectionCount());
                while (true) {
                    long temGcCount = bean.getCollectionCount();
                    if(temGcCount == fullGcCount) {
                        continue;
                    }else {
                        System.out.println(String.format("before the FullGC, sum of fullgc:%s, add FullGC count:%s", fullGcCount, temGcCount - fullGcCount));
                        fullGcCount = temGcCount;
                    }
                }
            }
        }
    }
});
t.start();

我运行了两次jmap -histo:live，触发了两次FullGC，对应的GC日志如下：

第一次GC日志 #

2023-01-10T19:18:03.496+0800: 80595.099: [Full GC (Heap Inspection Initiated GC) 80595.099: [CMS[YG occupancy: 168131 K (188736 K)]80595.174: [weak refs processing, 0.0015483 secs]80595.176: [class unloading, 0.0253856 secs]80595.201: [scrub symbol table, 0.0237105 secs]80595.225: [scrub string table, 0.0020402 secs]: 112558K->83931K(838912K), 0.2212898 secs] 280689K->252063K(1027648K), [Metaspace: 117424K->117424K(1155072K)], 0.2218481 secs] [Times: user=0.39 sys=0.04, real=0.22 secs]

第二次GC日志 #

2023-01-10T19:18:29.536+0800: 80621.139: [Full GC (Heap Inspection Initiated GC) 80621.139: [CMS: 83931K->85173K(838912K), 0.3054333 secs] 108263K->85173K(1027648K), [Metaspace: 117022K->117022K(1155072K)], 0.3058419 secs] [Times: user=0.29 sys=0.01, real=0.31 secs]

从日志看每次各触发1次FullGC，但我的程序输出显示第一次触发时FullGC次数增加了2次，第二次增加1次：

......
before the FullGC, sum of fullgc:1, add FullGC count:2
before the FullGC, sum of fullgc:3, add FullGC count:1
......

原因分析与修复 #

1. 代码初始化bug #

你的代码中存在一个明显错误：没有将fullGcCount初始化为CMS收集器当前的收集次数。

你定义了long fullGcCount = 0;，但找到ConcurrentMarkSweep的GarbageCollectorMXBean后，仅打印了初始计数，却未将fullGcCount更新为当前的bean.getCollectionCount()值。这会导致程序启动前已发生的CMS收集次数，被当作后续新增的次数统计进去。

修复方式：在打印初始计数后，将fullGcCount赋值为当前的收集次数：

if(bean.getName().equals("ConcurrentMarkSweep")) {
    fullGcCount = bean.getCollectionCount(); // 新增这行，初始化当前计数
    logger.info("init fullgc count:{}", fullGcCount);
    while (true) {
        // 后续逻辑不变
    }
}

2. 一次jmap -histo:live触发两次CMS计数的原因 #

第一次jmap触发后计数增加2，核心原因是jmap -histo:live触发的FullGC在CMS收集器中会执行两次关联的收集动作：

• 执行jmap -histo:live时，JVM会先触发一次Young区的对象晋升（ParNew收集），将Young区存活对象全部移动到Old区；
• 随后对Old区执行CMS FullGC，完成堆内存清理。

这两个动作都会被ConcurrentMarkSweep的GarbageCollectorMXBean统计为收集次数，因此一次jmap操作会导致计数增加2。而第二次jmap触发时，Young区内存占用较低，不需要额外的Young区晋升操作，仅执行Old区的CMS收集，因此计数只增加1。

另外，部分旧版本JDK的CMS收集器存在计数逻辑bug，也可能导致一次FullGC被统计为两次，建议检查并升级到稳定的JDK版本。

内容的提问来源于stack exchange，提问作者Wang Jun