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
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.344Yong 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.659Old 영역의 메모리가 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 31873histio 옵션을 통해 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