背景

当我正沉浸在自己的世界划水时，同事让帮看一下线上系统，说是CPU忽高忽低，服务器内存正常，在CPU占用高的时候查看堆栈日志，发现是GC线程在捣鬼，于是问怎么定位到具体的代码？

分析

我一想，GC线程一直在跑，导致CPU飙高，那必然是内存回收的问题啊。

分析内存问题，那得需要拿到堆转储快照，使用MAT工具进行分析；
定位代码，可以通过上一次的更新内容进行排查，也可以通过堆栈日志进行分析，二者结合更好。在开始动手之前，系统已经重启了几次，但是重启后只能坚持几分钟。我连上服务器观察了一会儿，服务便报了OOM，于是我赶紧开始排查。

解决

服务器操作

htop - 查看系统指标，并拿到应用pid，占用CPU高的线程id
printf %x 线程id - 线程id的十六进制数
jmap -dump:live,format=b,file=./dump.hprof pid - 拿到堆转储快照
jstack -l pid > stack.log - 拿到堆栈日志

本地操作

将拿到的堆转储快照和堆栈日志下载到本地机器进行分析。

MAT分析

结果显示，内存的94.81%是被com.mysql.jdbc.BufferRow对象所占用。而这个对象是用于保存查询出来的MySQL数据。因此怀疑是在代码中有着大批量查询数据的操作。

找到这一步的时候，我就建议他们先去排查上一次迭代更新的代码。我自己后续继续分析堆栈日志。

堆栈日志分析

根据堆栈日志分析，占用CPU最高的线程果然是GC线程

"GC task thread#0 (ParallelGC)" os_prio=0 tid=0x00007f68f801f800 nid=0x2cc2 runnable 

"GC task thread#1 (ParallelGC)" os_prio=0 tid=0x00007f68f8021800 nid=0x2cc3 runnable 

"GC task thread#2 (ParallelGC)" os_prio=0 tid=0x00007f68f8023000 nid=0x2cc4 runnable 

"GC task thread#3 (ParallelGC)" os_prio=0 tid=0x00007f68f8025000 nid=0x2cc5 runnable

此时需要定位到可能出现问题的代码，由于这里GC线程一直在跑，因此出问题的线程大概率是在BLOCKED或WAITING状态，据此，找到几个可能出现问题的代码，对这几个地方进行重点排查（不过这里已经用不上了，在我找到之前，已经找到出问题的地方了，并且跑问题代码的线程都是在BLOCKED或WAITING状态）

原因

根据排查，是因为在上次迭代的代码中，有一个高频操作的SQL语句查询没有加条件，导致大量的数据被查询出来。但因为这个系统的业务比较特殊，查询出来多余的数据也不影响系统的业务流程，因此使用时并无异常，测试也未发现问题。在上线后，由于线上的数据量过于庞大，才导致出现了OOM问题。
修改完成后紧急更新一波，问题解决。

小记

BufferRow对象

根据注释，BufferRow对象在驱动中被重用了，相当于已经做了一层保护来避免了内存溢出。

/**
 * A RowHolder implementation that holds one row packet (which is re-used by the driver, and thus saves memory allocations), and tries when possible to avoid
 * allocations to break out the results as individual byte[]s.
 * 
 * (this isn't possible when doing things like reading floating point values).
 */
public class BufferRow extends ResultSetRow {
}

MAT使用

在MAT加载堆转储快照时，报内存不足的异常，此时需要修改安装目录中MemoryAnalyzer.ini文件中的参数设置，重启即可。默认是1024M，可以根据需求进行修改，我这里改成了10240M

其他用到的JVM调试工具

jps -l - 查看jvm应用端口及启动类所在地址
jstat -gccause pid interval count - 查看JVM内存使用及GC情况，interval是输出的间隔时间（单位：毫秒），count是输出的次数

【日常记录】记一次线上OOM排查

背景

分析

解决