More than 1 year has passed since last update.

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

Posted at 2023-02-12

概要

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

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への接続設定としては以下のような設定をしています。

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で設定できるようにしています。

@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サーバーに私自身がアクセスして、チェックするためにコネクションを取得してしまっているため１となっている。

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

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

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 ここにデフォルトの記述があり、仕様通りです。

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

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

$ /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]$  <-- この時点でプロセスが終了

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

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.のエラーは１件も出ることはありませんでした。

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

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のエラーが発生した。
このエラーは今回のテストで３７件発生した。

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側のコネクション数には変動がなかった。

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

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サーバー側のコネクション数を確認

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のパラメータ設定を変更後はこのエラーが出なくなったことから、この事象が改善できたと考えられる。

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

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

まとめ

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

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

You get articles that match your needs
You can efficiently read back useful information
You can use dark theme

What you can do with signing up