Spring Boot Hikari Connection Pool 에러 핸들링

서버를 운영하다 보면 hikari connection과 관련된 에러를 겪게 된다. 은근히 놓치기 쉽고 빈번하게 발생 가능한 부분이라 정리를 해보려고 한다.

 

connection 관련 문제는 보통 아래의 에러 메시지와 함께 문제가 발생한다.

- org.springframework.transaction.CannotCreateTransactionException: Could not open JPA EntityManager for transaction
- Unable to acquire JDBC Connection
- HikariPool-1 - Connection is not available, request timed out after 3005ms.
- o.h.engine.jdbc.spi.SqlExceptionHelper   : SQL Error: 0, SQLState: null

 

 

에러의 내용은 트랜잭션을 만드는데 실패했고, JDBC Connection을 획득할 수 없다. hikariPool에서 커넥션을 이용할 수 없고 요청 시간이 지났다는 의미이다. 

 

그렇다면 왜 커넥션을 가져올 수 없는 것인지. 간단한 예시로 상황을 재현해보자.

 

connection에러 관련 상황 재현

우선, 테스트에 사용할 hikari관련 옵션이다.

spring:
  datasource:
    hikari:
      jdbc-url: jdbc:h2:mem:testdb;MODE=MySQL;DATABASE_TO_LOWER=TRUE
      username: sa
      password:
      connection-timeout: 3000
      maximum-pool-size: 5
      max-lifetime: 30000
      driver-class-name: org.h2.Driver

maximum-pool-size는 5로 설정되어있다. hikari pool에서 최대 5개의 커넥션을 관리한다는 의미이다.

connection-timeout은 3초로 설정되어있다. connection-timeout이란 커넥션을 요청한 뒤 몇 초까지 기다릴 것 인지를 의미한다. hikari pool에 커넥션을 요청했는데 일정 시간 안에 커넥션을 얻지 못하면 에러가 발생한다.

 

다음은 테스트에 사용할 비즈니스 로직이다.

@Entity
@Table(name = "orders")
class Order(
    @Id
    @GeneratedValue(strategy = GenerationType.IDENTITY)
    val id: Long,
)


interface OrderJpaRepository : JpaRepository<Order, Long>

@Service
class OrderService(private val orderJpaRepository: OrderJpaRepository) {

    private val logger = LoggerFactory.getLogger(this::class.simpleName)

    @Transactional
    fun saveWithDelay(order: Order, delay: Long) {
        logger.info("saveWithDelay 호출 : id : ${order.id}")
        Thread.sleep(delay)
        orderJpaRepository.save(order)
    }
}

코드는 단순하다. Order라는 엔티티를 저장하는데 delay와 함께 저장한다. 이때 주의할 점은 saveWithDelay가 트랜잭션으로 묶여있다는 점이다. 만약 10초의 딜레이와 함께 호출된다면, 트랜잭션은 10초 이상 유지되는 상황이 발생한다.

 

다음은 테스트 코드를 작성해본다.

@SpringBootTest
@TestConstructor(autowireMode = TestConstructor.AutowireMode.ALL)
@ActiveProfiles("test")
class OrderServiceTest(
    private val orderService: OrderService
) {
    @Test
    fun `동시에 10개의 order를 저장한다`() {
        val threadList = mutableListOf<CompletableFuture<Void>>()
        for (id in 1..10L) {
            val order = Order(id)
            threadList.add(CompletableFuture.runAsync { orderService.saveWithDelay(order, delay = 10000) })
        }
        threadList.forEach { it.join() }
    }
}

멀티 스레드를 사용해서 동시에 10개의 스레드를 만들고 10초의 딜레이를 걸어 saveWithDelay를 호출한다.

 

테스트 실행 결과는 다음과 같다.

2022-03-05 12:19:19.846  INFO 97918 --- [onPool-worker-3] OrderService                             : saveWithDelay 호출 : id : 9
2022-03-05 12:19:19.846  INFO 97918 --- [onPool-worker-5] OrderService                             : saveWithDelay 호출 : id : 2
2022-03-05 12:19:19.846  INFO 97918 --- [nPool-worker-17] OrderService                             : saveWithDelay 호출 : id : 8
2022-03-05 12:19:19.846  INFO 97918 --- [nPool-worker-19] OrderService                             : saveWithDelay 호출 : id : 1
2022-03-05 12:19:19.846  INFO 97918 --- [nPool-worker-31] OrderService                             : saveWithDelay 호출 : id : 7
2022-03-05 12:19:22.846  WARN 97918 --- [nPool-worker-13] o.h.engine.jdbc.spi.SqlExceptionHelper   : SQL Error: 0, SQLState: null
2022-03-05 12:19:22.846  WARN 97918 --- [nPool-worker-27] o.h.engine.jdbc.spi.SqlExceptionHelper   : SQL Error: 0, SQLState: null
2022-03-05 12:19:22.846  WARN 97918 --- [nPool-worker-21] o.h.engine.jdbc.spi.SqlExceptionHelper   : SQL Error: 0, SQLState: null
2022-03-05 12:19:22.846  WARN 97918 --- [onPool-worker-9] o.h.engine.jdbc.spi.SqlExceptionHelper   : SQL Error: 0, SQLState: null
2022-03-05 12:19:22.846  WARN 97918 --- [nPool-worker-23] o.h.engine.jdbc.spi.SqlExceptionHelper   : SQL Error: 0, SQLState: null
2022-03-05 12:19:22.846 ERROR 97918 --- [nPool-worker-13] o.h.engine.jdbc.spi.SqlExceptionHelper   : HikariPool-1 - Connection is not available, request timed out after 3004ms.
2022-03-05 12:19:22.846 ERROR 97918 --- [nPool-worker-23] o.h.engine.jdbc.spi.SqlExceptionHelper   : HikariPool-1 - Connection is not available, request timed out after 3004ms.
2022-03-05 12:19:22.846 ERROR 97918 --- [nPool-worker-27] o.h.engine.jdbc.spi.SqlExceptionHelper   : HikariPool-1 - Connection is not available, request timed out after 3004ms.
2022-03-05 12:19:22.846 ERROR 97918 --- [nPool-worker-21] o.h.engine.jdbc.spi.SqlExceptionHelper   : HikariPool-1 - Connection is not available, request timed out after 3004ms.
2022-03-05 12:19:22.846 ERROR 97918 --- [onPool-worker-9] o.h.engine.jdbc.spi.SqlExceptionHelper   : HikariPool-1 - Connection is not available, request timed out after 3004ms.
org.springframework.transaction.CannotCreateTransactionException: Could not open JPA EntityManager for transaction; nested exception is org.hibernate.exception.JDBCConnectionException: Unable to acquire JDBC Connection
java.util.concurrent.CompletionException: org.springframework.transaction.CannotCreateTransactionException: Could not open JPA EntityManager for transaction; nested exception is org.hibernate.exception.JDBCConnectionException: Unable to acquire JDBC Connection
	at java.base/java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:314)
	at java.base/java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:319)
	at java.base/java.util.concurrent.CompletableFuture$AsyncRun.run(CompletableFuture.java:1739)
	at java.base/java.util.concurrent.CompletableFuture$AsyncRun.exec(CompletableFuture.java:1728)
	at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:290)
	at java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1020)
	at java.base/java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:1656)
	at java.base/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1594)
	at java.base/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:183)
Caused by: 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:467)
	at org.springframework.transaction.support.AbstractPlatformTransactionManager.startTransaction(AbstractPlatformTransactionManager.java:400)
	at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:373)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	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.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:344)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:198)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
	at org.springframework.batch.core.configuration.annotation.SimpleBatchConfiguration$PassthruAdvice.invoke(SimpleBatchConfiguration.java:128)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
	at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:215)
	at com.sun.proxy.$Proxy96.getTransaction(Unknown Source)
	at org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:595)
	at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:382)
	at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:119)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:750)
	at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:692)
	at com.example.batch.OrderService$$EnhancerBySpringCGLIB$$73d450f0.saveWithDelay(<generated>)
	at com.example.batch.OrderServiceTest$동시에 10개의 order를 저장한다$1.run(OrderServiceTest.kt:20)
	at java.base/java.util.concurrent.CompletableFuture$AsyncRun.run(CompletableFuture.java:1736)
	... 6 more
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:111)
	at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getPhysicalConnection(LogicalConnectionManagedImpl.java:138)
	at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getConnectionForTransactionManagement(LogicalConnectionManagedImpl.java:274)
	at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.begin(LogicalConnectionManagedImpl.java:282)
	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:164)
	at org.springframework.orm.jpa.JpaTransactionManager.doBegin(JpaTransactionManager.java:421)
	... 28 more
Caused by: java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 3004ms.
	at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:695)
	at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:197)
	at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:162)
	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:108)
	... 35 more

이런 결과가 발생한 이유는 다음과 같다,

1. max-pool-size가 5로 설정되어 커넥션 풀에 5개의 커넥션이 존재한다.
2. saveWithDelay가 호출되면 트랜잭션에 의해 약 10초 동안 커넥션을 잡고 있는다.
3. 먼저 실행된 5개의 saveWithDelay는 커넥션을 획득했지만, 나머지 5개 스레드는 커넥션 풀에 커넥션이 존재하지 않아 대기한다.
4. 이때, 커넥션 풀로부터 커넥션 획득을 기다리는 시간이 connection-timeout으로 설정한 3초가 지나 예외가 발생했다.

논리적으로 그렇게 해석이 어려운 상황은 아니다. 그렇다면 어떻게 해결해야 할까? 방법은 굉장히 다양하다.

 

1. 사용하는 pool size를 늘린다.

spring:
  datasource:
    hikari:
      jdbc-url: jdbc:h2:mem:testdb;MODE=MySQL;DATABASE_TO_LOWER=TRUE
      username: sa
      password:
      connection-timeout: 3000
      maximum-pool-size: 10 // 5 -> 10으로 증가
      max-lifetime: 30000
      driver-class-name: org.h2.Driver

테스트의 결과는 당연히 성공한다.

그런데, pool size를 늘리는 방법이 단순하긴 하지만, 만능이라고 할 수는 없을 것이다.

예를 들어 OrderService에 대한 트래픽이 증가한다면, pool size를 늘린다고 하더라고 금방 커넥션이 고갈될 것이다.

나는 pool size를 늘려 해결하는 방식은 배치에 적용하곤 한다. 배치 작업은 특정 스레드 수를 지정할 수 있으며 처리되는 작업들이 예상 가능한 경우가 많기 때문이다.

 

2. connection timeout을 늘린다.

spring:
  datasource:
    hikari:
      jdbc-url: jdbc:h2:mem:testdb;MODE=MySQL;DATABASE_TO_LOWER=TRUE
      username: sa
      password:
      connection-timeout: 15000 // 3초 -> 15초로 증가
      maximum-pool-size: 5
      max-lifetime: 30000
      driver-class-name: org.h2.Driver

save에 약 10초가 소요되므로 connection-timeout이 발생하지 않는다.

 

테스트 결과는 성공한다. 하지만 이 방법도 pool size를 늘리는 방식과 마찬가지로 일시적인 해소는 될 수 있지만 상황에 따라 근본적인 해결책은 아니라고 생각된다.

 

3. 비즈니스 로직을 수정 (트랜잭션 짧게 가져가기)

설정은 처음 문제가 됐던 property를 사용하고 단순히 트랜잭션 어노테이션을 빼준다.

spring:
  datasource:
    hikari:
      jdbc-url: jdbc:h2:mem:testdb;MODE=MySQL;DATABASE_TO_LOWER=TRUE
      username: sa
      password:
      connection-timeout: 3000
      maximum-pool-size: 5
      max-lifetime: 30000
      driver-class-name: org.h2.Driver

@Service
class OrderService(private val orderJpaRepository: OrderJpaRepository) {

    private val logger = LoggerFactory.getLogger(this::class.simpleName)

    //@Transactional 트랜잭션 제거
    fun saveWithDelay(order: Order, delay: Long) {
        logger.info("saveWithDelay 호출 : id : ${order.id}")
        Thread.sleep(delay)
        orderJpaRepository.save(order)
    }
}

트랜잭션을 빼주면, delay로 인해 트랜잭션을 길게 가져가지 않고 orderJpaRepository.save(order)가 호출되는 순간만 트랜잭션을 가져간다. 따라서, 커넥션을 사용해도 save작업이 끝나면 바로 반납하기 때문에 connection-timeout이 발생하지 않는다. 

 

connection문제가 발생하면 먼저, 트랜잭션을 불필요하게 길게 가져가는 곳은 없는지 확인해봐야 한다.

 

테스트는 성공한다.

 

결론

hikari connection관련 문제의 원인이 무엇이고 어떻게 해결할 수 있는지 간단하게 알아봤다.

방법은 다양하지만, 상황에 맞게 사용하는 것이 중요하다. pool size를 늘리는 방식은 단순하지만 어떻게 트랜잭션을 가져가고, connection이 늘어났을 경우 db에 부하가 가진 않는지 등 고려해야 할 부분은 많다. 또한, 하나의 스레드에서 하나의 커넥션만 사용할 것이라는 보장은 전혀 없기 때문에 정확한 pool size를 조절하려면 이런 부분까지 고려가 되어야 한다.