GC 로그로 할당률과 메모리 누수 구분하기

"메모리가 부족하다"거나 "GC가 너무 자주 돈다"는 보고를 받으면 먼저 힙을 늘리고 싶어집니다. 하지만 같은 증상 뒤에 전혀 다른 원인이 숨어 있을 수 있습니다. 잠깐 쓰고 버릴 객체를 아주 빠르게 만드는 프로그램은 GC를 자주 부르지만, 정리가 끝나면 힙이 금방 다시 비워집니다. 반대로 어딘가에 객체가 계속 쌓이는 프로그램은 GC를 할 때마다 남는 양이 늘어나다가 결국 OutOfMemoryError로 멈춥니다.

앞의 경우는 할당률(allocation rate), 즉 단위 시간에 새로 만드는 객체의 양이 문제입니다. 뒤의 경우는 GC가 끝난 뒤에도 살아남는 객체들, 즉 생존 객체 집합(live set)이 문제이고, 흔히 메모리 누수라고 부르는 상황이 여기에 속합니다. 둘은 고치는 방법이 다르므로 힙 크기를 바꾸기 전에 어느 쪽인지부터 가려야 합니다. 이 글에서는 그 구분에 쓰는 도구 세 가지를 차례로 다룹니다. 프로그램 안에서 메모리 사용량을 읽는 MemoryMXBean, JVM이 GC를 할 때마다 남기는 GC 로그, 실행 중인 JVM에 진단 명령을 보내는 jcmd입니다.

힙과 가비지 컬렉션의 기본 개념은 JVM 메모리 구조: 스택, 힙, 메서드 영역에서 다뤘습니다. GC 로그와 jcmd의 출력 형식은 HotSpot JVM의 것입니다. OpenJDK를 비롯한 대부분의 JDK 배포판이 HotSpot을 쓰지만, 출력 형식은 버전과 수집기에 따라 조금씩 다릅니다. 이 글의 출력은 모두 2코어 Linux의 JDK 21에서 기본 수집기인 G1(Garbage-First)으로 실행해 얻은 것입니다.

메모리 크기를 int로 계산하면 생기는 일

도구를 보기 전에, 메모리 크기를 어림할 때 흔히 저지르는 실수부터 보겠습니다. 원소 1억 개에 원소당 32바이트가 필요하다면 모두 몇 바이트일까요? 다음 프로그램은 이 곱셈을 int로 계산하고, 그 크기의 byte 배열을 만들려고 합니다.

public final class MemoryBudgetOverflowFailure {
    public static void main(String[] args) {
        int elements = 100_000_000;
        int bytesPerElement = 32;
        int bytes = elements * bytesPerElement;
        System.out.println("wrong-bytes=" + bytes);
        byte[] allocation = new byte[bytes];
        System.out.println(allocation.length);
    }
}

wrong-bytes=-1094967296
Exception in thread "main" java.lang.NegativeArraySizeException: -1094967296
	at MemoryBudgetOverflowFailure.main(MemoryBudgetOverflowFailure.java:7)

정답은 3,200,000,000바이트인데 출력은 음수입니다. int가 담을 수 있는 가장 큰 값은 2,147,483,647이라서 곱셈 결과가 범위를 넘었고, 자바의 int 연산은 이럴 때 예외를 던지지 않고 결과의 하위 32비트만 남깁니다. 그래서 3,200,000,000에서 2³²(4,294,967,296)를 뺀 −1,094,967,296이 됩니다. 이 값이 그대로 new byte[bytes]에 들어가자 배열 길이가 음수라는 NegativeArraySizeException이 났습니다. 계산 도중에 일어나는 오버플로는 변수 스코프와 숫자 형변환에서도 다뤘습니다.

이번에는 음수가 나와 곧바로 예외가 났으니 오히려 다행인 경우입니다. 넘친 결과가 우연히 작은 양수였다면 프로그램은 엉뚱한 크기의 배열을 아무 말 없이 만들었을 것입니다. 그래서 크기 계산은 long으로 하고, Math.multiplyExact처럼 넘치면 예외를 던지는 메서드를 쓴 다음, 배열로 만들 수 있는 크기인지 따로 확인해야 합니다. 배열 길이는 int이므로 3.2GB짜리 byte 배열 하나는 힙이 아무리 커도 만들 수 없습니다. 이 확인을 코드로 옮기는 일은 글 끝의 연습 문제에서 해 봅니다.

이렇게 계산한 값은 데이터가 차지하는 바이트일 뿐, 실제 힙 사용량과는 다르다는 점도 기억해 둡니다. HotSpot에서는 객체마다 머리(header)가 붙고 객체 크기도 8바이트 단위로 맞춰지며, 배열을 담는 컬렉션도 따로 메모리를 씁니다. 실제로 얼마를 쓰는지는 어림이 아니라 이 글과 다음 글에서 다룰 도구로 측정합니다.

더 깊이: 배열 길이의 실제 상한

JLS(Java Language Specification)는 배열의 길이와 인덱스가 int라는 것만 정할 뿐, Integer.MAX_VALUE 길이의 배열을 만들 수 있다고 약속하지는 않습니다. JVM 구현은 그보다 조금 작은 길이에서 거절할 수 있습니다. 다음 프로그램은 명령줄에서 받은 길이로 byte 배열을 만들어 봅니다.

public final class ArrayLimit {
    public static void main(String[] args) {
        int length = Integer.parseInt(args[0]);
        try {
            byte[] array = new byte[length];
            System.out.println("ok " + array.length);
        } catch (OutOfMemoryError error) {
            System.out.println(length + " -> " + error);
        }
    }
}

java -Xmx8m ArrayLimit 2147483647
java -Xmx8m ArrayLimit 2147483646
java -Xmx8m ArrayLimit 2147483645

2147483647 -> java.lang.OutOfMemoryError: Requested array size exceeds VM limit
2147483646 -> java.lang.OutOfMemoryError: Requested array size exceeds VM limit
2147483645 -> java.lang.OutOfMemoryError: Java heap space

힙을 8MB로 제한했으니 세 경우 모두 실패하는 것은 당연하지만, 오류 메시지가 다릅니다. 앞의 두 길이는 힙 크기를 따지기도 전에 'VM이 허용하는 배열 크기를 넘었다'는 이유로 거절됐고, 세 번째는 힙이 부족하다는 평범한 오류입니다. 즉 이 HotSpot에서 byte 배열 길이의 상한은 Integer.MAX_VALUE - 2입니다. JDK의 ArrayList 같은 구현이 내부 배열을 키울 때 꼭 필요하지 않으면 Integer.MAX_VALUE - 8을 넘기지 않는 것도 이런 구현별 차이를 피하려는 것입니다.

프로그램 안에서 힙 사용량 읽기

java.lang.management 패키지는 실행 중인 JVM의 상태를 자바 코드로 읽을 수 있는 관리용 객체, MXBean을 제공합니다. 메모리 쪽에서는 힙 전체를 요약하는 MemoryMXBean과, 메모리를 더 잘게 나눈 메모리 풀(memory pool)마다 하나씩 있는 MemoryPoolMXBean을 씁니다. 둘 다 ManagementFactory에서 얻습니다. 다음 프로그램은 힙 전체의 값 세 가지를 출력한 뒤 풀마다 사용량을 출력합니다.

import java.lang.management.ManagementFactory;
import java.lang.management.MemoryPoolMXBean;
import java.lang.management.MemoryUsage;

public final class MemoryPoolSnapshot {
    private static String megabytes(long bytes) {
        return bytes < 0 ? "undefined" : String.format("%.2f MiB", bytes / 1024.0 / 1024.0);
    }

    public static void main(String[] args) {
        MemoryUsage heap = ManagementFactory.getMemoryMXBean().getHeapMemoryUsage();
        System.out.println("heap-used=" + megabytes(heap.getUsed()));
        System.out.println("heap-committed=" + megabytes(heap.getCommitted()));
        System.out.println("heap-max=" + megabytes(heap.getMax()));

        for (MemoryPoolMXBean pool : ManagementFactory.getMemoryPoolMXBeans()) {
            MemoryUsage usage = pool.getUsage();
            System.out.println(pool.getName() + " used=" + megabytes(usage.getUsed()));
        }
    }
}

heap-used=0.00 MiB
heap-committed=94.00 MiB
heap-max=1496.00 MiB
CodeHeap 'non-nmethods' used=1.33 MiB
Metaspace used=0.72 MiB
CodeHeap 'profiled nmethods' used=0.21 MiB
Compressed Class Space used=0.07 MiB
G1 Eden Space used=1.00 MiB
G1 Old Gen used=1.05 MiB
G1 Survivor Space used=0.00 MiB
CodeHeap 'non-profiled nmethods' used=0.08 MiB

힙 전체의 세 값은 이런 뜻입니다. used는 객체가 실제로 차지한 양이고, committed는 JVM이 운영체제에서 받아 와 바로 쓸 수 있게 확보해 둔 양입니다. max는 힙이 커질 수 있는 상한으로, -Xmx 옵션으로 정합니다. 여기서는 옵션을 주지 않았으므로 HotSpot이 사용 가능한 메모리의 4분의 1 정도로 정한 값이 나왔습니다. 이 환경에서 JVM이 인식한 메모리는 5,979MB였습니다. committed는 사용량에 따라 max까지 늘어나기도 하고 다시 줄어들기도 합니다. megabytes가 음수를 undefined로 바꾸는 것은, 상한이 정해지지 않은 경우 getMax()가 -1을 돌려주기 때문입니다.

풀 목록에서 G1으로 시작하는 세 개가 힙입니다. 새로 만든 객체는 Eden에 들어가고, GC에서 살아남은 객체는 Survivor를 거쳐 Old로 옮겨 갑니다. 대부분의 객체는 만들어지자마자 곧 쓰레기가 되므로, 젊은 영역(Eden과 Survivor)만 자주 정리해도 적은 비용으로 많은 메모리를 되찾을 수 있습니다. 이것이 힙을 세대로 나누는 이유입니다. 나머지 풀은 힙 밖의 영역입니다. Metaspace와 Compressed Class Space에는 로딩된 클래스의 정보가, CodeHeap으로 시작하는 풀에는 JIT 컴파일러가 만든 기계어 코드가 들어갑니다.

풀 이름은 수집기마다 다릅니다. 같은 프로그램을 java -XX:+UseSerialGC MemoryPoolSnapshot으로 실행해 시리얼 수집기를 고르면, 힙 풀의 이름이 Eden Space, Survivor Space, Tenured Gen으로 바뀝니다. 그러니 모니터링 코드에서 풀 이름을 고정된 값으로 가정하면 안 되고, 어떤 수집기로 실행했는지도 함께 기록해야 합니다. 또 운영 코드라면 더 이상 유효하지 않은 풀에서 getUsage()가 null을 돌려주는 경우도 처리해야 합니다.

이 출력에는 이상한 점이 하나 있습니다. 힙 전체의 used는 0.00 MiB인데, 풀 목록에서는 G1 Eden Space와 G1 Old Gen에 1 MiB 남짓씩 잡혀 있습니다. G1은 힙 전체 사용량과 풀별 사용량을 서로 다른 방식으로 집계해 두었다가 돌려주기 때문에, 같은 순간에 읽어도 둘이 맞아떨어지지 않을 수 있습니다. 이런 숫자는 정밀한 회계 장부가 아니라 추세를 보기 위한 지표로 다뤄야 합니다.

한 번 읽은 값으로 누수를 판단할 수 없는 이유도 여기에 있습니다. 힙 사용량은 객체를 만들면 오르고 GC가 돌면 떨어지기를 되풀이하므로, 아무 순간에나 읽은 값은 톱니 모양 그래프의 아무 점일 뿐입니다. 누수를 의심할 때 봐야 하는 것은 GC 직후의 사용량이 시간이 지나면서 어떻게 변하는가입니다. MemoryPoolMXBean의 getCollectionUsage()는 그 풀에서 가장 최근 GC가 끝난 직후의 사용량을 돌려주므로, 이 추세를 지표로 모을 때 쓸 수 있습니다.

만든 양과 남은 양은 다르다

할당률과 생존 객체 집합을 구체적인 숫자로 보겠습니다. 다음 프로그램은 100번의 회차마다 1,024바이트짜리 배열을 200개씩 만들고, 그중 회차마다 첫 번째 배열 하나만 목록에 남깁니다. 나머지 199개는 다음 반복으로 넘어가는 순간 어디에서도 참조하지 않는 쓰레기가 됩니다. 마지막에는 만든 배열 길이의 합과 남긴 배열 길이의 합을 따로 출력합니다.

import java.util.ArrayList;
import java.util.List;

public final class BoundedAllocationPressure {
    public static void main(String[] args) {
        List<byte[]> retained = new ArrayList<>();
        long allocatedBytes = 0;

        for (int round = 0; round < 100; round++) {
            for (int item = 0; item < 200; item++) {
                byte[] value = new byte[1_024];
                value[0] = (byte) item;
                allocatedBytes += value.length;
                if (item == 0) {
                    retained.add(value);
                }
            }
        }

        long retainedBytes = retained.stream().mapToLong(value -> value.length).sum();
        System.out.println("allocated-bytes=" + allocatedBytes);
        System.out.println("retained-bytes=" + retainedBytes);
        System.out.println("retained-objects=" + retained.size());
    }
}

allocated-bytes=20480000
retained-bytes=102400
retained-objects=100

배열을 모두 100 × 200 = 20,000개 만들었으니 만든 데이터는 20,000 × 1,024 = 20,480,000바이트, 약 19.5MiB입니다. 그중 목록에 남은 것은 회차마다 하나씩 100개, 100 × 1,024 = 102,400바이트(100KiB)뿐입니다. 이 프로그램은 실행하는 동안 20MB 가까이 할당하지만, 끝까지 살아 있는 데이터는 그 200분의 1입니다. 그림의 표가 말하듯 이 숫자들은 소스 코드에서 센 배열 데이터의 길이이며, 배열의 머리나 목록 자체가 쓰는 메모리는 들어 있지 않습니다.

두 숫자는 할당률과 생존 객체 집합에 각각 대응합니다. 할당률은 만든 양을 걸린 시간으로 나눈 값이므로, 같은 20MB라도 1초에 만들었는지 1분에 만들었는지에 따라 GC가 받는 부담이 다릅니다. 생존 객체 집합은 GC가 끝난 뒤에도 남는 객체들로, 이 예제에서는 목록에 남긴 배열 100개와 JVM이 원래 쓰던 객체들입니다. 할당률이 높으면 GC가 자주 돌고, 생존 객체 집합이 크면 GC 한 번이 살아 있는 객체를 찾아 옮기는 데 시간이 더 걸립니다. 이 차이를 눈으로 보여 주는 것이 GC 로그입니다.

GC 로그 읽기

HotSpot은 JDK 9부터 JVM의 여러 로그를 -Xlog 옵션 하나로 다루는 통합 로깅(unified logging)을 씁니다. GC 로그도 그중 하나로, gc 태그를 켜면 GC가 일어날 때마다 한 줄씩 남습니다. 앞의 프로그램을 컴파일하고 힙을 32MB로 고정해 실행해 보겠습니다.

javac BoundedAllocationPressure.java
java -Xms32m -Xmx32m -Xlog:gc BoundedAllocationPressure

[0.012s][info][gc] Using G1
[0.081s][info][gc] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 7M->1M(32M) 0.823ms
allocated-bytes=20480000
retained-bytes=102400
retained-objects=100

-Xms32m -Xmx32m은 힙의 처음 크기와 최대 크기를 모두 32MB로 정해서, 실행 중에 힙이 커지거나 줄지 않게 합니다. 로그 한 줄은 대괄호로 묶인 머리말과 본문으로 나뉩니다. 머리말의 [0.081s]는 JVM이 시작한 뒤 흐른 시간, [info]는 로그 수준, [gc]는 태그입니다. 첫 줄은 이 JVM이 G1 수집기를 쓴다는 뜻이고, 둘째 줄의 본문이 GC 한 번의 요약입니다.

• GC(0): 이 JVM에서 0번째 GC라는 번호입니다. 자세한 로그를 켜면 같은 GC에 관한 여러 줄이 이 번호로 묶입니다.
• Pause Young (Normal): 젊은 영역만 정리하는 GC이고, 그동안 애플리케이션 스레드가 모두 멈춘다(pause)는 뜻입니다.
• (G1 Evacuation Pause): GC가 일어난 이유입니다. Eden이 가득 차서 살아 있는 객체를 다른 영역으로 옮기는(evacuate) 작업이 필요해졌다는 뜻입니다.
• 7M->1M(32M): GC 직전의 힙 사용량이 7MB, 직후가 1MB라는 뜻입니다. 괄호 안은 그때 확보돼 있던 힙 크기입니다.
• 0.823ms: 애플리케이션이 멈춰 있던 시간입니다.

7MB가 1MB로 줄었다는 것은 Eden에 있던 객체 대부분이 이미 쓰레기였다는 뜻입니다. 남은 1MB 남짓에는 그때까지 목록에 남긴 배열과 JVM이 원래 쓰던 객체가 들어 있습니다. 멈춘 시간은 실행할 때마다 달라지므로 정확한 밀리초를 기대값으로 삼지 말고, 숫자의 크기와 추세를 읽습니다.

그런데 약 20MB를 할당했는데 GC는 한 번뿐입니다. G1이 Eden의 크기를 스스로 조절하기 때문입니다. 뒤에서 볼 자세한 로그를 켜면, 이 GC 직후 G1이 다음 Eden의 크기를 영역(region) 18개로 늘려 잡았다는 기록이 나옵니다. 이 실행에서 영역 하나는 1MB였으므로 나머지 할당이 늘어난 Eden에 다 들어갔고, GC가 더 일어나지 않았습니다.

GC가 자주 일어나게 해서 패턴 보기

이 프로그램은 0.1초도 안 돼 끝나므로 GC가 한두 번밖에 일어나지 않습니다. 패턴을 보려고 젊은 영역의 크기를 4MB로 고정하는 HotSpot 옵션 -Xmn4m을 더해 보겠습니다. 젊은 영역이 작으면 금방 차므로 GC가 자주 일어납니다. 이 옵션은 실험용입니다. G1에서 젊은 영역 크기를 고정하면 일시 중지 시간 목표에 맞춰 크기를 조절하는 기능이 꺼지므로 운영 환경에서는 보통 쓰지 않습니다.

java -Xms32m -Xmx32m -Xmn4m -Xlog:gc BoundedAllocationPressure

[0.005s][info][gc] Using G1
[0.036s][info][gc] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 5M->1M(32M) 0.717ms
[0.037s][info][gc] GC(1) Pause Young (Normal) (G1 Evacuation Pause) 4M->1M(32M) 0.686ms
[0.039s][info][gc] GC(2) Pause Young (Normal) (G1 Evacuation Pause) 4M->1M(32M) 0.970ms
[0.040s][info][gc] GC(3) Pause Young (Normal) (G1 Evacuation Pause) 4M->1M(32M) 0.870ms
[0.041s][info][gc] GC(4) Pause Young (Normal) (G1 Evacuation Pause) 4M->1M(32M) 0.880ms
[0.042s][info][gc] GC(5) Pause Young (Normal) (G1 Evacuation Pause) 4M->1M(32M) 0.804ms

GC가 1밀리초 남짓한 간격으로 여섯 번 일어났지만, GC 직후의 사용량은 매번 1MB로 같습니다. 객체를 많이 만들지만 거의 다 곧바로 쓰레기가 되는, 할당률은 높고 생존 객체 집합은 작고 안정된 모습입니다. 이 로그로 할당률도 어림할 수 있습니다. GC(1)이 끝난 뒤부터 GC(5)가 시작되기까지 약 0.005초 동안 GC가 네 번 있었고, 매번 1MB에서 4MB까지 약 3MB가 찼으니 0.005초에 12MB쯤 할당한 셈입니다. 로그의 숫자가 MB와 밀리초 단위로 반올림돼 있어 정확하지는 않지만, 초당 GB 단위의 속도로 할당하고 있다는 것은 알 수 있습니다.

비교를 위해, 만든 배열을 하나도 버리지 않고 모두 목록에 남기는 프로그램을 같은 옵션으로 실행해 보겠습니다. 누수가 있는 프로그램을 흉내 낸 것입니다.

import java.util.ArrayList;
import java.util.List;

public final class RetainAllAllocation {
    public static void main(String[] args) {
        List<byte[]> retained = new ArrayList<>();
        for (int round = 0; round < 100; round++) {
            for (int item = 0; item < 200; item++) {
                retained.add(new byte[1_024]); // 만든 배열을 하나도 버리지 않는다
            }
        }
        System.out.println("retained-objects=" + retained.size());
    }
}

javac RetainAllAllocation.java
java -Xms32m -Xmx32m -Xmn4m -Xlog:gc RetainAllAllocation

[0.004s][info][gc] Using G1
[0.037s][info][gc] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 5M->4M(32M) 2.692ms
[0.041s][info][gc] GC(1) Pause Young (Normal) (G1 Evacuation Pause) 7M->7M(32M) 2.192ms
[0.044s][info][gc] GC(2) Pause Young (Normal) (G1 Evacuation Pause) 10M->10M(32M) 2.566ms
[0.047s][info][gc] GC(3) Pause Young (Normal) (G1 Evacuation Pause) 13M->13M(32M) 2.477ms
[0.049s][info][gc] GC(4) Pause Young (Normal) (G1 Evacuation Pause) 16M->16M(32M) 2.122ms
[0.052s][info][gc] GC(5) Pause Young (Concurrent Start) (G1 Evacuation Pause) 19M->19M(32M) 2.158ms
[0.052s][info][gc] GC(6) Concurrent Mark Cycle
[0.056s][info][gc] GC(6) Pause Remark 21M->21M(32M) 0.367ms
[0.058s][info][gc] GC(6) Pause Cleanup 21M->21M(32M) 0.035ms
[0.063s][info][gc] GC(6) Concurrent Mark Cycle 10.936ms
retained-objects=20000

이번에는 GC 직후의 사용량이 4MB, 7MB, 10MB로 GC마다 약 3MB씩 늘어납니다. 젊은 영역에서 살아남은 객체가 Old 영역으로 옮겨져 계속 쌓이기 때문입니다. 생존 객체 집합이 커지는 모습이고, 실제 서비스에서 이런 추세가 몇 시간씩 이어진다면 누수를 의심해야 합니다. 또 Old 영역에 쌓인 양이 G1이 정한 기준을 넘자, G1은 GC(5)에 Concurrent Start를 표시하고 Old 영역에서 살아 있는 객체를 찾아 표시하는(marking) 작업을 애플리케이션과 동시에 시작했습니다. 이어지는 Pause Remark와 Pause Cleanup은 이 작업 중간에 짧게 멈추는 단계입니다. 이 프로그램은 20MB를 남기고 끝났지만, 힙보다 많이 남기려 했다면 결국 OutOfMemoryError: Java heap space로 멈췄을 것입니다.

두 로그를 나란히 놓으면 GC 로그에서 가장 먼저 읽을 것이 무엇인지 분명해집니다. 화살표 오른쪽, 즉 GC 직후의 사용량이 제자리에 머무르면 할당률 쪽을, 계속 올라가면 생존 객체 집합 쪽을 의심합니다. 화살표 왼쪽의 값과 GC 사이의 간격은 할당률을 어림하는 데 씁니다.

운영 환경에서 남기는 GC 로그

실제 서비스에서는 더 자세한 로그를 파일로 남겨 둡니다. 다음 명령은 GC와 관련된 로그 전부와 세이프포인트 기록을 gc.log 파일에 씁니다.

java -Xms32m -Xmx32m -Xlog:gc*,safepoint:file=gc.log:time,level,tags BoundedAllocationPressure

-Xlog의 값은 콜론으로 구분한 세 부분으로 되어 있습니다. 첫 부분 gc*,safepoint는 무엇을 남길지를 정합니다. gc*는 gc 태그가 들어 있는 모든 태그 조합(gc,heap이나 gc,start 같은 것)이고, *가 없는 safepoint는 태그가 정확히 safepoint인 기록, 즉 JVM이 GC 같은 작업을 하려고 모든 스레드를 멈춰 세우는 지점인 세이프포인트의 기록입니다. 둘째 부분 file=gc.log는 어디에 쓸지를, 셋째 부분 time,level,tags는 줄마다 붙일 머리말을 정하며 여기서는 벽시계 시각과 로그 수준, 태그를 붙입니다. 이렇게 만든 gc.log에서 GC(0)에 해당하는 부분을 일부 옮기면 다음과 같습니다.

[2026-10-27T09:34:38.659+0900][info][gc,start    ] GC(0) Pause Young (Normal) (G1 Evacuation Pause)
[2026-10-27T09:34:38.672+0900][info][gc,heap     ] GC(0) Eden regions: 6->0(18)
[2026-10-27T09:34:38.672+0900][info][gc,heap     ] GC(0) Survivor regions: 0->1(1)
[2026-10-27T09:34:38.672+0900][info][gc,heap     ] GC(0) Old regions: 2->2
[2026-10-27T09:34:38.672+0900][info][gc,heap     ] GC(0) Humongous regions: 0->0
[2026-10-27T09:34:38.672+0900][info][gc          ] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 7M->1M(32M) 12.891ms
[2026-10-27T09:34:38.672+0900][info][safepoint   ] Safepoint "G1CollectForAllocation", Time since last: 42149737 ns, Reaching safepoint: 2557 ns, Cleanup: 2827 ns, At safepoint: 12915945 ns, Leaving safepoint: 20920 ns, Total: 12942249 ns

gc,heap 줄은 영역 종류별로 GC 전후에 영역을 몇 개 썼는지 보여 줍니다. Eden regions: 6->0(18)은 Eden 영역 6개가 GC 뒤에 모두 비었고, 다음 Eden의 크기를 18개로 잡았다는 뜻입니다. 앞에서 GC가 한 번뿐이었던 이유가 이 줄에 있습니다. Humongous regions는 영역 크기의 절반 이상인 큰 객체를 따로 담는 G1의 거대 객체(humongous object) 영역입니다. 마지막 safepoint 줄의 At safepoint는 스레드들이 멈춰 있던 시간을 나노초로 적은 것으로, 바로 위 GC 요약의 12.891ms와 거의 같습니다. 같은 프로그램인데도 앞의 실행에서는 0.823ms였으니, 멈춘 시간이 실행마다 크게 달라질 수 있다는 것도 함께 확인할 수 있습니다.

운영 환경에서는 로그 파일이 끝없이 커지지 않게 회전(rotation) 설정을 함께 둡니다. -Xlog:gc*:file=gc.log:time,level,tags:filecount=5,filesize=10m처럼 넷째 부분에 출력 옵션을 주면, 파일 하나가 10MB가 될 때마다 다음 파일로 넘어가며 정해 둔 개수만큼의 파일을 돌려 가며 씁니다. 쓸 수 있는 태그와 문법은 지금 쓰는 JDK에서 java -Xlog:help로 확인합니다.

약한 참조로 만든 캐시는 참조 큐로 정리한다

누수의 흔한 원인 하나는 캐시입니다. 한 번 넣은 항목을 꺼내지 않는 HashMap은 생존 객체 집합을 끝없이 키웁니다. 그래서 약한 참조(weak reference)로 값을 붙잡는 캐시를 쓰기도 합니다. WeakReference가 가리키는 객체는 다른 곳에서 보통의 참조, 즉 강한 참조로 붙잡고 있지 않으면 GC가 회수할 수 있고, 회수된 뒤에는 그 WeakReference의 get()이 null을 돌려줍니다.

하지만 객체가 회수된다고 캐시가 저절로 깨끗해지지는 않습니다. 객체를 가리키던 WeakReference 자신과, 그것을 찾는 데 쓰던 키나 부가 정보는 여전히 맵이나 목록에 남아 있기 때문입니다. 이것을 치우려면 WeakReference를 만들 때 참조 큐(ReferenceQueue)를 함께 등록합니다. 그러면 비워진 참조가 그 큐에 들어오므로, 큐에서 꺼낸 참조에 해당하는 항목을 지우면 됩니다. 다음 프로그램은 1KB 배열 100개를 약한 참조로만 붙잡아 두고, System.gc()로 GC를 요청한 뒤 큐를 비우며 목록에서 항목을 지웁니다.

import java.lang.ref.Reference;
import java.lang.ref.ReferenceQueue;
import java.lang.ref.WeakReference;
import java.util.ArrayList;
import java.util.List;

public final class WeakReferenceQueueInventory {
    public static void main(String[] args) {
        ReferenceQueue<byte[]> queue = new ReferenceQueue<>();
        List<WeakReference<byte[]>> references = new ArrayList<>();
        for (int index = 0; index < 100; index++) {
            references.add(new WeakReference<>(new byte[1_024], queue));
        }

        System.gc();
        int enqueued = 0;
        Reference<? extends byte[]> reference;
        while ((reference = queue.poll()) != null) {
            enqueued++;
            references.remove(reference);
        }

        long cleared = references.stream().filter(ref -> ref.get() == null).count();
        System.out.println("enqueued=" + enqueued);
        System.out.println("still-tracked=" + references.size());
        System.out.println("cleared-but-tracked=" + cleared);
    }
}

enqueued=0
still-tracked=100
cleared-but-tracked=100

큐에서 꺼낸 참조는 0개이고, 목록에는 100개가 그대로 남았습니다. 그런데 마지막 줄을 보면 남은 100개는 모두 이미 비워진 참조입니다. GC는 배열 100개를 회수하고 참조도 모두 비웠는데, poll()을 부른 순간에는 큐가 비어 있었던 것입니다. 참조를 비우는 일과 큐에 넣는 일이 같은 순간에 일어나지 않기 때문입니다. OpenJDK에서는 GC가 비운 참조를 Reference Handler라는 별도 스레드가 조금 뒤에 큐에 넣습니다. poll()은 기다리지 않고 지금 큐에 있는 것만 꺼내므로, System.gc() 바로 다음 줄에서 부르면 아직 아무것도 없을 수 있습니다.

이 예제에서 결과를 확인하려면 poll() 대신 시간 제한을 두고 기다리는 remove(timeout)을 씁니다. 반복문의 조건을 다음처럼 바꾸고, remove는 기다리는 도중에 인터럽트되면 InterruptedException을 던지므로 main 선언에 throws InterruptedException을 붙입니다.

while ((reference = queue.remove(100)) != null) { // 큐가 비어 있으면 최대 0.1초 기다린다

enqueued=100
still-tracked=0
cleared-but-tracked=0

이번에는 100개가 모두 큐로 들어와 목록이 깨끗해졌습니다. remove(100)은 큐가 비어 있으면 최대 100밀리초를 기다리고, 그동안 아무것도 들어오지 않으면 null을 돌려주어 반복을 끝냅니다. 같은 프로그램을 HotSpot 옵션 -XX:+DisableExplicitGC로 실행하면 System.gc() 호출이 무시되어 enqueued=0, still-tracked=100, cleared-but-tracked=0이 나옵니다. GC가 일어나지 않아 아무 참조도 비워지지 않은 것입니다. System.gc()는 GC를 요청할 뿐 실행을 보장하지 않는다는 것을 이렇게 직접 확인할 수 있습니다.

실제 캐시는 이렇게 기다리지 않습니다. 캐시를 쓸 때마다 poll()로 그때까지 큐에 들어온 것을 치우면 충분하고, 표준 라이브러리의 WeakHashMap도 내부에서 이 방식으로 사라진 키의 항목을 정리합니다. 다만 약한 참조는 '다른 곳에서 더 이상 쓰지 않으면 지워도 된다'는 뜻이지, '메모리가 부족하면 지운다'는 뜻이 아닙니다. 그래서 대부분의 캐시에는 최대 항목 수나 유효 시간을 정해 두고 오래된 항목부터 내보내는 방식이 더 알맞습니다. 이때 캐시 적중률과 내보낸 항목 수를 지표로 함께 봐야 크기를 제대로 정할 수 있습니다.

실행 중인 JVM에 jcmd로 묻기

GC 로그는 JVM을 시작할 때 켜야 하지만, jcmd는 이미 실행 중인 JVM에 진단 명령을 보낼 수 있습니다. JDK에 함께 들어 있는 도구이며, 대상 JVM과 같은 사용자로 실행해야 합니다. 연습 대상으로 게시글 제목 5만 개를 만들어 둔 채 1분 동안 기다리는 프로그램을 띄워 보겠습니다.

import java.util.ArrayList;
import java.util.List;

public final class IdleBoard {
    public static void main(String[] args) throws InterruptedException {
        List<String> posts = new ArrayList<>();
        for (int i = 0; i < 50_000; i++) {
            posts.add("post-" + i);
        }
        System.out.println("ready " + posts.size());
        Thread.sleep(60_000);
    }
}

이 프로그램을 실행해 둔 채 다른 터미널에서 jcmd -l을 실행하면, 실행 중인 JVM의 프로세스 번호(pid)와 메인 클래스가 나옵니다. 아래 예에서 pid는 16949였고, 실행할 때마다 달라집니다. 이 pid를 넣어 힙 요약과 클래스별 히스토그램을 요청합니다.

jcmd -l
jcmd 16949 GC.heap_info
jcmd 16949 GC.class_histogram

16949:
 garbage-first heap   total 98304K, used 5415K [0x00000000a2800000, 0x0000000100000000)
  region size 1024K, 5 young (5120K), 0 survivors (0K)
 Metaspace       used 193K, committed 384K, reserved 1114112K
  class space    used 10K, committed 128K, reserved 1048576K

16949:
 num     #instances         #bytes  class name (module)
-------------------------------------------------------
   1:         58087        1946504  [B ([email protected])
   2:         58006        1392144  java.lang.String ([email protected])
   3:          1032         416224  [Ljava.lang.Object; ([email protected])
   4:          1507         186408  java.lang.Class ([email protected])

GC.heap_info는 앞의 MXBean 값과 비슷한 힙 요약입니다. 확보한 힙 96MB 가운데 약 5MB를 쓰고 있고, 영역 크기는 1MB입니다. GC.class_histogram은 힙의 객체를 클래스별로 세어, 차지한 바이트가 큰 순서로 보여 줍니다. 클래스 이름은 JVM 내부 표기라서 [B는 byte[]를, [Ljava.lang.Object;는 Object[]를 뜻합니다. 맨 위의 byte[] 5만 8천여 개와 String 5만 8천여 개는 대부분 우리가 만든 제목 5만 개입니다. Java 9부터 String 객체는 글자를 내부의 byte 배열에 담으므로 문자열 하나가 객체 두 개로 보입니다.

이 밖에 jcmd 16949 VM.version은 JVM 버전을, jcmd 16949 VM.flags는 실제로 적용된 JVM 옵션을 보여 줍니다. 이 실행의 VM.flags에는 명령줄에서 주지 않은 -XX:+UseG1GC와 -XX:MaxHeapSize=1568669696도 나왔습니다. JVM이 스스로 정한 값까지 보여 주므로, 문제가 생긴 프로세스의 설정을 기록해 둘 때 유용합니다. 1,568,669,696바이트는 앞의 MXBean 예제에서 본 heap-max 1496 MiB와 같은 값입니다.

히스토그램은 어떤 타입이 메모리를 많이 쓰는지는 알려 주지만, 누가 그 객체들을 붙잡고 있는지는 알려 주지 않습니다. 그래서 누수를 찾을 때는 몇 분 간격으로 히스토그램을 여러 번 떠서 계속 늘어나는 타입을 찾고, 그 타입의 객체가 어떤 참조 경로로 살아 있는지는 힙 덤프(heap dump)를 떠서 Eclipse MAT나 VisualVM 같은 분석 도구로 확인합니다. 힙 덤프는 그 순간 힙에 있는 객체 전부를 파일로 쓴 것입니다.

jcmd 16949 GC.heap_dump /tmp/board-heap.hprof

GC.heap_dump는 파일 이름을 이름 붙은 옵션이 아니라 위치로 받는 인수입니다. 뒤에 나올 JFR.start처럼 filename=을 붙여 값을 받는 명령도 있어서 헷갈리기 쉬운데, JDK 21에서 jcmd 16949 GC.heap_dump filename=heap.hprof라고 쓰면 Dumping heap to filename ...이 출력되고 filename이라는 이름의 파일이 생깁니다. 또 상대 경로는 jcmd를 실행한 위치가 아니라 대상 JVM의 작업 디렉터리를 기준으로 풀리므로, 위처럼 절대 경로를 쓰는 편이 안전합니다.

히스토그램과 힙 덤프는 가벼운 조회가 아닙니다. jcmd 16949 help GC.class_histogram처럼 help를 붙이면 명령마다 설명이 나오는데, 두 명령 모두 Impact: High로 표시됩니다. GC.heap_dump의 설명에는 -all 옵션을 주지 않으면 전체 GC를 요청한다는 말도 있습니다. 힙이 클수록 그동안 애플리케이션이 오래 멈추고, 덤프 파일도 사용 중인 힙만큼 커집니다. 게다가 덤프에는 힙의 모든 객체가 들어 있으므로 비밀번호나 개인정보가 담긴 문자열도 그대로 들어갑니다. 운영 서버에서 덤프를 뜰 때는 디스크 여유와 정지 시간을 미리 따지고, 파일은 민감한 자료로 다뤄 접근 권한과 보관 기간을 정해야 합니다.

증상에서 원인 후보로

지금까지 본 도구로 메모리 문제를 다음처럼 나눠 볼 수 있습니다. 표의 셋째 열은 그 가설을 확인하려면 다음에 무엇을 볼지입니다.

넷째 줄은 힙 덤프만으로는 설명되지 않는 경우입니다. 운영체제가 보는 프로세스의 메모리는 힙에 스레드 스택, 클래스 정보, JIT 코드, NIO의 직접 버퍼 같은 힙 밖의 메모리를 더한 것이기 때문입니다. HotSpot에서는 -XX:NativeMemoryTracking=summary 옵션으로 JVM을 시작해 두면 jcmd <pid> VM.native_memory summary로 이 영역들을 항목별로 볼 수 있습니다. 마지막 줄의 클래스 로더 누수는 같은 클래스를 다른 로더로 계속 새로 로딩하는 환경에서 생기며, 클래스 로딩 로그를 읽는 방법은 클래스 로딩과 초기화에서 다뤘습니다.

정리

• 메모리 크기는 long과 Math.multiplyExact로 계산하고, 배열로 만들 수 있는 크기인지 따로 확인합니다. int 곱셈은 넘쳐도 예외 없이 엉뚱한 값을 냅니다.
• MemoryMXBean과 MemoryPoolMXBean의 값은 순간의 숫자입니다. 풀 이름은 수집기마다 다르고, 누수 판단에는 GC 직후 사용량의 추세가 필요합니다.
• GC 로그에서는 화살표 오른쪽, 즉 GC 직후 사용량을 먼저 봅니다. 일정하면 할당률을, 계속 오르면 생존 객체 집합을 의심합니다.
• 약한 참조가 비워지는 시점과 참조 큐에 들어오는 시점은 다릅니다. 캐시는 큐를 꾸준히 비워 남은 항목을 치우고, 보통은 크기와 시간 기준으로 항목을 내보냅니다.
• jcmd의 히스토그램은 많이 쓰는 타입을, 힙 덤프는 객체를 붙잡은 참조 경로를 보여 줍니다. 둘 다 영향이 큰 명령이고, 힙 덤프에는 민감한 데이터가 들어갑니다.

연습 문제

원소 수와 원소당 바이트 수를 받아 byte 배열의 길이로 쓸 수 있는 int 값을 돌려주는 checkedArrayLength를 작성하세요. 계산은 long으로 하고, 음수 입력이나 int 범위를 넘는 결과는 IllegalArgumentException으로 거절합니다. 실제로 배열을 만들 필요는 없습니다.

다음 네 입력에 대해 결과를 먼저 예상한 뒤 실행해 보세요. 특히 마지막 입력은 int 상한 검사와 long 곱셈 오버플로 가운데 어디에서 걸러지는지 생각해 봅니다.

1. 원소 1,000개, 원소당 32바이트
2. 원소 100,000,000개, 원소당 32바이트
3. 원소 0개, 원소당 32바이트
4. 원소 Long.MAX_VALUE개, 원소당 2바이트

public final class SafeMemoryBudgetSolution {
    static int checkedArrayLength(long elements, long bytesPerElement) {
        if (elements < 0 || bytesPerElement < 0) {
            throw new IllegalArgumentException("negative input");
        }
        long bytes;
        try {
            bytes = Math.multiplyExact(elements, bytesPerElement);
        } catch (ArithmeticException overflow) {
            throw new IllegalArgumentException("budget overflows long", overflow);
        }
        if (bytes > Integer.MAX_VALUE) {
            throw new IllegalArgumentException("array too large: " + bytes);
        }
        return Math.toIntExact(bytes);
    }

    public static void main(String[] args) {
        long[][] inputs = {{1_000, 32}, {100_000_000, 32}, {0, 32}, {Long.MAX_VALUE, 2}};
        for (long[] input : inputs) {
            try {
                System.out.println("ok: " + checkedArrayLength(input[0], input[1]));
            } catch (IllegalArgumentException exception) {
                System.out.println("rejected: " + exception.getMessage());
            }
        }
    }
}

ok: 32000
rejected: array too large: 3200000000
ok: 0
rejected: budget overflows long

다음 글

JFR로 실행 기록 남기고 분석하기에서는 JVM에 내장된 기록 장치인 Java Flight Recorder로 GC, CPU, 할당 이벤트를 한 파일에 모아 봅니다. 이 글에서 GC 로그로 어림했던 할당률과 GC 일시 중지를 JFR에서는 이벤트로 직접 볼 수 있습니다.