Java JIT·GC·메모리를 JDK 26 에서 실측하기

시리즈: Java 강좌 6/6 (고급). 올바른 Java 코드는 쓸 수 있고, 이제 JVM 이 그 코드를 어떻게 다루는지 알고 싶은 분을 위한 글입니다. 코드는 언제 빨라지는지, 메모리는 어디로 가는지, 왜 플래그 하나로 같은 프로그램이 다르게 움직이는지. 다 읽으면 -Xlog:gc 출력을 읽고, GC 를 소문이 아니라 측정으로 고르고, jcmd 로 누수를 찾고, 거짓말하는 벤치마크를 알아볼 수 있습니다.

"운영 서버에서만 느리다", "새벽 배치가 OOM 으로 죽었다"는 문제는 대개 세 곳 중 하나에서 옵니다. JIT 가 아직 아무것도 컴파일하지 않은 시점에 잰 경우, 습관으로 고른 GC, 그리고 계속 늘기만 하는 메모리. JVM 튜닝은 면접 단골 주제이기도 한데, 이 글은 외운 답 대신 작은 프로그램으로 하나씩 뜯어봅니다. 숫자는 모두 아래 환경에서 직접 잰 것이고, 예상 밖의 결과(힙 절반에서 OOM, 누수로 죽어 가는 JVM 에 attach 실패)는 출력을 그대로 남겼습니다.

실행 환경: OpenJDK 26 (Temurin 26+35), Apple Silicon Mac (M1 Pro, 8 코어, 메모리 16GB), macOS. 이 기기의 기본값은 최대 힙 4GB, G1 입니다. 시간은 대부분 3 회 중앙값이고, JIT 워밍업 실험만은 워밍업 자체가 주제라서 묶음별로 보여 줍니다.

JIT 워밍업 측정: 첫 묶음과 정상 상태

HotSpot 은 모든 메서드를 먼저 바이트코드 인터프리터로 실행하면서 호출 횟수와 루프 횟수를 세고, 자주 쓰이는 메서드를 단계적으로 컴파일합니다. 먼저 C1 이 프로파일링을 넣어(tier 3), 다음에 C2 가 그 프로파일로(tier 4) 컴파일합니다. 같은 작은 묶음을 2,000 번 재 봅니다.

/** Time the same small batch 2,000 times and watch the JIT kick in. */
public class Warmup {
    static int collatzSteps(long n) {                // pure CPU, no allocation
        int steps = 0;
        while (n != 1) { n = (n & 1) == 0 ? n >>> 1 : 3 * n + 1; steps++; }
        return steps;
    }
    static long batch() {                            // 1,000 calls per batch
        long total = 0;
        for (long n = 1; n <= 1_000; n++) total += collatzSteps(n);
        return total;
    }
    public static void main(String[] args) {
        int[] show = {1, 2, 3, 5, 10, 20, 50, 100, 200, 500, 1000, 2000};
        long check = 0; int k = 0;
        long start = System.nanoTime();
        for (int b = 1; b <= 2000; b++) {
            long t0 = System.nanoTime();
            check += batch();
            long us = (System.nanoTime() - t0) / 1_000;
            if (k < show.length && b == show[k]) { System.out.printf("batch %4d: %,6d us%n", b, us); k++; }
        }
        System.out.printf("total %,d ms, checksum %d%n", (System.nanoTime() - start) / 1_000_000, check);
    }
}

계단이 세 개 보입니다. 첫 묶음이 약 350µs(일부는 인터프리터, 일부는 컴파일 중), 5 회째쯤부터 약 75µs, 200 회째쯤부터 46µs 입니다. 정상 상태는 첫 묶음보다 7.6 배 빠릅니다. -XX:+PrintCompilation 을 붙이면 각 단계가 언제 일어났는지 보입니다(열: 시작 후 ms, 컴파일 ID, % 는 OSR, tier).

20    8       3       Warmup::collatzSteps (38 bytes)
20    9 %     4       Warmup::collatzSteps @ 2 (38 bytes)
36  116       4       Warmup::collatzSteps (38 bytes)
37    8       3       Warmup::collatzSteps (38 bytes)   made not entrant: not used
...
44  127 %     4       Warmup::batch @ 4 (29 bytes)
45  128       4       Warmup::batch (29 bytes)

collatzSteps 는 36ms 에 C2(tier 4)에 도달했고 C1 버전은 버려졌습니다(made not entrant). 100~200 회째 즈음의 두 번째 단축은 호출하는 쪽인 batch() 가 45ms 에 tier 4 로 컴파일된 시점과 맞습니다. 이때부터 C2 가 collatzSteps 를 루프 안에 인라인할 수 있게 됩니다. 'C1 만' 열을 보면 C2 가 더해 주는 몫이 보입니다. C1 은 76µs, C2 는 46µs 에서 멈췄습니다.

-Xint 와 기본값 비교: JIT 의 값어치

-Xint 는 JIT 를 끕니다. 그러면 묶음마다 약 900µs 가 들고, 전체는 117ms 가 아니라 1,940ms 였습니다. 합계로 16.6 배, 정상 상태 기준 약 20 배(910µs 대 46µs) 느립니다. 인터프리터는 빨라지지 않으니 열이 평평합니다. -Xint 의 쓸모는 하나뿐입니다. 버그가 -Xint 에서 사라지면 JIT 관련 문제(또는 컴파일러가 드러낸 데이터 경쟁)를 의심할 수 있습니다. 측정을 '공정하게' 하려고 쓰면 안 됩니다.

이스케이프 분석 간단히

C2 는 객체가 만들어진 메서드 바깥에서 보이는지 확인합니다. 보이지 않으면 할당 자체를 생략하고 필드를 레지스터에 둘 수 있습니다(스칼라 치환). 루프 밖으로 나가지 않는 record 로 확인합니다.

record Point(double x, double y) {}

static double sumDistances(int n) {
    double s = 0;
    for (int i = 0; i < n; i++) {
        Point p = new Point(i, i + 1);            // never stored, never returned
        s += Math.sqrt(p.x() * p.x() + p.y() * p.y());
    }
    return s;
}

한 라운드에 5,000만 번 돌리면서, 스레드가 할당한 바이트 수를 com.sun.management.ThreadMXBean.getThreadAllocatedBytes 로 셌습니다.

== default (EA on)
round 1:   57 ms, allocated      7 MB
round 3:   50 ms, allocated      0 MB
round 5:   49 ms, allocated      0 MB
== -XX:-DoEscapeAnalysis
round 1:  326 ms, allocated  1,525 MB
round 3:   80 ms, allocated  1,525 MB
round 5:  117 ms, allocated  1,525 MB

1,525MB 는 정확히 5,000만 × 32 바이트, 한 번에 Point 하나입니다. 이스케이프 분석이 켜져 있으면 정상 상태의 할당은 0 이었습니다. 교훈은 '끄라'가 아니라, 핫 루프 안의 작고 수명 짧은 객체는 공짜인 경우가 많으니 재 보지도 않고 record 를 손으로 풀어 헤치지 말라는 것입니다. 객체를 필드에 저장하거나, 인라인되지 않는 메서드에 넘기거나, 메서드가 너무 커서 인라인되지 않으면 이스케이프 분석은 포기합니다.

같은 프로그램을 GC 4 종으로

할당이 많은 프로그램입니다. 16~495 바이트 byte[] 를 2,000만 개(Random(42) 고정) 만들고, 8 개 중 1 개를 20만 칸짜리 링에 보관해 약 50MB 의 살아 있는 데이터를 늘 유지합니다.

Random rnd = new Random(42);
byte[][] live = new byte[200_000][];          // the long-lived working set
for (int i = 0; i < 20_000_000; i++) {
    byte[] b = new byte[16 + rnd.nextInt(480)];
    b[0] = (byte) i;
    if ((i & 7) == 0) live[rnd.nextInt(live.length)] = b;   // 1 in 8 survives a while
    checksum += b[0];
}

java -XX:+Use<X>GC -Xmx1g -Xlog:gc:file=gc.log Churn 으로 실행했습니다. 실제 로그 줄(발췌)입니다.

G1        [0.874s][info][gc] GC(23) Pause Young (Normal) (G1 Evacuation Pause) 675M->207M(862M) 7.355ms
Serial    [1.218s][info][gc] GC(122) Pause Young (Allocation Failure) 606M->449M(622M) 17.816ms
Parallel  [0.779s][info][gc] GC(32) Pause Young (Allocation Failure) 341M->104M(342M) 5.028ms
ZGC       [0.275s][info][gc] GC(3) Minor Collection (Allocation Rate) 432M(42%)->226M(22%) 0.047s

ZGC 줄이 함정입니다. 0.047s 는 프로그램이 계속 도는 동안 진행된 동시 사이클 전체 길이이지 정지 시간이 아닙니다. 그냥 -Xlog:gc 로는 ZGC 의 정지가 아예 안 나오니 gc+phases 를 더합니다.

[0.375s][info][gc,phases] GC(5) Y: Pause Mark Start (Major) 0.009ms
[0.386s][info][gc,phases] GC(5) Y: Concurrent Mark 10.114ms
[0.386s][info][gc,phases] GC(5) Y: Pause Mark End 0.008ms
[0.387s][info][gc,phases] GC(5) Y: Pause Relocate Start 0.006ms

'Pause' 줄을 모두 합산했습니다(로그를 Python 스크립트로 집계, 각 3 회).

CPU 사용자 시간은 같은 프로그램을 로그 없이 /usr/bin/time -p 아래에서 따로 돌려 쟀습니다.

읽는 법입니다. Parallel 은 정지할 때마다 8 코어를 모두 쓰고 동시 작업을 하지 않으니 가장 먼저 끝났습니다. ZGC 는 애플리케이션을 거의 멈추지 않았지만 일을 다른 스레드에서 하느라 G1 보다 CPU 를 55% 더 썼고, 바쁜 서버라면 그 값을 치릅니다. Serial 은 GC 스레드 하나에 기본 Young 영역이 작아서 125 번 수집했습니다. G1 은 모든 열에서 중간이고, 그래서 기본값입니다. G1 의 실행 간 편차가 커서(835~1,087ms) 이 표에서 15% 미만 차이는 잡음으로 보세요.

힙 크기, OutOfMemoryError, 그리고 G1 의 의외의 동작

-Xmx64m 힙을 1MB 블록으로 채웁니다.

List<byte[]> keep = new ArrayList<>();
while (true) {
    keep.add(new byte[1 << 20]);
    if (keep.size() % 16 == 0) System.out.println("holding " + keep.size() + " MB");
}

max heap = 64 MB
holding 16 MB
Exception in thread "main" java.lang.OutOfMemoryError: Java heap space
    at Oom.main(Oom.java:10)

'holding 32 MB' 는 끝내 나오지 않았습니다. 64MB 힙이 1MB 배열 31 개에서 바닥났습니다. 이유는 로그에 있습니다. Pause Young (Normal) (G1 Humongous Allocation). 이 힙에서 G1 은 리전을 1MB 로 잡았습니다(-XX:+PrintFlagsFinal 에서 G1HeapRegionSize = 1048576). 리전 절반 이상인 객체는 humongous 가 되어 리전을 통째로 차지하는데, new byte[1048576] 은 데이터 1MB 에 16 바이트 헤더가 붙으니 리전 2 개가 필요합니다. 오류까지 몇 개가 들어갔는지 셌습니다.

16 바이트 줄였을 뿐인데 G1 에 들어가는 양이 두 배가 됐습니다. 리전에 비해 큰, 정확히 2 의 거듭제곱 크기 버퍼가 최악입니다. 해결책은 힙을 키우기(리전도 커짐), -XX:G1HeapRegionSize= 지정, 버퍼를 조금 줄이기 중 하나입니다.

알아 두면 좋은 실제 출력이 두 개 더 있습니다. -XX:+ExitOnOutOfMemoryError 를 붙이면 Terminating due to java.lang.OutOfMemoryError: Java heap space 를 찍고 종료 코드 3 으로 끝나므로, 반쯤 죽은 프로세스로 남지 않고 감시 도구가 재시작할 수 있습니다. 그리고 힙이 꽉 차서 오류 처리조차 할당하지 못하면 스택 트레이스 없이 이것만 나옵니다.

Exception: java.lang.OutOfMemoryError thrown from the UncaughtExceptionHandler in thread "main"

흔한 실수: static Map 으로 생기는 메모리 누수

실수: 요청마다 새 키를 넣는 static HashMap 을 캐시로 쓴다.

static final Map<String, Session> CACHE = new HashMap<>();          // the leak
...
cache.put("req-" + req, new Session("user" + (req % 100), new byte[1024]));

실제로 일어나는 일 (-Xmx256m):

requests=   50,000  entries=   50,001  heapUsed=  63 MB
requests=  100,000  entries=  100,001  heapUsed= 120 MB
requests=  150,000  entries=  150,001  heapUsed= 180 MB
requests=  200,000  entries=  200,001  heapUsed= 253 MB

Exception: java.lang.OutOfMemoryError thrown from the UncaughtExceptionHandler in thread "main"

도는 동안 JDK 에 들어 있는 jstat 과 jcmd 로 밖에서 관찰했습니다.

$ jcmd -l
69893 Leak
$ jstat -gcutil <pid> 3000
  S0     S1     E      O      M     CCS    YGC     YGCT     FGC    FGCT  ...
     - 100.00   0.00  91.67  73.19  20.54      8     0.009     0     0.000
     - 100.00   0.00  98.34  73.26  20.54     37     0.037     0     0.000
     -      -  33.33  67.30  73.84  20.54     44     0.054     1     0.024
     - 100.00  12.50  99.99  73.84  20.54     55     0.086     1     0.024
$ jcmd <pid> GC.class_histogram
 num     #instances         #bytes  class name (module)
   1:        227556       79768448  [B (java.base@26)
   2:        155023        3720552  java.lang.String (java.base@26)
   3:         75104        2403328  java.util.HashMap$Node (java.base@26)
   4:         72451        1738824  Leak$Session

O 열(Old 영역 사용률 %)이 Full GC(FGC = 1) 뒤에도 99.99 까지 다시 올라갑니다. 쓰레기가 아니라 살아 있는 데이터라는 뜻입니다. 히스토그램에서 Leak$Session 과 HashMap$Node 개수가 같이 늘어나니 Map 이 원인임이 바로 보입니다. jcmd <pid> GC.heap_info 에는 86 old (86M), 1 humongous (1M) 이 나왔습니다. 함정이 하나 더 있습니다. 더 빨리 진행되는 설정으로 돌렸을 때는 JVM 이 Full GC 를 연달아 하느라 jcmd 가 AttachNotSupportedException: ... state is not ready to participate in attach handshake! 로 실패했습니다. 일찍 attach 하거나 -XX:+HeapDumpOnOutOfMemoryError 를 붙여 띄워 두세요.

고치는 법: 캐시에 상한을 둡니다. 접근 순서 LinkedHashMap 이면 다섯 줄로 LRU 가 됩니다.

static final Map<String, Session> LRU = new LinkedHashMap<>(16, 0.75f, true) {
    @Override protected boolean removeEldestEntry(Map.Entry<String, Session> e) {
        return size() > 10_000;
    }
};

같은 프로그램, 같은 힙으로 80 초 돌리자 60만 요청을 처리했고, 모든 줄에서 entries= 10,000 이었으며 힙은 17~53MB 사이였습니다(스레드 안전하지 않으니 공유한다면 감싸거나 전용 캐시 라이브러리를 쓰세요).

시작 시간: java File.java 대 컴파일된 클래스

java Hello.java 는 실행할 때마다 소스를 메모리에서 컴파일합니다. 각각 20 번 실행한 중앙값을 Python 스크립트에서 쟀습니다.

소스 실행은 매번 약 250ms 를 컴파일에 씁니다. 스크립트나 학습용으로는 괜찮지만 셸 루프에서 반복 호출하는 CLI 도구에는 맞지 않습니다. -Xshare:off 는 JDK 에 들어 있는 클래스 데이터 공유 아카이브를 끄며 약 25ms 늘어납니다. AOT 캐시 첫 시도는 실제 오류로 실패했습니다.

$ java -XX:AOTCacheOutput=hello.aot -cp cls Hello
Error occurred during CDS dumping
Cannot have non-empty directory in paths

AOT 캐시는 클래스패스에 JAR 만 받습니다. JDK 의 jar 도구로 JAR 를 만들자 -XX:AOTCacheOutput 이 10MB 캐시를 썼고, 시작 시간이 43ms 에서 35ms 로 줄었습니다. 그 전에는 첫 단계가 실패해서 -XX:AOTCache=hello.aot 가 존재하지 않는 파일을 가리켰는데, JVM 은 [error][aot] Unable to map shared spaces 를 찍고도 캐시 없이 프로그램을 실행한 뒤 종료 코드 0 으로 끝났습니다. 빌드 스크립트로는 알아챌 수 없습니다.

벤치마크에 대한 솔직한 주의점 (JMH 없음)

위 숫자는 모두 System.nanoTime() 과 평범한 루프로 쟀고 JMH 는 쓰지 않았습니다(이번 환경에 없었기 때문). 그래도 성립하는 건 차이가 크기 때문입니다. 손으로 짠 측정에서 흔히 생기는 일:

• 워밍업 없음: 첫 묶음은 정상 상태보다 7.6 배 느렸다. 초반 라운드는 버리고, 워밍업이 사용자에게 중요하면 따로 보여 준다.
• 죽은 코드: 결과를 쓰지 않으면 C2 가 작업째 지울 수 있다. 여기 프로그램은 모두 체크섬을 출력한다.
• 인라인이 대상을 바꾼다: 두 번째 단축은 호출하는 쪽 이 컴파일되면서 생겼다. 마이크로벤치마크는 특정 인라인 문맥 안의 메서드를 잰다.
• 잡음: G1 의 실제 시간은 같은 조건에서 835~1,087ms 로 흔들렸다. 반복하고, 중앙값을 내고, 15% 미만 차이는 의심한다.
• 기기: M1 Pro 는 성능 코어 6 개와 효율 코어 2 개. 어느 쪽에서 돌지는 스케줄러가 정한다.

2 배보다 작은 차이를 따지려면 JMH 를 쓰세요.

판단표와 버전 메모

• JDK 26 에서만 확인했습니다. ZGC 는 JDK 23 부터 기본이 세대별(위 로그의 Y:/O:), 한 단계짜리 -XX:AOTCacheOutput 은 JDK 25 에서 추가, AOT 캐시 자체는 JDK 24(JEP 483)입니다. 예전 JDK 로 직접 확인하지는 않았습니다.
• 소스 파일 직접 실행(java Hello.java)은 JDK 11 부터, 여러 파일로 된 소스 프로그램은 JDK 22 부터입니다. 여기서는 단일 파일 형태만 썼습니다.
• 이 JDK 에는 jfr 명령이 없었고 jcmd 와 jstat 은 있었습니다.

이것으로 Java 강좌를 마칩니다. 같은 런타임의 스레드 쪽 이야기는 5강에서 다뤘습니다.

이전 강좌: 5강: 가상 스레드와 동시성 · 처음으로: 1강: 타입·문자열·동등성

관련: Python 강좌 6강: 프로파일링과 최적화 · VB.NET 강좌 6강: .NET 10 의 VB.NET 과 C# 연동