CompletableFuture로 인한 DeadLock 해결 (Hikari Pool Error)

김예지·2024년 2월 19일

트러블슈팅

목록 보기

4/4

문제 원인

레시피 업로드 로직을 개선한 후, 50명이 동시에 업로드를 요청하는 테스트를 진행하였다.

레시피 업로드 시 멀티스레드를 사용하는데, 이전보다 처리 속도가 (10명 동시 업로드 기준) 34배정도 ~~PM 설득해서 바꾸길 잘함~~ 빨라지니 초반에는 잘 동작하는 듯 하다가 Hikari Pool이 부족하다는 에러가 발생했다.

Feb 17 13:46:54 ip-10-0-2-172 web[2251]: Caused by: java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30000ms.
Feb 17 13:46:54 ip-10-0-2-172 web[2251]: #011at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:696)
Feb 17 13:46:54 ip-10-0-2-172 web[2251]: #011at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:197)
Feb 17 13:46:54 ip-10-0-2-172 web[2251]: #011at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:162)
Feb 17 13:46:54 ip-10-0-2-172 web[2251]: #011at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128)
Feb 17 13:46:54 ip-10-0-2-172 web[2251]: #011at org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:122)
Feb 17 13:46:54 ip-10-0-2-172 web[2251]: #011at org.hibernate.internal.NonContextualJdbcConnectionAccess.obtainConnection(NonContextualJdbcConnectionAccess.java:38)
Feb 17 13:46:54 ip-10-0-2-172 web[2251]: #011at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:108)
Feb 17 13:46:54 ip-10-0-2-172 web[2251]: #011... 92 more

Hikari Pool Log

먼저, Hikari Pool의 로그를 확인하기 위해 application.yml에 로깅 설정을 해주었다.

spring:
  datasource:
    hikari:
      leak-detection-threshold: 3000
      #최소 2초(2000ms) ~ 최대 30분으로 누수 판별 기준 값 설정.
      #해당 시간이 지나면 누수 의심 로그를 출력한다.
      #누수가 의심된 connection이 반환되면, 잘 반환했다는 정정 로그를 출력한다.

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

생성된 HikariPool의 Connection 개수는 총 10개. 현재는 10개 모두 idle 상태인 것을 알 수 있다.

HikariPool-1 - Pool stats (total=10, active=0, idle=10, waiting=0)

문제 파악

1. Pool 누수?

3,000ms 내에 release되지 않아 누수 의심 로그가 출력된 Connection이 있었지만, 이후 전부 다 잘 반환되었다는 정정 로그를 받았다.
결국 Pool이 누수되는 곳은 없었다.

2. 데드락 발생

2024-02-19 14:04:38.407 ERROR 26412 --- [onPool-worker-7] o.h.engine.jdbc.spi.SqlExceptionHelper   : HikariPool-1 - Connection is not available, request timed out after 30002ms.
2024-02-19 14:04:38.710 DEBUG 26412 --- [nPool-worker-31] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Timeout failure stats (total=10, active=10, idle=0, waiting=10)
2024-02-19 14:04:38.710  WARN 26412 --- [nPool-worker-31] o.h.engine.jdbc.spi.SqlExceptionHelper   : SQL Error: 0, SQLState: null
2024-02-19 14:04:38.710 ERROR 26412 --- [nPool-worker-31] o.h.engine.jdbc.spi.SqlExceptionHelper   : HikariPool-1 - Connection is not available, request timed out after 30005ms.

위의 로그 기록을 살펴보면 Hikari Pool이 부족해진 이유를 짐작할 수 있다.

해당 로그는 한번만 출력된 것이 아니라, 총 50건의 요청에 대해 Timeout failure stats (total=10, active=10, idle=0, waiting=41)부터 시작하여 Timeout failure stats (total=10, active=10, idle=0, waiting=10)이 될 때까지 request timed out after 3000*ms를 반복하며 출력되었다.

여기서 두 가지 해결해야 할 부분이 발생한다.

50건의 요청을 했는데, 왜 active=10, waiting=41 총 51건의 DB connection이 요청되었는가. @Transactional 내에서는 하나의 connection을 유지하지 않나?
active중인 connection의 동작이 완료 후 pool로 반환되어 waiting개수가 줄어든 것이 아니라, reqeust timed out으로 인해 waiting 중인 요청들이 Exception을 내고 도망(?)을 간 상태이다.

(2.)번 상황을 통해, active중인 connection들이 자원을 release 하지 못하는 Deadlock이 발생했다는 것을 유추할 수 있다.

Deadlock이 발생한 이유는 (1.)번에서 총 51건의 connection이 발생한 원인을 살펴보면 될 것이다.
자. 문제의 원인을 이해하려면, 먼저 HikariCP의 동작 방식에 대해 알아야 한다.

HikariCP의 동작 방식

https://techblog.woowahan.com/2664/
우아한 기술블로그에 비슷한 트러블슈팅이 있어 참고하였다.

Thread가 HikariPool에 Connection을 얻을 때

HikariPool.getConnection()

(특정한 Thread-1이 connection을 요청하는 상황이라고 가정한다.)

Thread-1이 HikariCP에 Connection을 요청한다.
HikariCP는 Thread-1가 이전에도 요청했던 내역이 있는지 확인한다.
Thread-1가 HikariCP를 이전에 사용한 적이 있다면, 그 때 할당했던 Connection이 사용 가능한 상태인지 확인한다. 다른 Thread가 해당 Connection을 점유(active)하고 있지 않다면, Thread-1에게 해당 Connection을 할당한다.
그 외의 경우, HikariCP는 Pool에서 Loop를 돌며 사용 가능한(idle) Connection이 있는지 찾는다.
idle 상태인 Connection이 없다면, Thread-1은 handoffQueue에서 다른 Thread가 Connection을 반납하기를 대기한다.
handoffQueue에서 30,000ms 대기 후에도 Connection을 할당받지 못하면 Exception을 던진다.

Thread가 HikariPool에 Connection을 반환할 때

 (ProxyConnection) Connection.close()

Thread-1이 commit을 마치고 (ProxyConnection) Connection.close()를 실행한다.
HikariCP가 해당 Connection의 상태를 idle로 변경한다.
handOffQueue에 할당을 대기중인 Thread에 해당 Connection을 할당한다.
이번에 사용한 Connection을 Thread-1의 이용 내역(Thread local 내의 list value)에 추가한다.

문제 발생 위치

그런데 만약, Service에서 @Transactional로 Connection을 하나 얻은 상황에서

같은 Service 내에 새로운 DB 커넥션이 생기면 어떻게 될까?

Hikari의 maximum-pool-size가 10개(default)인 상황에서 한 개의 요청만 들어왔다면, 필요한 Connection은 2개므로 정상적으로 동작할 것이다.

그러나, 요청이 동시에 10개가 들어왔고 @Transactional이 getConnection()으로 이미 10개의 Connection을 모두 점유한 상태라면?

각 Thread의 두번째 getConnection()은 handOffQueue에 들어가@Transactional이 Connection을 반환하기를 Wait하는 상태가 될 것이다.

그러나, @Transactional의 Connection은 모든 로직이 수행된 후 반환되므로, active 상태로 로직이 다 수행되기만을 기다리는 Deadlock이 발생한다.
wait 상태였던 두 번째 Connection 요청들은 모두 30,000ms가 지나 Exception을 반환한다.

이후 @Transactional의 Connection도 active 상태에서 어떠한 행동도 취하지 않으니, 결국 HikariCP가 해당 연결을 풀에서 회수한다.

물론, 여러 클라이언트에서 동시에 요청이 들어올 때 위의 예시처럼 모든@Transactional이 한 번에 모든 Connection을 소비하지는 않을 것이다.

일부 Thread는 2번째 Connection까지 연결되어 정상적으로 동작하겠으나, 해당 상황이 누적되어 모든 @Transactional이 Connection을 차지하면 언제든 Deadlock이 발생할 수 있다.

내 경우 Timeout failure stats (total=10, active=10, idle=0, waiting=41)가 그 시점이었던 것이다.

Pooling-locking

사실 이 문제는 이미 HikariCP에 issue로 등록되어, 해결 방법이 제시되어 있다.
https://github.com/brettwooldridge/HikariCP/wiki/About-Pool-Sizing

Tn은 전체 Thread 개수(위의 예시에서는 10개)
Cm은 각각의 Thread에서 동시에 필요한 Connection 수이다.(예시에서 2개)

위의 예시로는, 10 * (2 - 1) + 1 = 11 총 11개의 Connection이 있다면 Deadlock은 발생하지 않는다.

하지만, 위의 값은 Deadlock이 발생하지 않을 최소의 Connection 값이므로 +1대신 적절한 값 만큼 +n을 더해줄 수 있다.

해결 과정

위의 내용을 바탕으로 생각해보면, 내 코드에서도 Service에서 두 번 이상의 DB 연결이 발생한다는 결론이 나온다.

정말? 도대체 어디서..?

먼저 maximum-pool-size를 1로 설정해 내 코드에서 정말 두 개 이상의 커넥션이 요청되는지 확인한다.

spring:
  datasource:
    hikari:
      maximum-pool-size: 1

application.yml을 구성하고 한번의 요청을 보낸다.

1. maximum-pool-size: 1인 경우

HikariPool-1 - Timeout failure stats (total=1, active=1, idle=0, waiting=0)
SQL Error: 0, SQLState: null
HikariPool-1 - Connection is not available, request timed out after 30009ms.

@Transactional말고 누군가 새로운 Connection을 요청하다가, Time Out이 발생했다.

2. maximum-pool-size: 2인 경우

HikariPool-1 - Pool stats (total=2, active=0, idle=2, waiting=0)
HikariPool-1 - Fill pool skipped, pool is at sufficient level.

문제 없이 잘 수행되었다.
이를 통해, 하나의 Service 내에서 최소 2번의 connection이 발생한 것을 확인할 수 있다.

해결

문제는 속도 개선을 해보겠다고 멀티 스레드를 추가한 데에서 발생했다.
코드 예시는 아래와 같다.

CompletableFuture<TestRecipe> savedRecipeFuture = 
    CompletableFuture.supplyAsync(() ->{
        TestRecipe buildRecipe = null;
        buildRecipe = RecipeConverter.toTestRecipeWithImageUrl(request);

        return testRecipeRepository.save(buildRecipe);
});

CompletableFuture 안에 Repository.save()가 있다..

기존 지식으로는 @Transactional은 처음부터 끝까지 한 개의 Connection을 쓰기 때문에, 병렬적인 코드를 구성하여도 한개의 Connection을 사용할 것이라고 생각했다.

막연히 경합 문제는 DB자체의 Lock이 해결해주지 않을까.. 라고 생각한 나의 잘못이었다.

@Transactional 내에서 CompletableFuture을 쓰면, 비동기로 처리되기 때문에 새로운 커넥션이 요구된다. 이 때문에 2번 이상의 DB 연결이 발생했다.

실제로, Repository.save()가 발생하는 부분의 CompletableFuture를 제거하니, maximum-pool-size: 1인 상황에도 로직이 정상적으로 동작했다.

그럼.. 이전에 실패했던 50개 업로드는 이제 정상 동작할까?

빠르고 아름답게 성공...

결론 및 제안

이 공식을 사용해 어떻게든 CompletableFuture을 넣어보고 싶었으나, 사용자의 동시 요청 수를 예측할 수 없으므로 이 경우에는 공식을 적용할 수 없다고 판단하였다.

대신, 추후 MQ 등을 적용하며 요청될 최대 Thread 개수가 제한적인 상황일 때 HikariCP의 max-pool-size를 최적화 하여 사용할 수 있을 것이다.

참고
https://saramin.github.io/2023-04-27-order-error/
https://techblog.woowahan.com/2664/

김예지

이전 포스트