[Flicker] DB Connection Pool 고갈 장애 모니터링 및 해결 방안

 

Flicker 프로젝트에 모니터링을 붙이고 나니 그래프가 잘 그려지는 건 좋은데,

정작 아무 일도 안 일어나니 잘 동작하는 건지 알 수가 없었다.

 

그래서 일부러 장애를 만들어보기로 했다. 첫 번째 대상은 커넥션 풀로 정해 k6 부하테스트를 진행했다.

*프로젝트 링크 : https://github.com/sns-service

 

왜 커넥션 풀인가

Spring Boot는 HikariCP라는 커넥션 풀을 쓴다. DB 커넥션을 매번 새로 맺으면 비용이 비싸서, 미리 DB 커넥션을 여러 개 만들어두고 돌려쓰는 구조다. (기본 10개)

문제는 이 10개가 다 쓰이는 중일 때다. 11번째 요청이 오면 누군가 커넥션을 반납할 때까지 기다린다. 반납이 안 되면? 설정된 시간(기본 30초)만큼 기다리다 예외를 던진다. 이게 커넥션 풀 고갈이다.

 

1차 시도 — 안 터졌다

단순하게 풀 사이즈를 10에서 3으로 줄이고, k6로 동시 접속 50명을 때린다.

export const options = {
  stages: [
    { duration: '20s', target: 50 },
    { duration: '2m',  target: 50 },
    { duration: '20s', target: 0 },
  ],
};

 

결과:

총 요청:      20456
실패 요청:    0
평균 응답:    43ms
최대 응답:    7568ms

 

실패가 0이고 평균 43ms로 멀쩡하다.

그런데 최대 응답이 7568ms, 7.5초로 나왔다. 대부분 빨랐는데 일부가 7.5초까지 걸렸다는 뜻으로, 커넥션을 기다린 요청이 있긴 있었다. 다만 30초 안에 결국 받아내서 실패로는 안 잡힌 거다.

 

이유를 생각해보니 쿼리가 너무 빨랐다. /api/feeds/random이 밀리초 단위로 끝나니까 커넥션을 금방 반납한다.

3개로도 50명을 돌려막을 수 있었던 거여서, 부하가 부족한 거였다.

 

2차 시도 — 풀 1개, 200명

확실하게 터뜨리기로 했다. 풀 사이즈를 1로, 동시 접속을 200으로 설정

총 요청:      12292
실패 요청:    416
평균 응답:    1988ms
p95 응답:     2880ms
최대 응답:    7384ms

 

이번엔 터졌다. 평균 응답이 43ms에서 1988ms로 47배 뛰었다.

실패도 416건으로, k6가 thresholds crossed를 뱉으면서 빨간 글씨로 SLA 위반을 알렸다.

 

K6 콘솔

 

CloudWatch 그래프

CloudWatch > Dashboards > flicker-overview (5개 지표)

 

1. CPU Utilization

 

2. Target Response Time

 

3. Database Connections

 

그래프가 말해준 것

CloudWatch 대시보드를 보는데, 세 개의 선이 각각 다른 얘기를 하고 있었다. EC2 CPU는 부하 구간에 20%까지 치솟았다. (평소 1% 미만이던 게)

 

커넥션을 기다리는 톰캣 스레드들이 쌓이면서 CPU를 점유한 것으로 보인다. 

 

응답시간도 2초까지 올라갔다.

그런데 RDS 커넥션 수는 1을 계속 유지했다.

 

이 세 번째가 제일 인상적이었다. "DB에 부하가 걸렸다"고 하면 커넥션 수가 늘어날 거라 생각했는데, 풀 사이즈가 1이면 커넥션은 1을 넘지 못한다. 그게 상한이니까.

DB는 한가한데 애플리케이션(쓰레드)이 커넥션을 못 얻어서 줄 서 있는 상황이다. 따라서 EC2 CPU 사용률이 증가했다.

 

만약 이게 실제 장애였다면, 이 그래프 조합만으로 원인을 좁힐 수 있었을 것 같다. 커넥션은 평평한데 응답만 느리면? 풀 사이즈가 부족을 의심해볼 수 있다. 지표 하나가 아니라 여러 개의 관계를 봐야 안다는 걸 배웠다.

 

로그가 안 남는 문제

원인을 확정하려면 로그가 필요해서 HikariCP가 커넥션을 못 주면 Connection is not available 같은 걸 남길 텐데, CloudWatch Logs에서 아무리 검색해도 안 나왔다.

원인은 k6의 요청 타임아웃을 10초로 걸어놨는데, HikariCP의 커넥션 타임아웃은 기본 30초이다. 그러니까 이런 순서가 됨:

1. 요청이 커넥션을 기다린다
2. 10초 지나면 k6가 먼저 포기하고 연결을 끊는다 (실패로 기록)
3. HikariCP는 아직 30초를 안 채웠으니 에러를 안 던진다

클라이언트는 실패했는데 서버 로그엔 흔적이 안남는 상황이다. 그래서 HikariCP 타임아웃을 3초로 줄이고, k6 타임아웃을 30초로 늘렸다. 이제 서버가 먼저 3초 만에 포기하고 로그를 남겨 족적을 볼 수 있게 되었다.

 

다시 부하를 주니 로그가 떴다.

 

CloudWatch > Live Tail 

 

SQLTransientConnectionException. Transient는 일시적이라는 뜻이다.

DB가 죽은 게 아니라 "지금은 커넥션을 못 준다"는 뜻으로, 풀 이름(FlickerHikariCP)까지 찍혀서 풀 고갈 에러가 난 것이다.

 

request time out after 5157 ms : 5.1초가량 기다리다 포기

내가 설정한 HIKARI_TIMEOUT = 3000 보다 조금 긴데, 대기 큐 처리 시간 감안하여 정상 범위라고 한다.

 

고치기

해결은 간단하다. 풀 사이즈를 다시 10으로 올렸고, 그리고 똑같은 200명 부하를 다시 줬다.

총 요청:      48598
실패 요청:    0
평균 응답:    277ms
p95 응답:     731ms
처리량:       303/s

 

 

풀 사이즈를 10으로 되돌리고 같은 부하를 다시 줬더니 실패 0건, 처리량은 4배가 됐다.

 

결론

이번에 얻은 결론은, 톰캣 스레드 풀 수치와 DB 커넥션 풀 수치는 따로 정하면 안 되고 같이 맞춰야 한다는 것이다.

 

스레드를 200개 열어놓고 커넥션을 10개만 주면, 190개는 항상 대기할 위험을 안고 있는 셈이다. 반대로 커넥션만 잔뜩 늘리면 DB가 터진다. 두 수치의 비율이 시스템의 실제 동시 처리량을 결정한다.

적정값은 결국 부하 패턴과 DB 사양에 따라 정해야 하는 거라서  "우리 트래픽에선 이 정도"를 부하 테스트로 찾아야 한다.

 

다음엔 Prometheus를 붙여서 JVM과 스레드 상태를 안쪽에서 들여다볼 생각이다. 스레드 풀과 커넥션 풀의 관계를 이번엔 그래프로 직접 보고 싶다.