一次频繁Full GC问题排查过程分享

问题描述

• 应用收到频繁Full GC告警

问题排查

• 登陆到对应机器上去，查看GC日志，发现YGC一分钟已经达到了15次，比Full GC还要频繁一些，其中Full GC平均10分钟超过了4次，以下图
  
  
• 使用jstat -gcutil 5280 1000查看实时GC状况，年老代采用的是CMS收集器，发现触发Full GC的缘由是年老代占用空间达到指定阈值70%（-XX:CMSInitiatingOccupancyFraction=70）。

• 这时候猜想是某个地方频繁建立对象致使，经过jmap -dump:format=b,file=temp.dump 5280 dump文件，而后下载到本地经过jvisualvm分析对象的引用链的方式来定位具体频繁建立对象的地方，dump文件下载下来有5G多，整个导入过程都花了10多分钟。想查看所占空间较多对象的引用链，直接OOM了，dump对象太大了。这时候就换了种思路，查看占用空间比较大的一系列对象，看能不能找出什么端倪。占用空间最大的几类对象以下图
  
  
  发现排第一的chart[]对象里面，存在一些metrics监控的具体指标的相关内容，排第二的io.prometheus.client.Collector$MetricFamilySample$Sample和排第9和第13对象都是spring boot中metrics指标监控相关的对象，因此此时怀疑metrics监控的某个地方在频繁建立对象，首先考虑的是否由于metrics指标太多致使的，因而登陆线上机器curl localhost:8080/mertrics > metrics.log，发现响应内容有50多M，参考其余相关的正常应用，指标总共内容也就10多M左右，打开指标内容发现了不少相似以下图的指标
  
  
  
  看到了这里已经能够肯定代码中上报这个指标是存在问题的，并无达到咱们想要的效果，因此也怀疑也是这个地方致使的Full GC频繁。

  问题初步解决

• 因为这个指标也可有可无，初步解决方案就把上报该指标的代码给干掉。上线后看下Full GC问题是否会获得改善，果真，上线后Full GC告警问题已经解决。

初步解决后的思考，为何会有这个问题？

• 外部监控系统，每25s会来调用metrics这个接口，这个接口会把全部的metrics指标转成字符串而后做为http响应内容响应。监控每来调用一次就会产生一个50多M的字符串，致使了频繁YGC，进而致使了晋升至年老代的对象也多了起来，最长年老代内存占用达到70%触发了Full GC。

根源问题重现

• 此处采用metrics的做用：统计线程池执行各种任务的数量。为了简化代码，用一个map来统计，重现代码以下

import java.util.Map;
    import java.util.concurrent.*;
    import java.util.concurrent.atomic.AtomicInteger;
    
    /**
     * 线程池经过submit方式提交任务，会把Runnable封装成FutureTask。
     * 直接致使了Runnable重写的toString方法在afterExecute统计的时候没有起到咱们想要的做用，
     * 最终致使几乎每个任务（除非hashCode相同）就按照一类任务进行统计。因此这个metricsMap会愈来愈大，调用metrics接口的时候，会把该map转成一个字符返回
     */
    public class GCTest {
        /**
         * 统计各种任务已经执行的数量
         * 此处为了简化代码，只用map来代替metrics统计
         */
        private static Map<String, AtomicInteger> metricsMap = new ConcurrentHashMap<>();
    
        public static void  main(String[] args) throws InterruptedException {
            ThreadPoolExecutor threadPoolExecutor = new ThreadPoolExecutor(10, 10, 0, TimeUnit.SECONDS, new LinkedBlockingQueue<>()){
                /**
                 * 统计各种任务执行的数量
                 * @param r
                 * @param t
                 */
                @Override
                protected void afterExecute(Runnable r, Throwable t) {
                    super.afterExecute(r, t);
                    metricsMap.compute(r.toString(), (s, atomicInteger) ->
                            new AtomicInteger(atomicInteger == null ? 0 : atomicInteger.incrementAndGet()));
                }
            };
            /**
             * 源源不断的任务添加进线程池被执行
             */
            for (int i =0; i < 1000; i++) {
                threadPoolExecutor.submit(new SimpleRunnable());
            }
            Thread.sleep(1000 * 2);
            System.out.println(metricsMap);
            threadPoolExecutor.shutdownNow();
        }
        static class SimpleRunnable implements Runnable{
    
            @Override
            public void run() {
                System.out.println("SimpleRunnable execute success");
            }
            /**
             * 重写toString用于统计任务数
             * @return
             */
            @Override
            public String toString(){
                return this.getClass().getSimpleName();
            }
        }
    }

最终解决

• 能够把submit改为execute便可

总结

• 以上重显代码能够看出metricsMap中的元素是会愈来愈多的。若是就这样下去，最终的结果也会出现OOM。
• 根本缘由仍是对ThreadPoolExecutor不够熟悉，因此出现了此次问题。
• 我的感受Full GC类问题是比较让人头疼的。这些问题并不会想代码语法问题同样，ide会提示咱们具体错在哪里，咱们只要修改对应地方基本都能解决。形成Full GC频繁的缘由也有不少，好比多是jvm参数设置不合理、Metaspace空间触发、频繁建立对象触发等等。
• 若是肯定了是频繁建立对象致使，那么接下来的目的就是肯定频繁建立对象的对应代码处，这时候能够选择经过dump线上堆栈，而后下载到本地。选择一些可视化分析工具进行分析。最终定位到出问题的代码处，而后解决问题。

版权声明
做者：wycm
出处：https://www.cnblogs.com/w-y-c-m/p/9919717.html
您的支持是对博主最大的鼓励，感谢您的认真阅读。
本文版权归做者全部，欢迎转载，但未经做者赞成必须保留此段声明，且在文章页面明显位置给出原文链接，不然保留追究法律责任的权利。