Heap Dump로 Memory Leak 분석하고 해결하기 (H2 CacheLongKeyLIRS memory leak)

 

사내 컨플루언스에 히스토리 저장 목적으로 작성했던 글을 가져왔습니다.

문제 분석과 해결 과정을 나타낸 글이라서, 두서가 없는 글입니다.

 

가볍게 읽어주세요 :)

 

환경

AWS EC2 or ompremise

JDK 17

Spring Boot 2.7

H2 Database 1.4.200 file write mode

jdbc:h2:file:/data/happy;CACHE_SIZE=2097152;WRITE_DELAY=300;DB_CLOSE_DELAY=30;DB_CLOSE_ON_EXIT=FALSE;AUTO_SERVER=TRUE;

 

 

문제 발생

 

메모리가 지속적으로 증가하고, 지속적으로 스프링 서버가 죽는다는 제보를 받았습니다.

 

해당 도커 컨테이너는 4코어 메모리 2GB 환경에서 실행되고 있었고, 처리량과 서버 스팩을 생각해보면 꽤나 여유있는 환경이었습니다.

 

그렇지만 도커 컨테이너로 실행되던 jvm 이 엄청나게 많은 메모리를 차지하고 있었고, QA 환경에서 동일 환경으로 구성하여 재현을 시도했습니다.

 

 

실제로 3시간만에 메모리 사용량이 40% -> 90%까지 올라갔고, 혹시나 절대적인 메모리 부족 현상 때문에 그런가 싶어서 4GB로 올려봤지만, 동일한 현상이 재현되었습니다.

 

 

메모리 덤프를 떠보자

이런저런 옵션들을 바꿔보고 고민하다가, 결국 예상가는 문제점이 떠오르지 않아서 메모리 덤프를 시도했습니다.

 

메모리 덤프는 jmap을 통해서 떠볼 수 있습니다.

 

docker exec -it 33d1dbbfd7ab sh

jhsdb jmap --pid 1

 

Attaching to process ID 1, please wait...
ERROR: ptrace(PTRACE_ATTACH, ..) failed for 1: Operation not permitted
Error attaching to process: Can't attach to the process: ptrace(PTRACE_ATTACH, ..) failed for 1: Operation not permitted
sun.jvm.hotspot.debugger.DebuggerException: Can't attach to the process: ptrace(PTRACE_ATTACH, ..) failed for 1: Operation not permitted
	at jdk.hotspot.agent/sun.jvm.hotspot.debugger.linux.LinuxDebuggerLocal$LinuxDebuggerLocalWorkerThread.execute(LinuxDebuggerLocal.java:187)
	at jdk.hotspot.agent/sun.jvm.hotspot.debugger.linux.LinuxDebuggerLocal.attach(LinuxDebuggerLocal.java:345)
	at jdk.hotspot.agent/sun.jvm.hotspot.HotSpotAgent.attachDebugger(HotSpotAgent.java:651)
	at jdk.hotspot.agent/sun.jvm.hotspot.HotSpotAgent.setupDebuggerLinux(HotSpotAgent.java:589)
	at jdk.hotspot.agent/sun.jvm.hotspot.HotSpotAgent.setupDebugger(HotSpotAgent.java:368)
	at jdk.hotspot.agent/sun.jvm.hotspot.HotSpotAgent.go(HotSpotAgent.java:337)
	at jdk.hotspot.agent/sun.jvm.hotspot.HotSpotAgent.attach(HotSpotAgent.java:142)
	at jdk.hotspot.agent/sun.jvm.hotspot.tools.Tool.start(Tool.java:203)
	at jdk.hotspot.agent/sun.jvm.hotspot.tools.Tool.execute(Tool.java:134)
	at jdk.hotspot.agent/sun.jvm.hotspot.tools.JMap.main(JMap.java:202)
	at jdk.hotspot.agent/sun.jvm.hotspot.SALauncher.runJMAP(SALauncher.java:340)
	at jdk.hotspot.agent/sun.jvm.hotspot.SALauncher.main(SALauncher.java:500)
Caused by: sun.jvm.hotspot.debugger.DebuggerException: Can't attach to the process: ptrace(PTRACE_ATTACH, ..) failed for 1: Operation not permitted
	at jdk.hotspot.agent/sun.jvm.hotspot.debugger.linux.LinuxDebuggerLocal.attach0(Native Method)
	at jdk.hotspot.agent/sun.jvm.hotspot.debugger.linux.LinuxDebuggerLocal$1AttachTask.doit(LinuxDebuggerLocal.java:336)
	at jdk.hotspot.agent/sun.jvm.hotspot.debugger.linux.LinuxDebuggerLocal$LinuxDebuggerLocalWorkerThread.run(LinuxDebuggerLocal.java:162)

 

https://stackoverflow.com/questions/2913948/jmap-cant-connect-to-make-a-dump

Jmap can't connect to make a dump

 

 

 

 

메모리 덤프를 뜨려고 시도했으나, docker 환경에서는 해당 프로세스를 실행한 실행한 사용자 이름이 달라서 덤프를 뜰 수 없다고 합니다.

 

docker 에서 메모리 덤프를 뜨는 방법

 

docker exec 5593e3c179bb jcmd 1 GC.heap_dump /tmp/center4.hprof -all dump

 

굿! 잘됩니다.

 

참고로 -all 옵션을 붙여야 GC 를 실행하지 않은 상태로 가져옵니다.

 

종종 메모리가 정리되는 케이스가 있었기 때문에, 혹시라도 GC 가 적절한 타이밍에 못 도는 것인가? 라는 가설도 있었기에 GC를 돌리지 않고 힙 메모리를 그대로 가져왔습니다.

 

// 도커 컨테이너에서 꺼내기
docker cp 5593e3c179bb:/tmp/dump.hprof /home/ubuntu/memory_dump/dump.hprof

// 내 로컬로 가져오기
sudo scp -i /Users/user/workspace/key/.pem ubuntu@43.201.88.41:/home/ubuntu/memory_dump/dump.hprof /Users/user/workspace/memory_dump

 

Hprof 파일을 로컬로 들고왔고, 1.2GB 크기였습니다.

 

 

Eclipse MAT 메모리 분석 툴 열기

 

https://eclipse.dev/mat/downloads.php

Eclipse Memory Analyzer Open Source Project | The Eclipse Foundation

 

• mac 에서 설치하는 경우, application 폴더로 옮기고 열어야합니다.
• 메모리 할당도 늘리고 작업하는 것을 추천합니다. MAT이 OOM 뜨더라구요..
  • https://jojoldu.tistory.com/738
• 덤프 파일 권한 변경해줘야합니다!

 

open a heap dump 메뉴를 통해서 원하는 힙 덤프 파일을 열어줍니다.

 

 

정상 / 비정상 시점을 나눠서 5번 정도 진행했는데, 비정상적인 메모리 시점에서는 m2 프로세스 기준 7시간이 소요됐습니다.

시간이 오래걸리면 오히려 버그를 찾을 수 있다는 희망에 좋아해야겠네요.

 

 

 

 

덤프가 완료되면 mat 에서 자동 분석 결과를 추천해줍니다.

메모리 릭이 의심되는 상황이니, Leak suspects report 를 열어봅시다.

 

 

본격적으로 객체 분석하기

 

 

overview 에서 이미 비정상적인 객체가 탐지되었다고 합니다.

 

실제로 spring boot 가 사용하는 메모리는 작았고, H2 프로세서를 사용하면서 나오는 메모리 비용이었습니다.

 

 

 

더 디테일하게 해당 정보를 찾아보면,,

CacheLongKeyLIRS 라는 이름의 객체가 6억~15억 byte 정도 생성된 것을 확인할 수 있었습니다.

 

 

 

실제로 구글링을 해보니 h2 에 메모리 릭 이슈가 잦은 것을 확인할 수 있었습니다.

그러나 저희는 비즈니스 특성상 h2를 사용해야했고, 문제 해결 방법을 찾기 시작했습니다.

 

 

CacheLongKeyLIRS: H2의 캐시

https://javadoc.io/doc/com.h2database/h2/1.4.192/org/h2/mvstore/cache/CacheLongKeyLIRS.html

CacheLongKeyLIRS - h2 1.4.192 javadoc

메모리를 차지하고 있는 캐시가 어떤건지를 파악하기 시작했습니다.

 

문서를 읽어보니 얼추 다른 RDBMS 의 Buffer Pool과 비슷한 역할을 하는 것 같습니다.

 

 

그런데 요놈이 무슨 이렇게 많은 메모리를 들고 있는걸까요?

 

의심 케이스1 - 캐시 사용량 제한하기

캐시 사용량을 제한해야겠다는 생각이 들어서 docker-compose 를 열었더니, 설정값을 보고 놀랐습니다.

 

...?

 

CACHE_SIZE=2097152

에..

 

해당 도커 컨테이너에 할당된 메모리가 2GB 인데, 캐시 사이즈가 2GB로 설정되어 있었습니다.

 

문제를 찾았다는 생각에 기뻐했고, 바로 캐시 사용량을 제한했습니다.

 

SET CACHE_SIZE 8192

 

일단 캐시 사이즈를 작게 가져가고, 문제 재현이 되지 않으면 적절한 캐시 사이즈를 튜닝해야겠다는 생각으로 8mb 만 설정했습니다.

(사실 현재의 서비스는 이정도만 줘도 충분할 것 같습니다)

 

 

그러나 문제는 해결되지 않았고 또다시 메모리 95%를 찍고 있었습니다.

 

 

의심케이스2 - 트랜잭션 or 커넥션을 닫는 것에 실패하는 케이스가 있나?

https://groups.google.com/g/h2-database/c/PlcWbtEOvI0/m/qEaWkHTaAQAJ?utm_medium=email&utm_source=footer

트랜잭션이 닫히지 않으면 해당 캐시들이 GC 가 되지 않는다고 합니다.

 

추측: 그렇다면 어딘가 트랜잭션을 닫는 것에 실패한 케이스가 누적되고 있으며, 어쩌다가 메모리 사용량이 다시 뚝 떨어지는거는 해당 커넥션 or 트랜잭션이 자동으로 정리된건가?

 

 

예전부터 찝찝한 놈들이 있는데, 혹시 얘들때문인가…?

항상 정체 모를 친구들이 무의미하게 커넥션을 물고 있습니다.

이거는 왜 생기는거지?

 

커넥션 풀 때문인 것으로 일단 추측. 그런데 그런 것 치고는 너무 적지 않나…?

→ Nop. 풀 설정이 minimum-idle: 5 라서 적을 수 있음.

 

의심케이스3 - LOB 데이터를 처리할 때 캐시에서 처리하고 default 시간동안 반환되지 않는건가?

 

https://groups.google.com/g/h2-database/c/PlcWbtEOvI0/m/qEaWkHTaAQAJ?utm_medium=email&utm_source=footer

https://groups.google.com/g/h2-database/c/eXBzpF4WnNk

In-Memory H2 deleted rows not garbage collected.

I have that feeling that you just run queries with LOB in the result which causes extensive LOB cloning. Try to add ;LOB_TIMEOUT=1000 (1 sec instead of default 5 min)

 

위의 논의를 보면, lob 데이터를 매니징하면서 이 데이터의 처리를 위해서 내부적으로 clone을 하고 있나봅니다.

그래서 이 clone을 했던 것이 계속해서 캐시에 쌓이고, 해당 캐시가 정리되는 default 시간이 5분이라서 지워지는데에 시간이 좀 걸리는걸까요?

 

그러면 LOB_TIMEOUT=1000 해서 1초로 걸어보면 문제가 해결되는걸까요?????? 💨

 

 

Advanced

 

그런데 우리 서비스에서 lob 데이터를 사용하고 있는게 있나 .. ? nop.

 

우리 통계 배치 쿼리가 select insert 를 연산하면서 엄청 큰 데이터를 담을 공간이 임시로 보관한다면….??????

https://h2database.com/html/advanced.html#large_objects

 

 

이정도면 그냥 의심병..

 

... pass

 

의심케이스 4 - h2의 memory estimation 버그

https://github.com/h2database/h2database/pull/3626

Improve memory estimation of CacheLongKeyLIRS and correct some passed memory sizes by katzyn · Pull Request #3626 · h2database



h2 의 구 버전들에서는 메모리 Estimation이 잘 못 되어, 캐시가 무한정 늘어나고 메모리 leak이 발생한다고 합니다.

위의 PR에서 해당 이슈가 해결되었고, 그냥 슥슥 훑어보니 int -> long 타입으로 변경하고, 여유 상수 값을 더하면서 더 정확하게 메모리 사용량을 측정하는 것 같습니다.

 

 

 

버전을 업그레이드 하면 문제가 해결될 수 있겠네요!

 

H2 커뮤니티에 직접 도움 요청하기

https://github.com/h2database/h2database/issues/3957

h2 1.4.200 Memory Leak by CacheLongKeyLIRS · Issue #3957 · h2database/h2database

 

일단 개발 서버 반영은 출근해야 가능하니, 못난 영어 실력으로 h2 에 이슈를 올려 소심하게 도움을 요청해보았습니다.

빠르고 친절하게 알려주셔서 너무나도 감사했습니다. 이슈 해결되면 도네이션이라도 해야겠네용..

• (이미 시도) CACHE_SIZE 낮게 설정하기
• DB_CLOSE_ON_EXIT=FALSE AUTO_SERVER=TRUE 옵션 검토하기
• (위에서 언급) CACHE_SIZE 낮게 설정했더라도, 캐시 Estimation이 잘 못 되는 경우가 있어서 동일한 증상이 있었다고 함.

 

 

 

H2 최신버전(2.2.224)으로 업그레이드 시도

일단 구 H2 버전에서 이러한 문제들이 있다고 하는 것 같습니다.

h2 버전을 업데이트 하는 김에 설정을 다시 살펴봐야겠다는 생각이 들었습니다.

 

CACHE_SIZE=${spring.h2.cacheSize};

WRITE_DELAY=${spring.h2.writeDelay};

DB_CLOSE_DELAY=30;

DB_CLOSE_ON_EXIT=FALSE;

AUTO_SERVER=TRUE;

 

Combination of AUTO_SERVER=TRUE with DB_CLOSE_ON_EXIT=FALSE prevents correct database shutdown, so it can be a reason of some corruptions.

(This combination of settings is not allowed in modern versions of H2.)

https://github.com/h2database/h2database/commit/6a0f7a973251409f428565c7544dbd272de856f3

 

AUTO_SERVER=TRUE 와 DB_CLOSE_ON_EXIT=FALSE 옵션은 함께 사용하지 못한다고 합니다.

저는 저희 코드에 왜 이런 옵션을 넣었는지 히스토리를 뒤적거리기 시작했습니다.

 

 

AUTO_SERVER=TRUE

H2 기본 동작은 하나의 프로세스가 동작하고 있을때 다른 프로세스에서 접근할 수 없습니다.

 

그렇지만 저희 서버는 Active Active 상태로 로드밸런싱 되어서, 동일한 DB를 두 개의 서버가 참조하고 있었습니다.

그래서 해당 옵션을 활성화 시킨 것으로 파악했습니다.

 

 

DB_CLOSE_ON_EXIT=FALSE

 

느낌상 이전에 해당 옵션을 넣은 이유는, 1번서버가 DB를 닫는 경우 2번 서버에서 DB 접근을 못하는 케이스가 있을 것 같아서 넣은 것으로 추측합니다

 

 

그렇지만 위의 논의를 살펴보면 MSA 환경에서 H2에서 DB를 접근하는 경우, 왼쪽이 아닌 오른쪽과 같이 동작하는 것으로 보입니다. 그렇게되면 DB_CLOSE_ON_EXIT 에서 닫지 않는 프로세스는 본인의 프로세스이기 때문에 무관합니다.

 

그래서 DB_CLOSE_ON_EXIT=FALSE 옵션은 제거했습니다.

 

 

H2 버전 업그레이드 결과

메모리 누수 현상이 없어졌습니다.

 

결국 해당 현상은 잘못된 memory estimation으로 인해 h2의 캐시가 무한정 증식하는 버그였고, 최신 버전에서 패치가 된 것으로 보입니다.

 

h2 이전 이후에 많은 것이 바뀌어서 사이드이팩트를 조금 더 살펴볼 필요는 있을 것 같습니다.

 

 

캐시가 무한정 쌓이는 현상이라서 객체 생성 이후에 GC 가 일어나지 않는 일반적인 메모리 누수라고 볼 수는 없지만, 아무튼 heap dump를 통해 문제 원인을 파악하고 해결해나가는 과정이 너무나도 재미있었습니다. 덕분에 연관해서 많은 공부를 했고, 다음에 메모리 관련 이슈가 있을때 "힙 덤프 얼마 안걸리는데 제가 지금 떠볼게요!" 라고 자신있게 얘기해볼 수 있을 것 같습니다.

 

주말이 없어졌네요.

 

 

다음 문서를 보고 데이터 1.0 버전의 데이터를 2.0 버전으로 옮기는 작업도 진행했습니다.

https://www.h2database.com/html/migration-to-v2.html

Migration to 2.0