Java 애플리케이션 메모리 누수(Memory leak) 잡기

결론

💥 건 수 많은 데이터 처리할 때 Nested Map 사용 주의!

1. 작업 내용

File To MongoDB 애플리케이션을 개발해야 한다. raw 파일 데이터에서 “idx” 필드를 KEY 로 잡아 그룹핑 후 “seq” 순으로 “item”값을 연속으로 붙여 MonoDB 에 적재하는 작업이다.

raw 파일 데이터는 2GB에 1100만 건으로 건수가 굉장히 많은 형태라 속도 측면에서 걱정이 많았다. 그렇게 개발을 끝내고 애플리케이션을 실행했고..

application.log

2022-09-28 09:15:40.894  save start... 10000/2900873
2022-09-28 09:16:05.654  total count: [1507616] after saving // 25 초 
...
2022-09-28 11:50:44.135  save start... 2240000/2900873
2022-09-28 11:54:47.320  total count: [3115333] after saving // 4분...?

2022-09-28 11:54:47.321  save start... 2250000/29008
...
2022-09-28 11:57:07.447 ERROR Application run failed
java.lang.OutOfMemoryError: GC overhead limit exceeded       // o-<-<

?!?!

1만 건당 25초에서 점점 느려져 4분으로 치닫더니 결국 OutOfMemoryError 로 터지고 말았다.

2. OOM 원인 분석

속도가 점점 느려지는 경우는 경험상 Full GC 가 빈번하게 일어나는 경우였다. 그래서 이를 확인해보기 위해 애플리케이션을 재실행시키고 jstat 으로 힙 메모리 추이를 지켜보았다.

1) jstat

JVM 힙 메모리 상태를 실시간으로 파악할 수 있는 툴이며 JDK 11은 다운받을 때 포함되어있어 별도 설치는 필요 없다.

jstat -gc 3000 {PID}

: 3000ms(3초) 마다 힙 메모리 상태 출력

※ 데이터가 제목열에 비해 오른쪽으로 조금씩 치우쳐져 있다.

https://sergiomartinrubio.com/articles/java-memory-model-overview/

힙 메모리의 상황을 스냅샷처럼 찍어 3초마다 한 라인씩 출력한다. 내가 발견한 이상한 점은 아래와 같았다.

정상적이라면 S0U (S0 Usage), S1U (S1 Usage) 가 번갈아가면서 한쪽이 채워지면 한쪽이 비워지는 양상이어야하는데 둘 다 채워지고 있지 않다.
YGC (Youg GC count) 는 발생하지 않는데 FGC (Full GC count) 만 쭉쭉 올라간다.
FGCT (Full GC Time) 을 보면 Full GC 한 번에 4~5초의 긴 시간이 걸린다.
Full GC 가 일어남에도 불구하고 OU (Old generation Usage) 는 전혀 해소되지 않는다.

2) GC overhead limit exceeded

java.lang.OutOfMemoryError: GC overhead limit exceeded       // o-<-<

GC overhead limit exceeded 가 출력되는 원인을 찾아보니 CPU가 GC에 에너지를 많이 쏟지만 정작 확보되는 메모리는 얼마 되지 않는 경우 라고 한다. (This message means that for some reason the garbage collector is taking an excessive amount of time (by default 98% of all CPU time of the process) and recovers very little memory in each run (by default 2% of the heap).)

그래, OOM의 원인은 할당된 메모리가 제대로 반환되지 않는 memory leak 이었다.

그럼 어디 부분에서 메모리를 꽉 잡고 있는지 확인해볼까?

3. Memory leak 발생 장소 찾기

1) Eclipse MAT(Memory Analyzer Tool)

MAT 을 활용하면 힙 메모리 덤프 파일을 분석하여 memory leak 이 의심가는 부분을 시각화할 수 있다. 여기 에서 다운받아 MemoryAnalyzer.exe 를 실행하면 된다.

툴은 준비됐고 힙 메모리 덤프 파일은 어디서 공수하는가? MAT 에서도 덤프를 내려받는 메뉴가 있어 시도해보았지만 에러가 났다. 그래서 원래 하던대로 jmap 으로 덤프를 내려받았다.

jmap -dump:file=/path/to/file [pid]

덤프 파일을 MAT 에서 읽어들여 이곳저곳 탐색해보니 의심가는 정황을 발견하였다.

itemMap 이 눈에 튀게 다른 인스턴스 변수보다 1.7GB나 잡고 있었다. itemMap은 idx 키 값으로 엮여있는 Nested HashMap 구조이다.

Map<String, Map<Integer, String>> itemMap

{"idx": "1", {{"seq": 1, "item" : "101"}, {"seq": 2, "item" : "102"}}}
{"idx": "2", {{"seq": 3, "item" : "203"}, {"seq": 1, "item" : "201"}, {"seq": 4, "item" : "204"}}}
...
{"idx": "2900000",{...}}

key 만 약 290,0000 개...
value 요소 전부 합치면 1,110,000 개...

그렇다. 파일 데이터를 자료구조에 그대로 매핑시키려다보니 어마어마한 개수의 Map 과 데이터를 꽉 쥐고 있었기 때문에 아무리 GC가 발생해도 해소가 안 됐던 것이었다.

💡 Retained Heap: 해당 객체가 참조한 모든 객체의 메모리까지 합한 크기. GC 할 때 비워지는 공간

4. Memory leak 해결

itemMap 사이즈를 최대한 줄여보는 게 관건이었다. itemMap 을 메모리에 담는 목적은 몽고DB 에 다음 형태로 삽입하기 위함이다.

To. MongoDB

{"idx": "1", "items" : "101,102"}
{"idx": "2", "items" : "201,,203,204"}

items 필드에는 seq 순서대로 item 값을 담아야 한다. 그래서 기존 itemMap 은 seq 값까지 파일 구조 그대로 메모리에 모두 담은 뒤에 몽고DB 에 삽입하기 직전에 items 만들기 연산 (seq 순서대로 item 값을 이어붙이기) 을 수행하고 삽입하는 방식이었다.

items 만들기 연산

하지만 생각해보니 서브 Map 을 만들고 seq 까지 담고 이걸 애플리케이션 실행 내내 굳이 들고 있을 필요는 없었다. 몽고DB 삽입 직전이 아닌 애플리케이션 실행 후 파일을 읽는 그 시점에 items 만들기 연산을 미리 수행하면 공간 낭비를 줄일 수 있을 것이다.

Map<String, List<String>> itemMap

그래서 itemMap 구조를 value 가 HashMap 이 아닌 ArrayList 형태로 변환 후 로직을 변경하고 애플리케이션을 재실행해봤다.

그 결과

MAT

itemMap의 메모리 점유율은 약 50% 감소하였고

jstat

heap memory 상태도 memory leak 의 양샹이 눈에 띄지 않았다.

S0U, S1U 번갈아가면서 채움, 비움 반복
FGC 빈번 X, YGC 정상 수행
길지 않은 GCT (GC Time)