java.lang.OutOfMemoryError: Java heap space

OOM.. 서비스 로직에서 만나보고 싶었던 녀석.... 드디어 만났다.

OOM, 왜 발생했는가?

결론부터 말하면 100만개의 row로 부하테스트를 진행하다가 만났다.
교보 DTS 기업 협업으로 진행한 백오피스 프로젝트에서 각 기능마다 엑셀다운로드 하는 기능이 있었고, 해당 코드를 개선만했고, 부하 테스트는 진행해보지 않았었다. 이번 기회에 코드 리팩토링과 부하테스트를 진행보다가 100만개의 엑셀 row를 작성하면 기존 코드에서 OOM이 발생하는 상황을 마주했다. (기존코드에서 어떻게 리팩토링하고 성능 개선했는지는 추후에 작성 예정이다.)

해결하기 위한 과제

메모리 초과를 해결하는 게 과제이다. 

 

OOM을 보고 제일 먼저 떠오른게 GC 튜닝 이라는 단어였다. JVM 의 메모리가 꽉 차서 메모리 부족현상이 뜬 것일테고, 이는 동적 메모리 영역인 힙 영역에 객체가  계속 누적되어 나타난다고 생각했기 때문이다. 좀 더 자세하고 정확한 개선을 위해 "자바 성능최적화" 서적을 보면서 정확한 원인 분석과 제대로된 성능 개선을 목표로 잡았다.

대략적인 목표는 서적에서 아래 내용을 읽고 이해한 다음 문제 해결을 하기로 했다.

1. JVM의 동작 원리 이해
2. JVM 과 운영체제의 관계
3. 성능 테스트 유형
4. 가비지 수집의 기초
5. 자바 성능 분석의 잘못된 방법
6. 성능 테스트 패턴 및 안티패턴 중 기본 베스트 프렉티스

최소한 위 내용을 읽고 성능 분석 및 최적화를 하는게 맞다고 생각했다. (아는게 많으면 그만큼 얻어가는 것도 많다고 하지..)

책의 모든 내용을 읽고 시작하면 러닝커브가 너무 길어질 거 같고, 나머지 내용을 실제로 모니터링을 하면서 필요한 부분만 읽는게 좋다고 판단했다.

 

해당 포스팅은 문제 해결이 주 목적이라 책 내용을 안올리겠지만 얻어가는게 많았던 책이다. 추후 포스팅할 예정이다.

 

드디어 문제를 해결할 시간

이 포스팅의 메인 내용인 OOM을 어떤 방식으로 해결했는가? 이다.

해결하기 위해 먼저 실행환경을 분석하자. 원래는 운영 환경과 최대한 비슷한 환경을 구성해야한다. 프로젝트 당시 온프레미스 환경에 배포하고 있었고, 배포 환경에 대해 기록해두지 않기도 했고, 이번에는 모니터링 툴을 활용한 문제해결에 집중하기로 했다.

실행 환경

개선 전 코드는 여기서 확인 가능합니다.

 

먼저 로컬 실행환경을 분석해보자.

OS: MacOS

칩: Apple M3

코어 수: 8(4성능 및 4 효율)

메모리: 16GB

Java 17 사용

• GC: G1
• Xms: 물리 메모리의 1/64 = 256MB
• Xmx: 물리 메모리의 1/4 = 4GB

정말 GC가 성능 이슈를 일으키고 있는가?

터미널에 java OOM 오류를 뱉긴했지만, 책의 내용을 바탕으로 직접 눈으로 확인하고 싶었다.

 

아래 3가지 조건을 만족하면 성능의 문제가 GC에 있다는 것이다. 아래에서 언급하는 CPU는 모두 서버 전체에 대한 CPU가 아닌 자바 애플리케이션에서 사용하는 CPU기준이다. 

1. CPU 사용률이 100%에 가까운가?
2. 대부분의 시간이(90% 이상)이 유저 공간에서 소비되는가?(GC로깅을 통해 파싱 툴로 확인해보자.)
3. GC로그가 쌓이고 있다면 현재 GC가 실행중이라는 중이다.

1번은 부하테스트 시 java 프로세스에서 충분히 cpu 리소스를 사용하고 있는지 확인하기 위함이다. 스케줄링으로 인해 cpu를 빼앗기거나 컨텍스트 스위치 등으로 인해 cpu 사용률이 낮다면 GC 문제가 아니라는 것이다.

2번은 GC 자체는 유저 공간의 CPU 사이클을 소비하되 커널 공간의 사용률에는 영향을 미치지 않아서 유저 공간에서 소비되는 시간을 체크하는 것이다. JVM 프로세스가 유저 공간에서 CPU를 100% 에 가깝게 사용하고 있다면 GC를 의심해야한다.

- VisualVM CPU 100%인데 OS에서 user CPU가 60%? → JVM 외에도 다른 프로세스들이 user 영역 CPU를 점유하고 있다.
- VisualVM CPU 100%인데 OS에서 system CPU가 많다? → JVM에서 I/O, 시스템 콜 많이 발생 중 (ex. GC, JNI, socket 등)

 

성능 분석을 위한 준비

성능 분석은 데이터가 많이 준비되어야한다. GC 로깅은 필수이고, 어떤 모니터링 툴을 사용할 것인지, cpu 사용률을 어떻게 측정할 것인지 세팅해야한다.

필자는 데이터 수집을 위해 아래와 같은 준비를 했다. 

 

1. GC 로깅을 위한 플래그 설정, 해당 글을 참고했다. (`-Xlog:gc*:file={FILENAME}.log:time,uptime,level,tags`)
2. 로그 파싱 툴 선택: GCeasy (책에는 GCViewer가 소개되었는데 해당 툴은 java8 중심이라 GCeasy를 선택했다). GCeasy는 외부 서버의 나의 로그를 제공하는 것이므로 민감한 정보가 있는 로그는 다른 툴을 선택하거나 민감정보는 제외하자
3. 모니터링 툴 선택: VisualVM (책에서 해당 모니터링 툴을 다루는 법이 나와있어서 선택, 플러그인으로 VisualGC를 제공해서 실시간으로 힙 메모리 할당률을 확인할 수 있다.)
4. cpu 사용률 측정하기 위한 스크립트 작성: cpu 사용률을 측정하는 이유는 성능을 측정하는 지표 중 하나가 리소스 사용률을 측정하는 것이다. cpu 사용률은 애플리케이션 성능을 나타내는 지표이고, 부하 테스트 시에 cpu 사용률이 100%에 가까운지 확인해야한다. 만일 100%에 가깝지 않다면 애플리케이션에 cpu가 사용되지 않고, 컨텍스트 스위칭이나, I/O 경합, 락 등을 의심할 수 있는 단서가 된다. 

스크립트는 다음과 같이 작성했다. 유닉스에서 `vmstat` 로 나오는 리소스 상태 값과 동일한 포맷으로 보고 싶어서 아래처럼 작성했다. 아래에서 나온 결과는 python을 사용해서 .csv 로 변환 후 그래프로 확인했다.

#!/bin/bash

output_file="system_log_improve-last.txt"

echo "=== System Monitoring Log ===" > "$output_file"

while true; do
    ts=$(date '+%Y-%m-%d %H:%M:%S')
    echo "----- Timestamp: $ts -----" >> "$output_file"

    echo ">>> top output <<<" >> "$output_file"
    top -l 1 | grep "CPU usage" | sed -E 's/CPU usage: ([0-9\.]+)% user, ([0-9\.]+)% sys,.*/User: \1%  Sys: \2%/' >> "$output_file"

    echo "" >> "$output_file"

    echo ">>> vm_stat output <<<" >> "$output_file"
    vm_stat >> "$output_file"

    echo -e "\n\n" >> "$output_file"

    sleep 1
done

 

부하 테스트 진행 (100만개 row 생성하는 엑셀 파일 다운로드)

모든 준비가 끝났다. 이제 테스트를 진행해보자.

데이터베이스에 100만개의 데이터를 넣고, cpu 사용률을 측정하기 위한 스크립트 실행 후 애플리케이션을 실행했다.

실행 후 생성된 GC로깅 파일과 리소스 사용률 파일을 분석하면 된다.

먼저 모니터링 툴로 어떤게 문제인지 대략 감을 잡아보기로 했다.

 

결과 예상해보기

공부 차원에서 성능 분석을 하는 것이 목적이므로 먼저 결과를 예측해보자.

 

개선전

개선후

VirtualVM 으로 모니터링 해보기

여기서 중점적으로 볼 것

1. cpu 사용률이 100%인가? yes
2. 최대로 설정한 메모리 할당률까지 도달한 후 메모리 할당률이 내려가지 않고 있다.

heap에 공간 차는 속도를 봐라... 4GB까지 올라갔는데 대략 5분 가량 메모리 할당률이 유지가 되고 있다.

 

 

apache 라이브러리에서 생성되는 객체가 상대적으로 많은 메모리를 차지하고 있다.

 

heap 공간을 차지하는 주인공은 old gen에 있는 객체들이다.

엥? GC 동작안하나? 왜지? 라는 의문이 들었다.

GCeasy로 GC 로그 분석하기

유저 타임이 대략 77%를 차지한다. 

 

여기서 위에서 언급한 "정말 GC가 성능 이슈를 일으키고 있는가?"를 판단할 수 있다.

1. CPU 사용률이 100%에 가까운가? yes, VisualVM에서 보았듯이 100%를 찍고 있다.
2. 대부분의 시간이(90% 이상)이 유저 공간에서 소비되는가? no, 77%만 사용중이다.
3. GC로그가 쌓이고 있다면 현재 GC가 실행중이라는 중이다. yes

 

2번이 부합하지 않는다. 즉 GC만의 문제가 아니라는 것인데.... GC 로그에서 pause time을 확인해보자

위 사진을 보면 GC 병목 상태라고 한다. 문제점은 다음과 같다.

1. 총 GC 정지 시간: 48분: 프로세스가 거의 1시간 가까이 "정지(STW: Stop The World)" 상태에 있는 것을 의미한다.
2. 평균 시간 2.6초: 사용자 입장에서 2.6초는 매우 긴 시간이다.
3. 최대 18초 멈춤: 사용자 입장에서 프리즈(freeze))나 장애로 인식할 수 있는 수준이다.

결론은 GC 병목현상으로 인한 성능 이슈였다. 유저 타임에 90%이상 사용하지 않았지만 GC 문제라는 걸 알 수 있었다.

그럼 어떤 GC가 동작해서 pause가 길어진것일까?

pause 시간 중 각각 차지한 시간을 표로 나타낸 것

보면 Full GC를 수행하는데 가장 많은 시간을 차지한다. full GC가 총 452번 수행되면서 34분 18초를 멈추었다는 말이된다. full GC는 STW 이벤트를 발생시키고 모든 애플리케이션 스레드가 정지되고 ,GC만 작동하므로 사용자 입장에서 앱이 멈춘 것처럼 느껴지는 것이다.

 

 

또한 JVM memory size 수치를 보면 심각하다. Old Generation peek 수치가 할당된 양을 초과한다.

이런 이유를 자세히 알려면 GC의 G1 알고리즘을 제대로 이해할 필요가 있다.(추후에 포스팅)

 

이제 GC 이후 메모리 할당률이 어떻게 되는지 살펴보자.

위 사진은 GC 동작 후 메모리 할당량을 뜻한다. GC 동작을 하지만 객체가 줄지 않는다. 아래 사진을 보면 심지어 메모리 할당률이 최대4000mb를 넘어간다. (대략 4GB가 된다는 거다.)  -> 평균 메모리 할당률: 약 34mb/s

거의 수평선을 유지하는 곳을 확대해보면 evacutaion pause와 compaction pause만 발생하고 있다. 즉 살아있는 객체를 다른 영역으로 옮기고(evacuation), 공간 압축을 한다는 것이다. -> GC의 대상이 없다는 뜻

 

 

심지어 Full GC 가 엄청나게 발생하고 있다.

할당률 수치가 1GB/s 이상으로 일정 시간 지속한다면 십중팔구 가비지 수집기 튜닝만으로는 해결할 수없는 성능 문제가 터진것이다. 이 경우 성능을 향상시키려면 애플리케이션 핵심부의 할당 로직을 제거하는 리팩터링을 수행하여 메모리 효율을 개선하는 방법밖에 없다.
- 서적 "자바 최적화" 중 일부

이런 비정상적인 상황이 왜 일어났는지는 엑셀 생성과정에 관여하는 Apache POI라이브러리의 `XSSFWorkbook` 동작 방법을 살펴보면 된다.

 

개선 전 엑셀을 생성하는 코드는 아래와 같다.

try (Workbook workbook = new XSSFWorkbook()) {
        sheet = workbook.createSheet("Data");
        switch (aCase) {
            case RESOURCE_DESCRIBE -> describeDataDownload();
            case MEMBER -> memberDataDownload();
            default -> throw new IllegalArgumentException("Invalid case: " + aCase);
        }

        setColumnWidth();

        // 파일 쓰기
        workbook.write(httpServletResponse.getOutputStream());
    ....
}

XS

private void describeDataDownload() {
    String[] headers = {"스캔 날짜", "고객사", "Account Name", "Account ID", "서비스", "기능", "Resource ID", "tag", "Json"};
    createHeaderRow(headers);

    int rowNum = 1;
    for (Object data : writeDataList) {
        DescribeXlsxDto dto = (DescribeXlsxDto) data;
        Row dataRow = sheet.createRow(rowNum++);
        dataRow.createCell(0).setCellValue(dto.getScanTime());
        dataRow.createCell(1).setCellValue(dto.getResourceRegisterTime());
        dataRow.createCell(2).setCellValue(dto.getClient());
        dataRow.createCell(3).setCellValue(dto.getAccountName());
        dataRow.createCell(4).setCellValue(dto.getAccountId());
        dataRow.createCell(5).setCellValue(dto.getService());
        dataRow.createCell(6).setCellValue(dto.getResourceId());
        dataRow.createCell(7).setCellValue(dto.getTag());
        dataRow.createCell(8).setCellValue(dto.getResourceJson());

    }
}

 

DexcriveXlsxDto는 엑셀에 들어갈 메타 정보가 들어간 객체이다.

엑셀을 생성하기 위한 메타정보를 모두 가져온 후 한번에 write를 진행한다. -> 100만개의 객체가 메모리에 다 올라갈 때까지 heap 공간에는 GC 대상이 되는 객체가 없다는 말이다.

가비지 컬렉터 동작 방식: GC root와 GC 대상 골라내기

가비지 컬렉터는 GC root부터 시작해서 dfs로 reachability 객체를 찾아내고, unreachability 객체는 GC 대상이 된다.

XSSFWrokbook 객체 내부에 엑셀을 작성하기 위한 객체를 Map으로 관리하는데, 이 Map 객체는 old gen 객체이고 Map으로 관리되는 객체가 young gen 객체이다. 즉, old gen 객체가 young gen 객체를 참조하게 된다.

이렇게 되면 GC root는 old gen인 Map을 가르키고, old gen은 young gen 객체를 가르키면서 young gen 객체를 GC 대상인 객체로 인식하지 못한다.

 

이제 원인이 분명해졌다.

한번에 많은 row를 생성하는 로직이 돌아가면 컬렉터의 대상이 되는 객체는 없고, 그 많은 객체가 모두 메모리에 올라가야지만 엑셀 파일이 만들어지는 것이다.

 

그럼 메모리에 올라가는 row를 제한하면 되겠다 싶어서 매커니즘을 찾아보았다. -> SXSSF를 활용하라는 결과를 얻었다.

💡 SXSSF가 뭔데?

SXSSF is an API-compatible streaming extension of XSSF to be used when very large spreadsheets have to be produced, and heap space is limited​

SXSSF 는 대용량 엑셀파일을 생성하고, 힙 공간이 제한될 때 사용할 수 있는 XSSF의 스트리밍 확장이라고 한다.
SXSSF는 슬라이딩 윈도우 내의 행에 대한 접근을 제한함으로써 낮은 메모리 사용량을 달성하지만 XSSF는 문서 내의 모든 행에 대한 접근을 허용한다고 한다.

 

코드 개선하기

코드를 어떻게 개선했는지 자세한 내용을 추후 포스팅 예정이다.

개선된 코드는 여기서 확인 가능합니다.

 

SXSSF를 사용한 로직만 본다면 아래와 같다.

public SimpleExcelFile(List<T> data, Class<? extends BaseXlsx> type) {
    validateMaxRow(data);
    this.wb = new SXSSFWorkbook();
    this.resource = ExcelRenderResourceFactory.prepareRenderResource(type);
    renderExcel(data);
}

private void renderExcel(List<T> data) {
    sheet = wb.createSheet();
    renderHeadersWithNewSheet(sheet, ROW_START_INDEX, COLUM_START_INDEX);

    if (data.isEmpty()) {
        return;
    }

    int rowIndex = ROW_START_INDEX + 1; //header가 ROW_START_INDEX부터  시작하므로
    for (Object renderData : data) {
        renderBody(renderData, rowIndex++);
    }
}

 

SXSSF를 활용해서 엑셀을 만드는 코드이다.

 

SXSSF가 내부적으로 어떻게 구현되어있는지는 따로 포스팅 예정이다. 간단하게 설명하자면 SXSSFWorkbook 객체 내부에 row를 100으로 제한하도록했고, row를 생성할때 전달되는 인자가 100보다 커지면 Map 자료구조에서 그동안 생성한 객체를 remove하여 GC의 대대상이 되도록 한다.

 

개선 후 VirtualVM으로 모니터링하기

CPU사용률이 50% 도 안되는 것을 볼 수 있다. heap size는 최대 4GB까지 할당되지만 최대 메모리 사용률이 4GB를 넘지 않는다.

-> 여기서 알게된 점이 heap 공간을 초기값 만큼 할당했다가 어느정도 차면 맥시멈까지 할당해주는 이유가 아마 full GC를 최대한 발생하지 않으려고 하는게 아닌가 싶다

 

 

Eden영역에 메모리가 찼다가 GC발생하고, 다시 찼다가 GC 일어나고 (반복) 하는 현상을 보였다. Old 영역에는 꽉 차지 않았다. full GC가 발생하지 않았을 것으로 예상되었다.

개선 후 GCeasy로 GC로그 분석하기

유저 타임은 74%정도된다.

 

Young GC가 많이 발생하긴 하지만 많은 리소스를 사용하는 Full GC가 발생하지 않는 것만 해도 큰 개선이라고 생각한다.

이 그래프 메모리 할당률은 새 객체가 Eden 영역에 할당되는 지를 측정한 값이다. 즉 Allocatoin Rate은 초당 얼마만큼의 새 객체가 Eden 영역에 할당되는지를 측정한 값 -> 평균 메모리 할당률: 22.5mb/s
여기서 비정상적으로 스파이크가 튀다가 GC발생 후에 1,750mb 을 사용하는걸 확인할 수 있다.

 

 

1750mb의 메모리는 어느 영역에서 잡아먹는것인지 확인해보자

1. youn gen확인 -> GC 효율 좋음 -> 얘가 원인이 아니다.

갑자기 스파이크 뛰는 현상은 Young Gen에 메모리 할당률이 올라가서로 보인다.

할당률 최고 찍고 보라색 선(after GC)이 **거의 0에 가까워졌으므로**, 대부분의 객체가 Young에서 제거됨을 의미 -> Young GC 효율은 좋다는 것을 의미

 

2. old gen 확인 -> 얘가 문제 .. 위에서 본 GC이이후에도 메모리 유지되는게 old gen에 객체를 치우지 않아서로 추청된다. 여기에 있는 객체는 SXSSF가 설정한 sliding window의 크기만큼 유지되는 객체라고 생각된다. 그러면 메모리 할당률이 계속 일정한 것도 이해가 간다.

old gen에서 peek일때 그래프

이후에 old GC를 동작하게 하면 메모리 할당률이 더 좋아지지 않을까? 생각은 든다.

 

정리

1. java OOM이 발생하여, 원인을 찾기 위해 JVM 동작 원리 학습
2. GC인한 성능 이슈인지 확인하기 위해 3가지 조건에 충족하는지 확인하는 작업을 하기 위해 GC로깅 + 파싱 툴(GCeasy)을 활용
   • cpu usage를 확인(user usage >= 90% 인지 확인)
   • cpu 사용률 확인 (부하테스트 진행시 100%로 돌아가고 있나?)
   • GC로깅이 실시간으로 되고 있다면 GC가 돌아가고 있다는 것이다.
3. cpu 사용률은 100% -> 자바 애플리케이션이 cpu를 적극 활용중이라는 말이다. 다른 프로세스 또는 컨텍스트 스위칭 등으로 인해 CPU를 할당받지 못하는 상황이 아니라는 것이다.
4. CPU usage에서 user usage가 90%를 넘지 않아서 GC 문제가 아니라는 건가? 싶었지만 GC로깅을 더 분석한 결과 pause timedptj  Full GC 의 동작의 빈도가 높아서 pause가 길어지고, GC 병목현상이 있다는 것을 확인
5. GC는 기본값으로 두고 애플리케이션 코드 수정 -> 메모리에 올라가는 row 수 제한하는 sliding window 방식으로 변경
6. 100만개의 row 엑셀 파일을 다운 받는데 까지 8초가 걸리긴 하지만 OOM은 해결

얼만큼 개선되었는지 수치화하기 

• 초당 메모리 할당률(mb/s): 34 mb/s -> 22.5mb/s (메모리 할당률 그래프를 보고 분석한 것이므로 크로스체크 필요)
• full GC 횟수: 376 -> 0 (100%감소)
• young gc횟수: 612 -> 84 (86.3%감소)
• full GC 평균 시간 2s 491ms -> 0 (지연시간 대폭 감소, STW 발생하지 않음)
  • pause total time: 21m 3s 303ms -> 1s 226ms -> 99.9% 감소
• old gen 사용률(peek 기준): 3.96/2.84 * 100 (139.4)-> 1.68 / 1.9 * 100(88.4) -> 36.58% 개선
• young gen 사용률: 1.14/1.16 * 100 (98.27)- 1.87/2.1* 100 (89.04) -> 약 9.4% 개선
• 응답 속도 평균: (메모리 초과로 30분이상 지속됨) -> 86934 ms (무한한 처리에서 유한한 처리로 개선)
• GC pause 총시간(최대) : 10 sec 4 ms -> 160ms (0.984≈98.4% 개선)
• GC pause 평균: 1 sec 369 ms -> 14.3 ms -> 98.96% 개선
• metaspace사용량:  75.97/76.94(mb) * 100 -> 81.17/81.75 (mb)* 100 -> 0.5% 증가 (별로 차이 없음)