HikariPoolでタイムアウトが頻発するときの原因と対処法


## 概要

SpringBootを利用してMariaDBに接続するアプリケーションにおいて、HikariPoolが以下のエラーを出してタイムアウトする事象について、原因と対処法についてまとめています。

```java
java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30000ms.
```

## 原因と対処法

- 原因
    - 以下の制限を超えるようなリクエストが処理しきれない場合に発生
        - SpringBootで標準搭載されているConnection Pool＝HikariCPのデフォルトコネクションプールの最大サイズが`10`
        - HikariCPのconnectionTimeoutがデフォルトで`30秒`
    - つまり、１回のトランザクション処理において時間のかかる処理があり、大量のリクエストが来て空いているコネクションが無く、30秒の待ち時間を経過してしまった場合に発生するというもの。
- 対処法
    - maximumPoolSizeを大きくする。
        - 今回の記事ではここを対処法の結論としています。
    - connectionTimeoutを伸ばす
        - ユーザーの待ち時間が長くなるだけなのであまり意味ないか？

上記のような対処法が考えられるが、仕様を読む限り（または色々なブログサイトを読む限り）という状態で、実際に試してみないことには解決するのか不明ということもある。
上記原因と対処法についてサンプルを用いて動作確認し、実体験として確証を得たいと思います。

以下からはその確認を行なっていく。

## エラー再現の環境

- mysql  Ver 14.14 Distrib 5.5.62, for Linux (x86_64) using readline 5.1
- Java 11
- SpringBoot 2.1.4
- HikariCPを利用（デフォルト）

## 今回利用するSpringBootのサンプルアプリ

idとnameという適当なGETパラメータを指定してGET通信をすると、"test"という文字列が返却されるだけのRestControllerを実装した最小限のサンプルアプリを用意しています。
http://localhost:8080/sample?id=2&name=test

DBはMariaDBへ接続し、SpringBootのDBへの接続設定としては以下のような設定をしています。

```yaml:application-prod.yml
spring:
  datasource:
    url: "jdbc:mysql://192.168.33.10/sample?useUnicode=true&characterEncoding=UTF-8&autoReconnect=true"
    username: hoge
    password: password
```

ここでポイントとなるのが`spring.datasource.hikari.maximum-pool-size`などコネクションプールのサイズ指定をしておらず、この状態だとデフォルトの設定が利用される。ということ。

重たいトランザクション処理については、Serviceがトランザクション境界となるように構築して、そのメソッドの中でスリープを入れるようにしています。
どの程度の時間スリープすればいい感じでエラーが再現できるのかわからないため、application.ymlで設定できるようにしています。

```java
@Service
@Transactional
public class TestService {
    @Autowired
    private TestDao dao;
    @Autowired
    private SampleProperty prop;
    private Logger log = LoggerFactory.getLogger(this.getClass());     
    public void regTest(TestVo vo) {
        log.info("データの登録 : " + vo.toString());
        dao.insertTest(vo);
        // 何らかの重たい処理を想定
        try {
            log.info(prop.getSleepMillis() + " ms スリープします");
            Thread.sleep(prop.getSleepMillis());
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }
}
```

## SpringBootの起動前後でMariaDBのコネクション数をチェック

MariaDBを起動直後にコネクション数をチェックすると「１」となっていることを確認。
これはDBサーバーに私自身がアクセスして、チェックするためにコネクションを取得してしまっているため１となっている。

```shell
mysql> show status like 'Threads_connected';
+-------------------+-------+
| Variable_name     | Value |
+-------------------+-------+
| Threads_connected | 1     |
+-------------------+-------+
1 row in set (0.00 sec)
```

続いて、SpringBootのサンプルアプリケーションを起動した直後のコネクション数がどうなっているのか確認する。
JDKのインストールをしていないため、Eclipse同梱のJDKのパスを指定して起動。

```shell:local-machine
$ /Applications/Eclipse_2021-03.app/Contents/java/11/Home/bin/java -jar ./sample-0.0.1-SNAPSHOT.jar --spring.profiles.active=prod

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::        (v2.1.4.RELEASE)
```

起動を確認後、すぐにDBのコネクション数をチェック。
以下のように「１１」となっていることから、SpringBootで採用されているHikariCPのデフォルトのコネクションプールの数は１０ということがわかります。
※SpringBootを起動しただけで、いっさいリクエストをしていない状態で初回起動時にいきなり「１０」のコネクションプールを生成していることがわかります。
※https://github.com/brettwooldridge/HikariCP#readme ここにデフォルトの記述があり、仕様通りです。

```shell
mysql> show status like 'Threads_connected';
+-------------------+-------+
| Variable_name     | Value |
+-------------------+-------+
| Threads_connected | 11    |
+-------------------+-------+
1 row in set (0.00 sec)
```

念のため、SpringBootのプロセスを終了するとコネクションが解放されるのかも確認。

```shell
$ /Applications/Eclipse_2021-03.app/Contents/java/11/Home/bin/java -jar ./sample-0.0.1-SNAPSHOT.jar --spring.profiles.active=prod

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::        (v2.1.4.RELEASE)

^C[you_name_is_yu@You-name-is-YU-PC java-mariadb-cent8]$  <-- この時点でプロセスが終了
```

確保されたコネクション１０が解放され１０→１となっていることを確認。

```shell
mysql> show status like 'Threads_connected';
+-------------------+-------+
| Variable_name     | Value |
+-------------------+-------+
| Threads_connected | 1     |
+-------------------+-------+
1 row in set (0.00 sec)
```

## jMeterで負荷テストを行いコネクション数を確認

- application.ymlでのSleepの設定 : 1000
- jMeterの設定
    - ThreadGroup
        - Number of Threads(uses) : 100
        - Ramp-up period(seconds) : 10
        - Loop Count : 1

上記設定で負荷テストを実施したところ、`java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30000ms.`のエラーは１件も出ることはありませんでした。

エラーは出ていないものの、このようなリクエストが発生した場合に、コネクション数＝１０だと足りない状況が一時的に発生していたと思われますので、この状態でコネクション数がどうなっていたのかも確認します。

```shell
mysql> show status like 'Threads_connected';
+-------------------+-------+
| Variable_name     | Value |
+-------------------+-------+
| Threads_connected | 11    |
+-------------------+-------+
1 row in set (0.00 sec)
```

このように、大量のリクエストが一時的に発生したとしてもHikariCPの`maximumPoolSize=10(default)`が作用して10以上のコネクションを新たに生成するような挙動は確認されなかった。

## jMeterでもっと負荷を上げてコネクション数を確認

- application.ymlでのSleepの設定 : 1000
- jMeterの設定
    - ThreadGroup
        - Number of Threads(uses) : 1000  <-- 100から1000に増やした
        - Ramp-up period(seconds) : 10
        - Loop Count : 1

上記の状態で一度SpringBootアプリケーションを再起動して初期状態にしてjMeterでの負荷テストを実行。

HikariCPのconnectionTimeoutのエラーが発生した。
このエラーは今回のテストで３７件発生した。

![スクリーンショット 2023-02-12 9.59.37.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/246556/d062553d-bc29-f815-6e57-45e756c6d634.png)

```java:HikariCPの time out のログ
time:2023-2月-12 09:30:44.798 level:ERROR  thread:http-nio-8080-exec-85 logger:org.apache.catalina.core.ContainerBase.[Tomcat].[localhost].[/].[dispatcherServlet] message:Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is org.springframework.transaction.CannotCreateTransactionException: Could not open JPA EntityManager for transaction; nested exception is org.hibernate.exception.JDBCConnectionException: Unable to acquire JDBC Connection] with root cause
java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30001ms.
	at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:676)
	at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:190)
	at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:155)
	at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128)
	at org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:122)
	at org.hibernate.internal.NonContextualJdbcConnectionAccess.obtainConnection(NonContextualJdbcConnectionAccess.java:35)
	at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:106)
	at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getPhysicalConnection(LogicalConnectionManagedImpl.java:136)
	at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getConnectionForTransactionManagement(LogicalConnectionManagedImpl.java:254)
	at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.begin(LogicalConnectionManagedImpl.java:262)
	at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.begin(JdbcResourceLocalTransactionCoordinatorImpl.java:236)
	at org.hibernate.engine.transaction.internal.TransactionImpl.begin(TransactionImpl.java:86)
	at org.springframework.orm.jpa.vendor.HibernateJpaDialect.beginTransaction(HibernateJpaDialect.java:183)
	at org.springframework.orm.jpa.JpaTransactionManager.doBegin(JpaTransactionManager.java:401)
	at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:378)
	at org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:474)
	at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:289)
	at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:98)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
	at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:688)
	at sample.sample.service.TestService$$EnhancerBySpringCGLIB$$e7fb674e.regTest(<generated>)
	at sample.sample.controller.SampleController.sample(SampleController.java:18)
	at jdk.internal.reflect.GeneratedMethodAccessor50.invoke(Unknown Source)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
	at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:189)
	at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:138)
	at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:102)
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:892)
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:797)
	at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87)
	at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1038)
	at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:942)
	at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1005)
	at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:897)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:634)
	at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:882)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:741)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:99)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:92)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.springframework.web.filter.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:93)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:200)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:200)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:490)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:139)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343)
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:408)
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:834)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1415)
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.base/java.lang.Thread.run(Thread.java:834)
```

エラーが発生するものの、MariaDB側のコネクション数には変動がなかった。

```shell
mysql> show status like 'Threads_connected';
+-------------------+-------+
| Variable_name     | Value |
+-------------------+-------+
| Threads_connected | 11    |
+-------------------+-------+
```

## maximumPoolSizeを増やして負荷テストを行い改善するか確認

HikariCPの`maximumPoolSize`をデフォルトから変更して、負荷テストで37件のタイムアウトが発生した状態と同じ負荷テストを実施する。

- application.ymlでのSleepの設定 : 1000
- application.ymlでのmaximumPoolSize : 50
- jMeterの設定
    - ThreadGroup
        - Number of Threads(uses) : 100
        - Ramp-up period(seconds) : 10
        - Loop Count : 1

```yaml:application-prod.yml
spring:
  datasource:
    url: "jdbc:mysql://192.168.33.10/sample?useUnicode=true&characterEncoding=UTF-8&autoReconnect=true"
    username: hoge
    password: password
    hikari:
      maximum-pool-size: 50  # <-- ここの設定を追加
```

上記のようにyamlの設定を変更してSpringBootアプリケーションを起動後、リクエスト送信前にDBサーバー側のコネクション数を確認

```shell
mysql> show status like 'Threads_connected';
+-------------------+-------+
| Variable_name     | Value |
+-------------------+-------+
| Threads_connected | 51    |
+-------------------+-------+
1 row in set (0.00 sec)
```

設定が反映され、１１→５１に増加していることを確認したため、エラーが多発した負荷テストを実行する。
実行後にログを確認し、１件もエラーが出なくなったことを確認。

エラーが３７件発生していたログファイルをRenameしてapplication.log.01に変更し、新たにテストしたログが全てapplication.logに出力されている。
HikariCPのタイムアウトエラーを検索するが、application.log.01のテスト結果のログしかキーワードがヒットしておらず、maximumPoolSizeのパラメータ設定を変更後はこのエラーが出なくなったことから、この事象が改善できたと考えられる。
![スクリーンショット 2023-02-12 10.10.36.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/246556/9f2dbda9-3c67-3ad8-5ef9-ab5fd240aecc.png)
![スクリーンショット 2023-02-12 10.11.25.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/246556/3240ae4a-3aa4-4148-f82f-8078cd124a5f.png)

jMeterの実行時間としてもパラメータ調整後では処理が早くなっている。

|テスト|実行時間|TimeOutのエラー数|
|:--|:--|:--|
|maximumPoolSize=10の場合|100秒|37件|
|maximumPoolSize=50の場合| 23秒|0件|

## まとめ

```java
java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30000ms.
```

このエラーが出た時の対処法としては、やはりHikariCPのデフォルトのmaximumPoolSizeが影響していた。
DBサーバー側でもいくつまでコネクションがはれるのか、はれたとしてリソースに問題がないのかといった考慮が日露だとは思いますが、いったんサイズを増やして負荷テストを行うというのはありのような気がします。