[HikariCP] Possibly consider using a shorter maxLifetime value

Table Of Contents

0. 서론

1. Connection Pool이 무엇인가

2. Connection Pool이 왜 필요한가?

3. HikariCP의 주요 파라미터

4. 문제 분석

5. 후기 및 조치

6. 참고 문헌

 

클릭하시면 해당 content로 넘어갑니다.

 

---

 

 

0. 서론

 

지난주, 플랫폼 각 내부의 엔드포인트를 호출하여 각 서비스 및 데이터베이스가 살아있는지에 대해 모니터링 하는 Spring Boot Application에서 다음과 같은 에러 메시지를 보았다.

[WARN ] 2020-07-30 16:43:39 299545737 [PoolBase.java][isConnectionAlive](184) : HikariPool-1 - Failed to validate connection org.mariadb.jdbc.MariaDbConnection@23d06b10
(Connection.setNetworkTimeout cannot be called on a closed connection). Possibly consider using a shorter maxLifetime value.

[WARN ] 2020-07-30 16:43:39 299545737 [PoolBase.java][isConnectionAlive](184) : HikariPool-1 - Failed to validate connection org.mariadb.jdbc.MariaDbConnection@17387ed0
(Connection.setNetworkTimeout cannot be called on a closed connection). Possibly consider using a shorter maxLifetime value.

[WARN ] 2020-07-30 16:43:39 299545737 [PoolBase.java][isConnectionAlive](184) : HikariPool-1 - Failed to validate connection org.mariadb.jdbc.MariaDbConnection@709f57f6
(Connection.setNetworkTimeout cannot be called on a closed connection). Possibly consider using a shorter maxLifetime value.

[WARN ] 2020-07-30 16:43:39 299545737 [PoolBase.java][isConnectionAlive](184) : HikariPool-1 - Failed to validate connection org.mariadb.jdbc.MariaDbConnection@5b2ab008
(Connection.setNetworkTimeout cannot be called on a closed connection). Possibly consider using a shorter maxLifetime value.

 

 

 

위 에러 메시지를 의역하면 다음과 같다.

 

Failed to validate connection MariaDbConnection
MariaDB Connection의 유효성을 검증하는데 실패하였습니다.

(Connection setNetworkTimeout cannot be called on a closed connection)
(Connection setNetworkTimeout은 닫힌 connection에서 호출할 수 없습니다.)

Possibly consider usdig shorter maxLifetime value.
현재보다 더 짧은 maxLifetime 값을 사용하는 것을 고려해보시기 바랍니다.

 

사실, 위 메시지대로 maxLifetime값만 바꿔주면 뜨지 않을 warning message였지만, 내가 코드를 작성하였기 때문에, 끝까지 책임지고 고도화를 하고 싶었다.

 

위 warning이 왜 일어났는지에 대해 알기 앞서 Connection Pool이 무엇인지부터 알아보려고 한다.

 

 

 

 

1. Connection Pool이 무엇인가

Connection Pool은 Application(WAS, Container 등)이 실행되면서, DB와 Connection에 대해 정의된 객체를 여러개 저장하고 있다. Application이 DB와 Connection이 필요할 때, Connection Pool은 Connection 객체를 제공하며 DB Connection을 이용한 작업이 끝나게 되면 Connection 객체를 다시 회수받아 다른 작업시 Connection 객체를 사용할 수 있도록 수명 관리를 하게된다.

 

 

 

 

2. Connection Pool이 왜 필요한가?

 

다음 코드는 DB와 connection부터 시작해서 query실행, connection 종료까지의 샘플 코드이다.

try {
    sql = "SELECT * FROM SOME_TABLE";

    connection = DriverManager.getConnection(DB_URL, DB_USER, DB_PASSWORD);

    resultSet = connection.createStatement();

    resultSet = statement.executeQuery(sql);
    } catch (Exception e) {
    	logger.info(e.getMessage())
    } finally {
        connection.close();
        statement.close();
        resultSet.close();
    }
}

 

 

샘플 코드를 절차적으로 정리하면 다음과 같다.

1. DB Connection을 맺기 위해 JDBC Driver를 Load한다.
2. DB Connection Parameter를 이용하여 DB Connection 객체를 생성한다.
3. Connection 객체로부터 쿼리를 수행하기 위한 statement를 생성한다.
4. 쿼리를 수행하여 결과로 ResultSet 객체를 받아 필요한 데이터를 파싱하여 처리한다.
5. 처리가 끝나면 사용된 리소스를 반환한다.

 

위 절차 중 시간적인 cost가 가장 높은 부분은 connection 객체를 생성하는 부분이다. Connection을 생성할 시, DB와 파라미터 교환 뿐만 아니라 각 시스템에서 체크해야할 요소들이 많기 때문이다. 또한, 웹 어플리케이션은 클라이언트의 요청에 따라 스레드를 생성한다. 스레드를 생성할 때 마다 Connection 객체를 생성한다는 것은 물리적으로 계속하여 DB에 접근을 해야하는 것과 같으며 이는 곧 요청 수에 따라 Connection을 생성하게 되므로 서버에 과부하가 걸리기 쉽다.

 

이러한 상황을 방지하기 위해 미리 여유분의 Connection 객체를 만들어 Pool에 저장해놓았다가 클라이언트 요청이 생기면 Connection객체를 지원하주고, 작업 종료시 Connection 객체를 다시 반환하여 보관하는 방식으로 과도한 수의 Connection 객체가 생기는 것을 방지한다. 한번 맺은 DB Connection 객체를 작업이 끝나자마자 close하지 않고, Pool에 저장한 뒤, 다음 번에 동일한 Connection을 요청하면 바로 Pool에서 꺼내 제공을 함으로써 보다 개선된 Connection Time Cost를 보장해준다.

 

 

 

3. HikariCP의 주요 파라미터

서론의 에러메시지에서 문제가 된 파라미터의 기본값을 가장 먼저 찾아보기로 하였다. 이왕 이렇게 된 김에 HikariPool의 주요 파라미터들을 공부해보기로 했다.

HikariPool의 주요 파라미터는 다음과 같다.

 

• autoCommit
  • 풀에서 반환된 connection의 자동 커밋을 설정한다.

• connectionTimeout
  • 클라이언트가 connection으로부터 최대 대기할 수 있는 시간, 시간초과시 SQLException이 발생한다. 밀리세컨드 단위이며 최소 250ms, 디폴트 30000이다.

• idleTimeout
  • Pool 안의 유휴 connection의 최대 유효기간을 설정한다. 이 설정은 minimumIdle이 maximumPoolSize보다 작을때만 적용되며, minimumIdle 값보다 pool안의 connection object의 개수가 작거나 같으면 유휴 연결이 폐기되지 않는다.
  • connection이 유휴상태로 전환되기까지 일반적으로 평균 15초에서 최대 30초까지의 시간이 추가로 걸린다. 이 시간이 초과되기 전까지는 connection이 유휴상태로 전환되지 않는다.
  • 최소 10000ms 값은 적용되어야 하며, 기본적으로 600000ms(10분)이 적용되어있다.

• maxLifetime
  • Pool의 Connection의 최대수명을 제어한다. 현재 사용중인 connection은 폐기되지 않으며, connection이 closed상태일 때만 제거된다. Pool안에 존재하는 connection의 순간적인 대량 삭제를 방지하기 위해 약간의 음감쇠가 적용된다.
  • 의 공식문서를 보게되면, 이 파라미터를 데이터베이스 또는 인프라가 권고하는 connection time limit보다 짧게 잡을 것을 권장하고 있다.
  • idleTimeout에 따라 다르지만, 파라미터에 0을 setting하면 최대 생명주기는 infinite로 적용된다.
  • 최소 30000ms(30초) 값은 적용되어야 하며, 기본값으로 1800000(30분)이 적용되어 있다

 

• minimumIdle
  • Connection Pool에서 유지하는 최소 유휴 Connection의 개수를 설정한다. 유휴 Connection이 minimumIdle 값보다 작을 시, HikariPool은 추가 connection을 만들어 채워넣는다.
  • HikariCP의 공식문서에서는 급격한 수요에 대해서 최상의 퍼포먼스와 반응성을 위해서 이 값을 수정하지 않고 사용하는 것을 권장하고 있다.
  • 기본 값은 maximumPoolSize와 같은 값으로 설정되어있다.

• maximumPoolSize
  • Pool에서 유지할 유휴 connection, 사용중인 connection을 합친 최대의 connection 개수를 설정한다. 기본적으로 이 값은 실제 DB 벡엔드와의 연결 최대수를 결정한다.
  • Pool이 최대 사이즈에 도달했고, 유휴 Connection이 없을때 getConnection을 호출하면 connectionTimeout설정 값 전까지 getConnection이 지연되며, connectionTimeout을 초과시, SQLException이 발생한다.
  • 최적의 maximumPoolSize를 설정하는 것은 HikariPool을 적용한 환경에 대해 맞추는 것이 가장 좋으며, 이에 대해서는 다음 링크를 참고한다.

 

 

 

 

 

4. 문제 분석

 

위 주요 파라미터 중 우리가 주목해야 할 것은 HikarikPool의 maxLifetime과 DB 설정값 중의 wait_timeout이다. 

HikariPool이 적용된 환경은 따로 별도의 설정이 없었으며, connection을 맺고있는 DB의 설정은 다음과 같이 wait_timeout이 1200(20분)으로 설정되어 있었다.

 

 

 

서론에서의 로그는 HikariPool의 로그를 찍지 않고 있었기 때문에, HikariPool의 로그가 찍힌 화면을 다시 캡처해보았다.

 

 

위 로그를 보고 추측한 warning 원인은 다음과 같다.

---

1. 위 로그에서는 보이지 않지만, 같은 MariaDbConnection 객체를 이용하여 commit을 하고 있었으며, 아래와 같이 Wrapping하고 있는 Proxy객체는 같지만, 본질적인 MariaDBConnection의 객체는 같은 것을 쓰고있었다.
   • [DEBUG] 2020-08-11 12:02:23 613936563 [DataSourceTransactionManager.java][doCommit](326) : Committing JDBC transaction on Connection [HikariProxyConnection@861338066 wrapping org.mariadb.jdbc.MariaDbConnection@17b01e2a]
   • [DEBUG] 2020-08-11 12:02:08 390098262 [DataSourceTransactionManager.java][doCommit](326) : Committing JDBC transaction on Connection [HikariProxyConnection@205121260 wrapping org.mariadb.jdbc.MariaDbConnection@17b01e2a]
2. Spring Boot의 HikariCP 설정 프로퍼티 중, maxLifetime으로 인해, 사용하던 모든 Connection은 30분 주기로 위 사진과 같이 connection을 closing 후, 다시 새로운 connection을 생성하고 있었다.
3. 사용하고 있던 connection도 closing 하면서 새로운 connection이 필요하여 HikariCP에 새로운 connection 객체를 요청한 것으로 보인다.
4. 비교적 가장 오래전에 만들어진 객체를 HikariPool에서 발급 받은 후, HikariPool의 정책에 따라 이 connection이 유효한지를 검사한다.
5. 이미 DB에서는 20분이 지나 닫힌 connection에 대해 validate하게 되므로 위와 같이 닫힌 connection에 대해서 아무것도 할수 없다고 로그가 찍혔다.

---

 

 

위 추측이 맞는지에 대해 직접 HikariCP의 코드를 뜯어보기로 하였다.

HikariPool.class

 /**
    * Get a connection from the pool, or timeout after the specified number of milliseconds.
    *
    * @param hardTimeout the maximum time to wait for a connection from the pool
    * @return a java.sql.Connection instance
    * @throws SQLException thrown if a timeout occurs trying to obtain a connection
    */
   public Connection getConnection(final long hardTimeout) throws SQLException
   {
      suspendResumeLock.acquire();
      final long startTime = currentTime();

      try {
         long timeout = hardTimeout;
         do {
            PoolEntry poolEntry = connectionBag.borrow(timeout, MILLISECONDS);
            if (poolEntry == null) {
               break; // We timed out... break and throw exception
            }

            final long now = currentTime();
            if (poolEntry.isMarkedEvicted() || (elapsedMillis(poolEntry.lastAccessed, now) > aliveBypassWindowMs && !isConnectionAlive(poolEntry.connection))) {
               closeConnection(poolEntry, poolEntry.isMarkedEvicted() ? EVICTED_CONNECTION_MESSAGE : DEAD_CONNECTION_MESSAGE);
               timeout = hardTimeout - elapsedMillis(startTime);
            }
            else {
               metricsTracker.recordBorrowStats(poolEntry, startTime);
               return poolEntry.createProxyConnection(leakTaskFactory.schedule(poolEntry), now);
            }
         } while (timeout > 0L);

         metricsTracker.recordBorrowTimeoutStats(startTime);
         throw createTimeoutException(startTime);
      }
      catch (InterruptedException e) {
         Thread.currentThread().interrupt();
         throw new SQLException(poolName + " - Interrupted during connection acquisition", e);
      }
      finally {
         suspendResumeLock.release();
      }
   }

 

위 HikariPool.class의 코드를 보면, 중간에 closeConnection을 할지에 대해 판단하는 로직이 포함되어 있었다. 해당 로직에서 검사하는 것을 정리하면 다음과 같다.

• 해당 connection이 HikariCP에서 evict(직역하면 축출하다라고 함)되기로 한 객체인가?
• Connection이 살아있는지 Bypass할 수 있는 시간보다 최근 접근 시간이 더 크고, connection이 아직 살아있는가?

 

 

로그 상에서 connection이 evict하다고 하지 않았으므로, 두번째 검사 조건에서 true를 반환하였기 때문에  closeConnection을 하도록 하였을 것이다.

두번째 조건을 warning이 발생한 조건에 맞추에 분석해보면 다음과 같다.

• 하나의 connection 객체만 사용하고 있었으므로, 500ms보다는 훨씬 더 크기 때문에 true를 출력하였을 것이다.
• DB에서 wait_timeout 값이 20분이므로, getConnection하였을 때, false를 출력하였을 것이다.

 

 

다음, isConnectionAlive의 코드를 살펴보면 문제가 된 상황을 한눈에 볼 수 있을 것이다.

PoolBase.class

boolean isConnectionAlive(final Connection connection)
   {
      try {
         try {
            setNetworkTimeout(connection, validationTimeout);

            final int validationSeconds = (int) Math.max(1000L, validationTimeout) / 1000;

            if (isUseJdbc4Validation) {
               return connection.isValid(validationSeconds);
            }

            try (Statement statement = connection.createStatement()) {
               if (isNetworkTimeoutSupported != TRUE) {
                  setQueryTimeout(statement, validationSeconds);
               }

               statement.execute(config.getConnectionTestQuery());
            }
         }
         finally {
            setNetworkTimeout(connection, networkTimeout);

            if (isIsolateInternalQueries && !isAutoCommit) {
               connection.rollback();
            }
         }

         return true;
      }
      catch (Exception e) {
         lastConnectionFailure.set(e);
         logger.warn("{} - Failed to validate connection {} ({}). Possibly consider using a shorter maxLifetime value.",
                     poolName, connection, e.getMessage());
         return false;
      }
   }

위 코드를 보면, try문 첫번째에서 setNetworkTimeout을 실행하고 있다. 그러나 connection은 DB측에서 이미 close한 상태이기 때문에, close된 connection에서 작업을 할 수 없기 때문에 catch문의 로직이 실행 되었을것이다.

catch문을 보면 우리가 보았던 해당 로그가 보일 것이다.

 

위 분석을 통해 내가 예측한 추측한 결과와 실제 코드의 로직이 일치하는 것을 볼 수 있었다.

 

 

5. 후기 및 조치

HikariCP의 공식문서에서 maxLifeTime을 데이터베이스 또는 인프라가 권고하는 connection time limit보다 짧게 잡을 것을 권장하여 maxLifeTime을 기존 30분에서 15분으로 변경하고 jenkins를 통해 deploy한 결과, 그 이후로는 warning이 발생하지 않았다.

그러나 30분 내내 HikariCP에서 처음 받은 단 하나의 connection을 사용하는 현상은 아직 내가 이해를 하지 못하여 이에 대해서는 조금 더 보충하여 새로 글을 작성할 계획이다. 이번 기회를 통해 Connection관리가 App안에서 어떻게 이루어 지는지에 대한 개론을 파악할 수 있었다.

 

 

 

6. 참고 문헌

• https://github.com/brettwooldridge/HikariCP