반복되는 Full GC, 원인은 메모리 누수였다

About this offer

실시간 알림 기능을 구현한 뒤, 동시 접속 상황에서 어느 정도까지 안정적으로 동작하는지 확인하기 위해 부하테스트를 진행했습니다. 테스트를 진행하면서 Grafana로 CPU 사용률, 메모리 사용량, 응답 시간을 함께 확인했습니다. 시나리오를 여러 차례 반복하자 메모리 사용량은 계속 증가했고, CPU 사용률과 p99 응답 시간도 함께 올라갔습니다. 처음에는 단순히 부하가 많이 걸린 영향이라고 생각했습니다. 하지만 테스트가 끝난 뒤에도 메모리 사용량은 이전 수준으로 돌아오지 않았고, 같은 시나리오를 반복할수록 CPU와 p99가 이전보다 더 자주 튀었습니다. 또한 테스트 이후 애플리케이션 프로세스를 재시작하자 지표들이 다시 정상 수준으로 돌아왔습니다. 이러한 증상을 바탕으로 몇 가지 가능성을 먼저 확인했습니다. 1. 스레드 풀 고갈 의심 → 가능성 낮음 처음에는 동시 요청이 많아지면서 스레드 풀이 고갈되고, 대기 요청이 증가해 p99 응답 시간이 상승한 것이 아닐까 생각했습니다. 하지만 단순한 스레드 풀 고갈이라면 부하가 종료된 뒤 대기 중인 작업이 처리되면서 응답 시간도 다시 정상 수준으로 회복되는 흐름이 나타나야 합니다. 또, 테스트가 끝난 이후에도 메모리 사용량이 이전 수준으로 돌아오지 않았고, 테스트를 반복할수록 상태가 계속 악화됐습니다. 따라서 단순한 스레드 풀 고갈만으로는 설명하기 어려웠습니다. 2. 호스트 수준 문제 의심 → 가능성 낮음 다음으로 애플리케이션이 실행되는 인스턴스의 CPU, 메모리, 네트워크, 디스크 I/O 등의 자원 문제를 확인했습니다. Grafana에서 호스트 수준의 시스템 지표를 확인했지만 지속적인 CPU 포화나 메모리 부족, 네트워크 병목과 같은 문제는 보이지 않았습니다. 반면 애플리케이션 프로세스를 재시작하면 문제가 사라졌기 때문에, 호스트 자체보다는 애플리케이션 내부 문제일 가능성이 높다고 생각했습니다. 3. GC로 인한 Stop-the-World 문제 의심 Grafana에서는 당시 Heap 세부 지표를 충분히 수집하고 있지 않았습니다. 하지만 부하 테스트를 반복할수록 CPU와 p99가 함께 악화됐고, 메모리 사용량 역시 이전 수준으로 돌아오지 않았습니다. 애플리케이션 프로세스를 재시작하면 정상화되는 점을 보고, 애플리케이션 내부에 문제가 있음을 짐작했고, 특히 메모리가 계속 누적되는 상황에서 GC 가 더 자주 발생하거나 Stop-the-World 시간이 길어지면서 CPU 사용률과 p99 응답 시간에도 영향을 주는 것은 아닌지 의심했습니다. 다만 이 시점의 Grafana 지표만으로 GC 문제라고 확정할 수는 없었습니다. 그래서 GC 문제를 유발할 만한 코드가 있는지 확인하기 위해 AI 코드 리뷰도 함께 진행했습니다. SSE 연결 관리 코드가 의심됐다 리뷰 과정에서 실시간 알림에 사용하던 SSE 연결 관리 코드가 의심 지점으로 나왔습니다. SSE 연결을 생성하면 이후 알림 전송을 위해 SseEmitter 를 애플리케이션 메모리에 유지하고 있었습니다. private final Map<String, SseEmitter> emitters = new ConcurrentHashMap<>(); 문제는 SSE 연결이 종료된 이후에도 해당 연결과 관련된 상태가 메모리에서 정리되지 않고 남을 수 있다는 점이었습니다. 이미 사용이 끝난 연결 정보가 계속 참조된 상태로 유지되면 GC가 이를 회수할 수 없고, 연결이 반복될수록 관련 객체가 Heap에 계속 누적될 수 있습니다. SSE 연결 생성 ↓ 연결 상태를 애플리케이션 메모리에 유지 ↓ 클라이언트 연결 종료 ↓ 연결 상태가 정리되지 않고 남음 ↓ 객체에 대한 참조 유지 ↓ GC가 회수할 수 없음 하지만 코드만 보고 이것을 실제 원인이라고 단정할 수는 없었습니다. 그래서 로컬 환경에서 SSE 연결을 반복적으로 생성하고 종료하면서, 연결이 끝난 뒤에도 관련 상태가 실제로 남는지를 중심으로 재현 테스트를 진행했습니다. SSE 재접속으로 문제를 재현했다 로컬 환경에 애플리케이션 두 대를 띄우고, 일반 API 요청은 일정하게 유지한 채 SSE 재접속을 반복했습니다. 여기서 Heap 메모리는 애플리케이션당 320MiB 로 제한했습니다. 테스트에서는 실제 활성 SSE 연결 수와, 연결 종료 후에도 애플리케이션 내부에 남아 있는 연결 상태를 따로 확인했습니다. 정상적으로 정리된다면 연결이 종료된 뒤 두 값 모두 다시 감소해야 합니다. 하지만 재접속을 반복할수록 저장된 연결 상태는 계속 증가했고, 새로운 연결 생성을 중단해 활성 연결이 0 이 된 뒤에도 그대로 남아 있었습니다. 왼쪽 그래프를 보면 SSE 재접속을 중단한 뒤 활성 연결은 0 으로 돌아왔지만, 애플리케이션 내부에 저장된 연결 상태는 그대로 남아 있었습니다. 같은 시간대의 오른쪽 그래프에서는 Heap과 Old 영역의 사용량도 함께 증가하는 모습을 확인할 수 있었습니다. 여러 번의 GC를 거쳐 살아남은 객체는 Old 영역으로 승격됩니다. 따라서 연결은 이미 종료됐는데 Old 영역의 사용량이 계속 증가한다는 점에서, 종료된 연결과 관련된 객체가 제대로 정리되지 않고 계속 살아남고 있을 가능성을 의심했습니다. Full GC가 반복적으로 발생했다 다음으로 JVM 내부 상태를 더 자세히 확인하기 위해 VisualVM 을 사용했습니다. VisualVM에서 Heap 사용량과 GC activity 를 확인해보니, 테스트가 진행될수록 GC 이후에도 Heap 사용량이 이전 수준까지 내려오지 않고 점점 높아지는 모습을 확인할 수 있었습니다. 단순히 객체 생성량이 많아서 Heap 사용량이 증가한 것인지, 아니면 GC 이후에도 객체가 계속 살아남고 있는 것인지 확인할 필요가 있었습니다. 앞서 Grafana에서 Old 영역 사용량도 함께 증가하는 모습을 확인했기 때문에, GC가 발생하는 동안 어떤 Pause가 발생하고 있는지도 확인했습니다. 그래프를 보면 Young GC보다 Full GC가 발생한 구간에서 더 길게 정지한 것을 알 수 있습니다. 다만 이 그래프는 일정 구간에서 가장 길었던 GC 정지 시간을 보여주기 때문에, 선이 유지되는 시간을 하나의 GC 실행 시간으로 볼 수는 없습니다. 개별 Full GC에서 실제로 얼마나 오래 멈췄는지와 GC 전후 Heap 사용량은 GC 로그에서 확인했습니다. Pause Full (G1 Compaction Pause) 318M->260M(320M) 327.310ms Pause Full (G1 Compaction Pause) 318M->286M(320M) 291.926ms Pause Full (G1 Compaction Pause) 318M->291M(320M) 223.679ms 로그에서도 Full GC가 반복적으로 발생하고 있었고, GC 이후에도 Heap 사용량이 충분히 줄어들지 않는 모습을 확인했습니다. 이는 일부 객체가 계속 참조되고 있어 GC가 회수하지 못하고 있다는 것을 의미합니다. 그래서 다음으로는 부하가 끝난 뒤에도 이 상태가 계속 유지되는지 확인했습니다. 연결이 모두 종료된 뒤에도 Heap이 회수되지 않았다 SSE 재접속을 중단하고 활성 연결이 모두 종료될 때까지 기다렸습니다. 그 상태에서 Full GC를 여러 번 수행하면서 Heap 사용량이 얼마나 줄어드는지 확인했습니다. Pause Full (Diagnostic Command) 293M->269M(320M) 250.672ms Pause Full (Diagnostic Command) 269M->269M(320M) 237.300ms Pause Full (Diagnostic Command) 270M->269M(320M) 197.316ms Pause Full (Diagnostic Command) 270M->269M(320M) 197.966ms Pause Full (Diagnostic Command) 269M->269M(320M) 196.685ms 첫 번째 Full GC에서는 일부 메모리가 회수됐습니다. 하지만 이후 네 번의 Full GC에서는 Heap이 약 270MiB 수준에서 더 이상 내려가지 않았습니다. 두 애플리케이션 모두 비슷한 결과를 보였습니다. 애플리케이션 Full GC 이후 사용 Heap app1 약 270MiB app2 약 269MiB 이 시점에는 실제 SSE 활성 연결이 없는 상태였습니다. 그런데 Full GC를 여러 번 수행해도 Heap은 약 270MiB 수준을 유지했습니다. 즉, GC 자체는 실행되고 있었지만 일부 객체는 정리되지 않고 있음을 의미합니다. 따라서 단순한 GC 실행 여부의 문제가 아니라, 애플리케이션 어딘가에서 객체에 대한 참조가 계속 유지되고 있을 가능성이 있다고 생각했습니다. Heap Dump로 남아 있는 객체를 확인하다 Full GC 이후에도 Heap 사용량이 충분히 줄어들지 않았기 때문에 어떤 객체가 계속 살아남아 있는지 확인하기 위해 VisualVM으로 Heap Dump를 분석했습니다. 확인 결과, 종료된 SSE 연결과 관련된 객체들이 메모리에 그대로 남아 있었습니다. 특히 Heap Dump에서 확인한 SSE 연결 관련 객체 수가, 앞서 연결 종료 후에도 남아 있던 연결 상태 수와 거의 동일하게 나타났습니다. 즉, SSE 연결이 종료된 뒤에도 관련 상태가 애플리케이션 내부에 남아 있었고, 이 상태가 연결과 관련된 다른 객체들까지 계속 참조하고 있었습니다. 그 결과 해당 객체들은 더 이상 사용되지 않는데도 GC에 의해 회수되지 못한 채 Heap에 남아 있었습니다. 이를 통해 문제의 원인이 단순히 Heap 크기나 GC 설정 때문이 아니라, 종료된 SSE 연결과 관련된 상태가 계속 참조되면서 발생한 메모리 누수 라는 것을 확인했습니다. 연결 종료 시 참조도 함께 제거하다 원인은 SSE 연결이 종료된 뒤에도 관련 객체에 대한 참조가 메모리에 남아 있던 것이었습니다. 따라서 연결이 종료되는 시점에 저장해둔 SseEmitter 에 대한 참조도 함께 제거하도록 수정했습니다. emitterRepository.delete(userId); 핵심은 연결 자체가 종료되는 것뿐 아니라, 애플리케이션이 해당 연결에 대해 유지하고 있던 참조도 함께 정리하는 것이었습니다. 수정 후 같은 방식으로 SSE 재접속 테스트를 다시 진행했습니다. 이번에는 연결이 종료되자 애플리케이션 내부에 저장돼 있던 연결 상태도 함께 정리됐고, 활성 연결과 저장된 연결 상태 모두 0 으로 돌아왔습니다. Full GC 이후 Heap 사용량도 이전보다 크게 낮아졌습니다. 항목 app1 app2 활성 연결 0 0 저장된 연결 상태 0 0 Full GC 이후 Heap 약 57MiB 약 68MiB 수정 후에는 연결이 종료되면 관련 상태도 함께 정리됐고, Full GC 이후 Heap 사용량도 이전보다 크게 감소했습니다. 이를 통해 종료된 SSE 연결에 대한 참조가 계속 유지되던 것이 메모리 누수의 원인이었다는 것을 확인할 수 있었습니다. 마치며 이번 경험을 통해 여러 가능성을 의심한 뒤 재현 테스트와 JVM 분석 등을 통해 의심점을 좁혀가며 결론을 도출해내는 경험을 할 수 있었습니다. GC와 JVM 메모리 동작을 실제 문제와 연결해서 이해할 수 있었고, VisualVM과 Heap Dump를 활용해 원인을 추적하는 방법도 익혔습니다. GC가 개발자의 메모리 관리 부담을 줄여주지만, 그렇다고 메모리를 완전히 신경 쓰지 않아도 되는 것은 아니라는 점도 느꼈습니다. 무엇보다 문제를 재현하고 가설을 하나씩 좁혀가며 해결하는 과정을 직접 경험했다는 점이 의미 있었습니다.