Connection is not available, request timed out after 10000ms. (Unable to acquire JDBC Connection)

Connection is not available, request timed out after 10000ms. (Unable to acquire JDBC Connection)

장애 단서

• 커넥션이 존재하지 않아 요청시간이 10 초를 넘겨버려 발생됨 , 커넥션 풀을 할당 받지 못함
• 히카리 풀을 사용 중이며, spring boot 사용중임

확인해 볼것

Database config 설정

SHOW VARIABLES LIKE '%time%' 으로 데이터베이스의 타임아웃 환경 설정을 확인한다.

## 단위 : sec

**wait_timeout 28800**  
net_read_timeout 120
connect_timeout 10

MySQL 서버의 time out 설정은 크게 3가지가 있다.

• connect_timeout (bad handshake timeout)

• interactive_timeout (interactive 모드에서 connection time out)

• wait_timeout (none interactive 모드에서 connection time out)

튜닝시 다른 타임아웃 설정은 큰의미가 없으며, wait_timeout 을 살펴 보아야한다.

• 세부 옵션 정보
  • wait_timeout : 활동하지 않는 커넥션을 귾을때까지 서버가 대기하는 시간이다.
  • 플러그인 , API 라이브러리(python, php ,jdbc)를 이용한 connection
  • net_read_timeout : client → net → mysql server 구성에서 mysql 이 net 으로부터 read 하는 상황에서 세션을 끊을때가지 기다리는 시간
  • connect_timeout: mysql 서버에 연결할때까지의 연결 대기 시간.
  • Client 에서 MySQL 서버 접속시에 접속실패를 메시지를 보내기까지 대기하는 시간
  • 이 설정은 mysqld 와 mysql client 가 연결(connection)을 맺기 위해서mysqld 가 연결 패킷을 기다리는 최대 시간입니다.
    즉 TCP 연결을 맺는 과정(3-way handshake)에서, connect_timeout 동안에도연결 패킷이 들어오지 않으면 연결이 실패(취소가 아님)되고,bad handshake 로 응답합니다.
  • delayed_insert_timeout : insert 할대 딜레이가 생기는 경우 대기 하는 시간
  • interactive_timeout : 활동중인 커넥션이 닫히기 전가지 서버가 대기하는 시간
  • interactive 모드는 'mysql>' 과 같은 프롬프트 있는 콘솔이나 터미널 모드를말합니다.
  • mysqld 와 mysql client 가 연결을 맺은 다음, 다음 쿼리까지 기다리는최대 시간을 의미합니다.
  • 설정된 interactive_timeout 까지도 아무런 요청(쿼리)이 없으면 연결은취소되고, 그 이후에 다시 요청이 들어오면 연결은 자동으로 맺어집니다.

Application config 설정

## 단위 : ms
hikari:
      driver-class-name: com.mysql.cj.jdbc.Driver
      minimum-idle: 5
      maximum-pool-size: 200
      idle-timeout: 30000
      **connection-timeout: 30000**
      validation-timeout: 30000
      **max-lifetime: 580000**

• connection-timeout

  poll 에서 커넥션을 얻어오기까지 기다리는 최대 허용 시간 , 허용가능한 티임을 초과하면 예외가 발생된다. 가장 작은 시간은 250ms 이며, 기본 30000(30s)

  흔히 jdbc의 커넥션 타임아웃과 헷갈려서 실제 DB의 커넥션을 구할때까지의 시간으로 착각하기도 하는데 실제 DB의 연결시간과는 관련없다.

• idle-timeout:

  풀에서 유휴 상태로 유지시킬 최대 시간을 정성한다. (기본 10분)
  pool 에서 일을 안하는 커넥션을 유지하는 시간이다.

  이 옵션은 minimum-idle이 maximum-pool-size보다 작게 설정되어 있을경우에만 동작 되어 있다.

• max-lifetime

  • 커넥션 풀에서 살아있을수 있는 커넥션의 최대 수명시간 , 사용중인 커넥션은 해당 옵션에 영향을 받지 않는다. 사용중이지 않을때만 제거된다.
  • 풀 전체가 아닌 커넥션 별로 적용되며, 풀에서 대량으로 커넥션들이 제거됨을 방지하기 위함이다.
  • 중요한 설정이며, 데이터베이스에서 제한하는 커넥션 제한 시간보다(mysql : wait_timeout (기본 8시간)) 최소 30초는 작아야 한다. 0으로 설정하면 infinite lifetime 이 적용된다. default 는 1800000 ms 로 30분이다.

예상 원인

인프라의 wait_timeout 설정이 28800sec(8h)이라서 max-lifetime, idle-timeout 은 문제가 없는듯 하다. hikari pool 의 connection-timeout 설정이 10sec 인데 이걸 늘려 보고 모니터링좀 해봐야 겠다.

해결 방법

• spring 설정에서 사용한 환경설정이 db 셋팅 시간보다 길어서 발생될수 있다.
• 스프링 설정과 DB인프라의 설정을 확인하고 셋팅을 변경한다.
• database의 wait-time 시간보다 hikari 의 max-lifetime 시간을 작게 설정 한다.

Spring boot의 max-lifetime 이 20 분 인프라의 연결 유지시간이(mysql : wait_timeout) 10분이라 가정하자. 사용하지 않는 커넥션에 대해 DB는 10분이 지나면 DB인프라에서 커넥션을 끊어 버린다. 그러나 우리 어플리케이션은 MAX-LIFETIME은 20분임으로 10분이 지난 뒤에도 Hikari 의 해당 커넥션을 메모리에 유지하고 있고 이에대한 커넥션풀을 달라고 DB에가 다시 요청 하게 되는데 이 커넥션은 이미 끊겨 있음으로 에러가 발생된다. 즉 hikari max-lifetime 을 database의 wait-time 보다 작게 설정해야한다. (30 sec 이상 짧게 줄것을 권고함)

참고 (상세 로그 )

org.springframework.transaction.CannotCreateTransactionException: Could not open JPA EntityManager for transaction; nested exception is org.hibernate.exception.JDBCConnectionException: Unable to acquire JDBC Connection
    at org.springframework.orm.jpa.JpaTransactionManager.doBegin(JpaTransactionManager.java:448)
    at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:376)
    at org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:572)
    at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:360)
    at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:99)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:747)
    at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:689)
    at com.aereport.core.crawler.common.repository.AdsBulkRepository$$EnhancerBySpringCGLIB$$315a4937.bulkDataSave(<generated>)
    at com.aereport.core.crawler.common.repository.AdsBulkRepository$$FastClassBySpringCGLIB$$2476772b.invoke(<generated>)
    at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:769)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:747)
    at org.springframework.aop.support.DelegatingIntroductionInterceptor.doProceed(DelegatingIntroductionInterceptor.java:136)
    at org.springframework.aop.support.DelegatingIntroductionInterceptor.invoke(DelegatingIntroductionInterceptor.java:124)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:747)
    at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:689)
    at com.aereport.core.crawler.common.repository.AdsBulkRepository$$EnhancerBySpringCGLIB$$c698101c.bulkDataSave(<generated>)
    at com.aereport.core.crawler.media.v2.kakao.insights.KakaoAdGroupInsightCrawler.run(KakaoAdGroupInsightCrawler.java:238)
    at com.aereport.core.crawler.media.v2.kakao.insights.KakaoAdGroupInsightCrawler$$FastClassBySpringCGLIB$$7f10d8d5.invoke(<generated>)
    at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:769)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:747)
    at org.springframework.aop.framework.adapter.MethodBeforeAdviceInterceptor.invoke(MethodBeforeAdviceInterceptor.java:56)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:747)
    at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:93)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:747)
    at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:689)
    at com.aereport.core.crawler.media.v2.kakao.insights.KakaoAdGroupInsightCrawler$$EnhancerBySpringCGLIB$$2b87b6b2.run(<generated>)
    at com.aereport.core.crawler.media.v2.kakao.insights.KakaoAdGroupInsightCrawler$$FastClassBySpringCGLIB$$7f10d8d5.invoke(<generated>)
    at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:769)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:747)
    at org.springframework.aop.support.DelegatingIntroductionInterceptor.doProceed(DelegatingIntroductionInterceptor.java:136)
    at org.springframework.aop.support.DelegatingIntroductionInterceptor.invoke(DelegatingIntroductionInterceptor.java:124)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:747)
    at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:689)
    at com.aereport.core.crawler.media.v2.kakao.insights.KakaoAdGroupInsightCrawler$$EnhancerBySpringCGLIB$$4d218046.run(<generated>)
    at com.aereport.core.crawler.media.v3.kakao.module.KakaoCrawlerModule.insightCollectionProcess(KakaoCrawlerModule.java:136)
    at com.aereport.core.crawler.media.v3.kakao.module.KakaoCrawlerModule.process(KakaoCrawlerModule.java:63)
    at com.aereport.core.crawler.media.v3.kakao.module.KakaoCrawlerModule.start(KakaoCrawlerModule.java:55)
    at com.aereport.core.crawler.media.v3.kakao.runner.KakaoAutoCrawler.crawlerRun(KakaoAutoCrawler.java:65)
    at com.aereport.core.crawler.media.v3.kakao.runner.KakaoAutoCrawler.start(KakaoAutoCrawler.java:46)
    at com.aereport.schedule.independent.CrawlerKakaoSchedulerV3.lambda$scheduleKakaoAutoCrawler$0(CrawlerKakaoSchedulerV3.java:52)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)
Caused by: org.hibernate.exception.JDBCConnectionException: Unable to acquire JDBC Connection
    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.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:107)
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getPhysicalConnection(LogicalConnectionManagedImpl.java:134)
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getConnectionForTransactionManagement(LogicalConnectionManagedImpl.java:250)
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.begin(LogicalConnectionManagedImpl.java:258)
    at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.begin(JdbcResourceLocalTransactionCoordinatorImpl.java:246)
    at org.hibernate.engine.transaction.internal.TransactionImpl.begin(TransactionImpl.java:83)
    at org.springframework.orm.jpa.vendor.HibernateJpaDialect.beginTransaction(HibernateJpaDialect.java:184)
    at org.springframework.orm.jpa.JpaTransactionManager.doBegin(JpaTransactionManager.java:402)
    ... 55 common frames omitted
Caused by: java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 10000ms.
    at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:697)
    at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:196)
    at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:161)
    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:38)
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:104)
    ... 62 common frames omitted

https://javabom.tistory.com/101

https://m.blog.naver.com/PostView.naver?isHttpsRedirect=true&blogId=bomyzzang&logNo=221550485417