Critical GC 장애 대응기: 19초 서비스 중단에서 30ms 이하로

문제 상황

현재 참여하고 있는 프로젝트인 대학교 동아리 통합 플랫폼인 “띵동”에서 발생한 상황이다.

약 2년이라는 시간 동안 꾸준히 운영해 온 서비스인 만큼 접속하는 학생들의 수가 최대 MAU 5000까지도 늘어났기에 보다 더 안정적인 운영을 위해 서버, 애플리케이션, 데이터베이스의 매트릭을 수집하여 모니터링을 진행하고 있었다.

 

본격적으로 들어가기 전, 아래는 띵동 운영서버 환경이다.

• t2.micro: 약 1GB RAM (약 600-700MB 사용 가능), cpu 1 코어
• Serial GC
• Heap 235MB: 매우 작은 힙 크기

JVM 매트릭 중 GC의 pause 시간이 솟아올라있는 것을 확인하였다.

GC의 pause 시간은 GC가 동작하는 시간으로 모든 스레드가 정지하기 때문에, 즉 서비스가 중단되는 시간을 말한다. 그렇기에 짧은 시간을 유지하는 것이 중요했다.

 

하지만, 두 번에 걸쳐 약 19초, 16초 동안의 GC Pause 시간이 있는 것을 확인할 수 있었다.

CPU가 GC 작업에 참여하는 비율도 꽤 높게 올라가 있었다.

GC Pressure, Pause Durations

 

이때 정말 아쉽게도, gc 로그 및 힙 덤프를 찍어놓지 못해 정확한 원인을 파악할 수 없었다.

GC Pause 시간이 매우 긴 것을 보고, Full GC를 예상할 수 있었다. 또한, Full GC가 발생한 이유를 알아보기 위해 힙 메모리를 차지하는 세 가지 영역을 확인하였다.

 

여기서 특이점으로는 Old Generation인 Tenured Generation이 한계치인 128MB까지 도달하였다가, 작은 수치가 정리되고, 다시 점진적으로 증가해 한계치에 도달하는 모습을 볼 수 있었다.

heap space

결론적으로 Old Generation이 한계점에 도달하여 GC는 Full GC를 실행한 것이다.

 

그렇다면 왜 이런 일이 발생했을까?

앞서 말했듯이 gc 로그와 힙 덤프를 생성하지 못했다.

그래서 최대한 나와 비슷한 상황의 레퍼런스를 참고하고자 하였다.

여기서 궁금한 점은 세 가지이다.

 

Q1. Old Generation이 GC로 인해 정리되었을 때, 왜 저렇게 높은 수치를 유지하고 있을까?

 

띵동은 약 2년간 운영하면서 여러 프레임워크, 라이브러리를 사용하고 있다.

대표적으로 스프링 프레임워크, JPA/Hibernate, Tomcat, JVM 등 많은 클래스들을 로딩하고 있다. 사진을 보면 약 100MB가 베이스라인으로 보인다.

2년간 운영하며 여러 의존성들이 추가된 서비스가 100MB가 비정상적인 수치는 아니라 판단했고, 기본적으로 할당된 Memory 최대치가 적었던 것 같다.

 

Q2. Old Generation은 왜 점진적으로 증가할까?

 

Old Generation이 점진적으로 증가하는 것은 메모리 누수가 아니다. young generation에서 살아남은 객체들이 자연스럽게 넘어오는 것이다. 만약, 메모리 누수라면 gc가 작업한 후 Old Generation의 메모리가 이전보다 증가해야 하는데 같은 것을 볼 수 있었다.

 

Old Generation이 점진적으로 증가하는 이유는 Eden Space의 Memeory 최대치가 작았기 때문이다. Serial GC는 Eden Space의 메모리 최대치에 도달하면 Minor gc가 동작하고, 이 gc에 살아남은 객체들은 Suvivor Space로 이동시킨다. 이때 minor gc의 작업에서 특정 횟수이상을 살아남게 되면, Old Generation으로 승격시키게 된다.

Eden Space의 메모리 최대치가 작기 때문에 Minor GC가 빠른 시간 내에 많이 작업하게 되고, Old Generation으로 승격하게 되는 기준이 낮아지게 된 것이다.

이 때문에 점진적으로 증가하게 되었고, Old Generation도 메모리 최대치에 도달하게 된 것이다.

 

Q3. Full GC가 16-19초까지 걸리는 이유

 

Full GC가 길어진 가장 큰 원인은 Serial GC의 단일 스레드 한계 때문이다. Serial GC는 모든 객체 스캔, 해제, 압축을 하나의 스레드로 순차적으로 수행한다. 특히 Old Generation이 가득 차고 메모리 단편화까지 발생하면, 살아남은 객체를 이동하고 참조를 갱신하는 과정에서 시간이 크게 늘어난다. 결과적으로 작은 힙(235MB)이라도 복잡한 객체 그래프를 가진 애플리케이션에서는 16, 19초에 달하는 긴 Stop-The-World가 발생할 수 있다.

해결 방안

목표 : GC puase 시간 감소 및 Heap Space OOM 발생 예방

모니터링 시스템에서 GC pause 시간이 16-19초까지 치솟는 것을 확인했다. 이는 사용자들이 서비스를 이용할 수 없는 시간을 의미했기 때문에 즉시 해결해야 할 Critical 이슈이다.

 

1. 힙 크기 확장 (235MB → 512MB 이상)

가장 먼저 힙 크기를 확장했다. 기존 235MB의 힙은 최대 MAU 5,000명의 서비스 규모에 비해 지나치게 작았다. 힙 크기를 512MB 이상으로 확장함으로써, Young Generation의 크기가 커져 Minor GC가 발생하는 빈도를 줄일 수 있었고, 객체가 Old Generation으로 승격되는 속도를 늦춰 Full GC가 발생하는 시점을 지연시킬 수 있었다.

 

2. GC 알고리즘 변경 (Serial GC → G1GC)

Serial GC는 단일 스레드로 동작하여 Full GC가 발생했을 때 모든 애플리케이션 스레드를 멈추고 혼자서 모든 작업을 처리한다. 이것이 16-19초라는 극심한 GC Pause 시간의 주요 원인이었다.

그렇기에 짧고 GC Pause 시간을 달성하는 것이 주 목적인 G1GC(Garbage-First Garbage Collector)을 선택하였다. G1GC는 힙 영역을 작은 Region들로 나누고 Mixed GC가 발생해 Stop-The-World 시간을 단축시킨다.

 

3. 최대 GC pause 시간 지정

-XX:MaxGCPauseMillis 변수를 사용하여 GC pause 일시 정지 시간을 지정할 수 있다. 기본값은 200ms로 설정되어 있는데, 엄청 빠른 응답시간이 중요한 서비스가 아니기에 기본값으로도 충분하다 판단하여 따로 지정하지 않았다.

G1GC는 최대 일시 정지시간이라는 목표를 달성하기 위해 실시간으로 Collection Set을 조정한다. 각 GC cycle마다 200ms 내에 처리 가능한 Region들만 선택적으로 수집하고, 시간이 부족할 경우 나머지 Region들은 다음 cycle로 연기하는 것이다. 또한 Young Generation 크기를 동적으로 조절하여 pause 시간 목표를 유지하기도 한다.

 

번외) GC 로그 및 힙 덤프 설정 추가

향후 유사한 문제가 발생했을 때 신속하게 원인을 파악하기 위해 GC 로그 및 힙 덤프 설정 추가했다. 특정 조건(예: OOM 발생 시)에서 힙 덤프를 자동으로 생성하도록 설정했다.

결과

GC 알고리즘을 G1GC로 변경하고 힙 크기를 512MB로 확장한 후, 3일간의 모니터링 결과 GC Pause 시간이 30ms를 넘어간 적이 없음을 확인했다. 이전 16초, 19초와 비교하여 99% 이상 시간이 단축된 것을 알 수 있었다.

개선 후 Pause Duration