현재 플랫폼을 개발하고 운영하면서 몇 차례의 메모리 누수 문제를 겪었는데 이것들을 해결했던 과정과 그 원인을 적어보려고 한다. 발생한 지 몇 개월이 지난 것들이지만 혹시 나와 같은 문제를 겪는 사람이 있다면 도움이 되었으면 좋겠다.

문제 발생

가장 처음으로 발생했던 메모리 관련 문제는 서비스를 오픈하고 많은 날이 지나지 않았을 때였던 걸로 기억한다. 주말에도 마음 편하게 쉬지를 못하는 때였으니까... 아니나 다를까 정확한 선후 관계는 기억이 나지 않지만, 서비스가 느려진 것을 인지하고 각 서비스 상태를 모니터링했었다.

이 그래프에서 보다시피 특정 인스턴스 몇 대가 무슨 짓을 하는지 갑자기 CPU Utilization이 치솟는 현상이 있었고 이 서비스로 HTTP Call을 하는 다른 컴포넌트에도 영향을 미치고 있었다. 암담한 심정과 더불어 도무지 원인을 알 수가 없었는데 갑자기 CPU가 치솟는 현상을 경험한 적이 없었기 때문이다. 그래서 문제가 있는 인스턴스들을 재시작하였고 서비스 상태는 잠잠해진 듯했다. 문제가 언제 다시 발생할지 몰라 조마조마하긴 했지만.

원인 파악

계속 모니터링하다 보니 시간이 지나면 문제의 현상이 재현되었고 LB에서 제외하여 해당 인스턴스에서 문제를 파악해 보기로 했다. top 명령으로 보았을 때 java가 CPU를 가장 많이 점유하고 있는 것을 확인 할 수 있었고 top -H -p pid로 java의 특정 thread가 CPU를 많이 사용함을 알 수 있었다.

그리고 sudo -u user jstack -l pid 명령으로 jvm의 thread dump의 tid와 대조한 결과 그 thread가 GC thread라는 것을 알 수 있었다. 즉, 이유는 모르겠는데 GC를 수행하느라 CPU를 많이 쓰고 있고 GC가 수행되어도 메모리 해제가 되지 않았기 때문에 현재 상태에 도달했을 것이다. 이때부터 메모리 누수가 의심되기 시작했다. (그때 jstat을 사용했다면 좀 더 의미 있는 상태 분석을 했을 것 같다.)

메모리 분석

메모리 누수가 의심되는 상황이기는 했지만 역시나 원인이 짐작도 되지 않았다. 특별히 메모리를 많이 요구하는 코드도 없었기 때문이다. 그래서 메모리 분석을 위해 jvm의 heap dump를 받아보기로 했다. sudo -u user jmap -dump:format=b,file=dump.bin pid 명령을 사용했다.

dump는 시간이 꽤 걸렸는데 메모리 사용량에 따라 다르겠지만.. 기억하기로는 2G일 때 2시간 정도 걸렸던 듯하다. 시간이 걸리는 작업이기 때문에 작업을 걸어놓고 다른 것을 하다가 나중에 확인했을 때 터미널이 끊어져 있는 불상사를 맞이하고 nohup으로 백그라운드에서 수행한 기억이 있다. 그리고 AWS EC2에서는 package를 설치해야 jmap 실행이 가능했다¹.

덤프 파일 분석에는 eclipse의 MAT(Memory Analyzer)를 사용했다.

분석해보니 PartTreeJpaQuery라는 클래스에서 사용하는 ConcurrentHashMap이 메모리를 많이 차지하고 있었다. 관련된 내용이 있는지 검색해 보았고 나의 증상과 비슷해 보이는 Spring Data JPA 이슈를 발견할 수 있었다.

DATAJPA-1647

이 이슈에서는 JPA repository의 findBy...의 파라미터로 Pageable을 사용할 때 메모리 누수가 있는 것 같다고 제보하고 있었다. 그리고 이 이슈는 장애가 발생한 날의 불과 4일 전에 버전 올림 되면서 수정되었다. PR을 보면 이전에 넣은 기능을 롤백하는 것인데 DATAJPA-1575으로 2019년 8월 5일 2.2.0.RC2 버전에 포함되었다.

정리하면 2019년 8월 5일에 Spring Data JPA의 2.2.0.RC2에 추가된 기능을 2020년 1월 15일에 2.2.4와 2.3.0 버전 이상에서는 이전 코드로 되돌려 해결하였다. 문제가 있었던 프로젝트는 Spring Boot 2.2.0을 사용하고 있었고 댓글을 조회하고 페이징하기 위해 JpaRepository를 상속한 인터페이스에서 findBy...에 Pageable을 파라미터로 사용하고 있었다.

검증

같은 코드에서 Spring Data JPA 버전만을 변경하여 heap 메모리 사용을 비교해 보기로 했다. 환경은 Java 1.8을 사용하였고, Heap의 최초, 최대 크기는 1G로 설정했다. 그리고 nGinrder로 100명의 가상 유저로 요청을 시뮬레이션하였으며 Scouter로 모니터링하였다. 각 요청은 아래의 코드를 수행하게 했다.

    @GetMapping("/memoryLeakTest")
    public void memoryLeakTest() {
        commentRepository.findByComment("comment", PageRequest.of(1, 1));
    }

Spring Data JPA 2.2.0

시작 후 30분가량 후에 힙 사이즈가 최대치인 1G에 도달하였고 GC로도 메모리가 회수되지 않아 점차 사용 가능한 메모리가 줄어드는 모습을 보여주었다. 사용 가능한 메모리가 줄어들면서 TPS도 급감하였다. (날짜가 변경되어서 그런지 Scouter에서 Heap 메모리 로그가 전부 보이지 않는데 100M부터 점차 사용량이 증가하였다.)

Spring Data JPA 2.2.4

2시간 정도 수행하였는데도 600M 아래로 사용하고 있고 TPS 저하 현상도 보이지 않았다.

무엇을 하려고 했던 걸까?

위의 PR에서 보다 시피 이전 코드는 ParameterBinder를 생성하고 Map에 저장하여 재사용하려고 했고 변경된 코드는 ParameterBinder를 생성한 뒤에 별다른 작업 없이 바로 반환해주고 있다. 이전 코드에서는 생성 비용을 줄이려고 Map에 저장한 뒤에 재사용하는 것을 의도했지만 키로 사용한 ParameterMetadata객체의 동일성을 보장해주지 못해 메모리 누수가 발생한 것으로 보인다. 실제로 debugger로 확인했을 때 동일한 인수임에도 Map의 크기가 호출할 때마다 늘어나는 것을 볼 수 있었다.