关于统计JVM fullgc次数的问题?

最近有个项目,使用ManagementFactory.getGarbageCollectorMXBeans()统计gc次数,代码如下:

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("初始fullgc次数为:{}", bean.getCollectionCount());
                        while (true) {
                            long temGcCount = bean.getCollectionCount();
                            if(temGcCount == fullGcCount) {
                                continue;
                            }else {
                                System.out.println(String.format("本次GC前FullGC总次数:%s, 新增FullGC次数:%s", fullGcCount, temGcCount - fullGcCount));
                                fullGcCount = temGcCount;
                            }
                        }
                    }
                }
            }
        });
        t.start();

然后主动执行jmap -histo:live来触发fullgc。
然而两次触发,第一次统计出来的是2次fullgc,第二次统计出来的是1次fullgc。

本次GC前FullGC总次数:1, 新增FullGC次数:2
本次GC前FullGC总次数:3, 新增FullGC次数:1

两次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] 
2023-01-10T19:18:14.645+0800: 80606.249: [GC (Allocation Failure) 80606.249: [ParNew: 174448K->7453K(188736K), 0.0064120 secs] 258379K->91385K(1027648K), 0.0066002 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
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] 
2023-01-10T19:23:06.286+0800: 80897.889: [GC (Allocation Failure) 80897.889: [ParNew: 167808K->2754K(188736K), 0.0053567 secs] 252981K->87927K(1027648K), 0.0055657 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 

第一次的fullgc日志看着是多了class unloading这些阶段,但是不明白为什么认为是2次fullgc,求大神指教~

阅读 1.5k
撰写回答
你尚未登录,登录后可以
  • 和开发者交流问题的细节
  • 关注并接收问题和回答的更新提醒
  • 参与内容的编辑和改进,让解决方法与时俱进
推荐问题