와탭 블로그

전체보기

Java Process 메모리 추적기

2020년 08월 21일

와탭 수집서버 애플리케이션은 Java로 구현되어 있습니다.
UI를 담당하는 Front, 데이터 저장을 담당하는 Yard, 데이터 수신을 담당하는 Proxy 와 같이 각각 역할별로 이름 붙였습니다.

그중 몇몇 모듈이 이해되지 않을 만큼 메모리 사용량이 높아 추적을 시작하기로 했습니다.

memory chart 애플리케이션 시작 시점 메모리 사용량이 급증하고 이후로 줄어들지 않습니다.
alert message 간간히 날아오는 이 알람이 저를 불편하게 했습니다.

Java Heap 사이즈는 1Gb 인데 왜 프로세스 메모리는 2.6Gb 일까?

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

Java Heap = -Xms1g -Xmx1g

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

whatap 8925 8891 4 Aug12 ? 01:10:27 /data/whatap/lib/jdk/bin/java -Xms1g -Xmx1g -XX:OnOutOfMemoryError=kill -9 %p -javaagent:/data/agent/whatap.agent-2.0_15.jar -Duser.timezone=GMT -Dwhatap.name=awsSel.pa01 -Dwhatap.okind=awsSel.pa -Dwhatap.server.home=/data/whatap -Dwhatap.conf.path=/data/whatap/conf -XX:+UseG1GC -XX:+UseStringDeduplication -Dfile.encoding=UTF-8 -Djava.net.preferIPv4Stack=true -jar /data/whatap/lib/whatap.server.account-1.9.8.3371.jar

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

process memory usage

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

Heap memory chart Heap 1G는 여유가 넘치고 있습니다.
memory usage(byte) chart vm에 Account만 달랑 떠 있는데 메모리 사용량이 왜 이렇게 높습니까..

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

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

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

1단계 - NativeMemory 추적 옵션으로 확인하기

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

-XX:NativeMemoryTracking=detail

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

환경Heap Process Memory
운영 -Xms1g -Xmx1g 2.65g
테스트-Xms512m -Xmx512m 2g
heap size 무려 2Gb 를 넘게 사용하고 있습니다.!

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

jcmd <pid> VM.native_memory detail
Native Memory Tracking Option 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/

pmap -x <pid> 
Native Memory Tracking 01

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

pmap -x 15597 |sort -k 3 -n -r |more
Native Memory Tracking 02

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

vi /proc/<pid>/smaps

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

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

Native Memory Tracking 03

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

3단계 - gdb 로 dump 확인하기

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

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

7f49e0000000-7f49e3ff9000 64Mb #1
7f49e8000000-7f49ebffa000 64Mb #2
7f49f0000000-7f49f3ffa000 64Mb #3
7f49f8000000-7f49fbff9000 64Mb #4
7f4a00000000-7f4a03ff9000 64Mb #5

gdb 를 사용해 attach 합니다.

gdb -pid <pid>
gdb attach

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

(gdb) dump memory /tmp/dump_1 0x7f49e0000000 0x7f49e3ff9000
(gdb) dump memory /tmp/dump_2 0x7f49e8000000 0x7f49ebffa000
(gdb) dump memory /tmp/dump_3 0x7f49f0000000 0x7f49f3ffa000
(gdb) dump memory /tmp/dump_4 0x7f49f8000000 0x7f49fbff9000
(gdb) dump memory /tmp/dump_5 0x7f4a00000000 0x7f4a03ff9000

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

strings /tmp/dump_1 
strings dump

이런것도 보이고.

strings dump

이런 것도 보입니다.

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

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

메모리 덤프 내역을 바탕으로 가설을 세웠습니다.
가설 : 이 정보는 jar 모듈 압축이 해제된 내용들이다.

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

jar -xvf whatap.server.account.jar #압축을 풀고
find ./ -type f |xargs cat > is_looks_like_memory_dump #파일을 하나 만듭니다. 

확인해 보았습니다.

strings ./is_looks_like_memory_dump |more

똑같이 생겼습니다!!

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

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

sudo service account restart && sleep 3 && ./jstack `pgrep -f whatap.server.account`  
stack

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

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

InflaterInputStream 관련 버그를 확인했습니다. 현상과 정확히 일치합니다.
https://github.com/spring-projects/spring-boot/pull/14001

5단계 - 결론

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

마무리

Java의 Native Memory

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

이후에...

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

IT 서비스를 운영한다면 필요한 와탭 모니터링 솔루션, 지금 시작해보세요.

와탭 무료로 시작하기
송재진(jjsong@whatap.io)
Operation TeamLead Engineer
<  이전 글

다음 글  >

최신글