JMap, JHat으로 Heap Dump 분석

 프로덕션에서 돌아가는 프로그램이라면 그것이 어떤 종류이건간에  Out of Memory 또는 가비지 컬렉터(GC) Out of Memory의 가능성을 염두 해 두어야 한다. 어떤 프로그램이 테스팅 또는 스테이징 환경에서 문제 없이 돌아간다 하더라도 프로덕션에서는 다른 행동을 보일 수 있다. 엔지니어들이 제대로 테스팅을 하지 않아서가 아니라 프로덕션의 로드(load)가 다르고 프로덕션에서 사용하는 데이터가 테스팅 환경의 데이터와 다르고, 또 유저들이 꼭 엔지니어들이 의도한 대로 프로그램을 사용하지 않기 때문이다. 자바는 가비지 컬렉터(Garbage Collector) 덕분에 엔지니어가 일일히 메모리 관리를 하지 않아도 되지만, 그렇다고 Out of Memeory에러에서 자유롭다고 할 수 없다.

 이렇게 프로그램이 OOM(Out of Memory)으로 인해 종료되거나 시스템의 속도가 저하되는 것을 Memory Leak이라고 하는데 코드의 양이 많고 클 수록, 프로그램이 분산/병렬로 돌아 갈 수록, 또 테스팅 환경에서는 같은 버그를 확인 할 수 없는 경우 근본 원인(Root Cause)를 찾아내기가 힘들다. 이럴 때 프로덕션 프로그램의 힙 덤프(Heap Dump)를 분석한다면 메모리 유출(Memory Leak)이 어디서 발생하는지 찾아 낼 수 있다.

Out of Memory Errors

 OOM에러에는 여러가지가 있지만 이 포스트에서는 대표적으로 두 가지만 소개하도록 한다.

java.lang.OutOfMemorryError: heap space

Exception in thread "Thread-28" java.lang.OutOfMemoryError: Java heap space
    at java.util.Hashtable.rehash(Hashtable.java:402)
    at java.util.Hashtable.addEntry(Hashtable.java:426)
    at java.util.Hashtable.put(Hashtable.java:477)
    at com.sun.tools.hat.internal.model.Snapshot.rootsetReferencesTo(Snapshot.java:463)
    at com.sun.tools.hat.internal.server.RootsQuery.run(RootsQuery.java:74)
    at com.sun.tools.hat.internal.server.HttpReader.run(HttpReader.java:190)
    at java.lang.Thread.run(Thread.java:748)

 이 에러는 보통 프로그램이 자바의 힙(heap) 공간을 전부 사용해서 더 이상 오브젝트를 힙 공간에 할당 할 수 없다는 뜻이다. 이 에러가 난다고 해서 항상 메모리 유출이 일어난다는 뜻은 아니다. 당신의 프로그램이 원채 메모리를 많이 요구하는 것 일 수도 있다. 그런 경우 다음과 같이 프로그램 시작시 힙 메모리 사이즈를 파라미터로 넘겨 해결 할 수 있다. (4g대신 원하는 메모리 사이즈 입력)

java -Xmx4g MyApplication

java.lang.OutOfMemoryError: GC Overhead limit exceed

 엔지니어들이 자바 프로그램에서 따로 메모리 관리를 하지 않아도 되는 이유는 가비지컬렉터가 주기적으로 돌며 사용하지 않는 오브젝트들을 제거 해 주기 때문이다. 가비지 컬렉터의 동작 방식은 시간이 된다면 다른 포스트에서 이야기하도록 하겠다. 중요한 것은 메모리 유출이 일어나거나 위 처럼 프로그램이 메모리가 원체 부족한 경우 가비지컬렉터가 힙 공간을 복구하지 못할 때 이 예외가 발생한다는 것이다. 오라클 문서(링크)에 따르면, 자바 프로세스가 약 98%의 시간을 가비지 컬렉터를 실행하는데 소모하고, 실행 이후에도 2% 이상의 힙 공간을 다섯 번 이상 확보하지 못하는 경우 이 예외가 발생한다. 

Heap Dump 분석

자바 프로세스에 더 큰 메모리를 할당하는 것은 위의 예외를 해결하는 한 방법이 될 수 있다. 그러나 이 방법은 당신의 프로그램 자체가 큰 경우이고, 메모리 유출이 일어나느 경우에는 결국 더 큰 메모리 조차도 꽉 차 또 같은 예외가 발생 할 것이다. 그런 경우 실행중인 자바 프로세스의 메모리 덤프를 받아 분석 하면 어디에서 메모리 유출이 일어나는지 찾아 낼 수 있다.

작업 환경 설정 정보

• Macbook Pro
• JDK : jdk1.8.0_202
• IDE : IntelliJ

예제 프로그램

 OOM 메모리를 내기 위해 다음과 같은 프로그램을 작성했다.

import java.util.HashMap;
import java.util.Map;

public class HeapDumpTest {
    private Map<Integer, MemoryObject> leak = new HashMap<>();

    public static void main(String[] args) {
        HeapDumpTest heapDumpTest = new HeapDumpTest();
        heapDumpTest.run();
    }

    public void run() {
        for(int i = 0; ; i++) {
            // 해시맵에 저장만 하고 빼내지 않아 결국 OOM이 나는 구조.
            leak.put(i, new MemoryObject(i));
            System.out.println("leaking object " + leak.get(i).index);
            if( i == 5000 ) {
                try {
                    // 데모를 위해 5000번 이후 sleep.
                    System.out.println("Sleeping after adding " + i + "th element.");
                    Thread.sleep(100000000L);
                } catch (final Exception e) {
                    e.printStackTrace();
                }
            }
        }
    }

    class MemoryObject {
        int index ;
        MemoryObject(final int index) {
            this.index = index;
        }
    }
}

이 프로그램을 돌리면 다음과 같이 프로그램이 맵에 계속해서 새 오브젝트를 더하고 5001번 후에 sleep 할 것이다. 원래는 20000개까지 돌도록 놔뒀는데, 이후의 jhat 서버를 돌리는데 cpu소요가 너무 많이되어 데모를 위해 5000개 까지만 넣도록 변경했다. 실제 프로덕션 프로세스에 적용 시 jhat서버에 충분한 cpu와 메모리를 할당 해야 할 것이다.

leaking object 4996
leaking object 4997
leaking object 4998
leaking object 4999
leaking object 5000
Sleeping after adding 5000th element.

JMap을 이용해 Heap Dump 캡쳐

JMap이란 JDK에 포함된 톨이다. 이 툴을 이용하여 현재 실행중인 자바 프로세스의 힙 덤프를 생성 할 수 있다. 

자바 프로세스가 OOM을 내고 종료되기 전에 Heap Dump를 캡쳐 해야 한다. 일단 다음의 명령어를 통해 현재 실행중인 자바 프로세스를 확인하도록 하자.

➜ jps
 881
 2490 Launcher
 2491 HeapDumpTest
 2492 Jps

HeapDumpTest의 프로세스 아이디는 2491이다. 어딘가에 복사 해 두도록 하자.

이제 jmap명령어를 이용해 힙 덤프를 따오도록 하자. 명령어는 다음과 같다.

jmap -dump:live,file=<file-path> <pid>

• dump:live - 현재 힙내의 액티브 메모리 레퍼런스가 있는 오브젝트들만 캡쳐한다.
• file - 힙 덤프를 저장할 경로
• pid - 힙 덤프를 생성하고자 하는 프로세스의 pid (jps를 통해 확인한 프로그램의 pid)

➜ jmap -dump:live,file=./heapdump.bin 2491 
    Dumping heap to /Users/fsoftwareengineer/heapdump.bin ...
    Heap dump file created

지정한 경로에 heapdump.bin이 생성되었음을 확인 할 수 있다.

JHat을 이용한 메모리 덤프 분석

JMap과 마찬가지로 JHat또한 JDK에 포함된 툴로, 이 툴을 사용해 로컬 서버를 돌려 웹 환경에서 힙덤프를 분석 할 수 있다.

jhat -J-Xmx<MEMORY_SIZE> -port <PORT> <HEAP_DUMP_PATH>

다음과 같이 7000 포트에 jhat서버를 실행시킨다. <HEAP_DUMP_PATH>는 jmap으로 생성된 heapdump.bin의 경로를 사용하면 된다.

➜ jhat -J-Xmx6g -port 7000 ./heapdump.bin
        Reading from ./heapdump.bin...
        Dump file created Sat Jan 26 20:18:19 PST 2019
        Snapshot read, resolving...
        Resolving 27213 objects...
        Chasing references, expect 5 dots.....
        Eliminating duplicate references.....
        Snapshot resolved.
        Started HTTP server on port 7000
        Server is ready.

서버가 실행됐다면 http://localhost:7000을 통해 다음과 같은 화면을 확인 할 수 있다.

이 화면에서 우리는 모든 패키지들과, 클래스들, 또 유용한 쿼리들을 볼 수 있다. 예제 코드에는 HeapDumpTest 클래스와 MemoryObject 클래스 두개가 있으므로 화면에서도 두개의 클래스를 볼 수 있다.

이제 메모리 유출을 찾기 위해  "Show heap histogram"을 클릭해 들어가도록 하자.

이 표는 전체 메모리를 가장 많이 차지하고 있는 순서로 정렬되어있다. 그래서 처음 5-10개의 오브젝트들이 메모리 유출을 하고 있을 가능성이 높다. 아까 코드에서 해시맵에 계속해서 MemoryObject를 넣기만 했다. 힙 덤프를 캐칭하는 당시 5001개의 오브젝트들이 저장되었고 따라서 MemoryObject의 Instance Count가 5001(0~5000)인 것을 확인 할 수 있다. 만약 어떤 오브젝트의 전체 메모리가 당신이 예상했던 것 보다 높다면 그 오브젝트가 메모리 유출을 하고 있을 가능성이 높다. 이제 MemoryObject(빨간 네모)를 눌러보자. 누르면 다음과 같은 화면으로 이동하면서 아래에 모든 인스턴스들이 리스트의 형태로 나타날 것이다.

References to this object: 에 있는 인스턴스 중 하나를 클릭하면 다음과 같은 화면으로 이동한다.

인스턴스를 누르면 그 인스턴스에 해당하는 디테일이 나온다. 이제 어느 레퍼런스가 이 인스턴스를 가지고 있는지 찾기 위해 Exclude weak refs를 눌러본다.

다음과 같은 화면을 통해 이 인스턴스가 어디에 속하는지 알 수 있다. 이 인스턴스는 즉 HeapDumpTest클래스의 leak이라는 필드에 연결되어 있고, 그 필드는 그 아랫줄인 HashMap의 레퍼런스를 가지고 있다는 뜻이다. 따라서 leak이라는 HashMap이 이 인스턴스를 가지고 있고 이 해시맵이 메모리 유출의 근본 원인임을 도출 할 수 있다.