文章目录

  • 前言
  • 一、事情起因
  • 二、分析stack日志
  • 1.列出当前进程的运行列表
  • 2.打印进程的GC情况
  • 3.列出进程下消耗最高的线程
  • 4.导出进程的快照
  • 5.查看线程异常信息
  • 6.导出进程的dump文件
  • 三、dump文件分析
  • 1.MAT工具分析报告
  • 2.Histogram大对象分析
  • 3.优化后结果
  • 总结


前言

最近遇到了一次生产环境上服务CPU高的问题，本篇会记录问题处理全过程，并分享给大家，希望能够帮助到遇到同样问题的人。

一、事情起因

运营在群里面反馈系统（3年前老项目）速度很慢，然后自己也去试了一下发现所有页面都数据加载都很慢，然后服务器也报警了，这个服务CPU彪升到100%了，初步推测是内存泄漏了。

二、分析stack日志

1.列出当前进程的运行列表

指令： top -c

pin_memory关掉掉性能_内存泄漏


如上图 PID=21398的进程CPU已经超过100%

2.打印进程的GC情况

指令：jstat -gcutil 21398 1000 1000

pin_memory关掉掉性能_linux_02

幸存者空间异常？

S0 0.00 S1 100.00 ？幸存者区的空间是不是很奇怪，我第一时间也没有看懂。

pin_memory关掉掉性能_pin_memory关掉掉性能_03


仔细看了一下，JVM参数指定的是G1GC，因为G1的堆布局跟HotSpot VM里其它GC不一样——它只有一组逻辑上的survivor space，而不像其它HotSpot GC一样有两段明确、固定的地址空间用作survivor space——所以用jstat看G1的话肯定是survivor space 0显示0%，survivor space 1显示100%，这个是正常的。

老年代空间占用率超过 82%，老年代空间占用率高一般都是代码写的有问题，这个和之前猜测的内存泄漏问题可以对上（加上重启服务止血后所有功能都正常了，锁定是内存泄漏问题）。

方法区空间占用率超过94.66，方法区存储的是类的加载信息、常量、静态变量等，按照经验来说方法区内存溢出都是新导入的框架不兼容等问题导致的，排查了一下没有引入奇怪的框架，之后分析重点放在 常量和静态变量这块。

3.列出进程下消耗最高的线程

指令 ：top -Hp 21398

pin_memory关掉掉性能_pin_memory关掉掉性能_04


如上图 PID=21771的线程CPU已经 99.9%

21771是十进制的数，快照中线程是十六进制，将其转为十六进制：550b

4.导出进程的快照

指令： jstack -l 21398 > ./21398.stack
备注： stack文件很小

5.查看线程异常信息

指令：jstack -l 21398 > ./21398.stack

pin_memory关掉掉性能_pin_memory关掉掉性能_05


从stack日志中也只能看出来好多线程都在等待中且有死锁问题，如果有经验的就能从大量线程time_waiting就能猜到是tcp连接池有问题，在项目中全局搜索了一下发现根本就没有配置线程池，那么具体是什么问题还得分析dump文件。

6.导出进程的dump文件

jmap -dump:format=b,file=21398.dmp 21398

备注：导出的是堆内存的dump文件 体积和堆一致，体积大，速度非常慢，有可能会影响到服务。

jmap -dump:live,format=b,file=21398.hprof 21398

备注：导出的是堆内存中存活的dump文件 体积要小于堆（推荐），hprof是给MAT分析用的。

pin_memory关掉掉性能_jvm_06

三、dump文件分析

1.MAT工具分析报告

pin_memory关掉掉性能_pin_memory关掉掉性能_07

2.Histogram大对象分析

pin_memory关掉掉性能_jvm_08


Histogram：

  1. Class Name ： 类名称，java类名；
  2. Objects ： 类的对象的数量；
  3. Shallow Heap ：一个对象内存的消耗大小，不包含对其他对象的引用；
  4. Retained Heap ：可以被GC回收到内存的总和；

从以上分析结果来看，可以得出结论：

  1. Retained Heap没有可被GC回收的对象，实锤了是内存泄漏问题；
  2. 内存泄漏的’凶手‘就是 byte[]对象，大小已经超过1G了，重点分析；
  3. char[] 这个也存在隐患，需要具体分析。

byte[]内容分析：

pin_memory关掉掉性能_内存泄漏_09


byte[]中存放都是http请求头信息，实际这些请求头信息拷贝出来也就几百B，为什么这里所有对象都整整齐齐全部占用了约10M，猜测是某个地方配置问题，然后先检查了一下配置文件，果然发现了“凶手”，和byte[]的大小一致，真凶找到了如下：

pin_memory关掉掉性能_linux_10


这块去了解了一下应该算spring boot的一个bug，你配置这个参数后它会帮你默认构造你传入的size大小的数组，请求量较大就直接OOM。

然后我追溯了一下git历史提交记录发现是第一次搭建项目就提交了这个配置（很明显是抄其他项目的配置），埋下了一个大坑，可见项目脚手架何其重要。
解决方案 就是去掉这个配置即可。

char[]内容分析：

pin_memory关掉掉性能_jvm_11


这问题就很明显了是日志问题，仔细核对了一下服务日志，发现有重复打日志（用aop打日志，在controller层中也打日志了），每天日志量大概在2.5G左右（服务业务并不复杂，日志量明显不对），还发现日志打印都是用字符串拼接，根据以上分析日志改造如下：

  1. 日志输出由字符串拼接改为占位符；
  2. private static final Logger logger = LoggerFactory.getLogger(xxx.class); 改为用注解方式 。

以上问题基本上分析完了。

3.优化后结果

经过持续观察将近半个月，CPU高的问题已经彻底解决了。

总结

实际中遇到的CPU飙高的问题往往都是需要从多个维度分析，远比一些写demo然后定位内存溢出问题（可以直接定位到错误代码）要复杂得多，最后推荐一下MAT工具，真的非常好用。