에러 없이 서버가 죽는다고? 병렬 다운로드 환경에서 발생한 장애 대응기

date

Dec 11, 2024

slug

server-crashes-sliently-in-parallel-download

status

Published

들어가며

문제 상황

저희 팀에서는 외부 수주 사업 관리를 위한 솔루션 개발 프로젝트를 담당하고 있습니다. 사업 특성 상 외부 기관에 제출해야 하는 문서들이 많기 때문에, 사업 진행현황 및 결과물 등을 취합하여 다양한 엑셀 양식으로 export 할 수 있어야 한다는 핵심 요구사항이 있었습니다. 이 과정에서 만들어지는 엑셀 파일은 프로젝트 당 최대 10만 ~ 20만 건에 달합니다. 이렇게 만들어진 대량의 엑셀 파일을 압축하여 zip 파일로 담당자가 다운로드할 수 있어야 합니다.

의사결정 및 초기 구현

해당 요구사항을 구현하기 위해 두 가지 방법을 고려했습니다.

서버에서 전체 엑셀 파일 생성 및 압축 → 클라이언트에게 단일 zip 파일 다운로드 API 제공

서버에서 단일 엑셀 파일 다운로드 API 제공 → 클라이언트에서 병렬로 요청하여 받아온 뒤 압축

1번 방법은 서버 측 부담이 늘어나며, 2번 방법은 클라이언트 측 부담이 늘어납니다.

결론적으로는 2번 방법을 선택했습니다. 이유는 다음과 같습니다.

CPU Bound 작업에 부적합한 서버 스펙

현재 서버 스펙의 경우 ECS + Fargate 기반으로 기존 EC2 대비 낮은 CPU 리소스를 사용하고 있습니다 (개발서버 / 상용서버 기준 각각 0.5, 1vCPU)
따라서 이러한 무거운 워크로드의 경우 서버가 아닌 클라이언트의 컴퓨팅 파워를 통해 처리하도록 하면 더 효율적이라고 판단했습니다.

구현 공수 없이 누리는 병렬 처리의 이점

2번 방식의 장점 중 하나는 클라이언트 측에서 서버로 병렬적으로 요청을 보내기 때문에, 순차적으로 엑셀 파일을 만드는 1번 방식보다 (이론상 톰캣 쓰레드 풀의 개수만큼 배로 빠르게) 더 빠르게 작업을 완료할 수 있습니다.
1번 방식에서도 ThreadPoolExecutor + CompletableFuture 를 사용하여 비동기 병렬 처리가 가능하지만, 리소스 세팅의 복잡성이나, 모니터링의 어려움, 구현 복잡성 등의 문제로 당장의 고려 대상에서 제외했습니다.

서버 측 공수

이게 핵심인데요, 이 모든 것들을 감수하고 1번을 선택할만큼 서버 측 공수가 충분하지 않았습니다.

개발환경으로 배포 후 테스트 해본 결과 502 Bad Gateway와 함께 병렬 다운로드 중간에 별도 에러 알림 없이 배포된 ECS 컨테이너가 다운되는 현상이 발생했습니다.

문제의 원인을 찾아서 (1)

낮은 스펙으로 인한 OOM?

맨 처음 떠오른 원인은 과도한 병렬 요청으로 인한 OOM이었습니다.

현재 저희 인프라의 경우 ELB를 앞에 두고, ECS + Fargate 기반으로 배포하고 있습니다. 개발서버의 경우 비용 절감을 위해 0.5vCPU + 1GB 메모리 구성으로, 백엔드 배포 환경 치고는 상당히 빠듯한 스펙으로 운용하고 있습니다. 예전 대용량 엑셀 다운로드 기능 구현 시 OOM으로 크게 고통받았던 적이 있어서 이번에도 비슷한 이슈일 것이라고 생각했지만, Cloudwatch에서 관련 메트릭을 확인해본 결과 메모리 사용률은 40%대로 큰 문제 없이 유지되다가 갑자기 다운되는 것을 확인할 수 있었습니다.

번외로 Fargate 인스턴스의 경우 (특히 T계열의) EC2 인스턴스와 다르게 CPU 사용률 100%를 꽉 채워서 사용하더라도 괜찮습니다.

헬스 체크 엔드포인트에서의 문제 발생

스프링부트 애플리케이션에 대한 로그가 아닌, ECS 상에서 발생한 이벤트에 대한 로그를 확인할 수 있습니다.

로그를 보면 ECS가 해당 작업 컨테이너를 unhealthy 상태로 판단하여 종료 처리하고, 새로운 작업 컨테이너를 시작했다는 것을 알 수 있습니다. 그렇다면 왜 ECS가 unhealthy 상태로 판단했을까요?

AWS의 ALB(로드 밸런서)는 평가 규칙에 따라 요청을 라우팅할 타깃 그룹을 결정합니다. 이때 ALB가 라우팅할 수 있는 타깃 그룹으로 등록하려면 상태 검사(헬스 체크) 기준을 통과해야 합니다. 헬스 체크의 경우 일반적으로 HTTP 요청을 통해 200 응답을 받는 식으로 수행됩니다.

스프링부트의 경우 스프링부트 액추에이터를 통해 헬스 체크 엔드포인트를 구성할 수 있습니다. 기본적으로 /actuator/health 엔드포인트를 사용하지만, 보안 측면에서 커스텀 엔드포인트를 구성하는 걸 추천드립니다 (ex: /my-actuator/health).

해당 인스턴스가 타깃 그룹에 등록된 이후에도 AWS는 지속적으로 헬스 체크 엔드포인트로 요청을 보내서, 해당 인스턴스가 유효한지 확인합니다. 해당 컨테이너에서는 헬스 체크 엔드포인트로의 요청을 처리하는 과정에서 문제가 생겼기 때문에 200 응답을 받지 못하여 해당 인스턴스가 unhealthy 상태가 되었고, 컨테이너가 다운된 것입니다.

헬스 체크 응답이 느린데요?

그렇다면 헬스 체크 API에 어떤 문제가 생겼길래 200 응답을 내려주지 못한 걸까요?

가장 합리적인 추론은, 클라이언트에서 엑셀 압축을 위해 한 번에 200개의 병렬 요청을 보내면서 (뭔지 모를) 문제가 발생했고, 이 과정에서 헬스 체크 API가 영향을 받았다는 것입니다. 다시 한번 로그를 검토하는 과정에서, 헬스 체크 API와 관련된 로그를 확인할 수 있었습니다.

로그 내용으로 미루어보았을 때, 헬스 체크 응답에 13초라는 긴 시간이 소요되면서 경고 목적으로 로그가 출력되는 것으로 추정됩니다.

하지만 아직 아리송한 부분이 있습니다.

위에서 우리는 헬스 체크 엔드포인트로부터 200 응답을 받지 못했기 때문에 unhealthy 상태가 되었을 거라고 예상했습니다. 하지만 헬스 체크 API는 13초로 다소 지연되긴 했지만 아예 200 응답을 못 내려줄 정도는 아니었습니다. 요청이 지연되어서 타임아웃 문제가 발생했다고 하기엔, 13초는 그렇게까지 긴 시간은 아닙니다.

아무래도 unhealthy 판정 로직에 다른 무언가가 있는 것 같습니다. 이에 대해 알아봅시다.

팩트는 타깃 그룹이 건강해지고 있다는 거임

타깃 그룹이 healthy한 상태, 혹은 unhealthy한 상태로 판정되려면 어떤 기준이 필요할까요?

현재 문제의 원인이 되는 타깃 그룹의 헬스 체크 관련 옵션을 보겠습니다.

정상 임계 값 / 비정상 임계 값

healthy 상태로 판정되기 위해 연속으로 성공해야 하는 횟수를 말합니다. 여기서는 ‘2 연속 상태 검사 성공’ 이므로, 헬스 체크 API가 2연속으로 200을 응답하면 타깃 그룹은 healthy 판정을 받습니다.
반대로 unhealthy 상태로 판정되기 위해서는 타깃 그룹 등록 이후 헬스 체크 API 요청에서 2연속으로 실패해야 합니다.

제한 시간 ***

헬스 체크 API 요청을 몇 초 동안 기다릴 것인지를 지정합니다. 즉, 타임아웃 시간을 지정합니다.
여기서는 제한 시간이 2초이므로, 2초 동안 헬스 체크 API가 응답하지 않으면 ‘실패’ 처리됩니다.
이렇게 ‘실패’한 요청이 2회 이상이면, unhealthy 처리됩니다.

간격

헬스 체크 API를 어떤 주기로 요청할 것인지를 지정합니다. 여기서는 5초이므로, 5초마다 한번씩 상태를 검사합니다.

성공 코드

헬스 체크 API의 응답의 상태 코드를 지정합니다. 200이면 200 응답이 온 경우 ‘성공’으로 처리합니다.

현재 제한 시간은 2초이지만, 헬스 체크 응답에는 13초가 소요되었습니다. 즉, 타임아웃이므로 실패 처리됩니다. 5초 뒤 다시 헬스 체크를 보내지만, 마찬가지로 응답이 딜레이되어 타임아웃으로 실패합니다. 2번 연속 실패했으므로 해당 타깃 그룹은 unhealthy 처리되고, 컨테이너는 종료되었다가 다시 시작합니다.

문제의 해결책을 찾아서 (1)

헬스 체크 방식을 바꿔볼까요?

첫 번째로 생각해볼 수 있는 방법은, ‘제한 시간’을 늘리는 것입니다. 이렇게 하면 응답이 지연되더라도 제한 시간이 지나기 전까지는 타임아웃으로 판정되지 않습니다.

로그를 확인했을 때 헬스 체크가 최대 25초 ~ 30초까지 지연되는 것을 확인했습니다. 따라서 제한 시간을 넉넉하게 60초로 지정해보면 어떨까요?

제한 시간의 경우 간격보다 작아야 한다고 하네요. 생각해보니 그렇습니다. 5초 주기로 요청을 보내는데, 타임아웃을 60초로 잡으면 이상하잖아요? 첫 번째 요청이 최대 12번째 요청이 보내진 이후에야 실패 처리된다면 판정이 어려울 겁니다. 아무튼, 간격을 늘리면 해결될 일입니다.

두 번째 방법은, 연속 실패 횟수에 해당하는 ‘비정상 임계값’을 늘리는 것입니다.

최대값인 10개로 지정해봅시다. 그렇다면 9번째 요청까지 실패하더라도, 아직 healthy 상태로 존재하게 됩니다. 마지막 10번째 요청이 타임아웃 내에만 응답해준다면, 9번 연속 실패하더라도 카운트가 초기화됩니다.

그렇게 막 바꿔도 괜찮은가요?

사실 아닙니다.

ECS + Fargate 환경은 EC2 환경과 다르게 미리 사전에 프로비저닝된 인스턴스로 배포하는 것이 아니라, 배포 워크플로가 트리거되면 그때 Fargate 인스턴스를 프로비저닝하고, 이미지를 다운로드 받고, 컨테이너를 띄우는 방식이기 때문에, EC2나 ECS + EC2 구성에 비해 ECS + Fargate 구성은 배포 속도가 매우 느린 편입니다.

이때 배포된 인스턴스를 타깃 그룹에 등록하고, healthy 판정을 받는 것까지 워크플로에 포함되며, 이 단계는 전체 프로세스에서 상당히 큰 비중을 차지합니다. 생각해보세요. 간격 5초 + 2연속 성공 시 healthy 판정이라면 10초면 해당 단계가 완료됩니다. 기본값은 어떨까요? 간격 30초 + 5연속 성공 시 healthy 판정으로 150초가 소요됩니다. 즉 배포 최적화를 하지 않는 경우 2분 20초나 배포가 지연되는 것입니다.

이때 배포 최적화에 기여하는 값은 ‘간격’과 ‘정상 임계값’ 입니다. 따라서 해당 값은 최대한 변경하지 않아야 합니다. 위에서 우리가 헬스 체크 실패로 인한 unhealthy 판정을 위해서 조정할 수 있는 값은 ‘제한 시간’과 ‘비정상 임계값’ 이었습니다. ‘비정상 임계값’의 경우 최대치로 설정하더라도 문제 없습니다. 단 ‘제한 시간’의 경우 ‘간격’보다 작아야 하기 때문에, (건드리지 말아야 하는 값인) ‘간격’이 5초이므로 4초까지만 설정할 수 있습니다.

간격을 늘리면 제한 시간도 늘릴 수 있겠지만, 대신 배포 시간이 지연됩니다. 이슈 하나 해결하자고 배포를 느리게 만드는 건 썩 달갑지 않은 해결책입니다. 그러니 4초 + 10연속 실패로 지정해봅시다.

더 근본적인 원인 찾기

위와 같이 설정함으로써, 우리는 4초 * 10연속 실패 = 최대 40초까지 unhealthy 판정을 지연시켰습니다. 하지만 여전히 문제가 존재합니다. 40초가 지난 이후에도 계속해서 헬스 체크 API가 딜레이되면 어떡하죠? 모든 청크를 처리하는 데 40초 이상이 소요된다면 여전히 unhealthy 상태에 빠지게 될 겁니다.

확실하냐고요? 네.

그래프가 V자를 그리는 모습을 보실 수 있는데요, 최소 5초까지 떨어지는 걸 보실 수 있습니다. 저 지점이 “하나의 청크가 마무리되고, 다음 청크의 첫 번째 요청이 들어오는” 시점입니다. 그리고 청크의 첫 번째 요청은 가장 빠르게 처리될 것이므로, 개별 엑셀 API는 아무리 빨라도 5초는 걸린다는 걸 알 수 있습니다.

그리고 헬스 체크 응답 레이턴시는 각 엑셀 API 응답 레이턴시와 비슷한 경향성을 보입니다. 가령 엑셀 API 레이턴시가 10초라면, 헬스 체크 레이턴시도 9~11초 사이에 처리됩니다.

한편 헬스 체크가 실패 처리되기 위한 타임아웃은 4초이고 unhealthy 판정까지 40초가 걸립니다. 위 그래프에서 최소 1분 이상 처리 시간을 요구하므로, 위 해결책이 완전하지 않음을 알 수 있습니다. 실제로 기존 문제 상황이었던 1천 건 압축 케이스는 해결했지만, 1만 건 이상에서는 동일한 문제가 발생함을 확인했습니다.

그렇다면 다른 방법을 찾아야 합니다. 헬스 체크 실패 기준을 바꾸고 할 것이 아니라, 더 근본적인 해결책이 필요하다는 거죠.

왜 헬스 체크가 10초, 20초씩이나 딜레이되는 걸까요? 좀 더 빠르게 응답하게 만들 순 없나요?

더 근본적인 원인을 찾아봅시다.

문제의 원인을 찾아서 (2)

가설 세우기

저희 팀은 모든 API 응답 및 응답 레이턴시를 로그에 기록하고 있습니다.

전체 응답 딜레이 패턴을 시각화한 그래프를 보여드리겠습니다.

2000 ~ 3000 인덱스 사이 값에 대한 그래프만 모아 보면 이렇습니다.

가장 먼저 보이는 것은 요청 100개 단위로 반복되는 패턴입니다. 즉 청크 단위로 처리되는 것이 보입니다.

또한 하나의 청크를 처리할 때 딜레이는 선형적으로 증가한다는 것 역시 알 수 있습니다.

이 그래프로부터 어떤 정보를 얻을 수 있을까요?

먼저 헬스 체크 API 응답이 지연되는 이유는 자명합니다. 클라이언트에서 엑셀 API로 요청을 보낼 때 청크 단위로- 즉 동시에 여러 개의 요청을 보내기 때문에 지연이 발생하는 겁니다.

그렇다면 클라이언트에서 청크 크기를 너무 크게 잡았기 때문에 문제가 발생한 게 아니었을까요?

제가 세운 가설은 이렇습니다.

💡

시스템 내 존재하는 어떠한 병목 지점에서 한번에 처리할 수 있는 요청보다 더 많은, 청크 단위 요청이 들어온다.

그러면 이 요청들은 한번에 처리되지 못한 채, 큐에 쌓여서 대기하게 된다.

먼저 도착한 요청들은 금방 처리되지만, 뒤에 쌓인 요청들은 더 오래 기다려야 하기 때문에 위와 같은 패턴이 나타난다.

큐잉 딜레이?

즉 큐잉 딜레이입니다. 하지만 이런 질문을 던질 수도 있습니다.

Q) 원래 큐잉 딜레이는 위의 그래프처럼 선형적이지 않고, 아래처럼 지수적으로 증가하지 않나요?

https://networkengineering.stackexchange.com/questions/76468/questions-about-queuing-delay

그 말도 맞습니다. 아마 네트워크 책에서 위 그래프(La (패킷 길이 * 평균 도착률) / R (전송률)) 를 보셔서 그렇게 생각하셨을 거라고 생각합니다. 그리고 하나 정정하자면, 위 그래프는 지수함수가 아닌 쌍곡선 함수입니다. 잠시 네트워크 지식을 복습해보는 시간을 가져봅시다.

위에서 등장하는 x축 값, 즉 La / R 을 ‘트래픽 강도’ 라고 하는데요, 이 트래픽 강도가 1에 가까워질수록 큐에 패킷이 계속 쌓이면서 딜레이가 무한정 증가하게 됩니다.

먼저 i번째 패킷에 대하여 딜레이를 계산해보도록 합시다. 첫 번째 패킷은 지연 시간이 없습니다. 그리고 두 번째 패킷은 첫 번째 패킷을 기다려야 하므로 L/R 만큼 기다립니다. 즉 i번째에 도착한 패킷은 (i-1)L/R 만큼 기다리게 됩니다. 그렇다면 총 N개의 패킷에 대하여 평균 지연 시간은 다음과 같이 구할 수 있습니다.

그러므로 패킷 순서 n에 대하여 딜레이 시간은 n에 비례한다고 생각하실 수도 있습니다.

그런데 위 그래프는 쌍곡선 함수일까요?

위와 같이 딜레이를 계산하려면 한 가지 가정이 필요합니다.

바로 패킷들이 일정한 간격을 두고 도착해야 한다는 것입니다. (D/D/1 큐잉 모델)

현실에서는 이렇지 않을 가능성이 매우 높습니다.

이때 각 패킷은

매우 작은 확률을 가지고 → 전체 시간 대비 패킷 도착 시간은 매우 짧으므로

독립적으로 → 각 사용자들이 다른 사용자와 무관하게 네트워크를 사용하므로

도착합니다.

통계학에서는 이런 상황에서 푸아송 분포를 가정합니다.

이때 평균 대기 시간 W은 M/M/1 큐잉 모델 공식을 따릅니다.

이때 는 시스템이 얼마나 바쁜지를 나타내는 지표로, 서비스률 대비 입력률의 비율을 나타냅니다. 네트워크 사례에서는, 패킷 길이(L) * 패킷 도착률(a) / 전송률(R) = La/R 로 나타낼 수 있습니다. 즉 전체 패킷 길이를 시간 당 처리율로 나눈 것입니다.

이때 La/R 이 1로 가까워지면, 분모가 0으로 수렴하므로 W는 무한대로 발산합니다. 즉, 위의 그래프에서 봤던 것과 동일합니다.

반면 저희가 다루는 100개 배치 처리 사례는 도착 요청이 푸아송 분포를 따르지 않습니다. 또한, 100개 단위로 경계가 설정되어 지연 시간이 무한히 늘어나지 않습니다. 가령 청크 단위가 100개라면 최대 지연은 100 * n에 비례하는 값입니다. 즉, 우리가 실험한 그래프에서 봤던 것처럼 청크 인덱스에 따른 지연이 “선형적으로” 증가합니다.

범인 찾기 (1) - 스레드 풀 고갈

큐잉 딜레이로 인해 병목 지점이 될 만한 요소들은 많지 않습니다. 가장 먼저 생각나는 것은 스레드 풀입니다.

클라이언트 측 확인 결과 청크 크기는 100개로 잡고 있음을 확인했습니다.

그리고 톰캣의 최대 스레드 수는… 기본값이 200입니다.

즉 청크 100개는 충분히 처리할 수 있는 능력을 가지고 있습니다.

뭔가 이상하죠?

결국 톰캣 스레드 풀 사용 현황을 확인하기 위해 APM을 도입했습니다.

위 그래프를 봅시다.

최소 스레드 값은 10입니다. 즉 idle 상태인 스레드가 10개 존재하다가, 100개의 청크 요청이 한번에 들어오면 10개는 idle 상태의 스레드가 처리하고, 나머지 90개의 요청은 90개의 스레드를 생성하여 처리합니다. 그리고 요청이 처리됨에 따라 busy 상태의 스레드가 서서히 감소하는 것을 볼 수 있습니다.

애초부터 최대 200개의 요청이 동시에 들어오지 않기 때문에 스레드 풀은 전혀 문제가 될 일이 없었고, 이를 모니터링 결과를 통해 확인할 수 있었습니다.

그렇다면 진짜 범인은 누구일까요?

범인 찾기 (2) - DB 커넥션 풀 고갈

고민 끝에 같은 ‘풀’ 계열이 하나 더 떠올랐습니다. 바로 DB 커넥션 풀입니다.

HikariCP에 대한 통계 정보를 확인해봅시다.

네. 문제 원인은 바로 DBCP였습니다.

HikariCP는 기본적으로 10개의 커넥션 풀 사이즈를 가집니다. 이때 100개의 동시 요청이 들어오자 pending 상태인 커넥션이 100개로 치솟습니다. 그리고 각 청크의 처리가 수행되면서 점차 대기 중인 커넥션이 줄어드는 것을 볼 수 있습니다. 하지만 청크 뒷쪽의 요청은 큐잉 딜레이에 따라 점차 레이턴시가 증가하게 됩니다.

뒤에서 정상 작동하는 케이스의 메트릭 그래프를 스포 겸 미리 보여드리겠습니다.

요청 100개가 한번에 들어오면서 pending 그래프가 확 치솟는 것을 볼 수 있습니다. 그리고 큐에 쌓인 커넥션 요청이 점차 처리되면서 다시 낮아집니다. 하나의 청크가 전부 처리되면, 다음 청크 요청이 들어오면서 다시 100개로 치솟습니다. 모든 청크가 처리될 때까지 이러한 요청이 반복됩니다. 그래프를 보시면 대략 10000개 이상의 엑셀 파일을 처리했음을 알 수 있습니다.

실제 로그 패턴을 분석하더라도 위와 같이 청크 하나를 처리할 때까지 레이턴시가 증가하다가, 청크 하나가 끝나면 다시 레이턴시가 뚝 떨어지는 것을 볼 수 있었습니다.

더더 근본적인 원인 찾기

원래 이야기로 돌아와서, 우리는 스레드 풀이 아닌 DB 커넥션 풀이 문제라는 것을 파악했습니다. 그러면 헬스 체크가 지연되는 문제의 원인 역시 다르게 파악해야 합니다. 단순히 많은 요청을 톰캣의 스레드 풀이 처리할 수 없어서 헬스 체크 API가 지연되었던 것이 아닙니다. 톰캣은 가능한데, DB 커넥션 풀이 감당할 수 없었던 것이죠.

여기서 궁금한 점이 하나 생깁니다.

우리가 생각하는 헬스 체크 API는 딱히 DB 엑세스를 필요로 하지 않습니다. 그런데 왜 헬스 체크가 DB 커넥션 풀 고갈에 영향을 받는 것일까요?

문제의 해결책을 찾아서 (2)

헬스 체크는 왜 DB 커넥션을 필요로 할까

정황상 헬스 체크가 DB 커넥션 풀을 필요로 하는 것은 확실해보입니다. 아니라면 DBCP 고갈로 인한 큐잉 딜레이의 영향을 헬스 체크 API가 같이 받을 리가 없겠죠.

헬스 체크 API의 경우 위에서 언급했듯 스프링 부트 액추에이터의 헬스 체크 엔드포인트를 통해 제공됩니다. 그렇다면 스프링 부트 액추에이터에 문제의 원인이 존재할 것입니다. 액추에이터 공식 문서를 확인해봅시다.

스프링 부트 액추에이터 (1) - 개요

액추에이터 공식 문서를 확인해봅시다.

예상하셨겠지만 스프링 부트 액추에이터의 헬스 체크 엔드포인트는, 단순히 스프링 부트 애플리케이션이 실행 중인지의 여부를 응답하는 것 이상의 역할을 합니다.

💡

헬스 정보를 사용하여 실행 중인 애플리케이션의 상태를 확인할 수 있습니다. 이는 종종 모니터링 소프트웨어에서 프로덕션 시스템이 다운될 때 누군가에게 경고하는 데 사용됩니다. 헬스 엔드포인트에서 노출되는 정보는 management.endpoint.health.show-details 및 management.endpoint.health.show-components 속성에 따라 달라지며, 다음 값 중 하나로 구성할 수 있습니다: never, when-authorized, always

기존 헬스 체크 엔드포인트는 "status": "UP" 정보만을 내려줍니다. show-details: always 로 설정해보고 다시 엔드포인트에 접근해봅시다.

액추에이터가 스프링부트 애플리케이션과 통합된 다른 컴포넌트의 상태- 여기서는 DB의 상태를 체크하는 것을 알 수 있습니다.

스프링 부트 액추에이터 (2) - DB 상태 체크

이중에서 DB 상태는 어떻게 체크할까요?

공식 문서의 Auto-configured HealthIndicators 섹션을 통해 알아봅시다.

db

DataSourceHealthIndicator

Checks that a connection to DataSource can be obtained.

액추에이터는 DataSourceHealthIndicator 로 DB 상태를 체크하고 있음을 알 수 있습니다. 이때 AbstractHealthIndicator 의 doHealthCheck 추상 메서드를 오버라이드하여 헬스 체크 방식을 구현할 수 있습니다. DataSourceHealthIndicator 의 경우 dataSource 프로퍼티가 null이 아닌 경우 private 메서드인 doDataSourceHealthCheck 를 통해 실제 헬스 체크를 수행합니다. 아래는 해당 메서드의 구현입니다.

validationQuery가 지정되어 있지 않으면 기본적으로 isConnectionValid() 를 통해 DB 상태를 검사합니다.

isConnectionValid 를 호출합니다.

Connection#isValid 를 통해 데이터베이스 상태를 검사합니다. 즉 헬스 체크 엔드포인트가 DB 커넥션을 필요로 하는 것을 알 수 있습니다.

위에서 isConnectionValid 는 timeout을 0으로 설정하여 커넥션 유효성을 검증합니다. 이때 0으로 설정되었다는 것은 isValid 의 자바독 주석에서 볼 수 있듯이 타임아웃을 적용하지 않겠다는 의미이므로, 커넥션 풀이 고갈된 상태에서는 계속해서 대기하게 되므로 헬스 체크 API 레이턴시가 다른 API의 경향성을 따라가게 되는 것이죠.

스프링 부트 액추에이터 (3) - 판정 로직

💡

해당 섹션은 스킵하셔도 괜찮습니다.

액추에이터는 자신의 상태를 어떻게 체크할까요?

💡

헬스 정보는 HealthContributorRegistry 의 콘텐츠로부터 수집됩니다 (기본적으로, 모든 HealthContributor 인스턴스들은 ApplicationContext 에 정의되어 있습니다). 스프링 부트는 auto-configured된 다수의 HealthContributor 들을 포함하고 있으며, 이를 직접 수동으로 작성할 수도 있습니다.

HealthContributor 는 HealthIndicator 혹은 CompositeHealthContributor 중 하나입니다. HealthIndicator 는 Status 를 포함하여 ‘실제’ 헬스 정보를 제공합니다. CompositeHealthContributor 는 다른 HealthIndicator 들을 조합한 결과를 제공합니다. 이들을 같이 사용하면, contributor들은 전체 시스템의 헬스 상태를 나타내는 트리 구조를 이루게 됩니다.

기본적으로, 최종 시스템의 헬스 상태는 StatusAggregator로부터 도출됩니다. 이는 각 HealthIndicator의 헬스 상태를 상태 순서를 기준으로 순서대로 정렬합니다. 이 정렬된 리스트의 첫번째 상태가 전체 헬스 상태가 됩니다. 만약 HealthIndicator가 StatusAggregator에 자신의 상태를 반환하지 않으면 UNKNOWN 상태가 사용됩니다.

최종 시스템의 헬스 상태 결정이 조금 이해가 어려울 수도 있습니다.

StatusAggregator 인터페이스를 구현한 SimpleStatusAggregator 의 경우 DEFAULT_ORDER 에 따라서 status를 정렬한 뒤, 이 정렬된 리스트의 첫번째 상태를 최종 상태로 결정합니다.

이 DEFAULT_ORDER 는 무엇일까요?

보면 알겠지만, DOWN → OUT_OF_SERVICE → UP → UNKNOWN 순서입니다. 이 순서로 정렬하겠다는 의미입니다.

여러 개의 상태들 중 대부분이 UP 이더라도, 하나라도 DOWN 혹은 OUT_OF_SERVICE 가 존재하면 정렬된 상태 리스트에서는 해당 값이 앞으로 오게 되므로, 전체 시스템 상태는 DOWN 혹은 OUT_OF_SERVICE 로 결정됩니다.

정리하자면, 스프링 부트 액추에이터는 여러 개의 헬스 컨트리뷰터 중 어느 하나라도 문제가 발생하면 전체 시스템에도 문제가 있다고 판단합니다.

저희는 DB 상태가 DOWN이라서 발생한 문제는 아닙니다. 애초에 DOWN 판정을 받지도 않았기도 하고요. 문제는 이 UP 판정을 받기 위해서는 커넥션 풀로부터 커넥션을 받아온 뒤 isValid 여부를 체크해야 하는데, 이때 커넥션 풀이 고갈되면서 API 응답이 지연되어 지금의 문제가 발생한 것입니다.

한편, 공식 문서에서는 이런 내용이 나옵니다.

💡

Health Indicators는 일반적으로 HTTP를 통해 호출되며 커넥션 타임아웃 전에 응답해야 합니다. Spring Boot는 응답하는 데 10초 이상 걸리는 Health Indicator에 대해 경고 메시지를 기록합니다. 이 임계값을 구성하려면 management.endpoint.health.logging.slow-indicator-threshold 속성을 사용할 수 있습니다.

우리가 아까 봤던 로그가 바로 이것이었죠.

Health contributor org.springframework.boot.actuate.jdbc.DataSourceHealthIndicator (db) took 23789ms to respond

진짜 해결책?

이 문제의 근본적인 원인은, 우리가 헬스 체크 API에 기대하는 기능과, 실제 헬스 체크 API의 기능이 다르기 때문입니다. 우리는 해당 서비스의 헬스 체크 엔드포인트로 접근했을 때, 서비스가 라이브 상태이면 200을 응답받기를 원합니다. 액추에이터가 지원하는, 여러 컨트리뷰터들의 상태를 집계하여 최종 상태를 결정하게 만드는 그런 기능들은 필요하지 않습니다.

우리는 순수하게 서비스가 라이브 상태인지 확인할 수 있는 (만약 라이브 상태라면 200을 반환하는) 엔드포인트가 필요합니다. management.health.defaults.enabled 프로퍼티를 false로 설정하면, 연동된 컴포넌트의 상태를 검사하지 않으므로, 서버가 살아있다면 (톰캣 스레드 풀이 고갈되지 않는 이상) 제때 200을 응답하도록 만들 수 있습니다.

해당 옵션 적용 이후 정상적으로 작동하는 것을 볼 수 있습니다.

마무리

요약

이번 글에서는 클라이언트에서 대량의 엑셀 파일을 다운로드하기 위해 서버로 병렬 요청을 보내게 되면서 헬스 체크 응답이 지연되고, 이로 인해 서버 인스턴스가 unhealthy 처리되어 조용히 다운되었다가 재시작되는 문제를 트러블슈팅한 과정을 다루었습니다. 해당 문제 해결을 위해 APM을 도입하여 문제 원인이 톰캣 스레드 풀이 아닌 DB 커넥션 풀 고갈임을 파악했습니다. 한편 Spring Boot Actuator에서는 헬스 체크 시 DB 상태를 같이 검사하는데, 이때 DB 커넥션을 필요로 하므로 헬스 체크 API가 DBCP 고갈로 인한 영향을 같이 받기 때문에 문제가 발생하게 됩니다. 헬스 체크가 DB 상태를 검사하지 않도록 변경하여 해당 이슈를 해결했습니다.

후기

이번 문제 해결 과정은 꽤 재밌었습니다!

AWS 로드 밸런서의 타깃 그룹과 헬스 체크 같은 인프라 영역에서 문제를 식별하여

딜레이 로그를 시각화하고 분석하여 병목 지점에서 큐잉 딜레이 패턴이 발생한다는 것을 파악하고

APM을 도입하여 스레드 풀과 DB 커넥션 풀에서 이러한 패턴을 발견, 진짜 원인을 찾은 뒤

스프링 부트 액추에이터의 작동 원리를 통해 이러한 문제가 발생한 이유를 이해해보았습니다.

다양한 영역들을 넘나들면서 문제의 원인을 추적하고, 각 요인들이 어떻게 연결되어 있는지 살펴보는 과정이 정말 흥미로웠습니다.

무엇보다, 모니터링의 중요성을 체감할 수 있었던 기회였습니다. 예전 사이드 프로젝트에서 APM을 도입했을 때는 이렇게 대량의 데이터를 다룰 일이 없다 보니 써먹을 일이 많지 않기도 하고, 일하는 환경도 백오피스 솔루션을 다루다 보니 필요성을 크게 느끼지 못했습니다. 신규 프로젝트에서도 APM 도입을 공수 핑계로 미루고 있다가 이번 트러블슈팅 때 급하게 붙이게 되었는데, 정말 큰 역할을 해주었습니다.

이번 사례에서도 볼 수 있듯이 APM 덕분에 문제가 스레드 풀 고갈이 아닌 DBCP 고갈로 인해 발생했다는 핵심 원인을 정확하게 파악할 수 있었습니다. 특히 일정이 타이트한 상황, 그러니까 성능 테스트 없이 라이브 환경으로 바로 배포하고 이후 들어오는 후속 이슈를 보면서 대응해야 하는 경우에 모니터링이 매우 유용하다고 느꼈습니다.

후속 아티클

후속 편에서는 1) APM을 도입하면서 있었던 의사결정 과정과 2) Spring Boot 애플리케이션에 Prometheus + Grafana 툴을 도입하는 방법 3) 그리고 도입 후 운영하면서 있었던 몇 가지 레슨런을 공유해보려고 합니다.

이번 편은 트러블슈팅 과정에서의 생각이나 잡다한 TMI를 담다 보니 글의 호흡이 유달리 긴 편이었는데, 다음엔 꼭 적당한 길이에서 마무리해보도록 하겠습니다.

읽어주셔서 감사합니다.

p.s - 추천 레퍼런스

토스에서도 비슷한 상황을 겪었다고 합니다. 여기서도 액추에이터에 대해 자세히 설명하고 있으니 한번 확인해보시면 좋을 듯 합니다. (링크)

단 저 글은 스프링 부트 액추에이터 (3) - 판정 로직 섹션의 내용처럼 UP / DOWN 결정 로직으로 인해 문제가 발생했던 것이고, 저희는 액추에이터가 DB 커넥션을 필요로 하는데 커넥션 풀이 고갈되어서 발생한 문제라 원인이 조금 다릅니다.

p.p.s - 문제의 해결책을 찾아서 (4) + 더더더 근본적인 해결책 찾기

액추에이터 헬스 체크 설정을 변경함으로써 문제는 해결되었지만, 다른 궁금증도 생겼습니다.

아까 전 Tomcat의 최대 스레드 풀 크기 디폴트 값은 200개라고 했습니다. 그리고 HikariCP의 커넥션 풀 크기 디폴트 값은 10개라고 했고요. 두 디폴트 값이 이렇게 차이나도록 세팅된 이유는 무엇일까요? 이로 인해서 100개의 동시 요청이 들어왔을 때 90개의 요청이 대기하는 문제가 발생했습니다.

스프링 부트는 ‘설정보다 관습(convention over configuration)’ 이라는 철학을 채택할 정도로, 개발자가 세세한 설정에 신경쓰지 않고 개발할 수 있도록 풍부한 Auto-configuration 기능을 지원하고 있습니다. 따라서 디폴트 값을 의도적으로 불편하게 세팅하지는 않았을 겁니다. 뭔가 이유가 있겠죠?

내용이 길어지는 관계로 이번 글에서는 언급하진 않았지만, 후속 편에서 이와 관련된 내용을 다뤄보겠습니다.