HikariCP を使ったプロジェクトでコネクションプールの枯渇に出くわしたので、トラブルシューティングしたときの方法をメモ
確認環境
- Spring Boot 2.2.2
- AdoptOpenJDK 11.0.3
- macOS Mojave 10.14.6
背景
Spring Boot + HikariCP を使った Web アプリケーションで、DB 接続時に次のような例外が発生しました。
Caused by: java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 15006ms.
at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:697) ~[HikariCP-3.4.1.jar:na]
at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:196) ~[HikariCP-3.4.1.jar:na]
at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:161) ~[HikariCP-3.4.1.jar:na]
at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128) ~[HikariCP-3.4.1.jar:na]
at org.springframework.jdbc.datasource.DelegatingDataSource.getConnection(DelegatingDataSource.java:99) ~[spring-jdbc-5.2.2.RELEASE.jar:5.2.2.RELEASE]
...
HikariCP で例外が発生していることと、15秒でタイムアウトしていることから、application.yml での設定とも矛盾がなく、コネクションプール周りの問題だろうと予想しました。
application.yml
spring:
datasource:
hikari:
connection-timeout: 15000
maximum-pool-size: 3
デバッグログの出力
HikariCP のデバッグログを有効にすることで、コネクションプールの状態（プールしているコネクション数や実際に利用されているコネクション数）をログ出力させることができます。
application.yml
logging:
level:
+ com.zaxxer.hikari: debug
2つ目のログを見ると、プールされている3つのコネクションがすべて利用中で、さらに4スレッドがコネクションの空きを待っていることが分かります。
2020-05-01 16:03:13.859 DEBUG 79664 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Pool stats (total=1, active=0, idle=1, waiting=0)
...
2020-05-01 16:03:43.866 DEBUG 79664 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Pool stats (total=3, active=3, idle=0, waiting=4)
コネクションリークの検出
コネクションプールの状態だけでなく、コネクションプールの解放漏れ（＝コネクションリーク）を検出できると便利です。HikariCP にはそのための設定 leakDetectionThreshold が用意されています。
application.yml
spring:
datasource:
hikari:
connection-timeout: 15000
maximum-pool-size: 3
+ leak-detection-threshold: 5000
コネクションリークの検出を有効にすると、設定値（ミリ秒）を超えても解放されていないコネクションがあるとリークの可能性ありとしてログに出力されるようになります。これにより、コネクションリークの発生箇所にアタリをつけることができます。
2020-05-01 16:09:37.387 WARN 93600 --- [l-1 housekeeper] com.zaxxer.hikari.pool.ProxyLeakTask : Connection leak detection triggered for org.postgresql.jdbc.PgConnection@1d2d8846 on thread pool-2-thread-1, stack trace follows
java.lang.Exception: Apparent connection leak detected
at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128) ~[HikariCP-3.4.1.jar:na]
at org.springframework.jdbc.datasource.DelegatingDataSource.getConnection(DelegatingDataSource.java:99) ~[spring-jdbc-5.2.2.RELEASE.jar:5.2.2.RELEASE]
at org.springframework.jdbc.datasource.DataSourceUtils.fetchConnection(DataSourceUtils.java:158) ~[spring-jdbc-5.2.2.RELEASE.jar:5.2.2.RELEASE]
at org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:116) ~[spring-jdbc-5.2.2.RELEASE.jar:5.2.2.RELEASE]
at org.springframework.jdbc.datasource.TransactionAwareDataSourceProxy$TransactionAwareInvocationHandler.invoke(TransactionAwareDataSourceProxy.java:226) ~[spring-jdbc-5.2.2.RELEASE.jar:5.2.2.RELEASE]
at com.sun.proxy.$Proxy106.createStatement(Unknown Source) ~[na:na]
...
まとめ
この記事では、コネクションリークに出くわしたときに有用な HikariCP の設定を紹介しました。