GC가 도는 동안 스레드는 무엇을 하는가 (Minor와 Major, safepoint, 그리고 배포 직후의 cold)

[배경 - 패널은 만들어 놓고 설명은 못 했다]

아주이벤트 대시보드를 짜면서 JVM 패널을 몇 개 넣었어요. 그중 하나가 이거예요.

{
  "title": "GC Pause (초/분)",
  "targets": [
    { "expr": "rate(jvm_gc_pause_seconds_sum{application=\"$application\"}[1m])",
      "legendFormat": "{{action}} {{cause}}" }
  ]
}

monitoring/grafana/dashboards/ajouevent.json 에 있는 패널입니다. 옆 패널에는 jvm_threads_states_threads 도 붙여뒀어요. 그런데 이 그래프가 튀었을 때 제가 할 수 있는 말은 “GC가 좀 돌았나 보네” 가 전부였습니다. GC가 도는 동안 톰캣 스레드가 무엇을 하고 있는지를 설명하지 못했어요.

두 번째 계기는 배포입니다. 새 이미지를 올리고 나면 한동안 응답이 느립니다. 특히 특정 조회 API가 유독 그래요. 저는 이걸 “원래 그런 것” 으로 넘겨왔습니다. 그런데 원래 그런 것이면 원인이 있을 텐데, 그 원인을 몇 개나 댈 수 있는지 세어보니 하나도 확실한 게 없었어요.

그러다 Dockerfile을 다시 봤어요.

FROM eclipse-temurin:21-jre-alpine
WORKDIR /app
COPY --from=builder /app/build/libs/*.jar app.jar
ENTRYPOINT ["java", "-jar", "app.jar"]

JVM 옵션이 한 줄도 없습니다. 힙 크기도, GC 종류도, GC 로그도 없어요. 메일상자의 core 와 worker 도 똑같습니다. 그쪽은 compose에 JAVA_TOOL_OPTIONS 자리가 이미 있는데, 거기 들어 있는 건 48번 글에서 넣은 타임존 한 줄뿐이에요.

core:
  environment:
    TZ: Asia/Seoul
    JAVA_TOOL_OPTIONS: "-Duser.timezone=Asia/Seoul"

그리고 세 프로젝트의 compose 파일을 전부 훑어봤는데 mem_limit 도 deploy.resources.limits 도 없었습니다. 즉 JVM이 힙 크기와 GC 종류를 혼자 정하고 있고, 저는 그 결정이 무엇인지 모르고 있었습니다.

먼저 이 글의 측정 범위를 밝혀둘게요. 여기 나오는 숫자는 운영 서버가 아니라 제 노트북에서 돌린 작은 프로브 프로그램의 값입니다. 측정 환경은 Temurin 21.0.3 (LTS), macOS arm64, 11코어에 18GB 메모리예요. 운영과 같은 벤더의 같은 메이저 버전을 쓰긴 했지만 운영 서버의 GC 통계가 아닙니다. 절대값이 아니라 구조와 상대 비교로 읽어주세요.

[문제 상황 분석 - JVM은 메모리를 어디에 나눠 두는가]

힙과 힙 밖

GC 이야기는 결국 힙 이야기입니다. 다만 JVM이 쓰는 메모리가 전부 힙은 아니에요. 대시보드에 jvm_memory_used_bytes{area="heap"} 와 area="nonheap" 을 나눠 그린 이유가 여기 있어요.

 ┌──────────────────── JVM 프로세스 ────────────────────┐
 │                                                      │
 │  ┌──────────────── 힙 (GC 대상) ─────────────────┐   │
 │  │  Young 영역                                    │   │
 │  │   ┌─────────────┬──────┬──────┐               │   │
 │  │   │    Eden     │  S0  │  S1  │               │   │
 │  │   └─────────────┴──────┴──────┘               │   │
 │  │  Old 영역                                      │   │
 │  │   ┌──────────────────────────────────┐        │   │
 │  │   │  오래 살아남은 객체들              │        │   │
 │  │   └──────────────────────────────────┘        │   │
 │  └────────────────────────────────────────────────┘  │
 │                                                      │
 │  힙 밖 (GC가 청소하지 않는다)                          │
 │   메타스페이스   : 클래스 메타데이터                    │
 │   코드 캐시      : JIT가 만든 기계어                    │
 │   스레드 스택    : 스레드 하나당 기본 1MB               │
 │   다이렉트 버퍼  : NIO, 네트워크                        │
 └──────────────────────────────────────────────────────┘

여기서 바로 나오는 사실이 하나 있어요. 컨테이너 메모리는 힙보다 항상 커야 합니다. 스레드 300개면 스택만 300MB고, 코드 캐시와 메타스페이스도 수십에서 수백 MB를 씁니다. 힙을 컨테이너 크기와 같게 잡으면 GC가 아니라 OOM Killer를 만나요.

왜 세대로 나누는가

세대 가설이라는 관찰이 있습니다. 대부분의 객체는 아주 빨리 죽고, 오래 산 객체는 계속 오래 산다는 거예요. 서버 코드를 떠올려보면 납득이 됩니다. 요청 하나가 만드는 DTO, 엔티티, 문자열은 응답이 나가는 순간 전부 쓰레기가 됩니다. 반면 스프링 빈이나 커넥션 풀은 프로세스가 죽을 때까지 살아 있어요.

그래서 힙을 두 영역으로 나눕니다. 새 객체는 Eden에 만들고, 거기가 차면 살아 있는 것만 골라서 옮깁니다. 죽은 객체는 아무 일도 하지 않아요. 이게 핵심입니다. GC 비용은 쓰레기의 양이 아니라 살아남은 객체의 양에 비례합니다.

객체가 태어나는 자리

new 한 번에 무슨 일이 벌어지는지 보면 이해가 빨라집니다.

1. 스레드가 자기 TLAB(Thread Local Allocation Buffer)의 포인터를 하나 밀어낸다
   → 락이 없다. 포인터 증가 한 번이라 거의 공짜다
2. TLAB이 부족하면 Eden에서 새 TLAB을 받아온다
3. Eden도 부족하면 → Minor GC

스레드마다 Eden의 한 조각을 미리 떼어 갖고 있기 때문에 할당이 빠릅니다. 그리고 이 구조 덕분에 자바에서 짧게 사는 작은 객체를 만드는 비용은 생각보다 싸요. 비싼 건 그 객체가 안 죽고 살아남을 때입니다.

[Minor와 Major - 이름이 헷갈리는 이유]

Minor GC

Eden이 차면 일어납니다. 하는 일은 이래요.

[Minor GC 전]                        [Minor GC 후]
 Eden  ████████████ (꽉 참)           Eden  ░░░░░░░░░░░░ (비었다)
 S0    ██ (age 1~2)                   S0    ░░
 S1    ░░                             S1    ███ (살아남은 것 + age 증가)
 Old   ██████                         Old   ███████ (age 넘긴 것이 승격)

Eden과 사용 중인 Survivor에서 살아 있는 객체만 반대편 Survivor로 복사하고, Eden은 통째로 비웁니다. 살아남을 때마다 age가 1씩 오르고, 임계값을 넘으면 Old로 승격돼요. Survivor가 꽉 차도 승격됩니다.

살아남은 게 적으면 Eden 크기가 아무리 커도 빠릅니다. 반대로 요청 하나가 대용량 리스트를 만들어 오래 붙잡고 있으면, Eden이 작아도 Minor GC가 비싸져요.

Major GC와 Full GC

여기가 헷갈리는 지점이에요. 저도 계속 섞어 썼어요. 정리하면 이렇습니다.

용어를 이렇게 나눠 쓰는 게 표준은 아닙니다. 문서마다 Major와 Full을 같은 뜻으로 쓰기도 해요. 그래서 저는 이제 이름 대신 로그에 찍히는 문자열로 이야기하기로 했습니다. Pause Young 인지 Pause Full 인지가 훨씬 명확하니까요.

특히 G1에서 Pause Full 이 보이면 그건 정상 동작이 아니라 동시 정리가 할당 속도를 못 따라잡았다는 신호입니다. 뒤에서 실제로 이게 쏟아지는 경우를 재봤어요.

승격이 문제가 되는 순간

Old로 승격된 객체는 Minor GC로는 안 없어집니다. 그래서 “짧게 살 예정이었는데 얼떨결에 오래 산 객체” 가 GC 입장에서 제일 나쁩니다.

제 코드에서 그런 자리를 하나 찾았어요. FCM 전송 풀의 큐 설정이에요.

ajou:
  fcm:
    executor:
      callback:
        core-pool-size: 8
        max-pool-size: 32
        queue-capacity: 500
      default-pool:
        core-pool-size: 32
        max-pool-size: 128
        queue-capacity: 50000

queue-capacity: 50000 은 20번 글에서 서블릿 스레드를 풀어주려고 넉넉히 잡은 값입니다. 그런데 GC 관점에서 다시 보면 이야기가 달라져요. 큐에 5만 개가 쌓이면 그 5만 개의 태스크 객체와 거기 잡힌 참조가 전부 살아 있는 객체입니다. 큐에 오래 머물수록 age가 올라가고 Old로 승격됩니다. 즉 큐 깊이가 곧 Old 영역 점유예요.

메일상자의 초기 동기화도 비슷해요.

initial-sync:
  max-threads: 2000
  thread-list-page-size: 500
  thread-batch-size: 5

30번 글에서 배치를 5로 쪼갠 이유를 외부 API 부하로 설명했는데, 여기 이유가 하나 더 있었습니다. 한 번에 2,000통을 메모리에 올리면 그건 전부 살아 있는 객체고, 처리에 몇 초라도 걸리면 Old로 넘어갑니다. 배치를 쪼개는 것은 GC 입장에서도 옳은 선택이었어요. 그때는 모르고 한 일이지만요.

[멈춤의 정체 - safepoint]

“스레드를 멈춘다”는 정확히 무엇인가

이게 제가 제일 궁금했던 부분입니다. GC 스레드가 힙을 정리하려면 객체 그래프가 움직이면 안 됩니다. 애플리케이션 스레드가 참조를 바꾸는 중이면 살아 있는 객체를 놓칠 수 있으니까요.

그래서 JVM은 safepoint 라는 지점을 씁니다. 순서는 이래요.

1. VM 스레드가 "다들 멈춰" 플래그를 세운다
2. 각 애플리케이션 스레드는 자기가 실행하다가
   safepoint 폴링 지점에 도달하면 스스로 멈춘다
     - 메서드 리턴 직전
     - 루프의 백엣지 (되돌아가는 지점)
     - 객체 할당 지점
   ※ JIT가 컴파일한 코드 안에 이 폴링이 심어져 있다
3. 전부 멈추면 GC 작업을 한다
4. 끝나면 다 같이 깨운다

여기서 두 개의 시간이 나옵니다. 모두가 멈추기까지 걸린 시간과 멈춰 있는 동안 GC가 일한 시간이에요. 이 둘을 따로 재봤어요.

$ java -Xlog:safepoint:file=sp.log ... StallProbe 6000

[0.072s] Safepoint "G1CollectForAllocation",
         Reaching safepoint: 34750 ns, At safepoint: 930250 ns, Total: 978375 ns

6초 동안 safepoint에 1,550번 들어갔고, 집계하면 이래요.

멈추라는 신호부터 실제로 다 멈추기까지는 평균 21μs 로 짧았습니다. 대부분의 시간은 멈춘 뒤 GC가 일하는 데 쓰여요. 다만 최대값이 148μs 인 것도 눈여겨볼 만합니다. JIT 컴파일된 긴 카운트 루프처럼 폴링 지점이 드문 코드가 있으면 이 값이 밀리초 단위로 뜁니다. 그 스레드 하나 때문에 나머지 전부가 기다려요.

그래서 몇 개가 멈추는가

이 “전부” 가 몇 개인지 제 설정으로 세어봤습니다. 톰캣 스레드 수를 따로 지정한 적이 없으니 기본값인 최대 200개고, 여기에 아주이벤트가 직접 만드는 풀이 더 붙어요.

톰캣 워커        최대 200  (server.tomcat.threads.max 미지정 → 기본값)
fcm-default-*    최대 128  (config/fcm.yaml)
fcm-callback-*   최대  32  (config/fcm.yaml)
스케줄러           4       (ajou.scheduler.pool-size)
그 밖에 하이카리 하우스키퍼, 레티스 I/O, 로그백 어펜더, JVM 내부 스레드

최대치까지 벌어지면 애플리케이션 스레드만 360개가 넘습니다. STW가 걸리면 이게 전부 동시에 얼어요. 스레드를 늘려서 처리량을 올리는 것과 GC 멈춤은 서로 다른 축이라는 게 여기서 분명해집니다. 스레드를 두 배로 늘려도 앞에서 잰 14.2ms 짜리 pause 동안 진행되는 일의 양은 똑같이 0이에요.

그리고 safepoint는 GC 전용이 아닙니다. 힙 덤프, 스레드 덤프, JIT 역최적화, 클래스 재정의도 전부 여기서 일어나요. jstack 을 한 번 뜨는 것도 전 스레드를 멈추는 동작입니다.

스레드가 실제로 멈춘 시간을 재기

이론은 알겠는데 진짜로 멈추는지 보고 싶었습니다. 그래서 아주 단순한 프로브를 짰어요.

// 스레드 A: 아무 일도 하지 않고 nanoTime()만 계속 읽는다
//           두 번 읽은 값의 차이가 곧 "이 스레드가 멈춰 있던 시간"이다
long prev = System.nanoTime();
while (running) {
    long now = System.nanoTime();
    long d = now - prev;
    prev = now;
    if (d > max) max = d;
}

// 스레드 B: 쓰레기를 만들어 GC를 유발한다. 64번에 한 번은 살려둔다
while (System.currentTimeMillis() < end) {
    byte[] junk = new byte[8 * 1024];
    if ((i++ & 0x3F) == 0) {
        survivors.add(new byte[64 * 1024]);
        if (survivors.size() > 4000) survivors.subList(0, 2000).clear();
    }
}

프로브 스레드는 계산도 안 하고 I/O도 안 합니다. 그러니 두 nanoTime() 사이가 벌어졌다면 그건 OS나 JVM이 이 스레드를 세운 시간이에요. 12초씩 돌리고 GC 로그와 대조했어요.

세 번 다 소수점 첫째 자리까지 맞았습니다. 애플리케이션 스레드가 멈춰 있던 가장 긴 시간이 GC의 가장 긴 pause와 같습니다. GC가 도는 동안 스레드가 무엇을 하냐는 질문의 답은, 적어도 STW 구간에 대해서는 “아무것도 안 합니다” 예요. 실행 중이던 자리에서 얼어 있다가 다 같이 깨어납니다.

한 가지 짚어둘게요. 이 프로브의 할당 스레드는 쉬지 않고 최대 속도로 쓰레기를 만듭니다. 실제 서비스보다 할당률이 훨씬 높아요. 그러니 아래 나오는 “전체 시간의 몇 %” 는 실제 서버의 비율이 아니라 압력을 최대로 걸었을 때의 모양으로 읽어야 합니다.

[GC 선택 - 내 컨테이너는 무엇을 고르는가]

JVM은 혼자 무엇을 정하는가

옵션을 안 주면 JVM이 알아서 정합니다. 이걸 에르고노믹스라고 불러요. 제 Dockerfile이 딱 이 경우예요.

Docker 데몬이 켜져 있지 않아서 진짜 cgroup 제한 대신 -XX:ActiveProcessorCount 와 -XX:MaxRAM 으로 컨테이너 상황을 흉내 냈습니다. 앞의 값은 JVM이 컨테이너의 CPU 쿼터를 읽어서 채우는 바로 그 값이에요.

java -XX:ActiveProcessorCount=1 -XX:MaxRAM=1g -XX:+PrintFlagsFinal -version \
  | grep -E "UseSerialGC|UseG1GC|MaxHeapSize|InitialHeapSize"

두 가지가 보여요.

최대 힙은 정확히 가용 메모리의 25%, 시작 힙은 1/64 입니다. 18GB 머신에서 4,608MB와 288MB가 나왔는데, 18432의 1/4과 1/64이 정확히 그 값이에요. 이건 우연이 아니라 MaxRAMPercentage=25.0, InitialRAMPercentage=1.5625 라는 기본값입니다.

코어가 1개면 GC가 Serial로 바뀝니다. HotSpot은 “서버급 머신” 인지 판정해서 G1을 쓸지 정하는데, 그 조건에 코어 2개 이상이 들어갑니다. 즉 컨테이너에 CPU 쿼터를 1로 주면 서버 애플리케이션이 Serial GC로 돕니다.

솔직히 밝혀둘 게 있어요. 서버급 판정에는 메모리 1,792MB 이상이라는 조건도 같이 걸리는데, 그 절반은 이 방법으로 재지 못했습니다. -XX:MaxRAM 은 힙 계산에만 쓰이고 판정에 쓰이는 물리 메모리는 그대로 18GB로 보이거든요. 코어 조건만 실측했고 메모리 조건은 문서에 기대고 있습니다.

Serial과 G1을 같은 부하로 돌려보기

위 프로브를 12초씩, 힙 512MB로 고정하고 GC만 바꿔봤어요.

Serial 쪽은 12초 동안 Full GC를 282번 했습니다. 힙 전체를 282번 훑은 거예요. 평균 7.4ms씩이고 그것만 합쳐도 2초가 넘습니다. G1은 같은 부하에서 Pause Full 이 한 번도 없었어요. 동시 마킹으로 Old를 정리하고 Young 수집에 얹어서 조금씩 회수했기 때문입니다.

로그를 나란히 놓으면 차이가 분명해요.

# Serial
[0.199s] GC(24) Pause Full (Allocation Failure) 481M->248M(494M) 14.006ms
[0.235s] GC(32) Pause Full (Allocation Failure) 475M->229M(494M)  7.384ms

# G1
[12.004s] GC(2508) Concurrent Mark Cycle                              ← 안 멈춘다
[12.005s] GC(2508) Pause Remark  350M->223M(512M) 0.120ms             ← 0.1ms
[12.009s] GC(2509) Pause Young (Prepare Mixed) 336M->208M(512M) 0.925ms
[12.016s] GC(2510) Pause Young (Mixed)         446M->233M(512M) 1.158ms

G1의 Concurrent Mark Cycle 은 애플리케이션과 같이 돕니다. 멈추는 건 Remark 와 Cleanup 뿐이고 각각 0.1ms 안팎이에요. 반면 Serial은 Old를 건드리려면 무조건 전부 멈춰야 합니다.

반복 실행해도 총 STW는 안정적이었습니다. G1은 2,348 / 2,277 / 2,306ms, Serial은 4,043 / 4,013ms가 나왔어요. 최대 pause만 실행마다 흔들렸어요.

힙을 키우면 다 좋아질 줄 알았습니다

여기서 제 예상이 빗나갔어요. 같은 프로브를 힙만 512MB에서 2GB로 늘려 돌렸습니다. GC가 덜 돌 테니 멈춤도 줄겠지 싶었죠.

총 시간은 줄었습니다. 횟수는 7분의 1이 됐고요. 그런데 최대 멈춤은 세 배가 됐습니다. 반복 실행에서는 61.7ms까지 나왔어요.

당연한 이야기였습니다. 힙이 크면 GC 사이 간격이 길어지고, 그동안 Eden에 쌓인 양이 많아집니다. 한 번 멈췄을 때 복사할 살아남은 객체가 그만큼 많아져요. 처리량은 좋아지고 최악 지연은 나빠집니다.

그러니 “메모리 넉넉하니까 힙 크게 잡으면 되지” 는 절반만 맞는 말이었어요. p99 응답 시간을 지켜야 하는 API 서버라면 힙을 키우는 것만으로는 안 되고, -XX:MaxGCPauseMillis 같은 목표를 같이 줘야 합니다. 이 값이 G1에게 Young 영역 크기를 조절하라고 알려주는 손잡이예요.

[배포 직후가 느린 이유 - cold의 정체]

이제 두 번째 질문이에요. 배포하고 나면 왜 느린가. 재보니 원인이 겹겹이었어요.

1. 코드가 아직 기계어가 아닙니다

자바 코드는 처음에 인터프리터로 실행됩니다. 바이트코드를 한 줄씩 읽어서 수행해요. 일정 횟수 이상 불리면 그때 JIT 컴파일러가 기계어로 바꿉니다. 단계가 두 개예요.

  실행 횟수 →
  [인터프리터] ──→ [C1 컴파일] ──→ [C2 컴파일]
   느리다        빨리 컴파일       느리게 컴파일
   즉시 실행     보통 성능         최고 성능
                 프로파일 수집     프로파일 기반 최적화

이걸 계층형 컴파일이라고 부릅니다. C1이 일단 빠르게 만들어서 쓰다가, 그동안 모은 프로파일로 C2가 최적화된 코드를 냅니다.

서비스 메서드를 흉내 낸 코드를 만들어 재봤어요. 문자열을 파싱하고 레코드를 만들고 정렬하고 집계하는, 조회 API에서 흔한 모양입니다. 200회씩 묶어서 배치별 평균을 찍었어요.

batch   0     45024 ns/op     ← 인터프리터
batch   1     14062 ns/op
batch   2      7337 ns/op     ← C1이 붙는다
batch   3      6063 ns/op
batch   7     10231 ns/op     ← 역최적화나 재컴파일로 튀는 구간
batch  11      4340 ns/op     ← C2까지
batch 299      4711 ns/op

SUMMARY first=46126ns steady=4529ns ratio=10.2x

첫 200번의 호출이 안정 상태보다 10배 느립니다. 그리고 인터프리터만 쓰도록 강제하면 얼마나 느린지도 재봤어요.

인터프리터는 완전히 데워진 코드보다 54배 느립니다. 배포 직후 첫 요청들이 밟는 게 정확히 이 구간이에요.

재밌는 건 세 번째 열입니다. 기본값의 첫 배치가 C1까지만 쓸 때보다 오히려 느립니다 (46,126 대 32,295). C2에게 넘길 프로파일을 모으느라 초반 코드에 계측이 붙어 있기 때문이에요. 두 번 돌려도 같은 방향이 나왔습니다. 나중에 빨라지려고 지금 손해를 보는 구조인데, 이건 로컬 개발에서 TieredStopAtLevel=1 이 체감상 빠른 이유이기도 합니다. 대신 운영에 그걸 쓰면 안정 상태가 14% 느려져요.

2. 클래스는 필요할 때 로드됩니다

자바는 클래스를 미리 다 읽지 않습니다. 처음 쓰이는 순간에 읽고, 검증하고, 링크하고, 초기화해요. 실제 jar를 로컬에서 띄우면서 세어봤어요.

java -Xlog:class+load:file=cl.log -jar AjouEvent_BE_V2-0.0.1-SNAPSHOT.jar

DB와 Loki에 못 붙어서 기동이 실패했는데도 클래스를 7,940번 로드했습니다. 스프링 컨텍스트를 올리는 것만으로 이만큼이에요. 그리고 이건 시작할 때 다 끝나는 게 아닙니다. 아직 아무도 호출하지 않은 API의 컨트롤러, 서비스, 그 안에서 쓰는 라이브러리는 첫 호출이 들어올 때 로드됩니다. 배포 직후 특정 API만 유독 느린 이유 중 하나예요.

3. 힙이 아직 작습니다

앞의 측정에서 시작 힙이 최대 힙의 1/64 라고 했습니다. 제 노트북 기준으로 288MB로 시작해서 4,608MB까지 늘어나요. 늘어나는 과정이 공짜가 아닙니다. 힙이 작을 때는 Eden도 작아서 GC가 자주 돕니다. 트래픽이 들어오면서 힙이 확장되고, 확장될 때마다 OS에서 메모리를 받아와요.

-Xms 와 -Xmx 를 같게 잡으라는 조언이 여기서 나와요. 어차피 쓸 메모리면 처음부터 잡아두고 시작하라는 겁니다.

4. 커넥션 풀이 비어 있습니다

아주이벤트의 풀 설정이에요.

spring:
  datasource:
    hikari:
      pool-name: HikariPool-Main
      maximum-pool-size: ${HIKARI_MAX_POOL_SIZE:10}
      minimum-idle: ${HIKARI_MIN_IDLE:5}
      connection-timeout: 30000
      idle-timeout: 600000
      max-lifetime: 1800000

하이카리는 기동할 때 커넥션을 한 개만 동기로 만들어 연결을 확인하고, minimum-idle 인 5개까지는 뒤에서 하우스키퍼 스레드가 천천히 채웁니다. 나머지 5개는 아예 미리 안 만들어요. 필요해진 순간에 그 요청이 기다리면서 만듭니다. 즉 기동 직후 몇 초 동안은 풀에 5개도 채 없을 수 있습니다. 커넥션 하나를 만들려면 TCP 핸드셰이크, 인증, 세션 변수 설정을 거쳐야 해요. 배포 직후 트래픽이 6개 이상 동시에 들어오면 그중 몇 개는 커넥션 생성 시간을 통째로 응답 시간에 얹고 갑니다.

이건 대시보드에서 바로 보입니다. 제가 이미 넣어둔 패널이에요.

hikaricp_connections_pending        ← 커넥션을 기다리는 요청 수
rate(hikaricp_connections_creation_seconds_sum[1m])
  / rate(hikaricp_connections_creation_seconds_count[1m]) * 1000
                                    ← 커넥션 하나 만드는 데 걸린 평균 ms

패널은 만들어놨는데 배포 직후에 이걸 본 적이 없었습니다. 다음 배포 때 볼 것을 하나 찾은 셈이에요.

max-lifetime: 1800000 도 같이 봐야 합니다. 30분마다 커넥션이 교체되니까 완전히 데워진 풀은 계속 유지되지 않습니다. 대신 한꺼번에 끊기지 않도록 하이카리가 시점을 흩어주긴 해요.

메일상자 쪽은 hikari 블록이 아예 없습니다. 스프링 부트 기본값이 그대로 적용되는데, 기본은 최대 10개에 minimum-idle 이 최대와 같아요. 즉 아주이벤트와 메일상자의 웜업 곡선이 서로 다릅니다. 이것도 이번에 처음 확인했어요.

5. DB 쪽도 같이 식어 있습니다

앱만 식은 게 아니에요. 애플리케이션을 재배포해도 DB는 그대로니까 여기는 덜 하지만, DB 서버까지 같이 재시작했다면 이야기가 다릅니다.

44번 글에서 정리한 버퍼 풀이 비어 있으면 모든 읽기가 디스크로 갑니다. 실행 계획 캐시, OS 페이지 캐시도 마찬가지예요. 그래서 “배포 직후 특정 쿼리만 느리다” 는 증상은 그 쿼리가 건드리는 페이지가 아직 버퍼 풀에 없다는 뜻일 때가 많습니다.

왜 하필 그 쿼리인가

다섯 층을 겹쳐 보면 배포 직후에 유독 느린 쿼리의 조건이 나옵니다.

느려지는 조건이 겹치는 지점
 ├─ 자주 안 불린다        → 클래스가 아직 로드 안 됨, JIT도 인터프리터 단계
 ├─ 스캔 범위가 넓다      → 버퍼 풀에 없는 페이지를 많이 읽음
 ├─ 결과가 크다           → 큰 객체를 많이 만들어 GC 압력, 승격 유발
 └─ 배포 직후 동시에 온다 → 커넥션 풀이 아직 minimum-idle 만큼만 열려 있음

드물게 불리면서 무거운 조회 API 가 정확히 여기 걸립니다. 그리고 이건 하나만 고쳐서는 안 없어져요. 층마다 대응이 다릅니다.

[해결 방법 - 지금 바꿀 것]

이 글은 “고쳤습니다” 가 아니라 “무엇을 모르고 있었는지 알아냈습니다” 에 가깝습니다. 아직 운영에 넣지 않았고, 넣을 순서를 정리해둘게요.

1. 컨테이너에 메모리 제한을 걸고 JVM에게 비율로 알려줍니다.

core:
  mem_limit: 1g
  environment:
    JAVA_TOOL_OPTIONS: >-
      -Duser.timezone=Asia/Seoul
      -XX:MaxRAMPercentage=70
      -XX:InitialRAMPercentage=70

-Xmx 대신 퍼센트를 쓰는 이유는 컨테이너 크기를 바꿀 때 옵션을 같이 안 고쳐도 되기 때문입니다. 70%로 잡는 건 나머지 30%를 스택, 메타스페이스, 코드 캐시, 다이렉트 버퍼에 남겨두려는 거예요. 앞서 본 것처럼 힙 말고도 쓰는 데가 많습니다.

2. GC를 명시합니다. 코어 하나짜리 컨테이너에서 조용히 Serial로 떨어지는 걸 막으려고요. 컨테이너를 2코어 이상으로 주고 -XX:+UseG1GC 를 박아둬요.

3. GC 로그를 켭니다. 이게 제일 먼저 할 일이에요.

-Xlog:gc*:file=/var/log/mailsangja/gc.log:time,uptime:filecount=5,filesize=20M

메트릭은 이미 프로메테우스로 가고 있지만, rate(jvm_gc_pause_seconds_sum[1m]) 로는 어떤 pause가 몇 ms 였는지를 못 봅니다. 평균에 묻혀요. 로그가 있어야 Pause Full 이 떴는지를 압니다.

4. 트래픽을 붙이기 전에 준비 상태를 확인합니다. 지금 아주이벤트 compose에는 앱 컨테이너에 헬스체크가 없습니다. 액추에이터가 9090에 떠 있으니 붙일 수 있어요.

app:
  healthcheck:
    test: ["CMD", "wget", "-qO-", "http://localhost:9090/actuator/health"]
    interval: 5s
    start_period: 60s

다만 /actuator/health 가 200을 준다고 JIT가 데워진 건 아닙니다. 이건 “죽지는 않았다” 를 보장할 뿐이에요.

5. 웜업은 조심해서 씁니다. 기동 후 주요 조회 API를 몇 번 호출해서 클래스 로딩과 C1 컴파일을 미리 시키는 방법이 있습니다. 실제로 효과가 있는 층은 클래스 로딩과 커넥션 풀이에요. C2까지 데우려면 수천 번은 불러야 해서 현실적으로는 부분적입니다.

검토했다가 버린 것

ZGC로 바꾸기. 최대 pause가 1ms 아래로 내려간다는 점은 매력적이었습니다. 다만 ZGC는 컬러 포인터 때문에 힙 밖 메모리를 더 쓰고, 동시 작업 스레드가 CPU를 계속 먹습니다. 지금 제 컨테이너는 코어 수도 넉넉하지 않고, 무엇보다 G1의 최대 pause가 문제라는 증거를 아직 운영에서 못 잡았어요. 문제를 확인하기 전에 수집기를 바꾸는 건 순서가 틀렸습니다.

CRaC이나 AOT 캐시로 기동 자체를 없애기. 체크포인트를 떠서 복원하면 JIT가 데워진 상태로 시작합니다. 그런데 복원 시점에 커넥션과 파일 디스크립터를 다시 잡아주는 코드가 필요하고, 이미지 빌드 파이프라인도 바뀝니다. 하루에 몇 번 배포하는 규모에 맞는 비용이 아니에요. 배포가 잦아지고 기동 시간이 실제 문제가 되면 그때 다시 봅니다.

힙을 무작정 키우기. 위에서 재본 대로 최대 pause가 오히려 나빠집니다. 버렸어요.

[측정하지 못한 것]

정직하게 남겨둡니다. 이 글의 숫자는 전부 제 노트북의 프로브에서 나왔고, 운영 서버에서 잰 값은 하나도 없습니다.

앞으로 확인할 것은 네 가지예요.

첫째, 운영 컨테이너가 실제로 어떤 GC와 힙 크기를 고르고 있는지. 위 표는 제 노트북에서 흉내 낸 값이라 EC2 인스턴스에서 다시 확인해야 합니다.

둘째, 배포 직후 GC pause와 커넥션 대기가 같은 시각에 겹치는지. 프로메테우스에 이미 두 메트릭이 다 들어가 있으니 그래프만 겹쳐 보면 됩니다.

셋째, 배포 직후와 10분 뒤의 p95 차이. k6 스크립트가 이미 있어서 두 번 돌려 비교하면 웜업 효과가 실제로 얼마인지 나와요.

넷째, 큐가 깊을 때 Old 영역이 실제로 부푸는지. FCM 큐 5만 개 이야기는 구조에서 나온 추론이라 확인이 필요합니다.

[결론]

세 가지를 알고 시작했다고 생각했는데 셋 다 반쯤만 알고 있었어요.

GC가 도는 동안 스레드는 얼어 있습니다. safepoint에 도달하는 데는 평균 21μs 로 짧았고, 멈춰 있는 시간의 대부분은 GC가 일하는 시간이었어요. 프로브가 잰 최대 멈춤이 GC 로그의 최대 pause와 소수점까지 맞은 게 이 글에서 제일 확실한 결과입니다.

Minor와 Major는 이름이 아니라 로그로 봐야 합니다. G1에서 Pause Full 이 보이면 그건 Major GC를 잘 하고 있다는 뜻이 아니라 못 따라잡고 있다는 신호였어요. Serial GC로 같은 부하를 돌렸더니 12초에 282번 나왔습니다.

옵션을 안 주면 JVM이 정하고, 그 결정은 컨테이너 크기에 달려 있습니다. 코어 하나짜리 컨테이너에서는 Serial로 떨어집니다. 제 Dockerfile에는 아무 옵션이 없으니 지금까지 전부 JVM에게 맡겨온 셈이에요.

배포 직후의 느림은 한 가지 원인이 아니었습니다. 인터프리터 실행이 54배, 클래스 로딩이 7,940개, 힙이 최대의 1/64, 커넥션 풀이 절반. 이 넷이 같은 시각에 겹칩니다. 그래서 어느 하나만 고쳐서는 체감이 안 바뀌어요.

한계도 적어둘게요.

첫째, 운영 측정이 없습니다. 프로브는 압력을 최대로 건 인공 부하고, 실제 서비스의 할당률은 훨씬 낮습니다. STW 19%라는 숫자를 그대로 옮기면 안 돼요.

둘째, 서버급 판정의 메모리 조건은 실측하지 못했습니다. 코어 조건만 확인했고 1,792MB 쪽은 문서에 기대고 있습니다. Docker를 띄워서 진짜 cgroup 제한으로 다시 봐야 합니다.

셋째, G1의 내부를 리전 단위까지 파고들지 않았습니다. Humongous 객체 처리, remembered set, 카드 테이블은 각각 따로 볼 주제라 뺐어요.

넷째, 가상 스레드를 다루지 않았습니다. 세 프로젝트 모두 자바 21인데 아직 spring.threads.virtual.enabled 를 켜지 않았습니다. 가상 스레드가 늘어나면 safepoint 도달 비용이 어떻게 되는지는 다음에 볼 주제예요.

패널을 만드는 것과 그 패널을 읽는 것은 다른 일이었습니다. 대시보드에 GC Pause 그래프를 그려둔 지 꽤 됐는데, 그 선이 올라갔을 때 무엇을 봐야 하는지는 이번에 처음 알았어요.