SpringBoot数据库连接泄露快速排查方法

1.前言

环境信息：

​ SpringBoot-2.7.6，MySql-5.7.36，使用的数据库连接池是默认的 Hikari。

现象如下：

2024-08-23 16:37:18.021 [ERROR] thread[http-nio-9095-exec-9] org.apache.juli.logging.DirectJDKLog.log-175: Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is org.springframework.jdbc.CannotGetJdbcConnectionException: Failed to obtain JDBC Connection; nested exception is java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30000ms.] with root cause
java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30000ms.
	at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:696)
	at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:197)
	at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:162)
	at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128)
	at org.springframework.jdbc.datasource.DataSourceUtils.fetchConnection(DataSourceUtils.java:159)
	at org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:117)
	at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:80)
	at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:646)
	at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:713)
    ...
    ...

通过日志初步判断是：无法在指定的时间内从数据库连接池中获取可用的数据库连接，猜想数据库连接池连接已耗尽。

2.小心求证猜想

思路：

​ 前面猜想池中的数据库连接耗尽，需要通过某种方法实时获取数据库连接池的状态，这里推荐一种比较简单的方式，通过修改 hikari的日志级别在日志中实时查看数据库连接池状态。

笔者这里用的日志框架是 logback，修改方式是在配置文件中添加一行，如下：

<logger name="com.zaxxer.hikari" level="DEBUG"/>

修改后重启程序，发现在日志中能实时看到连接池的状态，如下：

[DEBUG] thread[HikariPool-1 housekeeper] com.zaxxer.hikari.pool.HikariPool.logPoolState-421: HikariPool-1 - Pool stats (total=10, active=10, idle=0, waiting=0)

通过大模型对日志进行分析：

这条日志信息来自于HikariCP连接池，它提供了关于HikariPool-1连接池当前状态的详细信息。下面是对这条日志信息的详细分析：

• 日志级别：[DEBUG] 表示这是一条调试级别的日志信息。调试级别的日志通常用于开发者在开发和调试过程中获取更多的运行时信息，帮助定位问题或了解系统的内部状态。
• 线程信息：thread[HikariPool-1 housekeeper] 表示这条日志是由名为HikariPool-1 housekeeper的线程产生的。在HikariCP中，每个连接池都会有一个或多个“housekeeper”线程，它们负责执行诸如连接验证、空闲连接清理等后台任务。
• 类和方法：com.zaxxer.hikari.pool.HikariPool.logPoolState-421 表示这条日志信息是由HikariPool类的logPoolState方法在源代码的第421行产生的。这提供了日志信息产生的具体位置，有助于开发者在需要时查看源代码以获取更多上下文。
• 连接池名称：HikariPool-1 是这个连接池的名称。在HikariCP中，你可以配置多个连接池，每个连接池都有一个唯一的名称。
• 连接池状态：
  • total=10：表示连接池中的总连接数为10。这是连接池能够管理的最大连接数（或当前配置的连接数）。
  • active=10：表示当前有10个连接正在被使用，即这些连接当前正在执行数据库操作。
  • idle=0：表示当前没有空闲的连接。所有连接都在使用中。
  • waiting=0：表示当前没有线程在等待获取连接。这可能是因为所有需要的连接都已经被分配，或者没有线程尝试从池中获取连接。

分析：

• 从这条日志信息可以看出，HikariPool-1连接池当前处于高负载状态，因为所有的连接都在使用中（active=10，idle=0）。这通常意味着数据库操作非常频繁，或者可能存在一些长时间运行的操作占用了连接。
• 值得注意的是，尽管所有连接都在使用中，但没有线程在等待获取连接（waiting=0）。这可能是因为当前的数据库操作足以满足应用的需求，或者应用的并发级别还没有达到需要额外连接的程度。
• 如果应用的需求增加，或者长时间运行的操作导致连接长时间被占用，那么可能需要考虑增加连接池的总连接数（total），或者优化数据库操作以减少连接的使用时间。
• 另外，如果waiting值开始增加，那么可能需要进一步分析为什么连接无法及时释放，或者考虑增加连接池的大小以应对更高的并发需求。

---

结论：数据库连接池中的连接均处于被占用的状态，即无可用的数据库连接，连接已耗尽。

得到结论后，基于接口并发调用量并不高的前提，猜测导致数据库连接耗尽的原因是存在数据库连接泄露。

此接口使用的是 SpringBoot中的 JdbcTemplate来访问数据库，它在执行完 SQL后是会自动释放连接的。至此，推断大概率是业务代码中有地方手动取出了数据库连接池中的连接，然后又没有释放。

3.找到可能导致数据库连接泄露的代码

常规思路：

​ 人眼查看业务代码，加断点一步步调试。——慢就不说了，如果无法调试呢？

快捷思路：

​ 利用 hikari提供的 leak-detection-threshold参数设置一个超时值，自动检测可能存在数据库连接泄露的代码。

​ 补充：leak-detection-threshold参数表示连接可以离开池的时间，在超过这个时间后，如果连接仍然没有被关闭，HikariCP将记录一条警告消息，表示可能存在连接泄露。

修改方法，打开 SpringBoot配置文件（Application.yml），在数据库连接配置那里添加：

leak-detection-threshold: 30000

重启程序后，果然出现了有嫌疑的代码，如下：

2024-08-24 14:54:38.012 [DEBUG] thread[http-nio-9095-exec-7] com.zaxxer.hikari.pool.HikariPool.logPoolState-421: HikariPool-1 - Timeout failure stats (total=5, active=5, idle=0, waiting=0)
java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30001ms.
        at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:696)
        at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:197)
        at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:162)
        at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128)
        at com.xx.xx.utils.DataTools.getDbType(DataTools.java:20)
		...
		...

4.数据库连接泄露是如何发生的

分析问题代码：com.xx.xx.utils.DataTools.getDbType(DataTools.java:20) ，代码内容摘抄如下：

try {
  DatabaseMetaData dbmd = jdbcTemplate.getDataSource().getConnection().getMetaData();
  driverName = dbmd.getDriverName();
  } catch (SQLException e) {
    e.printStackTrace();
}

至此，找到了罪魁祸首：

jdbcTemplate.getDataSource().getConnection()

上面这段代码会从 连接池中取出数据库连接，使用完后没有还回或关闭数据库连接，故会导致数据库连接泄露。

5.总结

总结下快速排查数据库连接泄露的思路：

1. 确定问题是数据库连接耗尽（通过修改 hikari日志级别为 DEBUG）
2. SpringBoot配置文件增加 leak-detection-threshold（定位问题代码）
3. 分析问题代码是否有连接泄露的可能

排查数据库连接泄露问题，除了要充分利用框架的能力，比如 hikari的 leak-detection-threshold参数。还可以把一些日志或代码可以直接交给大模型进行分析，又快又准。