모니터링 장애 대응 실습 3편 - 앱이 죽어가는 신호, 메모리 누수와 에러율 급증

이 글의 한 줄: 추세형(메모리)과 급변형(에러)은 잡는 법도, 알림 거는 법도 다릅니다.

“모니터링 장애 대응 실습” 4부작의 3편입니다. 1편. 정상이 뭔지 모르면 장애도 못 본다 · 2편. 자원이 마르면 생기는 일 · 3편(현재 글) · 4편(예정)

2편의 두 장애는 DB라는 같은 뿌리에서 나왔습니다. 이번 편의 두 장애는 성격 자체가 다릅니다. 메모리는 서서히 무너지고, 에러는 갑자기 터집니다. 하나는 몇 분에 걸쳐 힙 그래프가 기울다가 앱째로 죽었고, 하나는 부하를 걸자마자 에러율이 0에서 20%로 수직 상승했습니다. 미리 결론을 하나 흘리자면, 이번 편에서 이 시리즈의 공식(“메트릭으로 탐지하고, 로그로 원인을 좁힌다”)이 처음으로 막힙니다. 죽는 순간의 로그가 어디에도 남지 않았기 때문입니다.

장애 3. 힙 그래프에서 톱니가 사라졌다

이렇게 망가뜨렸다

가장 흔한 메모리 누수 패턴을 그대로 재현했습니다. 싱글톤 빈이 쥔 컬렉션에 요청마다 데이터를 쌓고, 아무도 비우지 않는 코드입니다. OOM(OutOfMemoryError)이 빨리 재현되도록 힙은 작게 잡았습니다(-Xmx128m).

@Component
public class LeakyStore {
    private final List<byte[]> chunks = new ArrayList<>();

    public void append() {
        chunks.add(new byte[512 * 1024]);   // ★ 요청마다 512KB, 제거 로직 없음
    }
}

실무에서는 상한 없는 인메모리 캐시, 무한히 자라는 static 맵, 세션에 쌓이는 임시 데이터 같은 형태로 나타나는 문제입니다. 여기에 k6로 5 VU를 걸어 /api/leak을 반복 호출했습니다.

탐지: 우상향, 그리고 그래프가 뚝 끊겼다

1편에서 봤던 정상 힙 그래프는 톱니 모양입니다. 쌓이다가 GC가 회수하면 뚝 떨어지고, 다시 쌓이는 반복.

부하를 걸자 이 톱니가 사라졌습니다. 떨어지는 구간 없이 32MB에서 110MB까지 우상향만 했습니다. GC가 돌아도 회수할 게 없다는 뜻입니다. 살아있는 객체(컬렉션이 쥔 chunk)만 쌓이고 있으니까요.

동시에 GC pause 횟수가 급증했습니다. 회수할 것도 없는데 한계에 몰린 JVM이 GC만 반복해서 돌리는 구간입니다.

그리고 그래프가 뚝 끊겼습니다. OOM으로 앱이 죽으면서 Prometheus scrape 자체가 실패하기 시작한 것입니다. 설계 단계에서 리스크로 적어뒀던 “죽는 순간 관측도 같이 죽는다”가 그대로 재현됐습니다. 이 그래프의 끝은 데이터가 0이 된 게 아니라 데이터가 오지 않는 것이고, 실시간으로 보고 있지 않았다면 놓쳤을 마지막 지표는 사후에 시간 범위를 되돌려 캡처해야 했습니다.

k6 결과도 나빴습니다. 109건 중 10건 실패, 최대 응답 시간 59.99초(k6 기본 요청 타임아웃 60초에 닿은 값).

원인: 이번엔 로그가 아무 말도 안 했다

2편까지의 공식대로 Loki를 열어 OutOfMemoryError를 검색했습니다. 0건이었습니다. 앱은 분명히 OOM으로 죽었는데.

답은 Loki가 아니라 컨테이너 stderr에 있었습니다.

java.lang.OutOfMemoryError: Java heap space
Heap dump file created [161440886 bytes in 0.272 secs]
Exception: java.lang.OutOfMemoryError thrown from the UncaughtExceptionHandler
  in thread "http-nio-8080-Poller"
Exception: java.lang.OutOfMemoryError thrown from the UncaughtExceptionHandler
  in thread "http-nio-8080-Acceptor"

스레드 이름을 보면 /api/leak 같은 앱 코드가 아닙니다. Poller, Acceptor, 톰캣의 커넥터 스레드들입니다. 엄밀히 말하면 이 메시지들은 예외를 처리하는 과정에서 연쇄로 터진 OOM의 기록이라 최초 발생 지점까지 특정해주지는 않습니다.

다만 분명한 건, 이 OOM들이 전부 앱 로거(Logback)를 거치지 않고 stderr로 직행했다는 사실입니다. 그래서 JSON 로그로 안 찍히고, Alloy가 수집할 파일에도 안 남고, Loki까지 오지 못합니다. “로그로 원인을 좁힌다”는 공식이 여기서 처음 막혔습니다.

대신 원인을 확정한 건 두 가지였습니다. 톱니 없이 우상향만 하던 메트릭 곡선, 그리고 -XX:+HeapDumpOnOutOfMemoryError가 남긴 154MB짜리 힙덤프. 128MB 힙에서 나온 154MB짜리 덤프 파일은 그 존재 자체가 힙이 가득 찬 채 죽었다는 증거이고, 어떤 객체가 채웠는지 따져야 할 때 열어볼 사후 분석 자료로 남았습니다.

이 장애의 교훈을 한 줄로 줄이면 이렇습니다. 로그는 앱이 살아있어야 남습니다. 죽는 순간의 기록은 메트릭과 힙덤프에 남습니다.

해결: 상한을 걸었는데 그래프가 안 내려갔다

원인이 무제한 적재이니 해결은 상한입니다. 컬렉션에 최대 크기를 걸고 넘치면 오래된 것부터 버리게(FIFO) 고쳤습니다. 그런데 여기서 헛다리를 짚었습니다. 상한을 50청크에서 10청크로 확 줄였는데도 힙 used가 119MB에서 꿈쩍하지 않았습니다. “왜 안 내려가지?” 하고 한참 그래프만 노려봤습니다.

답을 찾다 보니 used 그래프의 높이는 살아있는 객체 크기만으로 정해지는 게 아니었습니다. 살아있는 건 10청크(5MB)뿐이어도, 요청마다 512KB짜리 쓰레기가 쏟아지면 G1은 힙에 여유가 있는 동안 회수를 서두르지 않습니다. 게다가 512KB는 128MB짜리 작은 힙에서는 기본 GC인 G1이 덩치 큰 객체로 따로 분류하는 크기입니다(이른바 humongous 객체). 일반 객체와 회수되는 방식이 달라 회수가 더 늦었을 수도 있습니다. GC 로그를 안 남겨서 어느 쪽이 주범인지 확정하지는 못했습니다. 다만 상한(살아있는 객체 축소)에 요청당 적재량 축소(512KB에서 128KB로)를 더하고 나서야 그래프가 내려온 것은 분명했습니다.

같은 5 VU 부하에서 힙은 35~56MB 톱니로 안정됐고, 576건 전부 실패 없이 살아남았습니다. 톱니가 돌아왔다는 건 GC가 회수할 수 있는 구조가 됐다는 뜻입니다. 재발 방지는 힙 사용률·GC pause 알림, 그리고 상한·TTL(만료 시간) 없는 컬렉션 캐시 금지 규칙으로 정리했습니다.

장애 4. 에러율 0%가 50초 만에 알림을 울렸다

이렇게 망가뜨렸다

이번엔 외부 의존성 장애입니다. 상품 상세 API가 외부 재고 서비스를 호출하는데, 그 서비스가 죽어 있는 상황(Connection refused)을 시뮬레이션했습니다. 포인트는 호출 코드가 예외를 잡지 않고 그대로 전파한다는 것. 외부가 죽으면 우리 API도 500으로 같이 죽는 구조입니다.

@GetMapping("/api/products/{id}/detail")
public ProductDetailResponse detail(@PathVariable Long id) {
    Product product = productService.findById(id);
    int stock = inventoryClient.fetchStock(id);   // ★ 외부 장애 시 예외가 그대로 전파, 500
    return ProductDetailResponse.of(product, stock);
}

k6로 30 VU를 걸되, 정상 조회 80%에 이 /detail 20%를 섞었습니다. 전체 트래픽의 일부만 죽는 부분 장애 프로파일입니다.

탐지: 대시보드를 보기 전에 Discord가 먼저 울렸다

1·2편과 결이 다른 지점이 여기입니다. 이번 실습 전에 Grafana Alert를 걸어뒀습니다. 에러율 5% 초과가 1분 지속되면 경고, 15% 초과가 30초 지속되면 심각. 부하를 걸고 나서 50초 만에 심각 알림이 Discord에 도착했습니다. 경고는 80초에 뒤따라왔습니다. 지속 조건이 짧은 심각이 먼저 우는, 설계했던 순서 그대로입니다.

대시보드의 에러율 패널은 시리즈 내내 0%에 붙어 있다가 처음으로 움직였습니다. 0%에서 20%대로. k6 집계로는 14,484건 중 실패가 20.42%(2,958건)였고, 그중 2,847건이 500 응답이었습니다(나머지 111건은 서버에 연결조차 못 하고 끊긴 k6 쪽 타임아웃).

흥미로운 건 나머지 지표입니다. 정상 API의 p95는 5.3ms로 평소 그대로였습니다. 시나리오 1(에러와 지연 동반), 시나리오 2(지연만), 시나리오 3(서서히 오르다 앱 다운)과 또 다른 조합, 전체는 멀쩡한데 특정 API만 전부 죽는 신호입니다. 에러율은 평균으로 뭉개면 20%지만 /detail 입장에서는 100% 장애입니다.

원인: 스택트레이스는 있는데 requestId가 없었다

Loki에서 ERROR 레벨로 좁히자 스택트레이스가 쏟아졌습니다. InventoryClient.fetchStock에서 시작해 ProductController.detail로 이어지는, 범인이 그대로 적힌 트레이스입니다.

여기서 이 편의 헛다리가 나왔습니다. 2편까지 하던 대로 스택트레이스에서 requestId를 집어 드릴다운하려고 봤더니 ERROR 로그에 requestId 필드가 없었습니다. 시리즈 내내 모든 로그에 심어온 값인데. 순간 MDC 필터가 고장 났나 싶어 필터 코드부터 다시 열었습니다.

필터는 멀쩡했습니다. 문제는 예외가 로깅되는 위치였습니다. 컨트롤러가 던진 예외를 아무도 안 잡으면 서블릿 컨테이너(톰캣의 StandardWrapperValve)까지 올라가서 로깅되는데, 그 시점은 우리 MdcRequestIdFilter가 finally로 MDC를 정리한 필터 체인 바깥입니다.

requestId를 심었다고 끝이 아니라, 예외를 어디서 잡느냐가 그 로그의 주인을 정한다는 걸 여기서 배웠습니다. 장애 3의 “OOM은 Loki에 안 남는다”와 짝이 되는 발견입니다. 관측 장치는 앱의 정상 경로 위에 깔리고, 장애는 그 경로 바깥에서 터집니다.

덤으로 하나 더. 실패한 요청은 Logbook의 응답 로그도 없었습니다(예외로 필터 체인이 끊겨 요청 라인만 남습니다). 그래서 드릴다운 대신 시간대 매칭으로 원인을 엮었습니다. /detail 요청 라인의 requestId와 2ms 뒤에 찍힌 ERROR 스택트레이스. 30 VU가 동시에 도는 환경이라 개별 요청과의 일대일 매칭까지 확정할 수는 없지만, 시각에 스택트레이스의 호출 경로까지 일치하니 같은 장애 흐름으로 판단하기엔 충분했습니다.

관측 도구 쪽 사건도 있었습니다. 스택트레이스 5,700건이 쌓이자 로그 패널 쿼리가 Loki의 60초 타임아웃을 넘겨 죽었습니다. 패널에 maxLines: 200 제한을 걸어 해결했는데, 장애가 폭주하는 바로 그 순간에 관측 도구까지 같이 멈출 수 있다는 건 예상 못 한 부분이었습니다. 관측 스택도 장애 트래픽에 대비가 필요합니다.

해결: 폴백 한 줄에 처리량이 10배로 돌아왔다

외부 서비스가 죽었다고 우리 API까지 죽을 이유는 없습니다. 예외를 컨트롤러에서 잡아 폴백으로 격리했습니다. 재고만 비운 채(stock: null) 200으로 응답하고, WARN 로그를 남깁니다.

try {
    stock = inventoryClient.fetchStock(id);
} catch (InventoryServiceException e) {
    log.warn("재고 조회 실패, 폴백 적용. productId={}", id);   // 필터 체인 안이라 requestId도 찍힌다
    stock = null;
}

같은 혼합 부하를 다시 걸었습니다. 외부 서비스는 여전히 죽어 있는데 5xx는 170,941건 중 0건. 알림은 부하 내내 Normal을 지켰고(안 우는 것이 복구의 증거입니다), 드릴다운은 요청·WARN·응답 3라인 매칭으로 돌아왔습니다. 예외를 필터 체인 안에서 잡으니 requestId 문제까지 같이 풀린 것입니다.

예상 밖의 수확은 처리량이었습니다. 110 RPS에서 1,163 RPS로, 10배가 뛰었습니다. 에러율 20%를 고쳤는데 처리량이 10배라니 산수가 안 맞는다 싶었는데, 가장 유력한 범인은 500 응답에 붙는 Connection: close 헤더였습니다. 에러 응답마다 커넥션이 끊겨 20%의 에러가 나머지 80%의 정상 요청까지 커넥션 재수립 비용으로 끌어내리고 있던 것으로 보였습니다. 실제로 장애 부하 중에는 k6에 연결 실패(dial 타임아웃)가 함께 찍혔고, 폴백으로 500이 사라지자 이 현상도 같이 사라졌습니다.

에러는 가용성만이 아니라 처리량도 갉아먹습니다.

재발 방지는 에러율 경고/심각 2단계 알림 상시화, 외부 의존성 호출의 폴백·타임아웃 규칙으로 정리했습니다. 다음 단계로는 서킷브레이커(장애가 반복되면 호출 자체를 차단하는 패턴)가 있습니다.

추세형과 급변형, 잡는 법이 달랐다

	장애 3. 메모리 누수	장애 4. 에러율 급증
장애의 속도	몇 분에 걸친 우상향 (추세형)	부하 직후 수직 상승 (급변형)
가장 먼저 운 신호	힙 톱니 소멸 + GC pause 급증	에러율 패널, 그리고 Discord 알림(50초)
로그의 역할	없음 (Loki에 안 남음, stderr와 힙덤프가 대신)	스택트레이스가 범인 지목 (단, requestId는 시간대 매칭으로)
해결	컬렉션 상한 + 적재량 축소	폴백으로 외부 장애 격리
복구의 증거	힙 그래프의 톱니 복귀	5xx 0건 + 알림이 내내 Normal

이 대비는 알림 설계로 그대로 이어집니다. 이번에 걸어둔 비율 임계치 + 지속 시간 알림은 급변형(에러율)을 50초 만에 잡았습니다. 하지만 몇 분에 걸쳐 서서히 기울다 죽는 추세형(메모리)이었다면 같은 방식으로 잡혔을까.

사실 급변형 쪽도 순탄치 않았습니다. 심각 알림이 처음엔 안 울렸는데, 임계를 잘못 잡아서였습니다. 그 이야기와 “4번의 장애에서 내가 예상한 신호 vs 실제 먼저 운 신호” 총정리는 마지막 편에서 다룹니다.

이것으로 계획했던 장애 4종이 모두 끝났습니다. 커넥션 풀 고갈, 느린 쿼리, 메모리 누수, 에러율 급증. 다음 편은 이 네 번의 장애를 관통하는 회고입니다. 메트릭은 언제를, 로그는 왜를 답한다는 이 시리즈의 공식이 어디까지 통했고 어디서 막혔는지(이번 편에서만 두 번 막혔습니다), 그리고 그 사이를 이어준 requestId 이야기입니다.

다음 편: 모니터링 장애 대응 실습 4편 - 네 번 장애를 내보고 알게 된 것 (작성 예정)