Hikari:Apparent connection leak detected连接泄露分析 原创

16-05-2019 13:25:46.494 [HikariPool-1 housekeeper] WARN  com.zaxxer.hikari.pool.ProxyLeakTask.run - Connection leak detection triggered for com.mysql.jdbc.JDBC4Connection@7c3beffb, stack trace follows
java.lang.Exception: Apparent connection leak detected
    at org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:111)
    at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:77)
    at org.mybatis.spring.transaction.SpringManagedTransaction.openConnection(SpringManagedTransaction.java:84)
    at org.mybatis.spring.transaction.SpringManagedTransaction.getConnection(SpringManagedTransaction.java:70)
    at org.apache.ibatis.executor.BaseExecutor.getConnection(BaseExecutor.java:336)
    at org.apache.ibatis.executor.SimpleExecutor.prepareStatement(SimpleExecutor.java:84)
    at org.apache.ibatis.executor.SimpleExecutor.doQuery(SimpleExecutor.java:62)
    at org.apache.ibatis.executor.BaseExecutor.queryFromDatabase(BaseExecutor.java:324)
    at org.apache.ibatis.executor.BaseExecutor.query(BaseExecutor.java:156)
    at org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:109)
    at org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:83)
    at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:148)
    at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:141)
    at org.apache.ibatis.session.defaults.DefaultSqlSession.selectOne(DefaultSqlSession.java:77)
    at sun.reflect.GeneratedMethodAccessor148.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:434)
    at com.sun.proxy.$Proxy107.selectOne(Unknown Source)
    at org.mybatis.spring.SqlSessionTemplate.selectOne(SqlSessionTemplate.java:167)

日志显示，检测到了连接泄露
Hikari配置如下：

hikari:
      maximum-pool-size: 100
      minimum-idle: 0
      leak-detection-threshold: 180000
      connection-timeout: 180000
      validation-timeout: 180000
      idle-timeout: 180000

leak-detection-threshold:用来设置连接被占用的超时时间，单位为毫秒，默认为0，表示禁用连接泄露检测。
connection-timeout:从连接池获取连接的超时时间。

分析源代码发现，该错误的原因是从连接池获取连接超时，触发了连接泄露检测。
此处spring调用了doGetConnection从hikari中获取连接
在org.springframework.jdbc.datasource.DataSourceUtils#doGetConnection中，

image.png

我们看看hikari中的实现，进入该方法继续看，
com.zaxxer.hikari.HikariDataSource#getConnection()

image.png

getConnection()又调用了另一个方法，在com.zaxxer.hikari.pool.HikariPool#getConnection(long)中，

image.png

com.zaxxer.hikari.pool.ProxyLeakTask#ProxyLeakTask(com.zaxxer.hikari.pool.ProxyLeakTask, com.zaxxer.hikari.pool.PoolEntry)中

image.png

这个地方是真正的获取连接的实现了，
分析上面的代码会发现，在获取Connection的时候，创建了一个ProxyLeakTask，这个task是一个定时任务，在leakDetectionThreshold毫秒后调用run()方法抛出Apparent connection leak detected异常。

Xnip2019-09-28_13-26-40.jpg

也就是说，获取到连接之后使用之前的时间+使用连接的时间+使用之后还回连接之前的时间，超出了leakDetectionThreshold毫秒，就抛出检测到连接泄露的异常。结合我们的业务发现，此处确实是使用连接的时间超出了leakDetectionThreshold毫秒，是因为执行了慢 sql，同时慢 sql 耗尽了连接池的连接，导致新线程获取连接超时，又导致了获取连接超时的报错。