Java Process 메모리 추적기

Java 프로세스 메모리 증가하는 이유

Java Heap 사이즈는 1Gb 인데 왜 프로세스 메모리는 2.6Gb 입니다. 와탭 서비스의 여러 모듈 중 고객 계정 정보를 관리하는 account 모듈이 있습니다. 다른 모듈에 비해 특별히 많은 일을 하지도 않고 CPU 사용량도 낮은데 유독 메모리 사용량만 높습니다. 비슷한 증상을 보이는 Notihub 모듈도 있습니다. Notihub는 발생한 이벤트를 SMS, Email, Slack 등으로 알려주는 역할을 하고 있습니다. 꽤 오랫동안 묶어있는 인지하고 있는 이슈 지만 이제라도 원인 추적을 하기로 했습니다.

Java Heap = -Xms1g -Xmx1g

Springboot 로 구현된 Account 의 Heap Size 는 1Gb 로 설정되어 있습니다.

1Gb Heap 을 사용하지만 프로세스 메모리 사용량은 2.65Gb 입니다.

Heap 사용 패턴은 별 문제가 없습니다.

Heap 1G는 여유가 넘치고 있습니다.

Native 영역에는 무슨 일이 일어나고 있을까요?

2.65Gb 의 전체 메모리 사용량 중 Java Heap 1Gb 를 제외한 나머지 1.65Gb 는 Native 메모리 영역입니다.

그렇다면, 부하도 적은 시간대에 복잡한 처리 없이 인증/권한 정보만을 제공하는 계정 관리 모듈에서 Heap 보다 1.5배 더 큰 메모리는 왜 사용 되고 있는 것 일까요?
Heap 이슈는 Java의 Heap Dump를 들여다 보면 되지만 Native 영역은 어떻게 확인하고 추적해야 할까요?

1단계 - Native Memory Tracking

Native Memory 추적의 시작은 옵션을 적용하고 데이터를 들여다 보는 것 입니다.

이 과정에 대한 내용은 Oracle Trouble Shoot 가이드에 친절히 설명되어 있습니다.

https://docs.oracle.com/javase/8/docs/technotes/guides/troubleshoot/tooldescr007.html](https://docs.oracle.com/javase/8/docs/technotes/guides/troubleshoot/tooldescr007.html

운영 환경에 위 옵션을 적용하기 찝찝하므로 같은 증상을 보이는 테스트 환경에서 시도합니다. 운영 환경과의 차이점은 Heap Size 이며 증상은 동일합니다.

무려 2Gb 를 넘게 사용하고 있습니다.!

NativeMemoryTracking 옵션을 적용한 상태에서 jcmd 명령을 사용해 확인해 보았습니다.

800Mb committed!

reserved 는 가용할 수 있는 메모리 영역, committed 는 실제 사용 중인 영역을 의미합니다. 분명 제 눈으로 2Gb 를 확인했는데 java 에서는 Heap 다 합쳐서 800Mb 남짓만 사용하는 것으로만 알고 있습니다.

나머지 1.2Gb 가 넘는 메모리는 jvm 도 모르는 길 잃은 친구들 입니다.

2단계 - pmap 과 smaps로 OS 시각에서 확인하기

jcmd 명령으로 확인한 사용량은 800Mb 입니다. JVM 은 800Mb만을 사용한다고 알고 있는 것이지요. 그렇다면 길 잃은 1.2Gb는 뭘로 추적해야 할까요?

JVM은 모른다고 합니다. 그러니 OS 시점에서 프로세스 메모리 정보를 봐야겠습니다. pmap 명령어를 사용하면 process의 memory map 을 확인 할 수 있습니다. https://www.howtoforge.com/linux-pmap-command/

눈에 잘 안들어 옵니다. RSS 기준으로 정렬해 다시 확인 해 봤습니다.

Total 2152720, 2Gb 이상 쓰고 있다고 나옵니다.
00000000e0000000 주소는 512Mb 로 설정한 Java Heap, 나머지는 최대 64Mb 단위로 나뉘어진 Native 영역입니다. /proc/<pid>/smaps 에서 주소 별로 차근차근 확인 해 보겠습니다.

pmap 결과보다 조금 더 상세한 정보를 제공하는 smap 에서 메모리 주소 범위를 확보합니다.

pmap 주소에서 앞자리 0 4개를 제외한 값은 smaps 의 시작 주소와 동일합니다.
프로세스가 차지하는 메모리를 나타내는 지표로 pss 를 확인 합니다. 시작 주소 00000000e0000000 인 Heap은 제외합니다.

실제 내역을 확인하기 위해 64Mb 크기로 나누어진 pss 값이 높은 메모리 주소를 여러 개 확보 합니다.

3단계 - gdb로 메모리 dump하기

메모리의 내용을 들여다보기 위해서 gdb 로 메모리 덤프를 확보합니다. https://www.gnu.org/software/gdb/

2단계 pmap 결과에서 나온 64Mb 단위 메모리 주소를 5개 정도 확보 해 메모장에 잘 적어 두었습니다.

gdb 를 사용해 attach 합니다.

확보한 주소로 dump 합니다. 16진수라 앞에 0x 붙입니다.

확보한 gdp 메모리 덤프 분석에 특별한 도구는 없으므로 strings 명령으로 dump 에서 문자열을 추출하고 눈으로 확인 합니다.
https://www.howtoforge.com/linux-strings-command/

이런것도 보이고.

이런 것도 보입니다.

많이 이상합니다. 분명히 JVM 이 놓친 구간의 메모리 정보를 확인했는데 죄다 Java Class, pom.xml 내용들 입니다.

4단계 - 추론하고 검증하기

메모리 덤프 내역을 바탕으로 가설을 세웠습니다.

가설 검증을 위해 jar 파일 하나를 골라 압축을 해제하고 이를 합하고 strings 로 문자열을 추출 해 보았습니다.

확인해 보았습니다.

똑같이 생겼습니다!!

jar 압축을 풀고 합친 후 문자열만을 추출한 내용과 메모리 덤프 내용은 똑같이 생겼습니다. 즉, 애플리케이션 실행 과정에서 사용된 정보들이 아닌 압축 해제된 jar 내용들이 메모리에 남아 길을 잃고 있었던 것입니다.

메모리는 애플리케이션 시작 시점 증가 했으므로 jar 압축이 해제 할만한 시간대의 Stack 정보를 확인 해 보았습니다.

빙고!!! "ZipInflaterInputStream" 올레! "hibernate"

서두에서 몇몇 모듈만 이 현상을 보인다고 했었는데 hibernate가 보입니다. 딱 들어맞습니다. 메모리 사용량으로 문제를 일으키는 모듈의 공통점은 hibernate를 사용하고 있는 것이었습니다.

InflaterInputStream 관련 버그를 확인했습니다. 현상과 정확히 일치합니다.

5단계 - 결론

Springboot의 Bug로 ZipInflaterInputStream.close() 가 Native Memory 를 해제하지 못했고 이로 인해 불필요하게 Gb 단위로 메모리를 점유하고 있었습니다. 이를 해결하기 위해서는 core 모듈인 org.springframework.boot.loader.JarFileEntries.class 가 업데이트 되어야 합니다.

Java Native Memory Tracking

그리 복잡하지 않음에도 Native Memory 영역을 들여다 보는 일을 어렵게 생각하는 분들이 많습니다. 과거에 Heap 영역에 존재하던 것 들이 Java8 이후부터 Native Memory 영역으로 대거 이사했습니다. 그래서인지 최근에는 Heap Dump뿐 아니라 Native Memory 영역을 계속 들여다 볼 일이 생기고 있습니다. 기본적인 지식이 있다면 꼭 개발자가 아니라도 위 과정과 같이 smaps 와 gdb를 사용해 Native Memory 영역을 분석 할 수 있으리라 생각합니다.

결과

테스트를 위해 SpringBoot 업그레이드 한 후 기동 했을 때 메모리 사용량이 2Gb에서 800Mb(Heap 512Mb)로 낮아진 것을 확인했습니다. 개발 부서 담당자에게 분석 내용과 Bug를 공유했습니다. 다만, SpringBoot 업그레이드 후 검증해야 할 부분이 너무 많아 차기 Major 과제로 진행 할 예정입니다