[Spring/Spring Boot] request timeout error / Fill pool skipped, pool is at sufficient level.

오류내용

org.springframework.dao.DataAccessResourceFailureException: could not extract ResultSet; nested exception is org.hibernate.exception.JDBCConnectionException: could not extract ResultSet
    at org.springframework.orm.jpa.vendor.HibernateJpaDialect.convertHibernateAccessException(HibernateJpaDialect.java:275)
    at org.springframework.orm.jpa.vendor.HibernateJpaDialect.translateExceptionIfPossible(HibernateJpaDialect.java:253)
    at org.springframework.orm.jpa.AbstractEntityManagerFactoryBean.translateExceptionIfPossible(AbstractEntityManagerFactoryBean.java:527)
    at org.springframework.dao.support.ChainedPersistenceExceptionTranslator.translateExceptionIfPossible(ChainedPersistenceExceptionTranslator.java:61)
    at org.springframework.dao.support.DataAccessUtils.translateIfNecessary(DataAccessUtils.java:242)
    at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:153)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
    at org.springframework.data.jpa.repository.support.CrudMethodMetadataPostProcessor$CrudMethodMetadataPopulatingMethodInterceptor.invoke(CrudMethodMetadataPostProcessor.java:138)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
    at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:93)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
    at org.springframework.data.repository.core.support.SurroundingTransactionDetectorMethodInterceptor.invoke(SurroundingTransactionDetectorMethodInterceptor.java:61)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
    at datadog.trace.instrumentation.springdata.RepositoryInterceptor.invoke(RepositoryInterceptor.java:41)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
    at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:212)
    ....
Caused by: org.hibernate.exception.JDBCConnectionException: could not extract ResultSet
    at org.hibernate.exception.internal.SQLExceptionTypeDelegate.convert(SQLExceptionTypeDelegate.java:48)
    at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:42)
    at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:113)
    at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:99)
    at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.extract(ResultSetReturnImpl.java:69)
    at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.getResultSet(AbstractLoadPlanBasedLoader.java:419)
    at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.executeQueryStatement(AbstractLoadPlanBasedLoader.java:191)
    at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.executeLoad(AbstractLoadPlanBasedLoader.java:121)
    at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.executeLoad(AbstractLoadPlanBasedLoader.java:86)
    at org.hibernate.loader.entity.plan.AbstractLoadPlanBasedEntityLoader.load(AbstractLoadPlanBasedEntityLoader.java:188)
    at org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:4273)
    at org.hibernate.event.internal.DefaultLoadEventListener.loadFromDatasource(DefaultLoadEventListener.java:511)
    at org.hibernate.event.internal.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:481)
    at org.hibernate.event.internal.DefaultLoadEventListener.load(DefaultLoadEventListener.java:222)
    at org.hibernate.event.internal.DefaultLoadEventListener.proxyOrLoad(DefaultLoadEventListener.java:281)
    at org.hibernate.event.internal.DefaultLoadEventListener.doOnLoad(DefaultLoadEventListener.java:124)
    at org.hibernate.event.internal.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:92)
...
Caused by: java.sql.SQLTransientConnectionException: xxDataSource - Connection is not available, request timed out after 100000ms.
    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:100)
    at org.apache.shardingsphere.driver.jdbc.core.connection.ConnectionManager.createConnection(ConnectionManager.java:369)
    at org.apache.shardingsphere.driver.jdbc.core.connection.ConnectionManager.createConnections(ConnectionManager.java:338)
    at org.apache.shardingsphere.driver.jdbc.core.connection.ConnectionManager.getConnections(ConnectionManager.java:327)
    ...

 

누수인가? Dead Lock인가?

누수 탐지를 위해 leakDetectionThreshold를 3초로 설정

default는 0으로 설정되어 있어 검출을 안함

datasource:
	hikari:
		leak-detection-threshold: 3000

 

이것도 아니네...

다시 로그레벨 부터 낮춰서 봐보자..!

#application.yml

logging.level:
	root:WARN
    org.springframework.transaction: DEBUG
    org.springframework.orm.jpa: DEBUG
    com.zaxxer.hikari: DEBUG

 

오 드디어 무언가 감지가 되었다!

2022-07-27 23:56:47.967 DEBUG 1 --- [rce housekeeper] com.zaxxer.hikari.pool.HikariPool        : xxDataSource - Pool stats (total=30, active=1, idle=29, waiting=0)
2022-07-27 23:56:47.967 DEBUG 1 --- [rce housekeeper] com.zaxxer.hikari.pool.HikariPool        : xxDataSource - Fill pool skipped, pool is at sufficient level.
2022-07-27 23:56:58.410  WARN 1 --- [ntainer#3-0-C-1] o.h.engine.jdbc.spi.SqlExceptionHelper   : SQL Error: 0, SQLState: 08003
2022-07-27 23:56:58.410 ERROR 1 --- [ntainer#3-0-C-1] o.h.engine.jdbc.spi.SqlExceptionHelper   : xxDataSource - Connection is not available, request timed out after 30030ms.
2022-07-27 23:56:58.410 ERROR 1 --- [ntainer#3-0-C-1] o.h.engine.jdbc.spi.SqlExceptionHelper   : No operations allowed after connection closed.
2022-07-27 23:56:58.410 DEBUG 1 --- [ntainer#3-0-C-1] o.s.orm.jpa.JpaTransactionManager        : Initiating transaction rollback
2022-07-27 23:56:58.410 DEBUG 1 --- [ntainer#3-0-C-1] o.s.orm.jpa.JpaTransactionManager        : Rolling back JPA transaction on EntityManager [SessionImpl(1388718910<open>)]
2022-07-27 23:56:58.410 DEBUG 1 --- [ntainer#3-0-C-1] o.s.orm.jpa.JpaTransactionManager        : Closing JPA EntityManager [SessionImpl(1388718910<open>)] after transaction

분명 pool stats를 보면 현재 active된 건 1개밖에 없음

• xxDataSource - Pool stats (total=30, active=1, idle=29, waiting=0)

이상하네..? maxLifetime < MySQL wait_timeout 이어야 한다는 글을 발견 

• https://do-hansung.tistory.com/41

 

확인해보니 정말 DB의 wait_timeout이 spring boot의 maxlifetimeout보다 훨씬 작게 설정이 되어있었다....

 

결론

• maxLifetime < MySQL wait_timeout 
• 문제가 해결되지 않을 땐 로그를 보자

 

---

끄적끄적

위 문제를 해결하는대에..거의 두달 가량을 소모한 것 같다.

이번 기회에 HikariCP, connection, transaction에 대해 깊게 공부해보는 기회가 되었다. 

 

참고글

https://imksh.com/73

https://jaehun2841.github.io/2020/01/08/2020-01-08-hikari-pool-validate-connection/