2024-12-16T08:00:30.000Z WARN 1 --- [ scheduling-1] o.h.engine.jdbc.spi.SqlExceptionHelper : SQL Error: 0, SQLState: 08S01
2024-12-16T08:00:30.001Z ERROR 1 --- [ scheduling-1] o.h.engine.jdbc.spi.SqlExceptionHelper : HikariPool-1 - Connection is not available, request timed out after 30000ms (total=0, active=0, idle=0, waiting=0)
2024-12-16T08:00:30.001Z ERROR 1 --- [ scheduling-1] o.h.engine.jdbc.spi.SqlExceptionHelper : Communications link failure
The last packet sent successfully to the server was 0 milliseconds ago. The driver has not received any packets from the server.
2024-12-16T08:00:30.001Z ERROR 1 --- [ scheduling-1] o.s.s.s.TaskUtils$LoggingErrorHandler : Unexpected error occurred in scheduled task
java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[na:na]
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) ~[na:na]
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ~[na:na]
at java.base/java.lang.Thread.run(Thread.java:833) ~[na:na]
Caused by: org.hibernate.exception.JDBCConnectionException: Unable to acquire JDBC Connection [HikariPool-1 - Connection is not available, request timed out after 30000ms (total=0, active=0, idle=0, waiting=0)] [n/a]
com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:686) ~[HikariCP-5.1.0.jar!/:na]
at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:179) ~[HikariCP-5.1.0.jar!/:na]
at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:144) ~[HikariCP-5.1.0.jar!/:na]
at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:127) ~[HikariCP-5.1.0.jar!/:na]
at org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:122) ~[hibernate-core-6.5.3.Final.jar!/:6.5.3.Final]
오류 상황
- Bottler 1차 배포를 완료한 후 2차 작업을 위해 서비스를 확인하던 중 프론트에서 요청한 API호출이 되지 않았습니다.
- 서비스가 정상적으로 동작하다가 발생한 상황이었기에 서버 로그를 확인했습니다.
- 위 로그는 확인한 로그 중 핵심 상황으로 보이는 로그입니다.
로그를 보며 생각한 문제 상황
- 코드에 작성된 스케줄러가 정상적으로 수행되지 못했나?
- ec2와 rds를 재부팅을 시도해볼까?
- hikariCP의 커넥션 관련 설정 문제가 있는게 아닐까?
ec2와 rds 재부팅 시도
- 당장의 문제를 해결해야했기에 단순하게 ec2와 rds 재부팅을 시도했습니다.
- 재부팅 이후에도 문제는 여전했고 ec2와 rds연결 자체의 문제 혹은 네트워크 이슈가 있을 것이라고 생각했습니다.
HikariCP 커넥션 관련 설정 서치
- HikariCP 설정이 기본값으로 되어 있을 경우 Connection 문제로 인한 DeadLock상황이 발생할 수 있다는걸 확인했습니다.
- HikariCP에 대한 이해를 가져가야 문제가 재발해도 해결할 수 있다고 생각해서 HikariCP와 DeadLock 상황을 찾아봤습니다.
HikariCP 동작 방식
- hikari에게 connection을 달라고 Thread A씨가 요청을 합니다
- hikari는 A씨가 늘 앉던 자리가 비어있는지 확인합니다
- 자리가 비어 있다면 해당 자리로 안내하지만 자리가 차있다면 다른 자리가 있는지 확인합니다
- 아예 자리가 만석이라면 A씨에게 잠시 대기해달라고 말합니다
- A씨는 30초 정도는 기다릴 수 있다고 하고 없으면 나가겠다고 합니다.
- 30초 내에 자리가 비면 해당 자리로 안내받고 아니면 나가게 됩니다.
즉, 정상적인 작업으로는 [커넥션 할당 → 작업 완료 → 커넥션 반환 → 풀에 저장] 인데
저희 문제 상황에서는 [RDS 연결 실패 → 커넥션 할당 불가 / 커넥션 반환 누락 → 풀에 유효한 커넥션 없음]으로 커넥션이 고갈된게 아닐까 했습니다.
스케줄러에서의 문제상황 확인
//RecommendationScheduler
public void processAllUserRecommendations() {
List<Long> userIds = userService.getAllUserIds();
userIds.forEach(asyncRecommendationService::processRecommendationForUser);
}
// AsyncRecommendationService
@Async
public void processRecommendationForUser(Long userId) {
List<String> keywords = userKeywordService.getKeywordsByUserId(userId);
List<Long> letterIds = letterBoxService.findReceivedLettersByUserId(userId);
List<Long> recommendedLetters = recommendService.getRecommendedLetters(keywords, letterIds, RECOMMENDATION_LIMIT);
redisLetterService.saveRecommendationsTemp(userId, recommendedLetters);
CompletableFuture.completedFuture(null);
}- HikariCP의 동작 방식을 고려하면 비동기 작업을 수행하는 스케줄러에서 문제가 발생할 수 있다고 생각했습니다
- processAllUserRecommendations를 보면 forEach를 통해서 한번에 모든 유저에 대한 작업을 호출하고 있는데 유저가 많아질 경우 forEach에 많은 유저에 대한 작업이 묶이게 된다고 생각했습니다.
- 실제로 개별로 테스트를 진행할 때는 문제가 없었으나 실제 사용자가 계정을 생성하게 되면서 문제가 발생하게 됐습니다.
- 비동기 작업의 스레드 풀 크기 제어와 HikariCP의 커넥션 풀 설정을 적절하게 설정해야하지 않을까 생각했습니다.
HikariCP DeadLock을 피하는법
- HikariCP wiki에서는 이 공식대로 Maximum pool size를 설정하면 Dead lock을 피할 수 있다고 합니다.
- 그러면 비동기 작업에서 사용하는 쓰레드풀도 이에 맞춰서 커스텀 설정을 해줘야 하는게 아닌가 생각했습니다.
- HikariCP 공식
- Optimal Pool Size=(CPU 코어 수×2)+보정값(1)
- CPU 코어 수: 1 (t2.micro 기준)
- 보정값: 보통 1~2로 설정
비동기 쓰레드 풀 설정에 관해서
비동기 작업 → 커넥션 풀 사용
- 비동기 작업 실행
- 스레드 풀에서 새로운 스레드가 생성됩니다.
- 각 스레드가 데이터베이스 작업을 요청하면 HikariCP 커넥션 풀에서 커넥션을 할당받습니다.
- 커넥션 반환
- 작업이 완료되면 커넥션은 HikariCP에 반환됩니다.
- 반환이 늦어지거나 누락되면 커넥션 풀 고갈로 문제가 발생합니다.
현재의 스케줄러에서의 고갈 원인 예상
- 쓰레드 풀의 크기가 커넥션 풀의 크기보다 큼
- 비동기 메서드에서 트랜잭션 반환이 보장되지 않음 => 예외 발생시 롤백되면서 커넥션 반환에 실패할 수 있음
- forEach 에서 한번에 많은 요청으로 인한 빠른 커넥션 고갈
최종 문제 상황 예상
- forEach 반복문이 빠르게 @Async 메서드를 호출
- 각각의 메서드들은 각 호출마다 쓰레드 풀에서 새 쓰레드를 할당 (기본 쓰레드 풀은 무제한 쓰레드를 생성할 수 있음)
- 동시 실행 스레드 수가 HikariCP의 최대 커넥션 풀을 초과
- user 1000명, maximum-pool-size = 10 이면 나머지는 대기하다가 타임아웃 발생 가능성이 높아짐
- 비동기 작업에서 예외를 잡아주지 않아 쓰레드가 계속 예외를 삼키고 계속 점유 => HikaiCP 커넥션 풀에 커넥션 반환x => 데드락 유발
- 현재 등록된 사용자를 고려해 봤을 때 타임아웃 보다는 비동기 작업에서 예외를 잡아주지 않는 것과 커넥션 풀 설정 문제로 추측됌
- 사용자가 많아질 것을 고려하여 배치 처리를 해서 동시 작업 수를 제어하는게 좋아보임
서비스 시점에서의 문제 상황 예상
- foreach를 통해서 디폴트로 설정된 hikariCP에서 작업을 하는데 설정된 커넥션풀보다 많은 예외가 나와서 데드락 상태가 걸림
- 더이상 추천할 편지가 없으면 오류가 나지만 그냥 넘기며 예외를 잡아주지 않음
- 해결 방법은 수동으로 커넥션 풀을 설정하고 이에 맞춰 배치처리하고 예외를 던지진 말고 로그로 캐치 처리
최종 해결 방안 예상
- HikariCP와 커넥션 풀을 일치 시켜 race-condition을 방지 => 각각 커스텀 설정
- 비동기 작업에서 예외 처리 추가
- 배치처리 도입
HikariCP 설정
- 현재 t2.micro 프리티어 ec2 1개 사용중
- CPU 1개
- rds max-connections: 151
- 전체 max_connections의 약 10~20%**를 사용하는 것이 적절
- 15 커넥션 이내가 적당
spring:
datasource:
hikari:
maximum-pool-size: 4 # HikariCP 최대 커넥션 풀 크기
minimum-idle: 1 # 최소 유휴 커넥션 수
idle-timeout: 30000 # 유휴 커넥션 반환 시간 (30초)
max-lifetime: 1800000 # 커넥션 최대 수명 (30분)
connection-timeout: 30000 # 커넥션 대기 타임아웃 (30초)
스레드풀 설정
spring:
task:
execution:
pool:
core-size: 4 # 최소 스레드 수 (HikariCP와 동일)
max-size: 4 # 최대 스레드 수 (HikariCP와 동일)
queue-capacity: 50 # 대기 큐 크기
shutdown:
await-termination: true # 종료 시 남은 작업을 마무리
await-termination-period: 30s # 종료 대기 시간'Bottler' 카테고리의 다른 글
| [Bottler] 서비스 순환 참조 및 직접 참조 에 대해 고민한 점 (0) | 2024.12.16 |
|---|
