Server/Spring JPA

HikariCP 커넥션 누수 해결기 (Session wait_timeout 적용!)

JaeHoney 2023. 4. 19. 08:24

HikariCP 커넥션 누수 해결기 (Session wait_timeout 적용!)

아래의 에러가 뜨면서 커넥션 연결이 실패하는 이슈가 발생했다.

the last packet successfully received from the server was 30,035 milliseconds ago.

조금더 로그를 올라가보니 이런 경고가 뜨고있었다. 아래와 같이 각 커넥션으로 연결을 시도하다가 모두 실패했다.

2023-04-18 08:01:12.345  WARN 20 --- [nio-8080-exec-9] com.zaxxer.hikari.pool.PoolBase          : HikariPool-3 - Failed to validate connection com.mysql.cj.jdbc.ConnectionImpl@1d5d809b (No operations allowed after connection closed.). Possibly consider using a shorter maxLifetime value. 
2023-04-18 08:01:12.346  WARN 20 --- [nio-8080-exec-2] com.zaxxer.hikari.pool.PoolBase          : HikariPool-3 - Failed to validate connection com.mysql.cj.jdbc.ConnectionImpl@656228eb (No operations allowed after connection closed.). Possibly consider using a shorter maxLifetime value. 
2023-04-18 08:01:12.346  WARN 20 --- [nio-8080-exec-2] com.zaxxer.hikari.pool.PoolBase          : HikariPool-3 - Failed to validate connection com.mysql.cj.jdbc.ConnectionImpl@1ee6e7a8 (No operations allowed after connection closed.). Possibly consider using a shorter maxLifetime value. 
2023-04-18 08:01:12.347  WARN 20 --- [nio-8080-exec-9] com.zaxxer.hikari.pool.PoolBase          : HikariPool-3 - Failed to validate connection com.mysql.cj.jdbc.ConnectionImpl@100d934e (No operations allowed after connection closed.). Possibly consider using a shorter maxLifetime value. 
2023-04-18 08:01:12.347  WARN 20 --- [nio-8080-exec-2] com.zaxxer.hikari.pool.PoolBase          : HikariPool-3 - Failed to validate connection com.mysql.cj.jdbc.ConnectionImpl@316d65af (No operations allowed after connection closed.). Possibly consider using a shorter maxLifetime value. 
2023-04-18 08:01:12.347  WARN 20 --- [nio-8080-exec-9] com.zaxxer.hikari.pool.PoolBase          : HikariPool-3 - Failed to validate connection com.mysql.cj.jdbc.ConnectionImpl@5a179137 (No operations allowed after connection closed.). Possibly consider using a shorter maxLifetime value. 
2023-04-18 08:01:12.348  WARN 20 --- [nio-8080-exec-2] com.zaxxer.hikari.pool.PoolBase          : HikariPool-3 - Failed to validate connection com.mysql.cj.jdbc.ConnectionImpl@4cf3ac6d (No operations allowed after connection closed.). Possibly consider using a shorter maxLifetime value. 
2023-04-18 08:01:12.348  WARN 20 --- [nio-8080-exec-9] com.zaxxer.hikari.pool.PoolBase          : HikariPool-3 - Failed to validate connection com.mysql.cj.jdbc.ConnectionImpl@2bbf9bb6 (No operations allowed after connection closed.). Possibly consider using a shorter maxLifetime value. 
2023-04-18 08:01:12.348  WARN 20 --- [nio-8080-exec-2] com.zaxxer.hikari.pool.PoolBase          : HikariPool-3 - Failed to validate connection com.mysql.cj.jdbc.ConnectionImpl@38a2e068 (No operations allowed after connection closed.). Possibly consider using a shorter maxLifetime value. 
2023-04-18 08:01:12.349  WARN 20 --- [nio-8080-exec-9] com.zaxxer.hikari.pool.PoolBase          : HikariPool-3 - Failed to validate connection com.mysql.cj.jdbc.ConnectionImpl@1ed2242a (No operations allowed after connection closed.). Possibly consider using a shorter maxLifetime value. 

원인

원인은 이미 예상했듯 커넥션 누수다.

Application의 HikariCP의 maxTimeOut으로 인해 커넥션 연결을 끊기도 전에 MySQL에서 wait_timeout으로 인해 연결을 끊어버리면 위와 같이 커넥션 누수가 발생한다.

  • HikariCP와 Tomcat-dbcp 철학이 달라서 발생한 문제라고 한다.
    • HikariCP는 Tomcat-dbcp와 달리 사용하지 않는 Connection을 빠르게 회수하도록 설계
    • Tomcat-dbcp는 지속적으로 DB에 Validation Query를 보내서 커넥션이 끊어지지 않도록 설계

HikariCP

아래는 PoolBase.isConnectionAlive() 메서드이다.

HikariConfig의 maxLifeTime이 끝나면 커넥션 풀에서 해당 커넥션을 종료 후 리소스(메모리)도 해제한다. 그리고 새로운 커넥션 객체를 생성해서 커넥션 풀에 추가한다.

img.png

중요한 점wait_timeout으로 인해 DBMS에서 이미 커넥션을 닫았다면 HikariCP는 어떤 행위도 할 수 없다. 로그만 찍어줄 뿐이다.

즉, DBMS에서 wait_timeout으로 커넥션을 끊기 전에 HikariCP의 maxLifeTime으로 커넥션을 해제해야 한다.

해결 방법 (알려진 솔루션)

아래는 이 문제를 해결하는 잘 알려진 솔루션이다.

1. maxTimeOut 조정

HikariCP에서는 maxTimeOut을 DB의 wait_timeout보다 2~3초 낮게 설정하는 것을 권장한다.

문제는 현재 MySQL 운영 서버의 wait_timeout이 15초이고, HikariCP의 maxTimeOut의 최솟값이 30초이다.

private void validateNumerics(){
    if(maxLifetime!=0&&maxLifetime<SECONDS.toMillis(30)){
        LOGGER.warn("{} - maxLifetime is less than 30000ms, setting to default {}ms.",poolName,MAX_LIFETIME);
        maxLifetime=MAX_LIFETIME;
    }
    // ... 생략
}

HikariCP는 maxTimeOut을 30초보다 낮게 잡으면 Default인 30분으로 강제로 설정한다.

  • HikariCP에서 maxTimeOut이 너무 낮으면 성능 저하나 커넥션 끊기는 이슈가 발생을 우려했다고 한다.

결국 해당 부분은 라이브러리를 교체하거나 내부를 뜯어고쳐야 한다. 권장되지 않는 방법이라서 적용하지 않았다.

2. wait_timeout 조정

MySQL 서버의 wait_timeout을 조금 더 높게 수정을 하면 이를 해결할 수 있다.

하지만 개발 운영팀에서는 기존의 PHP 레거시 코드 때문에 wait_timeout을 높이지 못한다는 답변을 받았다.

  • 기존에 존재하는 PHP 프로젝트의 특성상 커넥션을 맺고 커넥션을 닫지 않고 종료되는 일이 너무 많다.
  • 그 경우 빨리 커넥션을 끊지 않으면 성능이 크게 저하되다가 서버가 터질 수 있다고 함

3. autoReconnect 옵션을 설정

HikariCP의 JdbcUrl의 autoReconnect 파라미터를 true로 설정할 수 있다.

단, 해당 부분은 트랜잭션이 진행중일 때 연결이 끊기면 즉시 커밋되는 이슈가 있어서 정합성에 문제가 생겼다.

결국 이 방법도 적용할 수 없었다.

적용한 방법

다음으로 선택한 방법이 세션의 wait_timeout을 설정하는 방법이다.

wait_timeout 설정도 GLOBAL 설정이 있고, SESSION 설정이 있었다.

즉, SpringBoot 앱에서 MySQL 서버로 연결할 때 세션의 wait_timeout을 바꿀 수 있다면 해결할 수 있지 않을까..? 하는 생각이었다.

hikari:
  pool-name: HikariCP
  maximum-pool-size: 10
  connection-timeout: 10000
  validation-timeout: 10000
  max-lifetime: 580000
  # Session wait_timeout 수정
  connection-init-sql: set wait_timeout = 600

spring.datasource.hikari.connection-init-sql 프로퍼티를 사용하면 Connection 객체가 생성될 때 세션 wait_timeout을 수정할 수 있다.

문제가 생긴 프로젝트의 경우 다중 데이터 소스를 사용하고 있어서 아래와 같이 설정할 수 있었다.

if(hikariConfig.getDriverClassName().equals("com.mysql.cj.jdbc.Driver")) {
    long waitTimeOut = TimeUnit.MILLISECONDS.toSeconds(hikariConfig.getMaxLifetime()) + 5;
    hikariConfig.setConnectionInitSql(String.format("SET SESSION wait_timeout = %s", waitTimeOut));
}

세션의 wait_timeout을 HikariPool의 maxLifeTime보다 5초 더 높게 설정했다.

결과적으로 더 이상 커넥션 누수가 발생하지 않았고 maxLifeTime을 늘리라는 경고가 나타나지 않았다. 성공적으로 적용을 완료할 수 있었고 현재도 문제 없이 운영 중이다!

참고