JVM Memory Leak 만들고 탐지, 개선하기

개요

memory Leak은 보통 개발자의 실수로 발생할 수 있습니다.

사내에서 Socket과 관련된 코드를 작성하며 Close를 수행하는 절차에서 Memory Leak이 발생시켰던 코드를 예시로 의도적으로 memory Leak을 만들어내고 이를 탐지, 개선하는 작업을 수행해보고자 합니다.

 

Memory Leak이란?

메모리 누수현상이란 프로그램이 필요하지 않은 메모리를 계속 점유하고 있는 현상을 말합니다.

Java에서는 GC가 지속적으로 사용하지 않는 객체를 회수하지만 GC에 의해 회수되지 않고 계속 누적되는 현상입니다.

주로 List, HashMap 같은 콜렉션에 해당하는 객체를 해제하지 않고 계속 유지하다 보면 발생하게 됩니다.

Memory Leak이 발생하게 되면 어떻게 될까?

Memory Leak이 지속되어 GC의 Old영역에 누적된 객체로 인해 Major GC가 지속적으로 발생하게 되며, 프로그램의 응답속도가 늦어지다 결국에는 OOM(Out Of Memory) 오류가 발생되어 프로그램이 종료됩니다.

 

Memory Leak이 발생하는 코드 생성

Controller

@RestController
class MakeMemoryLeakController(
    private val scheduledExecutorServiceMemoryLeakConfig: ScheduledExecutorService,
    private val memoryLeakSessionManager: MemoryLeakSessionManager,
) {
    @GetMapping("/memory-leak")
    fun generateMemoryLeak(){
        repeat(100000){
            val userId = UUID.randomUUID().toString()
            memoryLeakSessionManager.registerSession(userId)

            //요청을 받으면 스케쥴링은 5초뒤에 시작되고, session을 제거한다.
            scheduledExecutorServiceMemoryLeakConfig.schedule(
                {
                    if(memoryLeakSessionManager.sessionIsOpen(userId)){
                        memoryLeakSessionManager.removeSession(userId)
                    }

                }, ScheduledPerformanceController.TIMEOUT_SECONDS, TimeUnit.SECONDS
            )
        }

    }
}

Session이 열려있다면 세션을 제거하는 코드를 작성하였습니다.

이 코드에서 누락된 부분은 Session이 Open 되지 않았다면 remove를 호출하지 않습니다.

즉, 메모리가 계속 쌓일 수 있습니다.

10만 번 호출하도록 하여 가시적으로 메모리 누수를 탐지하고자 했습니다.

 

MemoryLeakSessionManager

@Component
class MemoryLeakSessionManager {
    private val sessionMap: MutableMap<String, MySocket> = ConcurrentHashMap()

    fun registerSession(userId: String) {
        sessionMap[userId] = MySocket(userId = userId)
        logger.info {"session registered, userId: $userId"}
    }

    fun sessionIsOpen(userId: String): Boolean{
        val isConnected = sessionMap[userId]?.isConnected
        return isConnected ?: false
    }

    fun removeSession(userId: String) {
        sessionMap.remove(userId)
        logger.info {"session removed, userId: $userId"}
    }

    fun getSessionSize(): Int{
        return sessionMap.size
    }
}

data class MySocket(
    val userId: String,
    val isConnected: Boolean = false,
)

내부적으로 ConcurrentHashMap을 가지며 isConnected가 false인 MySocket 객체를 등록시키고 관리하는 클래스입니다.

이제 코드를 실행시키고 Controller를 한 번씩 호출해 보며 JVM Heap Memory 상태 모니터링을 수행해보고자 합니다.

 

Memory Leak 원인 찾기 - Terminal

Visual VM과 같은 Application의 Thread 및 GC 사용량을 모니터링할 수 있는 JDK 도구를 사용해도 되지만 jstat으로 JVM의 Heap Memory 상태를 확인해보고자 합니다.

 

분석 도구들은 모든 환경에서 사용가능하지 않을 수 있으며 가장 기본적인 분석 방법에 대해 익히는 것이 언젠가는 도움이 될 것 같습니다.

 

IntelliJ의 Terminal에서 jps 명령어를 사용하면 JVM의 Process ID와 프로그램 명을 확인할 수 있습니다.

junuu@aideulnalaui-MacBookPro study % jps
28087 Jps
1481 
24426 GradleDaemon
26606 ApplicationKt
26526 KotlinCompileDaemon

 

jps -v 명령어를 사용한다면 JVM의 옵션들도 살펴볼 수 있습니다.

-XX:ErrorFile: IDEA(IntelliJ) IDE의 Java 가상 머신에서 발생한 오류를 기록할 로그 파일 경로를 지정합니다.
-XX:HeapDumpPath: Out of Memory Error 발생 시 힙 덤프 파일을 저장할 경로를 지정합니다.
-Xms128m: 초기 힙 크기를 128MB로 설정합니다.
-Xmx750m: 최대 힙 크기를 750MB로 설정합니다.
-XX:+HeapDumpOnOutOfMemoryError: Out of Memory Error 발생 시 힙 덤프를 생성합니다.

 

PID로 GC 모니터링하기

jstat -gcutil -h3 [PID] 3000

- gcutil : GC 통계요약 옵션 (그 외 gc, gcnew, gcold 등이 존재)

- h3 : 3줄마다 헤드를 출력

- PID : process ID

- 3000: 3초마다 출력

 

초기 GC 상태

 S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT    CGC    CGCT     GCT   
  0.00 100.00  65.57  94.59  98.75  95.26     46    2.615     0    0.000     8    0.004    2.620
  0.00 100.00   3.28  61.51  98.75  95.26     47    2.692     0    0.000     9    0.010    2.702
  0.00 100.00   4.92  61.51  98.75  95.26     47    2.692     0    0.000    10    0.011    2.703

https://junuuu.tistory.com/126

Heap공간은 Yong 영역과 Old(O) 영역  그리고 Survival 0, Survival1, Eden 영역으로 나누어지며 객체들의 생명주기에 따라 이동하며 메모리정리가 발생하게 됩니다.

 

YGC는 Yong Generation의 GC횟수, FGC는 Old Generation의 GC횟수입니다.

 

함수를 어느 정도 호출했을 때

 S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT    CGC    CGCT     GCT   
  0.00 100.00  78.95  66.41  98.75  95.26     51    3.187     0    0.000    10    0.011    3.198
  0.00 100.00   0.00  67.18  98.75  95.26     52    3.334     0    0.000    10    0.011    3.344
  0.00 100.00  10.53  67.18  98.75  95.26     52    3.334     0    0.000    10    0.011    3.344

Yong Generation의 GC가 증가하고, Old 영역이 점점 증가하는 모습이 보입니다.

Memory Leak이 발생하고 있음을 암시합니다.

 

메모리가 가득 찼을 때

S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT    CGC    CGCT     GCT   
  0.00   0.00   0.00  99.98  98.09  94.12    150   11.573    33   90.072    17    0.036  101.682
  0.00   0.00   0.00  99.98  98.09  94.12    152   11.590    34   93.014    17    0.036  104.640
  0.00   0.00   0.00  99.95  98.09  94.12    153   11.597    35   96.026    17    0.036  107.659

Old 영역의 메모리가 100%에 가깝게 도달하였고 Old Generation의 Full GC의 count가 지속적으로 올라갑니다.

Application의 응답속도는 현저하게 느려졌으며 OOM이 발생하기 직전입니다.

 

OOM이 발생

* What went wrong:
Out of memory. Java heap space

 

문제가 발생했을 때 Jmap 명령어로 메모리 사용 현황 확인

jmap -histo:live {PID}
jmap -histo:live 31873

histio 옵션을 통해 PID에 해당하는 JVM 프로세스의 메모리 통계를 알아볼 수 있습니다.

 

상위 10개의 인스턴스

num     #instances         #bytes  class name (module)
-------------------------------------------------------
   1:      58885480     3299584032  [B (java.base@17.0.7)
   2:      58859600     1883507200  java.util.concurrent.ConcurrentHashMap$Node (java.base@17.0.7)
   3:      58883408     1413201792  java.lang.String (java.base@17.0.7)
   4:      58835189     1412044536  com.example.study.executor.session.MySocket
   5:           263      537108432  [Ljava.util.concurrent.ConcurrentHashMap$Node; (java.base@17.0.7)
   6:             6       18198200  [Ljava.util.concurrent.RunnableScheduledFuture; (java.base@17.0.7)
   7:          8756        1040232  java.lang.Class (java.base@17.0.7)
   8:          9735         617208  [Ljava.lang.Object; (java.base@17.0.7)
   9:          3676         365104  [I (java.base@17.0.7)
  10:         10576         338432  java.util.HashMap$Node (java.base@17.0.7)

concurrentHashMap에서 MySocket객체의 바이트가 가장 많이 잡혀있는 것을 알 수 있습니다.

5_888_5480개의 객체가 사용중입니다.

이를 통해 MySocket 객체가 지속적으로 쌓여서 발생하는 문제임을 예측하고 대응할 수 있습니다.

 

Heap Dump 뜨는 방법

IT에서 dump는 시스템 또는 시스템의 특정 구성 요소의 현재 상태를 캡처하고 저장하는 프로세스를 의미합니다.

특정 순간의 Java Heap 메로리의 스냅샷을 만들어냅니다.

 

jmap -dump:format=b,file={dump file 이름} PID

위의 명령어를 통해 파일덤프를 생성할 수 있으며 확장자는 일반적으로 .hprof를 사용합니다.

 

 

Memory Leak이 예상되는 코드 수정

//요청을 받으면 스케쥴링은 5초뒤에 시작되고, session을 제거한다.
            scheduledExecutorServiceMemoryLeakConfig.schedule(
                {
                    memoryLeakSessionManager.removeSession(userId)
                }, ScheduledPerformanceController.TIMEOUT_SECONDS, TimeUnit.SECONDS
            )

이제 특정상황에서 session을 remove 하는 것이 아니라 모든 상황에서 session을 remove 하도록 변경하였습니다.

 

이제 다시 위의 과정을 반복한다면?

 num     #instances         #bytes  class name (module)
-------------------------------------------------------
   1:           288       33799216  [Ljava.util.concurrent.ConcurrentHashMap$Node; (java.base@17.0.7)
   2:             6       27297096  [Ljava.util.concurrent.RunnableScheduledFuture; (java.base@17.0.7)
   3:         56609        5159816  [B (java.base@17.0.7)
   4:         53420        1282080  java.lang.String (java.base@17.0.7)
   5:          8864        1053120  java.lang.Class (java.base@17.0.7)
   6:         25372         811904  java.util.concurrent.ConcurrentHashMap$Node (java.base@17.0.7)
   7:         12621         761456  [Ljava.lang.Object; (java.base@17.0.7)
   8:          7200         633600  java.lang.reflect.Method (java.base@17.0.7)
   9:          4147         383064  [I (java.base@17.0.7)
  10:         11514         368448  java.util.HashMap$Node (java.base@17.0.7)

OOM은 발생하지 않고, GC도 안정적으로 보입니다.

heam dump를 확인해보아도 이상이 없어보입니다.

 

 

참고자료

https://techblog.woowahan.com/2628/

https://soft.plusblog.co.kr/51