记一次 Java 进程里面获取 Mysql 连接超时的问题排查(OOM)

---

一. 问题现象

   页面前端频繁出现 500 的报错，查看后端报错日志，发现了大量的 An attempt by a client to checkout a Connection has timed out.

二. 原因分析

1. 查询 Mysql 状态

   初步怀疑是 mysql 的满了造成进程里面拿不到新的连接了，于是一通排查连接的命令操作下来。 SHOW FULL PROCESSLIST命令默认只能查询当前登录 mysql 的账户所持有的线程，如果要查看所有用户的线程，请使用拥有 super 权限的账户登录，此处我们意向就是排查 mysql 的所有连接，所以此处应该使用 super 账户。排查之后发现大量线程都处于 sleep 的状态，连接数量也远远小于配置（SHOW VARIABLES LIKE '%connections%'）的最大 4000 的数量
   SHOW FULL PROCESSLIST 可以展示 mysql 中线程的状态，比如是否处于运行状态，运行时间，运行的 sql，连接的地址等信息，此处我主要关注了连接数量，发现过去最大连接也不过一百多而已，且绝大多数线程都处于 sleep 状态，也不存在慢 sql 这种导致 mysql 响应速度慢的问题。SHOW STATUS LIKE 'Max%connections'可以展示过去最多连接 Mysql 的线程数量
   mysql 里面查看到到的信息偏向于 mysql 的状态，如果上述连接过多，我们可以使用下列端口占用的命令找到连接最多的进程再进一步排查，此处不是连接过多的问题就不需要如下命令排查了
netstat -anp | grep 3305
lsof -i:3305

2. 排查连接池问题

   问题不是出在 mysql 里面，此时把矛头转向连接池相关了。google 了一手，出现获取连接超时的问题不外乎一些连接池参数设置有些问题比如获取连接时间过短或者代码的问题导致连接泄露，超出了连接池配置的最大线程池数量，此时想到了 arthas 来查询线程池的实时状态，观察一下各项参数是否正常。当使用 arthas 连接 java 进程的时候，突然发现 arthas 已经连接不上进程了，此时发现问题不简单了，连接池问题不至于让程序都不能正常响应了，看来 arthas 已经用不上了

3.进程内存&栈分析

   使用 jmap -heap 28441 命令查看内存使用状态，可以看到内存相关的配置还有当前已经使用的内存百分比，当时程序内存满了的图片已经不在，所以此处的程序 ID 28441 只是示意关注的参数，除了最后的 dump 文件之外均并非真实内存占用满了的程序的数据。如果发现程序占用内存接近百分比的时候，此时便可以怀疑内存不足的问题了

   使用 jstat -gcutil 28441 1000 命令每隔 1 秒打印一次内存相关的状态，注意 E(eden 内存区域 used)，O(old 内存区域 used)，M(method 内存区域 used)，FGC(Full GC 次数)，FGCT(Full GC 总时间)。如果内存不足的情况下，S0+S1+E+O+M 一直接近设置的 MaxHeapSize 参数，且每次打印 FGCT 的增长接近 1 秒。我们设想一个正常情况的程序，内存在一个范围内变化，比如 200MB-> 512MB 之间，增长到接近 512 MB 的时候，触发 Full GC 之后，内存占用量下降到 200MB 左右，每隔一段时间(几秒，几十秒或者单位为分钟)执行一次 Full GC，每次 Full GC 时间可能也就几百毫秒，那么 FGCT 必定不会每打印一次就增加一秒。FGCT 出现这种情况只能说明程序一直在内存不足，GC 线程一直忙于清理垃圾，但是依然无法清除一些存在引用的对象（心有余而力不足，虚拟机一直通知 GC 线程处理垃圾，但是由于程序里面的对象都被 GC Root 引用，那么只能一遍遍的扫描引用，实际并没有清理出有用的内存，反而占用了用户线程的时间）。当前的垃圾收集器在进行 Full GC 时候用户线程是无法工作（stop the world）的，这就解释了为什么获取连接的时候超时了。想想在用户线程获取数据库连接的时候，突然执行 Full GC 的 线程开始工作，暂停所有的用户线程，等 GC 线程忙活完，用户线程继续获取连接一对比此时的时间，已经超时了，于是就有了日志里面大量的获取连接超时的报错。不出意外，再等一会儿日志里面就应该出现 OOM Error 了。OOM 导致的问题远不止获取连接超时，这意味着程序整个响应时间无限延长，且一些需要内存的线程也无法正确执行，再仔细查看日志，发现报错果然并非只有连接超时的问题，存在着大量的 Exception 日志
   使用jmap -histo:live 28441 | head -10 可以查询程序里面存活的对象个数和总共占用的内存大小，这里我们只列出前几个占用最多的对象类型就是了。如果占用数量最大的是自己创建的对象类型，且这个对象只是在少量地方使用，此处我们大概就能定位代码位置了，到底是内存泄露还是真实的大数据量导致的内存不足的问题。但是很不巧的是，当时的程序对象 [C 对象达到了 390MB，大约占到了总内存的75% 左右，[C 代表了 char[]，这种类型太过于常见以至于仅仅通过这个类型我们依然无法定位具体的代码片段。
   数组类型的对象描述：

   此时我们需要祭出大杀器 jmap -dump:format=b,live,file=dump.hprof PID 来获取 dump 文件了，dump 文件里面可以说包含了 java 提供的工具包（如 jinfo，jmap，jstat，jstack）里面所有工具执行之后的快照结果。dump 参数会生成一个文件，这个文件需要借助内存分析工具来打开分析，此处我们使用的是 java 自带的 VisualVM。如下界面就是这个进程的概览页面，char[] 无论是实例个数还是内存占用都是最多的。以下是当时内存爆满之后的真实现场数据了

   选择左上角的 Objects 我们就可以看到所有的对象内容，点开 char[] 的内容，由于内存里面含有 1666854 个 char[] 对象，我们无法一一查看每个 char[] 类型对象的内容，所以我直接随机点开 0~1666854 前面，中间，后面几个区域内大概的数据，此时需要我们用数学找规律（比如大小相同，内容相似等方面）来定位哪一种内容才是占用内存的罪魁祸首了。终于再点击了几次之后，发现大量的对象占用在 272B 左右，这样的对象数量之多。我们可以点开这个对象被谁持有，直到点到含有 GC root 标志的对象。右键选择 Select in Threads 就可以定位到这个对象被线程持有的代码

   当我看到这个线程的调用栈路径（这个页面的内容其实也可以直接左上角选项框 Threads 直接跳转，和 jstack 命令的效果一致。此前没有直接跳转这个页面是因为线程数量比较多单凭肉眼直接去找哪一个线程持有的 char[] 对象最多也是很难），第一反应就是这个这个线程的调用栈特别长，再仔细一看，果不其然递归了。到了这一步，我们距离找到问题可以说已经非常近了。注意看前面带有 local variable 的地方，这些是在栈递归过程中持有的方法内部变量，本来方法执行完成这些对象就会被清理掉，但是因为这里的递归导致方法没有退出所以这些对象被 GC root 引用无法被清除。一层的递归代码也不多，也就十几行代码，此时我们可以打开 idea 里面看这十几行代码里面是不是存在着可能持有大量 char[] 的对象，也可以在这里点点点这些 local variable 的变量，找到持有 char[] 的对象的代码
   在点了几次之后，就发现了这个大对象，占用 828136B，这个对象里面有 2776 个 String 对象，而 String 里面存储的 value 是 char[] 持有的，这里面的 value 和我们在 Objects 选项框里面看到的 value 一样。再回到刚才的调用栈里面，搜索 CachedSessionLogManager.java:140 这一行代码发现被执行了 504 次。做一个大概的计算，504(次) * 272(B，char[] 大小) * 2776(个) / 1024 / 1024 = 362MB，问题找到这里其实大概就结束了，通过代码发现这里每次都持有了基本固定尺寸的 String List 去遍历，然后每一次递归又无法释放这个 String List，直到退栈之前都无法清除这个 List。照着这个继续下去，不是 OutOfMemoryError 就是 StackOverflowError 了

   代码大概长成如下样子，当然这是简化版本，实际代码比这复杂。关键就是LogUtils.listDirs持有了 String List 对象，可能写着代码的人也没有想到这儿的数量能达到 2776 个之多。有了上面这一连串的操作，可以拿这些分析找写代码的人去复现了，完美收工

public static void process() {
 for (String sessionDir : LogUtils.listDirs()) {
   process();
 }
}

参考文档：

1. Cannot connected to the database : An attempt by a client to checkout a Connection has timed out.
2. Java 对象描述