内存溢出+CPU占用过高:问题排查+解决方案+复盘（超详细分析教程）

怼烎@ 2022-12-27 04:58 226阅读 0赞

## 前言 ##

> 最近刚上线了一款社交项目，运行十多天后（运营持续每天推量），发现问题：
> 
>  *  系统OOM（资源不能被释放）导致服务器频繁且长时间FGC导致服务器CPU持续飚高
>  *  日志中内存溢出:**java.lang.OutOfMemoryError: Java heap space**
>  *  程序十分卡顿，严重影响用户使用
> 
> 从以下方面，为大家分享此次问题解决流程
> 
>  *  问题出现现象
>  *  临时解决方案
>  *  复现问题
>  *  定位问题发生原因
>  *  优化代码
>  *  优化后进行压测，上线
>  *  复盘

## 学完本博文，你的收获 ##

*  排查内存溢出的思路
 *  排查内存溢出过程中用到的命令及工具（Linux命令，[Eclipse Memory Anaylzer\[MAT\]][Eclipse Memory Anaylzer_MAT]）
 *  定位系统内存溢出的代码，并进行优化
 *  此次内存溢出问题复盘

## 解决方案流程图 ##

![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3UwMTI4MjkxMjQ_size_16_color_FFFFFF_t_70_pic_center]

## 问题&临时解决方案&定位问题&最终解决方案 ##

*  问题：
    
     *  业务反馈程序用的十分卡，同时测试自己测的也十分卡
     *  从ELK收集的请求日志发现确实存在问题，线上是两台部署：两台机器上都是，一次请求耗时由原来的几毫秒变为10几秒
     *  CPU跑的过高，当时是4核，CPU持续飙到350%+；
     *  当时一台服务器CPU截图：
        
        ![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3UwMTI4MjkxMjQ_size_16_color_FFFFFF_t_70_pic_center 1]
 *  临时解决方案
    
     *  当时为了减少对业务影响，直接将生产两台服务器上的项目进行重启
     *  项目启动参数中没有加内存溢出日志输出（后续博客为大家介绍JVM调优时讲解启动命令中加内存溢出日志输出），重启后出问题时项目的JVM信息丢失了
 *  复现问题方式：在开发环境对程序进行持续压测;压测相关服务器配置：
    
     *  服务器配置:8核，16G
     *  项目启动内存：136M
     *  Jmeter持续(循环)压发消息接口10分钟
 *  定位问题
    
     *  top命令查看最耗CPU的进程（进程:17038;CPU持续飙到595%+）
        
            # 输入top命令后键入P(大写P),进程按照CPU从高到底排序
            top
        
         *  1
         *  2
        
        ![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3UwMTI4MjkxMjQ_size_16_color_FFFFFF_t_70_pic_center 2]
     *  查看该进程中最耗CPU的线程(发现有一些线程占用CPU较高)
        
            # 17038为进程号,键入P(大写P),该进程中的线程按照CPU从高到底排序
            top -Hp 17038
        
         *  1
         *  2
        
        ![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3UwMTI4MjkxMjQ_size_16_color_FFFFFF_t_70_pic_center 3]
     *  将线程号转为16进制,同时查看这些线程当前正在干什么（在此以17045线程为例）
        
            # 将线程号转为16进制;其中17045为线程号
            printf '%x\n' 17045
            # 17038为进程号,0x4295为最耗CPU线程的十六进制
            jstack 17038 | grep '0x4295' -C10 --color
        
         *  1
         *  2
         *  3
         *  4
        
        ![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3UwMTI4MjkxMjQ_size_16_color_FFFFFF_t_70_pic_center 4]
     *  可以看到**最耗CPU的线程都是在进行GC**
     *  用Jmap命令查看当前堆的使用情况(发现老年代现在已占用99.8%+)
        
            # 其中17038为进程号
            jmap -heap 17038
        
         *  1
         *  2
        
        ![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3UwMTI4MjkxMjQ_size_16_color_FFFFFF_t_70_pic_center 5]
     *  查看gc频率的命令（其中O代表老年代占用率，FGC是FullGC次数，FGCT是fullGC时间；可以看出在频繁FullGC但是老年代有资源一直释放不掉）
        
            # 其中17038为进程号,5000是指每5秒(5000毫秒)输出一次
            jstat -gcutil 17038 5000
        
         *  1
         *  2
        
        ![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3UwMTI4MjkxMjQ_size_16_color_FFFFFF_t_70_pic_center 6]
     *  通过分析出问题时线上日志发现内存溢出；至此定位到问题根源是内存溢出导致（有未释放资源堆积，导致老年代被占满，然后频繁的FullGC但是资源一直释放不了）
        
            grep -m 10 'OutOfMemoryError' *.log
        
         *  1
        
        ![在这里插入图片描述][20201022222241586.png_pic_center]
 *  分析问题产生原因
    
     *  由于线上当时直接重启，未能保留当时的JVM内存文件；在开发环境进行循环压测，复现线上问题，然后导出dump文件进行分析找到原因
     *  生成dump文件命令
        
            # 其中fileName是导出后dump名称,pid为进程号
            jmap -dump:format=b,file=fileName.dump pid
        
         *  1
         *  2
     *  将dump文件导出到本地，用Eclipse Memary Analysis（MAT[官网下载地址][Link 1]） 进行分析
     *  MAT导入dump文件  
        ![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3UwMTI4MjkxMjQ_size_16_color_FFFFFF_t_70_pic_center 7]  
        ![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3UwMTI4MjkxMjQ_size_16_color_FFFFFF_t_70_pic_center 8]
     *  按对象排序视图进行查看（总览中看到对象总个数:14.1百万个）  
        ![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3UwMTI4MjkxMjQ_size_16_color_FFFFFF_t_70_pic_center 9]
     *  发现有两个类（ClassClassPath，ClassClassPathList）占用比较大，这两个类约占对象总数的**83%**（计算方式:5873361\*2/14100000=83%）
        
        ![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3UwMTI4MjkxMjQ_size_16_color_FFFFFF_t_70_pic_center 10]
 *  分析代码
    
     *  去代码中全局搜这两个类，发现只有在打日志的时候用到ClassClassPath类  
        ![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3UwMTI4MjkxMjQ_size_16_color_FFFFFF_t_70_pic_center 11]
     *  分析ClassClassPath相关代码：
        
         *  用到ClassClassPath对象是一个静态的ClassPool；
         *  问题原因:classPath一直被静态的全局pool所持有，导致GC一直释放不掉；  
            ![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3UwMTI4MjkxMjQ_size_16_color_FFFFFF_t_70_pic_center 12]  
            ![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3UwMTI4MjkxMjQ_size_16_color_FFFFFF_t_70_pic_center 13]  
            ![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3UwMTI4MjkxMjQ_size_16_color_FFFFFF_t_70_pic_center 14]  
            ![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3UwMTI4MjkxMjQ_size_16_color_FFFFFF_t_70_pic_center 15]
         *  当然顺着代码，顺藤摸瓜也找到了ClassPathList  
            ![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3UwMTI4MjkxMjQ_size_16_color_FFFFFF_t_70_pic_center 16]  
            ![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3UwMTI4MjkxMjQ_size_16_color_FFFFFF_t_70_pic_center 17]
 *  优化代码：每次用完ClassClassPath后将其释放
    
     *  每次对象使用完后从静态pool中移除
     *  注意:classPath=null这种方式是不能释放掉的  
        ![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3UwMTI4MjkxMjQ_size_16_color_FFFFFF_t_70_pic_center 18]
 *  优化后再次进行验证
    
     *  开发环境循环压测，用MAT分析dump文件，发现内存中已不再堆积ClassClassPath类;优化前后接口吞吐量也提升8.2%
     *  进行线上发布，观察一周后，对内存分析发现正常
 *  复盘：
    
     *  项目比对：
        
         *  为快速开发，社交的代码从原来金融项目基础上改造而来；
         *  原来金融项目没有内存溢出，而社交项目为什么内存溢出？
         *  通过ELK统计一段时间的访问量结果：
            
             *  社交目前日访问后台量65w+
             *  金融项目只有4.5W+
         *  社交和金融项目业务类型不一样，所呈现出的特点也不同
         *  去生产的金融项目中dump内存文件，用MAT工具分析，发现也存在ClassClassPath类堆积释放不掉，只不过由于访问量少，堆积量未占满老年代而已；果断在金融项目迭代时将其优化；
 *  程序预警：为减少业务影响，增加接口耗时的预警（后续博文为大家共享）；实现方式：  
    \- 在每次程序处理完进行预警（比如本次请求>阈值）;缺点：消耗性能影响正常业务  
    \- 在ELK清洗时用相关插件进行预警；优点：和业务解耦，对业务无影响
 *  服务器预警：运维增加CPU内存，日志内存溢出监控

## 总结 ##

*  解决内存溢出过程总结：
    
     *  不同的项目导致内存溢出原因是不同的；
     *  重要的是排查思路
     *  经过不断的耐心的去观察，测试，分析才能定位到问题并最终解决问题
 *  在这次分析内存溢出过程中，我们也针对我们项目的JVM启动参数进行了调优，在接下来的博文中为大家分享JVM调优

[Eclipse Memory Anaylzer_MAT]: https://www.eclipse.org/mat/
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3UwMTI4MjkxMjQ_size_16_color_FFFFFF_t_70_pic_center]: /images/20221120/86f90ecc62864d8d9fdffce95b10d38d.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3UwMTI4MjkxMjQ_size_16_color_FFFFFF_t_70_pic_center 1]: /images/20221120/395f3d5dae64436aa11995dd2b4777f8.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3UwMTI4MjkxMjQ_size_16_color_FFFFFF_t_70_pic_center 2]: /images/20221120/85e4cfeb504849fe875896604cc67983.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3UwMTI4MjkxMjQ_size_16_color_FFFFFF_t_70_pic_center 3]: /images/20221120/1378b145fd0e4ad59e95e83ef456f1ec.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3UwMTI4MjkxMjQ_size_16_color_FFFFFF_t_70_pic_center 4]: /images/20221120/0723be4399324d52ad34c70882f282fc.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3UwMTI4MjkxMjQ_size_16_color_FFFFFF_t_70_pic_center 5]: /images/20221120/a3449b0da013470586aa150383320cdc.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3UwMTI4MjkxMjQ_size_16_color_FFFFFF_t_70_pic_center 6]: /images/20221120/01ffb00cdea648428b819c66e4e68bd9.png
[20201022222241586.png_pic_center]: /images/20221120/089fbcb74a5e43adb7062e8de2afac1d.png
[Link 1]: https://www.eclipse.org/mat/downloads.php
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3UwMTI4MjkxMjQ_size_16_color_FFFFFF_t_70_pic_center 7]: /images/20221120/4f5047f085e044d0b3e21488286fb3da.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3UwMTI4MjkxMjQ_size_16_color_FFFFFF_t_70_pic_center 8]: /images/20221120/005111b3d1fd44a98db52ab2d76d8354.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3UwMTI4MjkxMjQ_size_16_color_FFFFFF_t_70_pic_center 9]: /images/20221120/47a0e21ab08341b2b554c7c6aaf003e5.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3UwMTI4MjkxMjQ_size_16_color_FFFFFF_t_70_pic_center 10]: /images/20221120/9b0f3f02e6b044449dd09906a891efaf.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3UwMTI4MjkxMjQ_size_16_color_FFFFFF_t_70_pic_center 11]: /images/20221120/d1ae6e0f608b4adb94dddb186ccf522e.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3UwMTI4MjkxMjQ_size_16_color_FFFFFF_t_70_pic_center 12]: /images/20221120/32d70074386f4c628c7ae8be58a03689.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3UwMTI4MjkxMjQ_size_16_color_FFFFFF_t_70_pic_center 13]: /images/20221120/7714aed4d69a42c983e8d08149d59adc.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3UwMTI4MjkxMjQ_size_16_color_FFFFFF_t_70_pic_center 14]: /images/20221120/8a2e5426290b46da9098f6ef6c2be3c1.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3UwMTI4MjkxMjQ_size_16_color_FFFFFF_t_70_pic_center 15]: /images/20221120/4c3ce6ee507f45cd86c7e47568db9d3f.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3UwMTI4MjkxMjQ_size_16_color_FFFFFF_t_70_pic_center 16]: /images/20221120/9139472a64384139970acd6d9c7e0863.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3UwMTI4MjkxMjQ_size_16_color_FFFFFF_t_70_pic_center 17]: /images/20221120/3a3731d951e84c38b5cf5a31ec5cef67.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3UwMTI4MjkxMjQ_size_16_color_FFFFFF_t_70_pic_center 18]: /images/20221120/9ffcc48b5c1c446da5a4d6b6b75570e9.png