이주호 · 개발 블로그

9. 멈춘 건 GC였다 — GC 폭주와 pause rate

9 min read

핵심 한 줄

주기적으로 멈추는데 락도 아니고 네트워크도 아닐 때, sum(rate(jvm_gc_pause_seconds_sum[1m])) 이 0.3을 넘는다면 범인은 GC 폭주다. 그런데 STW 중엔 /metrics 스크레이프 자체가 막혀 라이브 관측이 거짓 정상으로 보인다 — 이 시리즈에서 가장 까다로운 측정 함정이다.

시리즈 — 장애를 '구별 가능'하게 만든 카오스 벤치

0.서문 · 1.스택트레이스가 곧 원인인 유일한 순간 · 2.p99가 튀는데 아무도 안 던졌다 · 3.200 OK인데 답이 틀렸다 · 4.top frame은 표면이지 원인이 아니다 · 5.느린 쿼리의 진짜 범인은 인덱스 · 6.커넥션을 안 돌려줬다 · 7.CPU가 남는데 스로틀당했다 · 8.컨슈머가 못 따라잡았다 · 9.멈춘 건 GC였다 · 10.다 멈췄는데 데드락은 아니다 · 11.요청 하나에 쿼리 1+N · 12.캐시 만료에 떼로 몰렸다

1. 배경 — 지연의 수많은 얼굴

운영에서 p99 latency↑ 알림이 뜨면, 원인 후보가 십수 가지다. 락 경합·GC 폭주·N+1·커넥션풀 고갈·CPU 스로틀… 전부 같은 증상으로 도착한다. 이 시리즈의 목표는 각 원인을 다른 원인은 못 내는 단 하나의 신호로 가르는 것이다(0.서문).

W9의 주인공은 GC 폭주(GC thrashing) 다. 그런데 이 편에는 특별한 반전이 있다 — 판별 신호를 아는 것만으로는 부족하다. 그 신호 자체가 장애 중에 사라진다. GC의 stop-the-world(STW) 구간 동안 Prometheus 스크레이프도 함께 막히기 때문이다. 신호를 설계한 뒤 측정에서 한 번 더 미끄러지지 않으려면 이 함정까지 알아야 한다.

2. 무엇을 망가뜨렸나 — gcThrashing 세임: 짧은 수명 객체 폭증

chaos 프로파일에서 gcThrashing을 arm하면, GcPressure 컴포넌트가 chaos-gc-pressure 스레드를 띄운다. 이 스레드는 두 단계로 JVM을 궁지로 몬다.

// GcPressure.java (chaos seam — @Profile("chaos"), scenario key "gcThrashing")
// Phase 1: retain ~150 MB of long-lived chunks to fill the bounded heap.
while (held < retainBytes && state.isArmed(ActiveChaosFaults.GC_THRASHING)) {
    byte[] chunk = new byte[chunkKb * 1024];
    chunk[0] = 1;
    retained.add(chunk);          // 레퍼런스를 유지 → Old Gen을 점령
    held += chunkKb * 1024;
}
// Phase 2: churn short-lived garbage so GC runs constantly.
while (state.isArmed(ActiveChaosFaults.GC_THRASHING)) {
    byte[] garbage = new byte[chunkKb * 1024];
    garbage[0] = 1;               // JIT elision 방지; 그냥 버림 → Young Gen 압박
}

seam은 @Profile("chaos")로만 활성화되고 ChaosState를 직접 읽는다. disarm하는 순간 스레드가 retained set을 해제하고 self-terminate한다.

핵심 구조는 단순하다 — Old Gen은 retained chunks가 점령하고, Young Gen은 짧은 수명 쓰레기가 쉴 새 없이 채운다. Young GC는 자주 터지고 Old Gen은 비워지지 않으니 Full GC로 에스컬레이션한다. JVM은 점점 더 긴 STW에 시달린다. 앱은 작은 힙(-Xmx256m)으로 기동할수록 이 효과가 확실해진다.

3. 증상 — 주기적 지연 스파이크

부하를 주면 latency가 무작위처럼 보이는 주기적 스파이크 패턴으로 요동친다. GC가 없는 구간엔 정상처럼 응답하다가, STW가 걸리는 순간 모든 스레드가 정지하며 p99가 수십~수백 ms로 솟는다.

스레드 덤프를 찍어 봐도 스레드들은 RUNNABLE이다 — 락 때문에 멈춘 게 아니다. CPU도 바쁘지만 스로틀 당한 흔적은 없다(7.CPU가 남는데 스로틀당했다). DB 슬로우쿼리도 없다. 외부 호출 latency도 정상이다. 원인을 가리키는 지표가 GC 메트릭 외엔 아무것도 없다.

4. 판별 신호 — GC pause time rate

Actuator + Micrometer의 JvmGcMetrics는 GC 일시정지 누적 시간을 jvm_gc_pause_seconds_sum으로 노출한다. 이 값을 1분 rate로 보면 “JVM이 GC에 쓴 초/초(벽시계 비율)“가 나온다.

sum(rate(jvm_gc_pause_seconds_sum{service="petclinic"}[1m])) > 0.3

0.3을 넘는다는 것은 벽시계의 30% 이상을 GC가 먹고 있다는 뜻이다. GcThrashing 알림이 이 조건에서 발화한다.

이 신호가 다른 지연 원인과 어떻게 갈리는지 표로 놓으면:

신호GC 폭주락 경합CPU 스로틀
rate(jvm_gc_pause_seconds_sum)↑ > 0.3정상정상
petclinic_blocked_threads낮음 (RUNNABLE)↑ 높음낮음
container_cpu_throttled_seconds_total정상정상↑
petclinic_deadlocked_threads000

GC 폭주의 판별 신호

GC pause time rate가 높고, 스레드는 RUNNABLE이고, CPU 스로틀 흔적이 없을 때 — 그것은 GC 폭주다. 락·데드락(10.다 멈췄는데 데드락은 아니다)과 달리 BLOCKED 스레드가 없고, CPU 스로틀(7.CPU가 남는데 스로틀당했다)과 달리 cgroup 제한 흔적이 없다. jvm_gc_pause_seconds_sum rate가 유일한 판별자다.

5. 라이브 함정 — STW 중엔 스크레이프도 멈춘다

신호를 알아도 측정에서 미끄러지기 쉽다. GC의 stop-the-world 구간 동안에는 JVM 전체가 정지한다 — 애플리케이션 스레드뿐 아니라 Actuator의 /metrics 엔드포인트도. Prometheus가 하필 그 구간에 스크레이프를 시도하면 타임아웃이 나거나 이전 값이 그대로 유지된다.

결과적으로 그라파나 패널에서 GC pause 관련 값이 0 또는 이전과 같은 값으로 보인다. 알림은 분명 울렸는데 “현재” 패널은 정상처럼 보이는 혼란이 여기서 나온다.

라이브 게이지를 믿지 마라 — 창(window)으로 봐야 한다

STW 중에 스크레이프가 막히면 순간 게이지는 거짓 정상을 반환한다. 알림이 실제로 발화한 값을 확인하려면 max_over_time(...) 이나 rate(...[2m]) 처럼 창 안의 누적으로 봐야 한다. 예: max_over_time(sum(rate(jvm_gc_pause_seconds_sum{service="petclinic"}[1m]))[5m:]) — 이 시리즈에서 GC 편이 가장 측정이 까다로운 이유가 바로 이 구조적 사각지대다.

6. 교훈

신호가 사라지는 장애일수록 창(window)이 필요하다

GC 폭주의 판별 신호는 jvm_gc_pause_seconds_sum rate — 이것은 확실하다. 문제는 STW가 길수록 그 신호를 측정하는 시스템도 함께 멈춘다는 것이다. 순간 게이지가 아닌 rate/over_time 기반의 창 쿼리로 설계해야 장애 중에도 증거가 남는다. “장애 도구가 장애에 죽지 않게”(2.장애 도구가 장애에 죽지 않게)는 단지 인프라 이야기가 아니라 쿼리 설계 이야기이기도 하다.

관련 글

그래프 뷰

백링크