Native Memory Leak Detection.
1. 개요
java.lang.OutOfMemoryError: Direct buffer memory
협력 업체에서 통신이 안된단 연락을 받고 해당 프로세스의 로그를 열었을 때 위 에러가 제일 먼저 반겨주었다. Java는 일반적으로 Heap 메모리 영역을 이용하는 경우 JVM에서 관리를 하지만, Direct Buffer를 이용해 네이티브 메모리 영역을 사용하는 경우도 있다. 일례로 java.nio.DirectByteBuffer를 이용하는 경우인데, HeapByteBuffer와 다르게 DirectByteBuffer는 성능적으로 유리하단 점이 있어 DirectMemoryAccess(DMA)를 활용한다. 그런고로 Heap Memory 처럼 Garbage Collecting 이 이뤄지지 않기 때문에 사용자가 직접 이용한 메모리를 해제해줘야한다.
2. Netty
해당 프로세스는 Netty 란 프레임워크를 사용 중이다. NIO 서버, 클라이언트 프레임워크로서 TCP 요청 및 응답을 주고 받기 위해 사용 중이다. Netty 프레임워크에는 ByteBuffer를 직접적으로 사용하는 ByteBuf 란 클래스가 있다. Netty의 데이터 컨테이너로서 nio ByteBuffer에서 확장해 버퍼풀, 쓰기/읽기의 인덱스 분리 등을 지원한다. ByteBuf에서도 heap 또는 native 메모리 영역을 선택해서 이용할 수 있는데, io.netty.ByteBufAllocator를 통해 메모리 allocate가 가능하다.
ByteBuf heapBuf = ByteBufAllocator.DEFAULT.heapBuffer();
ByteBuf directBuf = ByteBufAllocator.DEFAULT.directBuffer();유의할 점은 앞서 밝혔지만, directBuffer 로 natvie memory 영역을 이용하는 경우 JVM, GC 에서 감지할 수 없어 명시적인 해제가 필요하다.
// directBuf.release();
// ByteBufAllocator로 memroy allocated 했을 때 ReferenceCountUtil을 이용할 수 있다.
ReferenceCountUtil.safeRelease(directBuf);3. 메모리 Leak Detecting
위와 같은 사전 지식에 기반하여 Memory Leak Point 추적을 시작해보자. 우선, JVM 옵션을 추가해야한다.
-XX:NativeMemoryTracking=summary
or
-XX:NativeMemoryTracking=detail위 기능을 통해 Java 어플리케이션의 native memory를 트랙킹할 수 있다. 위 설정을 추가한 다음 baseline을 지정해줘야 하는데, 위 기능에서 기준점 대비 메모리 증감을 볼 수 있도록 한다.
jcmd {PID} VM.native_memory baseline명령어를 실행했을 때 {PID} Baseline succeed. 란 메시지가 출력되면 기준점 설정이 완료됐단 뜻이다. 이후 jcmd 명령어를 통해 메모리 영역의 상황을 확인해보자.
jcmd {pid} VM.native_memory summary.diff
Native Memory Tracking:
Total: reserved=1607231KB +4027KB, committed=353295KB +4027KB
- Java Heap (reserved=131072KB, committed=131072KB)
(mmap: reserved=131072KB, committed=131072KB)
- Class (reserved=1115164KB +2KB, committed=74100KB +2KB)
(classes #11777 +2)
(malloc=5148KB +2KB #22604 +51)
(mmap: reserved=1110016KB, committed=68952KB)
- Thread (reserved=41554KB, committed=41554KB)
(thread #41)
(stack: reserved=41120KB, committed=41120KB)
(malloc=131KB #204)
(arena=303KB #80)
- Code (reserved=257280KB +14KB, committed=44408KB +14KB)
(malloc=7680KB +14KB #10801 +12)
(mmap: reserved=249600KB, committed=36728KB)
- GC (reserved=8268KB, committed=8268KB)
(malloc=3472KB #298 +1)
(mmap: reserved=4796KB, committed=4796KB)
- Compiler (reserved=255KB +5KB, committed=255KB +5KB)
(malloc=125KB +5KB #314 +8)
(arena=131KB #3)
- Internal (reserved=35454KB +4006KB, committed=35454KB +4006KB)
(malloc=35422KB +4006KB #15774 -9)
(mmap: reserved=32KB, committed=32KB)
- Symbol (reserved=15113KB, committed=15113KB)
(malloc=12899KB #134203 +2)
(arena=2214KB #1)
- Native Memory Tracking (reserved=2892KB +1KB, committed=2892KB +1KB)
(malloc=9KB #114)
(tracking overhead=2883KB +1KB)
- Arena Chunk (reserved=178KB, committed=178KB)
(malloc=178KB)
여기서 주목할 부분은
- Internal (reserved=35454KB +4006KB, committed=35454KB +4006KB)
(malloc=35422KB +4006KB #15774 -9) (mmap: reserved=32KB, committed=32KB)
이다 . 기준점 설정 이후 internal 메모리를 나타내는 부분인데, 해당 영역이 늘어난 것은 괜찮다. 정상적으로 메모리 해제가 된다면 다시 기준점으로 돌아가거나 몇 KB 차이 안나는 수준으로 떨어질 것이므로 정상적인 동작으로 판단할 수 있다. 단, 위 영역이 줄어들지 않고 늘어나기만 하는 경우 시간이 흐른 뒤에 결국,
java.lang.OutOfMemoryError: Direct buffer memory 가 log에 찍히는 것을 볼 수 있다. 실제로 네이티브 메모리 누수가 추정되는 위 프로세스는 시간이 지날 수록 internal 영역이 계속 늘어나기만 하고 있어 native memory leaking을 확신할 수 있었다.
- Internal (reserved=35582KB +4134KB, committed=35582KB +4134KB)
(malloc=35550KB +4134KB #15790 +7) (mmap: reserved=32KB, committed=32KB)
Native Memory 누수를 확신한 이후의 스텝은 코드 추적을 통해 판단 가능한 영역이지만, 비즈니스 로직이 복잡하게 얽혀있는 경우 그마저도 쉽지 않아 약간의 힌트가 필요하다.
pmap과 smaps
OutOfMemoryError가 Heap Memory 에서 발생한 경우, Heap dump를 발생하게 해 Heap Dump 분석이 용이했겠지만, non-heap 영역에서 발생했으므로, 메모리 덤프를 확인해야 한다. pmap 명령어의 경우 프로세스 아이디를 기준으로 프로세스의 메모리 맵을 출력하는 리눅스의 명령어이다. -x 옵션은 확장된 포맷으로 출력을 해주어 Address, Kbytes, RSS 등을 확인할 수 있는 옵션이다.
pmap -x {pid}
Address Kbytes RSS Dirty Mode Mapping
0000000000400000 4 4 0 r-x-- java
0000000000600000 4 4 4 rw--- java
0000000000d67000 404 308 308 rw--- [ anon ]
00000000f8000000 139648 80208 80208 rw--- [ anon ]
0000000100860000 1040000 0 0 ----- [ anon ]
00000030afe00000 128 116 0 r-x-- ld-2.12.so
00000030b0020000 4 4 4 r---- ld-2.12.so
00000030b0021000 4 4 4 rw--- ld-2.12.so
00000030b0022000 4 4 4 rw--- [ anon ]
00000030b0200000 1576 696 0 r-x-- libc-2.12.so
00000030b038a000 2048 0 0 ----- libc-2.12.so
00000030b058a000 16 16 8 r---- libc-2.12.so
00000030b058e000 8 8 8 rw--- libc-2.12.so
00000030b0590000 16 16 16 rw--- [ anon ]
00000030b0600000 524 56 0 r-x-- libm-2.12.so
00000030b0683000 2044 0 0 ----- libm-2.12.so
00000030b0882000 4 4 4 r---- libm-2.12.so
00000030b0883000 4 4 4 rw--- libm-2.12.so
00000030b0a00000 8 8 0 r-x-- libdl-2.12.so
00000030b0a02000 2048 0 0 ----- libdl-2.12.so
00000030b0c02000 4 4 4 r---- libdl-2.12.so
00000030b0c03000 4 4 4 rw--- libdl-2.12.so
00000030b0e00000 92 72 0 r-x-- libpthread-2.12.so
00000030b0e17000 2048 0 0 ----- libpthread-2.12.so
00000030b1017000 4 4 4 r---- libpthread-2.12.so
00000030b1018000 4 4 4 rw--- libpthread-2.12.so
00000030b1019000 16 4 4 rw--- [ anon ]
00000030b1600000 28 20 0 r-x-- librt-2.12.so
00000030b1607000 2044 0 0 ----- librt-2.12.so
00000030b1806000 4 4 4 r---- librt-2.12.so
00000030b1807000 4 4 4 rw--- librt-2.12.so
00000030bc200000 88 16 0 r-x-- libgcc_s-4.4.7-20120601.so.1
00000030bc216000 2044 0 0 ----- libgcc_s-4.4.7-20120601.so.1
00000030bc415000 4 4 4 rw--- libgcc_s-4.4.7-20120601.so.1
.
.
. 이하 생략정렬 기준이 메모리 주소로 정렬되어 아래와 같이 RSS(Resident Set Size) 기준으로 다시 정렬한다.
pmap -x {PID} | sort -k 3 -n -r | more
00000000f8000000 139648 80208 80208 rw--- [ anon ]
00007f448409f000 64900 63488 63488 ----- [ anon ]
00007f447c02b000 65364 59392 59392 ----- [ anon ]
00007f44c5000000 36160 36144 36144 rwx-- [ anon ]
00007f4480bfe000 28676 28676 28676 rw--- [ anon ]
00007f449c000000 41820 24576 24576 rw--- [ anon ]
00007f44a0000000 19180 19156 19156 rw--- [ anon ]
00007f44d4000000 18428 16808 16808 rw--- [ anon ]
00007f44d8034000 14396 13256 13256 rw--- [ anon ]
00007f44c43ce000 10592 10392 10392 rw--- [ anon ]
.
.
. 이하 생략맨 위의 00000000f8000000 주소는 128mb로 설정한 java heap 영역이라 제외 하고 smaps 명령어로 자세하게 확인해본다. smaps의 경우 프로세스 단위로 mapping된 메모리 정보를 훨씬 더 디테일하고 상세하게 볼 수 있는 명령어이다.
smaps 를 검색할 때 pmap 상 주소값에서 앞의 0000은 떼고 검색한다.
vi /proc/{PID}/smaps
7f447c000000-7f447c02b000 rw-p 00000000 00:00 0
Size: 172 kB
Rss: 172 kB
Pss: 172 kB
Shared_Clean: 0 kB
Shared_Dirty: 0 kB
Private_Clean: 0 kB
Private_Dirty: 172 kB
Referenced: 172 kB
Anonymous: 172 kB
AnonHugePages: 0 kB
Swap: 0 kB
KernelPageSize: 4 kB
MMUPageSize: 4 kB
VmFlags: rd wr mr mw me nr
7f447c02b000-7f4480000000 ---p 00000000 00:00 0
Size: 65364 kB
Rss: 0 kB
Pss: 0 kB
Shared_Clean: 0 kB
Shared_Dirty: 0 kB
Private_Clean: 0 kB
Private_Dirty: 0 kB
Referenced: 0 kB
Anonymous: 0 kB
AnonHugePages: 0 kB
Swap: 0 kB
KernelPageSize: 4 kB
MMUPageSize: 4 kB
VmFlags: mr mw me nr
7f4480bfe000-7f44827ff000 rw-p 00000000 00:00 0
Size: 28676 kB
Rss: 28676 kB
Pss: 28676 kB
Shared_Clean: 0 kB
Shared_Dirty: 0 kB
Private_Clean: 0 kB
Private_Dirty: 28676 kB
Referenced: 28672 kB
Anonymous: 28676 kB
AnonHugePages: 26624 kB
Swap: 0 kB
KernelPageSize: 4 kB
MMUPageSize: 4 kB
VmFlags: rd wr mr mw me ac
7f4484000000-7f448409f000 rw-p 00000000 00:00 0
Size: 636 kB
Rss: 624 kB
Pss: 624 kB
Shared_Clean: 0 kB
Shared_Dirty: 0 kB
Private_Clean: 0 kB
Private_Dirty: 624 kB
Referenced: 532 kB
Anonymous: 624 kB
AnonHugePages: 0 kB
Swap: 0 kB
KernelPageSize: 4 kB
MMUPageSize: 4 kB
VmFlags: rd wr mr mw me nr
7f448409f000-7f4488000000 ---p 00000000 00:00 0
Size: 64900 kB
Rss: 0 kB
Pss: 0 kB
Shared_Clean: 0 kB
Shared_Dirty: 0 kB
Private_Clean: 0 kB
Private_Dirty: 0 kB
Referenced: 0 kB
Anonymous: 0 kB
AnonHugePages: 0 kB
Swap: 0 kB
KernelPageSize: 4 kB
MMUPageSize: 4 kB
VmFlags: mr mw me nr여기서 RSS 값이 수상하게 높은 메모리 주소 값들을 여러 개 확보해 기록해둔다.
다음 스텝은 gdb 명령어로 memory dump.
gdb -pid 11679
...
(gdb) dump memory {dump 위치}/dump1 0x7f447c02b000 0x7f4480000000
(gdb) dump memory {dump 위치}/dump2 0x7f4480bfe000 0x7f44827ff000
(gdb) dump memory {dump 위치}/dump3 0x7f448409f000 0x7f4488000000
(gdb) dump memory {dump 위치}/dump4 0x7f4484000000 0x7f448409f000위 명령어를 통해 attach 하고 위에서 확보한 주소의 dump 실행한다. 참고할 점은 확보한 주소에 0x를 붙여 Hex로 표기해줘야한다. 이후 생성된 파일들을 strings 명령어를 통해 인간이 알아볼 수 있는 문자들을 확인한다.
strings dump1 | more
strings dump2 | more와 같이 dump 파일들을 확인하는데, dump2 파일에서 기동 이래로 특정 TCP 통신 전문들이 모두 네이티브 메모리 영역에 쌓여있는 것을 확인할 수 있었다. TCP 전문을 처리하는 곳에서 native memory를 이용하고선 해제 하지 않은 것이고, 처음엔 문제가 되지 않았지만 이렇게 전문들이 계속 쌓이다보면 결국 OutOfMemoryError가 발생하는 것으로 추정했다.
4. 소스 수정
누수 포인트를 찾았으니 소스를 수정하고 한동안 모니터링한다. Netty 의 ReferenceCountUtil을 통해 명시적으로 ByteBuf 참조를 해제시킨다.
InboundHandler.java
try {
// business logic
byteBuf = ByteBufAllocator.DEFAULT.directBuffer();
} catch (Exception e) {
// exception handling
} finally {
ReferenceCountUtil.safeRelease(byteBuf);
}특히, Netty 는 인바운드 핸들러를 통해 생선된 byteBuf 는 자동으로 해제되지 않는다.
cf. https://javacoding.tistory.com/149
safeRelease메소드는 이미 해제된 byteBuf 를 다시 해제 시도하는 경우 Exception을 발생시키지 않고 log 로만 남긴다. (release를 이용하는 경우엔 Exception이 발생함.)
5. 결과 모니터링
테스트 서버에 반영 이후 경과를 지켜본다. 신속한 테스트를 위해 아래와 같은 1초에 한 번씩 TCP 전문을 쏘는 클라이언트 프로그램을 만들어 실행시켰다.
try {
socket = new Socket(IP, PORT);
for (int i = 0; i < 99999; i++) {
System.out.println("Time : " + LocalDateTime.now());
try {
TimeUnit.SECONDS.sleep(1);
OutputStream out = socket.getOutputStream();
String message = "전문내용";
byte[] data = message.getBytes("UTF-8");
out.write(data);
out.flush();
} catch (Exception e) {
e.printStackTrace();
}
}
} catch (Exception e) {
e.printStackTrace();
} finally {
socket.close();
}
아래와 같은 소스를 통해 실제 native memory 사용량을 확인하여도 되고, jcmd 명령어나, pmap, smaps, gdb 등을 그대로 이용하여 재확인해도된다.
OperatingSystemMXBean operatingSystemMXBean = (OperatingSystemMXBean) ManagementFactory.getOperatingSystemMXBean();
long usedNativeMemory = operatingSystemMXBean.getCommittedVirtualMemorySize() - operatingSystemMXBean.getFreePhysicalMemorySize();
logger.info("used direct memory after release : " + usedNativeMemory);Native Memory Tracking:
Total: reserved=1568938KB -1776KB, committed=300134KB -1648KB
- Java Heap (reserved=131072KB, committed=131072KB)
(mmap: reserved=131072KB, committed=131072KB)
- Class (reserved=1106642KB +1KB, committed=64298KB +1KB)
(classes #10151 +11)
(malloc=4818KB +1KB #15520 -36)
(mmap: reserved=1101824KB, committed=59480KB)
- Thread (reserved=43491KB, committed=43491KB)
(thread #43)
(stack: reserved=43176KB, committed=43176KB)
(malloc=138KB #214)
(arena=177KB #84)
- Code (reserved=254419KB -13KB, committed=27959KB +115KB)
(malloc=4819KB -13KB #7503 -10)
(mmap: reserved=249600KB, committed=23140KB +128KB)
- GC (reserved=8265KB, committed=8265KB)
(malloc=3469KB #215 +10)
(mmap: reserved=4796KB, committed=4796KB)
- Compiler (reserved=219KB, committed=219KB)
(malloc=89KB #251 +13)
(arena=131KB #3)
- Internal (reserved=8333KB -1805KB, committed=8333KB -1805KB)
(malloc=8301KB -1805KB #13563 -167)
(mmap: reserved=32KB, committed=32KB)
결과를 확인해봤을 때 인터널 메모리 값도 사용 이후 적절히 해제되는 것으로 사료된다. 메모리 dump를 떠서 봤을 때도 위와 같이 전문이 지속적으로 찍히는 현상은 일어나지 않는 것으로 보인다. 당분간의 모니터링은 더 필요하겠지만, memory 분석을 이쯤에서 마쳐도 될 것 같다.
'로직과의 사투 > Operational Issues' 카테고리의 다른 글
| 로깅 룰 구축기 (2) - Jersey에 적용하기 (0) | 2023.09.26 |
|---|---|
| 로깅 룰 구축기 (1) (0) | 2023.09.26 |