스프링 부트 GC 로그 해석 실전 — Metadata GC Threshold로 Full GC가 길어질 때

운영 중 서비스가 갑자기 멈춘 듯 느려지고, 모니터링에 긴 스파이크가 찍히는 순간이 있다. 이럴 때 GC 로그는 원인을 추정이 아닌 증거로 보여준다. 특히 다음과 같은 문구가 보인다면 메타스페이스(Metaspace)가 범인일 가능성이 높다.

Pause Full (Metadata GC Threshold) 214M->214M(2048M) 43012.7ms

이번 글은 이 한 줄을 어디까지 읽어낼 수 있는지, 그리고 실제로 무엇을 확인하고 어떻게 조치하는지 단계별로 정리한다.

---

1) 샘플 로그와 한 줄 해석

다음은 실제 운영에서 캡처한 패턴을 단순화한 예시다. (Java 11, G1GC, unified logging)

[2.431s][info][gc] GC(365) Pause Young (Concurrent Start) (Metadata GC Threshold) 223M->214M(2048M) 5.01ms
[2.437s][info][gc] GC(365) Concurrent Mark Cycle
[2.498s][info][gc] GC(365) Pause Full (Metadata GC Threshold) 214M->214M(2048M) 43012.7ms

핵심 포인트:

• Pause Full: Full GC. 애플리케이션 스레드가 STW(Stop-The-World)로 멈춘다.
• (Metadata GC Threshold): 메타스페이스가 임계치에 닿아 GC가 트리거됨.
• 214M->214M(2048M): GC 전후 힙 사용량이 거의 안 줄었다. 회수할 게 없거나 대부분 살아 있는 객체/메타데이터다.
• 43012.7ms: 43초 동안 정지. 정상 범위를 벗어난 심각한 지연.

이 한 줄만으로도 “메타스페이스 압박 + Full GC 장시간”이라는 큰 그림이 나온다.

---

2) unified logging 형식 빠르게 파헤치기

-Xlog:gc* 로 남긴 라인은 보통 다음 정보를 담는다.

• 타임스탬프: [uptime][level][tag]
• 이벤트 번호: GC(365) 처럼 증가하는 카운터
• 이벤트 종류: Pause Young, Pause Full, Concurrent Mark Cycle 등
• 트리거: (Metadata GC Threshold), (Allocation Failure), (Humongous Allocation) 등
• Before/After/Total 힙: 사용량_before -> 사용량_after (힙총량)
• 소요 시간: 마지막에 ms 단위

로그를 볼 때는 “이벤트 종류 → 트리거 → 시간 → 전후 사용량” 순서로 훑으면 된다.

---

3) 10분 컷 점검 루틴

문제가 터졌을 때 최소한 아래만 보면 원인의 70%는 좁혀진다.

1. 트리거 문구 파악
   • Metadata GC Threshold면 메타스페이스,
     Humongous Allocation이면 대형 객체(배열/문자열),
     To-space exhausted면 승격 실패/단편화 가능성.
2. STW 시간 확인
   • Pause Full ... 43s 같은 구간이 몇 번, 어떤 패턴으로 반복되는지.
3. Before/After 비교
   • 줄지 않으면 “살아있는 데이터(혹은 누수)” 쪽.
4. 주기성
   • 배치, 트래픽 피크, 배포 직후 등과 맞물리지 않는지.
5. 메타/휴몽거스 지표
   • 메타스페이스/대형 객체 키워드가 반복되는지.

---

4) 손에 잡히는 커맨드: 지금 당장 확인

프로세스 PID가 12345라고 가정한다.

4.1 메타스페이스 및 클래스 로딩 상황

# 클래스 로딩 수치 추이 (1초 간격)
jstat -class 12345 1000

# 어떤 클래스 로더들이 얼만큼 먹고 있는지
jcmd 12345 VM.classloaders

# 클래스/메서드/인터프리터 메타데이터 통계
jcmd 12345 GC.class_stats

• Loaded/Unloaded가 계속 증가만 한다면 ClassLoader 누수 가능성.
• 특정 로더가 비정상적으로 많은 메모리를 들고 있으면 해당 로더 경로 추적.

4.2 GC 상황 스냅샷

# 현재 GC 설정과 힙 상태
jcmd 12345 VM.flags
jcmd 12345 GC.heap_info
jcmd 12345 GC.heap_dump /tmp/heap.hprof   # 필요 시 덤프

덤프는 Eclipse MAT, VisualVM, JProfiler 등으로 분석한다. 특히 ClassLoader Dominator Tree를 보면 누수 경로를 잡기 쉽다.

---

5) 스프링 부트에서 GC 로그 켜는 법

Java 11+

-Xlog:gc*:file=/var/log/app/gc.log:time,uptime,level,tags
-XX:+UseG1GC

컨테이너 환경이라면:

-XX:MaxRAMPercentage=70

Java 8

-XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:/var/log/app/gc.log
-XX:+UseG1GC

운영에서 흔한 실수는 “로컬에서는 GC 로그 안 켠 채로 운영만 켜는 것”. 동일 옵션으로 스테이징에도 켜두면 재현/비교가 수월하다.

---

6) 응급 조치 vs 근본 해결

6.1 응급 조치(지금 서비스가 멈춘다면)

• 메타스페이스 상향
• -XX:MaxMetaspaceSize=512m # 현재 200M대에서 막힌다면 512m 이상부터
• 명시적 GC 차단
• -XX:+DisableExplicitGC
• 힙 초기/최대 동일화
• -Xms4g -Xmx4g # 힙이 흔들리지 않게
• CPU/메모리 리소스 점검
  컨테이너 제한이 과하게 타이트하면 GC 워커가 제때 못 돈다.

6.2 근본 해결(재발 방지)

• ClassLoader 누수 제거
  • 재배포/재시작 사이클에서 이전 로더 참조 해제
  • 스케줄러, 스레드풀, 캐시가 로더를 붙잡고 있지 않은지 확인
• 동적 클래스 생성 최적화
  • 프록시/매퍼 재사용, 리플렉션 남용 절제
• 대형 객체 패턴 개선
  • 직렬화/역직렬화 버퍼 재사용, 스트리밍/청크 처리
• G1 튜닝(상황별)성격이 다른 워크로드에서는 수치가 달라질 수 있다. 지표로 검증하며 조정한다.
• -XX:InitiatingHeapOccupancyPercent=35 -XX:G1ReservePercent=20 -XX:+ParallelRefProcEnabled

---

7) 실무 체크리스트

• gc.log에 Metadata GC Threshold가 반복되는가
• Full GC 전후 사용량이 줄지 않는가
• jstat -class에서 Loaded가 꾸준히 상승하는가
• VM.classloaders에서 특정 로더가 비정상적으로 큰가
• 배포/재시작 이후부터 문제가 심해졌는가
• 컨테이너 CPU/메모리 제한이 과한가
• 응급 옵션(메타스페이스 상향, DisableExplicitGC)을 적용했는가

---

8) 마무리: 로그를 “읽는 습관”이 문제를 줄인다

GC 로그는 처음엔 낯설다. 하지만 “이벤트 종류 → 트리거 → 시간 → 전후 사용량” 네 가지만 통일된 순서로 읽는 습관을 들이면, 원인 후보를 빠르게 좁힐 수 있다. 이번 사례처럼 Metadata GC Threshold가 보이면 메타스페이스부터 점검하고, 필요 시 ClassLoader 누수를 의심하자. 응급 조치로 빈도를 낮추되, 근본 원인까지 잡아야 재발을 막을 수 있다.

---

부록 A. 스프링 부트 실행 스크립트 예시

JAVA_OPTS="
  -Xms4g -Xmx4g
  -XX:+UseG1GC
  -Xlog:gc*:file=/var/log/app/gc.log:time,uptime,level,tags
  -XX:MaxMetaspaceSize=512m
  -XX:+ParallelRefProcEnabled
  -XX:+DisableExplicitGC
"
exec java $JAVA_OPTS -jar app.jar

부록 B. 문제 재현/조사 템플릿

# 1) 현재 플래그와 힙 정보 수집
jcmd <pid> VM.flags
jcmd <pid> GC.heap_info

# 2) 클래스 로딩 추이 관찰(1초 간격, 60회)
jstat -class <pid> 1000 60

# 3) 클래스 로더/메타데이터 상세
jcmd <pid> VM.classloaders
jcmd <pid> GC.class_stats

# 4) 필요 시 힙덤프 채취
jcmd <pid> GC.heap_dump /tmp/heap-$(date +%s).hprof