서버를 운영하다 보면 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(
    @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
이런 결과가 발생한 이유는 다음과 같다,
max-pool-size가 5로 설정되어 커넥션 풀에 5개의 커넥션이 존재한다.
saveWithDelay가 호출되면 트랜잭션에 의해 약 10초 동안 커넥션을 잡고 있는다.
먼저 실행된 5개의 saveWithDelay는 커넥션을 획득했지만, 나머지 5개 스레드는 커넥션 풀에 커넥션이 존재하지 않아 대기한다.
이때, 커넥션 풀로부터 커넥션 획득을 기다리는 시간이 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를 조절하려면 이런 부분까지 고려가 되어야 한다.