内存溢出+CPU占用过高:问题排查+解决方案+复盘（超详细分析教程） #|【Java】|1024程序员节|OutOfMe

前言

最近刚上线了一款社交项目，运行十多天后（运营持续每天推量），发现问题：

系统OOM（资源不能被释放）导致服务器频繁且长时间FGC导致服务器CPU持续飚高

日志中内存溢出:java.lang.OutOfMemoryError: Java heap space

程序十分卡顿，严重影响用户使用

从以下方面，为大家分享此次问题解决流程

问题出现现象

临时解决方案

复现问题

定位问题发生原因

优化代码

优化后进行压测，上线

复盘

学完本博文，你的收获

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

解决方案流程图

文章图片

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

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