文章目录

  • 1. 问题发生
  • 2. 数据库连接关闭问题排查
  • 3. 问题的进一步排查
  • 4. 解决方法


1. 问题发生

日常敲代码突然收到生产环境异常告警，线上有一台机器 CPU 使用率飙升到 100 触发扩容，工作群里一下子鸡飞狗跳。 出现问题，首先当然是查看监控和日志，以下是相关现象：

  1. 从监控上看，CPU 飙升的同时，还伴随着大对象的分配和大量 GC
  2. 紧接着搜索 Error 日志，发现问题时间点附近只有如下异常，显然是数据库连接关闭后又在连接上执行命令导致。公司有专门的 DBA 团队在维护数据库，直接带着问题去找人就好了
org.springframework.jdbc.support.MetaDataAccessException: Error while extracting DatabaseMetaData; nested exception is com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: No operations allowed after connection closed.

2. 数据库连接关闭问题排查

DBA 的反馈是问题时间点附近有多个事务发生了并发更新锁等待，有事务长时间未提交，造成其他等待锁的事务超时，进而导致数据库主动关闭连接，除此之外就没有其他信息可以提供了。

此时排查整个项目代码，不存在多个触发点更新同一组表的情况，排除死锁。结合日志发现发生异常的接口短时间内被多次调用，每次调用都以异常结束，并且耗时都达到 10s 以上。根据操作日志和业务使用方联系上，证实对方使用一项功能时点击按钮没有反应，于是几秒内多次点击，直接导致了线上异常告警。至此，梳理线上故障产生的过程如下：

  1. 使用方点击按钮，发现没有反应（实际上是接口处理慢，没有返回），于是多次点击按钮触发接口调用，每次传过来的参数都一样
  2. 接口处理过程中发起了数据库事务，由于多次调用传入的参数都是一样的，所以最终是操作了同一组表的相同记录，存在并发更新锁的竞争
  3. 由于某些原因，首先发起数据库事务的线程处理缓慢，迟迟没有提交事务，导致其它线程发起的事务一直拿不到锁，直到超时后连接被数据库关闭，再在这个连接上发送命令就报出异常

经过以上梳理，显然造成数据库连接关闭问题的根因是从事务发起到事务提交两个节点之间存在耗时操作，导致事务长时间没有提交。到了这一步，基本锁定案发现场，结合代码和日志发现问题如下：

  1. 异常接口的处理逻辑中存在很多数据库操作，包括了表的更新和插入，事务范围比较大
  2. 业务使用方此次操作导致的数据变更量非常大，除了 10 张表数据更新，还包括了四万条数据的插入。由于四万条数据都是在内存中生成再一次插入数据库的，所以吃内存比较严重，可以和监控显示的堆内存使用上升相映证

3. 问题的进一步排查

问题排查至此，似乎根本原因就是大事务，只要拆分事务就能解决。然而这其中依然存在一些疑点：

  1. 数据库插入四万数据是否会慢到 10s 的级别？程序中有打印 SQL 语句的组件，从 SQL 语句执行的日志来看，插入四万条数据其实不到 1s 就返回了
  2. 如果仅仅是数据库执行慢，那顶多也就是网络 IO 耗时，为什么 CPU 会飙到 100 ？

公司基础设施还算完善，线上部署了 Arthas 用于排查问题，为了进一步排查，笔者决定复现问题，并同时使用 Arthas 实时监控程序运行状况。有关于 Arthas 的使用读者可以直接前往 官方传送门，笔者使用 thread -n 8 命令监控最忙的前 8 个线程，多次操作终于发现了 CPU 飙升 100 的罪魁祸首：

  1. 监控显示，最忙的线程的堆栈中正在执行的方法是字符串的匹配和替换，我们知道字符串匹配替换需要使用 CPU 资源
  2. 方法的触发点来自于 SQL 语句打印组件，该组件会切入 MyBatis 执行器，在数据库命令执行返回后打印 SQL，具体实现读者可以参考 MyBatis @Intercepts 实现打印 SQL 语句
  3. 结合上一节分析，数据库执行了一条四万数据量的插入命令，SQL 语句庞大无匹，在此基础上通过字符串匹配替换实现 SQL 语句的参数填充，不仅消耗了非常多的 CPU 资源，也导致了大量临时字符串对象的生成、回收，最终造成线程处理慢，事务长时间无法提交

4. 解决方法

分析到这里一切豁然开朗，解决方法自然不言而喻。由于 SQL 打印组件有开关配置属性，所以在生产环境改下这个属性关掉 SQL 打印功能，重新发布服务后问题解决，不再复现