배포하고 이틀 뒤 새벽이었다. 결제는 멀쩡히 되는데 마이페이지·주문내역 같은 조회 API가 간헐적으로 500을 뱉었다. 재현이 안 돼 더 골치였는데, 로그를 시간대로 잘라 보니 저녁 트래픽이 몰리는 20~22시에만 터졌다. 낮엔 하루 종일 멀쩡했다. 그 시간대 로그엔 이 줄이 도배돼 있었다.
HikariPool-1 - Connection is not available, request timed out after 30000ms풀에서 커넥션을 못 받고 connectionTimeout(기본 30초)을 다 기다리다 죽는 거다. 첫 생각은 뻔했다. 트래픽 늘었으니 풀이 작구나. maximumPoolSize가 기본값 10이었으니까. 그래서 30으로 올렸다. 그날 저녁은 넘어갔고, 이틀 뒤 같은 시간에 똑같이 터졌다. 그제야 인정했다. 커넥션 30개가 전부 물릴 정도면, 단순히 풀이 작은 게 아니라 누군가 커넥션을 쥐고 오래 안 놓는 거였다.
먼저 커넥션 풀이 뭘 하는지 정리하고 갔다
디버깅 전에 개념부터 다시 잡았다. 커넥션 풀은 미리 만들어 둔 DB 커넥션 몇 개를 돌려쓰는 창고다. 요청이 오면 창고에서 하나 빌려 쓰고, 끝나면 반납한다. HikariCP에서 이 동작을 좌우하는 값은 몇 개 안 된다. maximumPoolSize는 창고에 둘 수 있는 최대 커넥션 수, connectionTimeout은 빌리려고 기다리는 최대 시간(초과 시 위 에러), maxLifetime은 커넥션 하나의 수명, idleTimeout은 놀고 있는 커넥션을 정리하는 시간이다. 핵심은, 커넥션은 빌린 순간부터 반납할 때까지 다른 요청이 못 쓴다는 것. 그러니 반납이 늦으면 창고가 순식간에 빈다.
먼저 DB 탓이 아닌 걸 확인했다
습관적으로 슬로우 쿼리부터 의심했다. slow query log를 켜서 그 시간대를 봤는데 1초 넘는 쿼리가 하나도 없었다. 조회 쿼리는 다 수 ms짜리였고 DB CPU도 한가했다. maxLifetime이 DB의 wait_timeout보다 길어 끊긴 커넥션을 잡는 건 아닌지도 확인했는데 그것도 아니었다. 쿼리가 느린 게 아니라, 멀쩡한 쿼리를 감싼 커넥션이 반납이 안 되는 쪽이었다.
지표를 겹쳐 보니 그림이 나왔다
모니터링에서 hikaricp_connections_active(사용 중 커넥션 수)와 커넥션 평균 점유시간을 같은 그래프에 겹쳤다. 평상시 active는 2~3을 오갔는데, 터지는 구간에선 30에 딱 붙어 평평하게 눌려 있었다. 그리고 커넥션 하나를 쥐고 있는 평균 시간이 평소 수십 ms에서 1.8초까지 치솟아 있었다. 쿼리는 수 ms인데 점유가 1.8초라는 건, 커넥션을 잡은 채로 DB 일이 아닌 다른 뭔가를 1초 넘게 하고 있다는 뜻이었다.
leakDetectionThreshold로 범인을 찍었다
HikariCP엔 커넥션을 임계값보다 오래 쥐고 있으면 그 지점의 스택트레이스를 로그로 뱉어 주는 기능이 있다. 운영엔 부담이라 개발/스테이징에서 2초로 걸었다.
spring:
datasource:
hikari:
leak-detection-threshold: 2000켜자마자 스택이 올라왔다. at PaymentService.confirm(PaymentService.java:63). 63번 줄은 이랬다.
@Transactional
public void confirm(Long orderId) {
Order order = orderRepository.findById(orderId).orElseThrow();
order.markPaid();
pushClient.sendPaymentAlert(order.getUserId()); // 외부 HTTP 호출
}결제 완료 처리를 하면서 같은 트랜잭션 안에서 푸시 발송 API를 때리고 있었다. 이 API가 평소엔 200ms인데, 저녁에 푸시 벤더 응답이 느려지면 3~5초씩 걸렸다. @Transactional 안이니 DB 커넥션은 메서드가 끝날 때까지 반납되지 않는다. 결국 커넥션을 쥔 채로 남의 서버 응답을 3~5초씩 기다리고 있었던 거다.
로컬에서 그대로 재현해 봤다
확신을 얻으려고 재현했다. 스테이징에서 푸시 API 앞에 일부러 Thread.sleep(4000)을 넣고, 커넥션 풀을 10으로 줄인 뒤 부하 테스트로 초당 5건씩 결제를 때렸다. 15초쯤 지나자 active가 10에 붙었고, 20초 뒤부터 그 request timed out after 30000ms가 똑같이 떴다. 원인이 확정됐다.
왜 “풀을 더 키우기”가 답이 아니었나
풀을 100으로 올릴까 하다가 산수를 했다. 리틀의 법칙으로, 결제 피크가 초당 20건이고 건당 커넥션을 3초씩 쥔다면 동시에 필요한 커넥션은 20 × 3 = 60개다. 30으론 애초에 못 버틴다. 100으로 올리면 당장은 버티겠지만, DB의 max_connections를 위협하고 근본 원인인 점유시간은 그대로 둔 채 터질 시점만 미루는 것이었다. 풀 크기는 처방이 아니라 진통제였다.
고친 방식 — 왜 하필 AFTER_COMMIT인가
원칙은 하나. DB 트랜잭션 안에서 느린 외부 I/O를 하지 않는다. 알림은 결제가 확정된 뒤 보내도 되니 트랜잭션 밖으로 뺐다. 다만 그냥 @Async로 던지지 않고 @TransactionalEventListener의 AFTER_COMMIT을 골랐다.
@Transactional
public void confirm(Long orderId) {
Order order = orderRepository.findById(orderId).orElseThrow();
order.markPaid();
events.publishEvent(new PaymentConfirmed(order.getUserId()));
}
@TransactionalEventListener(phase = AFTER_COMMIT)
public void onConfirmed(PaymentConfirmed e) {
pushClient.sendPaymentAlert(e.userId());
}이유가 있다. 단순 비동기로 빼면 결제가 롤백되는 경우에도 알림이 먼저 나갈 수 있다. 취소된 결제의 완료 푸시가 가면 그건 그것대로 사고다. AFTER_COMMIT은 트랜잭션이 실제로 커밋된 뒤에만 리스너를 실행하니, 롤백되면 알림도 안 나간다. 발송 실패는 리스너 안에서 잡아 별도 재시도 큐로 넘겼다.
같은 함정이 나오는 다른 자리들
이 사건 뒤로 트랜잭션 안을 훑어보니 비슷한 지뢰가 더 있었다. 주문 저장 트랜잭션 안에서 이미지 파일을 S3에 업로드하던 코드, 정산 트랜잭션 안에서 외부 결제사 승인 API를 부르던 코드가 그랬다. 전부 커넥션을 쥔 채 네트워크를 기다리는 구조였다. 규칙을 하나 세웠다. 트랜잭션 안에서는 DB만 만진다. 외부 호출·파일 I/O·긴 계산은 트랜잭션 밖으로.
결과와 교훈
배포 후 커넥션 평균 점유시간이 1.8초대에서 40ms대로 떨어졌다. 피크에도 active는 5를 넘지 않았고, 그 30초 타임아웃 로그는 다시 보지 못했다. 풀 크기는 오히려 20으로 도로 내렸다. 넉넉해서가 아니라 커넥션을 짧게 쓰니 20으로 충분했다. 커넥션 풀 튜닝의 8할은 크기가 아니라 점유시간이라는 것, 그리고 트랜잭션 경계 안에 외부 호출이 끼는 순간 이런 일이 생긴다는 것. 지금은 새 서비스를 붙일 때 개발 환경에선 leak-detection-threshold를 켜두고 시작한다.