JVM-记一次线上应用无法访问(GC时间过长)

1.线上普罗米修斯频繁报警

有一台IP是247的机器,服务无法访问. 

imagexianshangbaojing

2.报错信息是redis超时2秒,导致获取当前登录用户信息失败(这是公共方法)。

发现报错时间与gc日志时间吻合,
但它是CMS的并发预清理阶段(concurrent-abortable-preclean),应该不会停顿才对,
只有init-remark和final-remark才会停顿。
奇怪,难道cpu的时间被抢走了?

cmsgctime

imagegctimeequest

3.调查近期上线的代码

刚上了一个在线生成简历并预览的功能。
因为生成时间慢,所以我把编译模板基于生产消费者模式提前生产一定数量,方便需要时直接消费

4.查看cpu信息,cat /proc/cpuinfo

发现是1核2线程的cpu。
当时买阿里云服务器没注意,以为买的都是2核,没想到前面带个v(虚拟核心数)。

imagedanhecpu

5.因为单核cpu,所以CMS的并发预清理阶段会用掉用户线程的cpu资源,导致暂停应用。

6.用gcesay打开gc日志看了下,发现并发预清理阶段平均时间4.7秒,其他都是1秒内。

gc日志并发预清理

gc日志cmstable

7.这时我有两个选择,

1.调低并发预清理的最大时长。
2.继续寻找为什么要4.7秒。
我选择2.继续寻找。

8.登陆阿里云ECS的监控控制台,

查看机器状况(CPU曲线,内存曲线,磁盘读写曲线),
发现这台机器的磁盘读写明显比其他应用的机器要猛的多。

9.立马iostat, free二连

发现用了磁盘交换(swap),
这个应用的java居然占用3G+的内存,以前都是1G左右。
那么GC标记一部分内存是用的磁盘IO, 肯定慢啊。
加内存条时间也来不及啊,接下来目标就是减少常驻内存,直至不用磁盘交换。

10.导出java堆信息,

发现byte数组和 char数组共占了1.5G,
还有个大对象HashMap存了1个多G的对象,
这个map就在我写的简历模板功能里。 
jmap -dump:live,format=b,file=heap_2020_01_11_00_59_dump.bin 12977

11.改正代码(1.改缓存数量的逻辑,2.生产者运行超过1秒就让出cpu时间)

1.以前生产者的逻辑是每个模板固定生产100个实例,
现在改为动态调整生产量, (全部消耗的模板数量 / 请求数量) * 2(为之后两个请求预留),
也就是 每次消耗的平均值 * 2个用户

2.生产者每隔1秒,主动Thread.yield();
private static final Runnable COMPILE_RUNNABLE = ()->{
        int compileCount = 0;
        int totalCompileCount = 0;
        int yieldCount = 0;
        long totalCompileTime = 0;
        long beginTimestamp = System.currentTimeMillis();

        for (Map.Entry<File, PoolQueue<XWPFTemplate>> entry : TEMPLATE_MAP.entrySet()) {
            File file = entry.getKey();
            PoolQueue<XWPFTemplate> queue = entry.getValue();
            queue.resize(RENDER_TOTAL_COUNT);//重新计算缓存池的大小 (根据历史平均值动态调整)
            while (!queue.isFull()){
                try {
                    queue.offer(directCompile(file, COMPILE_CONFIGURE));
                    totalCompileCount++;
                    compileCount++;

                    long intervalTime = System.currentTimeMillis() - beginTimestamp;
                    if(intervalTime > 1000){//优化线上的单核处理器,降低任务优先级. 编译超过1秒就让一次cpu
                        totalCompileTime += intervalTime;
                        yieldCount++;
                        log.info("Deepoove compile Thread.yield().yieldCount={},intervalTime={}/ms,compileCount={},currentTotalCompileCount={}",
                                yieldCount,intervalTime,compileCount,totalCompileCount);
                        Thread.yield();
                        beginTimestamp = System.currentTimeMillis();
                        compileCount = 0;
                    }
                } catch (FileNotFoundException e) {
                    log.error("Deepoove compile error. error={}",e.toString(),e);
                }
            }
        }

        totalCompileTime += System.currentTimeMillis() - beginTimestamp;
        if(totalCompileCount > 0 && totalCompileTime > 0) {
            PRODUCER_TOTAL_TIME += totalCompileTime;
            PRODUCER_TOTAL_COUNT += totalCompileCount;

            double tps = (double)(totalCompileCount) / (double)(totalCompileTime /1000);
            log.info("Deepoove compile end. tps={}/s, compileTime={}/ms, compileCount={}",
                    Math.round(tps),totalCompileTime,totalCompileCount);

            double totalTps = (double)(PRODUCER_TOTAL_COUNT) / (double)(PRODUCER_TOTAL_TIME /1000);
            log.info("Deepoove compile end. totalTps={}/s, totalCompileTime={}/s, totalCompileCount={}",
                    Math.round(totalTps),PRODUCER_TOTAL_TIME / 1000,PRODUCER_TOTAL_COUNT);
        }
    };

12.顺便把垃圾回收改为G1,

每个区域16M,设置最大停顿时长为600毫秒。

13.上线 (问题解决了!)

将主节点下掉,切换备节点,无感上线重启。
重启后就没有磁盘交换了。 

gc日志G1

gc日志G1table

打赏一个呗

取消

感谢您的支持,我会继续努力的!

扫码支持
扫码支持
扫码打赏,你说多少就多少

打开支付宝扫一扫,即可进行扫码打赏哦

备案信息公示
京ICP备18003381号
京ICP备18003381号-1