Connection is not available, request timed out after 10000ms. 에러의 원인은

SQLTransientConnectionException

프로젝트 중 발생한 에러입니다. 해당 에러는 요청 시 바로 발생하지 않아서 모르고 있다가 개발서버에 올려 테스트하던 중 발생을 확인하고 조치하였습니다.

커넥션 풀과 관련된 HikariCP Dead lock 이라고 불리는 에러였으며, 해결하기 위해 자료를 찾아보며 커넥션 풀이 프로그램에서 중요하고, 또 그렇기 때문에 자세하게 공부하여 잘 적용해야 한다고 느꼈습니다.

 

* 해당 포스팅의 내용은 커넥션 풀에 대해 이해도가 많이 부족하며, 에러의 원인과 해결에 대한 방법만 찾은 포스팅입니다.

 

(해결 방법은 포스팅 하단에 있으며 미리 원인을 말씀드리면 Querydsl에서 transform을 사용하면서 DB connection leak이 걸렸습니다. querydsl에서 transform 사용 시 트랜잭션 내부에서 실행되지 않는다면 해당 db connection은 해제되지 않습니다.)

 

 

 

먼저 에러 메세지 입니다.

 

SqlExceptionHelper   : HikariPool-1 - Connection is not available, request timed out after 10000ms.

org.springframework.dao.DataAccessResourceFailureException: Unable to acquire JDBC Connection; nested exception is org.hibernate.exception.JDBCConnectionException: Unable to acquire JDBC Connection

 

내용을 보면 JDBC Connection에 실패해서 발생하는 에러라는 것을 유추할 수 있는데요.

문제의 원인과 해결 방법은 무엇이었을까요?

 

 

---

 

 

HikariCP에 대해서 간략하게 먼저 설명하면 Brett Wooldridge에 의해 2012년 개발된 가볍고, 빠르고, 안정적인 JDBC Connection Pool이며, Spring boot 2.0부터 dafault JDBC connection pool으로 사용되고 있습니다.

 

HikariCP의 역할은 간단히 Database connection pool을 관리해주는 것입니다.

Connection Pool에 대해서도 간략하게 이야기하면 다음과 같습니다.

 

1. HikariCP는 서버와 데이터베이스의 연결을 위해 미리 정해놓은 만큼의 connection을 만들어서 pool에 담아놓습니다.
2. 요청이 들어오면 Thread가 connection을 요청하고, HikariCP내에 있는 connection을 제공해줍니다.
3. Thread는 connection을 사용하고 나서 pool로 다시 반환합니다.

 

 

# Hikari Setup
spring.datasource.hikari.connection-timeout=10000
spring.datasource.hikari.validation-timeout=10000
spring.datasource.hikari.maximum-pool-size=10
spring.datasource.hikari.max-lifetime=10000

그렇다면 실제로 오류가 발생한 원인을 찾아보기 위해 가장 먼저 어플리케이션의 connection에 대한 설정부터 확인해봤습니다.

 

여기서 주목해야 할 설정이 'connection-timeout'입니다.

connection-timeout은 pool에서 connection을 얻어오기까지 기다리는 최대 시간으로 허용 가능한 시간을 초과하면 SQLException이 발생합니다.

(default 값은 30000ms으로 30s가 됩니다.)

 

또 하나의 설정은 'maximum-pool-size'인데요. 

maximum-pool-size 옵션은 pool에 유지시킬 수 있는 최대 connection을 지정하는 옵션입니다.

(default 값은 10입니다.)

 

 

---

 

 

logging:
  level:
    com.zaxxer.hikari.HikariConfig: DEBUG
    com.zaxxer.hikari: TRACE

정확한 원인을 파악하기 위해 hikari 내용을 logging 설정하고 프로그램을 돌려봤습니다.

 

HikariPool

그리고 찾은 오류의 원인입니다.

 

• total : 전체 connection의 수
• active : 현재 사용하고 있는 connection의 수
• idle : 게으른 이라는 뜻으로 놀고 있는 (사용 대기 중인) connection의 수
• waiting : connection을 사용하기 위해 대기하고 있는 thread 수

 

어떤 요청을 여러 번 시도했는데 보시는 것과 같이 전체 10개의 커넥션 중에 active가 10개로 connection이 사용된 이후 다시 pool로 반환되지 않는 것을 확인할 수 있었습니다.

 

 

  @Override
  public List<Transaction> getTransactionList(Long userIdx, LocalDateTime start, LocalDateTime end,
      Integer page, Integer size) {

    List<Transaction> result = queryFactory.from(transaction)
        .where(transaction.userIdx.eq(franchiseeIdx))
        .transform(
            groupBy(formattedDate)
                .list(
                    Transaction.constructor(
                    
                    .
                    .
                    .
                    
                    )
                )
        );

(세부 코드 생략)

 

querydsl을 사용하여 내역을 가지고 오는 요청이었고, 오류의 원인은 이때 사용된 transform입니다.

 

현재 querydsl의 transform()을 사용 시 트랜잭션 내부에서 실행되지 않는다면 해당 db connection은 해결되지 않는 문제가 있습니다.

그렇기 때문에 요청이 발생했을 때 connection이 하나씩 사용되고, 반환은 되지 않아 결국 10개가 모두 사용된 시점에서 pool에 있는 connection의 수는 0개가 됩니다. 그렇기 때문에 이후 connection이 필요한 요청이 발생하여 thread가 connection을 요청하였지만 위에 어플리케이션에서 설정한 hikari.connection-timeout=10000, 10초가 넘어도 connection을 얻을 수가 없어서 SqlException을 발생한 것이었습니다.

 

해결방안은 transform을 트랜잭션 내부에서 실행하는 것입니다. 그렇게 되면 작업 후에도 connection이 반환되어 해당 오류가 발생하지 않습니다. 또 다른 해결 방법은 transform을 사용하지 않는 것입니다.

 

 

---

 

 

해당 에러는 'HikariCP Dead lock' 이라고 불리는 에러이며, 이런 간단한 원인이 문제일 수도 있지만 실제로 db와 server간에 connection 관련된 설정이 잘못되어 발생하는 경우도 있을 수 있습니다.

 

 

참고 자료

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

 

 

Querydsl 에서 DB connection leak 이슈

 

 

HikariCP Dead lock에서 벗어나기 (이론편) | 우아한형제들 기술블로그