G1과 ZGC가 p99에 남기는 차이 - 300배 짧은 pause가 꼬리의 11%를 가져갔다

GC 알고리즘 비교는 각 수집기가 무엇을 포기하는지 문서를 근거로 정리한 글이다. 거기서 ZGC의 pause는 힙 크기와 무관하게 1ms 미만이라고 썼다. 사실이다. 그런데 그 문장은 “그래서 내 서비스의 p99가 얼마나 좋아지는가”에 답하지 않는다.

pause 시간과 요청 지연은 같은 축이 아니다. 6ms pause가 0.7초에 한 번 있는 서버에서 요청이 2ms라면, 대부분의 요청은 pause와 겹치지 않는다. 그렇다면 pause를 0.07ms로 줄여도 꼬리에서 사라질 것이 별로 없다. 반대로 pause가 유일한 꼬리 원인이라면 300배 개선이 그대로 나타나야 한다. 어느 쪽인지는 재 보면 된다.

저장소는 spring-ops-lab이고 재실행은 한 줄이다.

./scenarios/t3/run.sh zgc 1

설계: 압력을 주는 쪽과 맞는 쪽을 분리한다

/api/alloc이 요청마다 12MB를 64KB 블록으로 할당하고 그중 1/4을 192MB 예산 안에서 붙잡는다. 전부 즉시 죽으면 old 세대가 비어 있어 수집기가 할 일이 없으므로, 일부는 살아남게 해서 승격이 일어나게 했다.

/api/fast는 PostgreSQL에서 한 행을 읽고 그 외에는 거의 할당하지 않는다. 이쪽이 피해자다. 자기가 만들지 않은 GC 비용을 얼마나 내는지가 이 실험의 질문이다.

k6가 두 엔드포인트를 한 런에서 함께 때린다. fast 50rps, alloc 20rps, 90초, open model이고 VU는 미리 할당한다. 모든 런이 6,302건(fast 4,501, alloc 1,801)을 채웠고 dropped_iterations는 0이었다. 도착률이 유지됐다는 뜻이고, 이것이 확인되지 않으면 open model이 조용히 closed model이 되면서 꼬리가 실제보다 낮게 나온다.

조건 중 두 가지가 결과를 좌우한다.

• 힙을 -Xms1g -Xmx1g로 고정했다. 컨테이너 기본값에 맡기면 mem_limit의 25%가 되고, 그러면 수집기 비교가 아니라 힙 크기 비교가 된다.
• 측정 전 20초 워밍업을 낮은 부하로 돌린다. JIT 컴파일이 측정 구간 안에 들어오면 첫 수집기가 불리해진다.

수집기는 g1 → zgc → zgc-gen → parallel 순서를 세 번 반복했다. 한 수집기를 3회 연속 돌리면 호스트의 드리프트가 마지막 수집기에 쌓인다. zgc는 -XX:+UseZGC 단독으로 JDK 21에서는 단일 세대이고, zgc-gen은 -XX:+ZGenerational을 더한 것이다. 12개 런 모두 앱이 살아 있는 상태로 끝났고 OutOfMemoryError는 0건이다.

컨테이너는 cpus: 2, mem_limit: 2g, JDK는 Temurin 21, k6는 v1.0.0이다.

pause: 세 자리 수 차이

런 3회의 중앙값이다. 백분위수는 런마다 구한 뒤 그 중앙값을 적는다. 백분위수를 런끼리 평균하지 않는다.

수집기	pause 수	총 pause	p50	p99	최대
Parallel	107	1,445.3 ms	8.40	67.16	94.54
G1	124	823.7 ms	5.87	15.93	24.13
ZGC (단일 세대)	102	1.9 ms	0.01	0.06	0.07
세대별 ZGC	159	3.0 ms	0.02	0.05	0.12

90초 중 stop-the-world에 쓴 비율은 Parallel 1.6%, G1 0.9%, ZGC 0.002%다.

pause 종류를 보면 각 수집기가 무엇을 하고 있었는지가 드러난다. 3회 합산이다.

수집기	종류
Parallel	Young (Allocation Failure) 287회(최대 18.65ms), Full (Ergonomics) 36회(최대 113.26ms)
G1	Young (Mixed) 68, Young (Concurrent Start) 67, Remark 67, Cleanup 67, Young (Prepare Mixed) 66, Young (Normal) 36 — 전부 evacuation pause
ZGC	Mark Start 103, Mark End 103, Relocate Start 103 — 각각 최대 0.08ms
세대별 ZGC	minor young 96×3, major young 36×3, old 36×2 — 최대 0.15ms

Parallel만 Full GC를 낸다. 110ms짜리 stop-the-world가 90초에 12번 있다는 뜻이고, 이 숫자가 뒤에서 그대로 요청 지연에 나타난다.

요청 지연: 300배가 11%가 됐다

같은 런의 클라이언트 측 숫자다.

수집기	fast p50	fast p95	fast p99	fast 최대	alloc p99	alloc 최대	실패
Parallel	2.12	8.03	15.42	98.78	22.07	102.67	0.00%
G1	1.91	7.44	13.62	50.59	17.95	40.66	0.00%
ZGC (단일 세대)	1.93	6.78	12.07	46.91	11.26	36.01	0.00%
세대별 ZGC	2.01	7.34	12.24	32.74	11.18	22.61	0.00%

G1에서 ZGC로 가면 최악 pause가 24.13ms에서 0.07ms로 약 300배 줄어든다. 그리고 피해자의 p99는 13.62ms에서 12.07ms로, 11% 줄어든다.

이 두 숫자의 간격이 이 실험의 결론이다. 산술은 단순하다. G1은 90초에 124번, 즉 0.7초마다 한 번 멈춘다. 평균 pause는 6ms 남짓이고, fast 요청은 2ms다. 50rps로 들어오는 요청 중 6ms 창에 걸리는 비율은 대략 0.8%이고, p99는 상위 1% 경계다. 즉 p99는 pause에 걸린 요청과 안 걸린 요청의 경계에 아슬아슬하게 있고, 그 위쪽 꼬리는 대부분 pause가 아닌 다른 것으로 채워져 있다. pause를 0으로 만들어도 다른 것은 그대로 남는다.

p99가 재현되는지도 확인해야 한다. 같은 조건 3회에서 fast p99는 G1이 13.51 / 13.70 / 13.62, ZGC가 12.07 / 12.92 / 11.46이었다. 1.5ms 차이는 런 간 흔들림보다 크다. 작지만 실재하는 차이다.

이득은 조용한 쪽이 아니라 할당하는 쪽에 있었다

표에서 더 크게 움직인 열은 alloc p99다. 17.95ms에서 11.26ms로 37% 낮아졌다. 피해자의 11%보다 세 배 넘는 개선이다.

수집기를 고르는 이야기는 보통 “느린 이웃 때문에 내 조용한 엔드포인트가 느려진다”는 틀로 시작한다. 이 측정은 그 틀을 뒤집는다. 할당을 하는 요청은 pause와 동시 수집의 CPU 경쟁을 둘 다 낸다. 자기가 힙을 채우는 중이므로 수집기가 일해야 하는 시점과 자기 실행 구간이 겹칠 확률이 높고, 할당 자체가 TLAB 재할당과 승격을 유발한다. 조용한 이웃은 겹칠 일이 드물다.

저지연 수집기가 가장 크게 돕는 대상은 그것을 필요로 한다고 지목되는 쪽이 아니라, 그 부하를 만들고 있는 쪽이었다.

가장 느린 요청은 무엇을 기다렸는가

런마다 “가장 긴 pause”와 “가장 느린 fast 요청”을 나란히 놓으면 수집기별로 성격이 갈린다.

수집기	런	최장 pause	최장 fast 요청	차이
Parallel	1	94.54	98.78	4.2
Parallel	2	113.26	117.91	4.7
Parallel	3	92.25	94.49	2.2
G1	1	38.53	50.59	12.1
G1	2	24.13	65.87	41.7
ZGC	1	0.07	62.34	62.3
ZGC	3	0.08	21.57	21.5

Parallel은 세 런 모두 5ms 안쪽으로 일치한다. “가장 느린 요청이 무엇을 기다렸나”에 Full GC라는 답이 있다. 여기서는 GC를 바꾸는 것이 옳은 조치다.

ZGC는 최악 요청이 최악 pause의 30만 배다. GC로 설명되는 부분이 사실상 없다. 그 요청은 CPU 2개를 수집기 스레드와 나눠 쓰다가 런큐에서 기다렸거나, PostgreSQL에서 기다렸거나, 할당 자체에서 시간을 썼다. 이 실험은 그것을 분리하지 못한다. GC 로그는 GC만 보여 준다. 나머지를 쪼개려면 off-CPU 프로파일링이 필요하고, 그건 별도 측정이다.

G1은 그 사이에 있다. 최장 pause가 최장 요청의 절반에서 1/3 정도를 설명한다.

세대별 ZGC는 p99가 아니라 max를 고쳤다

12.24 대 12.07ms는 어느 쪽 런 간 편차보다 작다. p99에서 세대별 ZGC가 단일 세대보다 낫다고 말할 근거가 이 데이터에는 없다.

차이가 일관되게 나타난 곳은 최대값이다. fast 최대 32.74 대 46.91, alloc 최대 22.61 대 36.01이고, 세 런 모두 같은 방향이었다. pause는 더 자주 하고(159 대 102) 총 시간은 더 쓰지만(3.0 대 1.9ms) 둘 다 측정할 가치가 없는 크기다. young 세대를 따로 수집하니 한 번에 옮기는 양이 작아지고, 그것이 p99가 아니라 꼬리 끝에서 보인다.

max는 표본 하나다

같은 조건 3회에서 ZGC의 fast 최대값은 62.34 / 46.91 / 21.57ms였다. 3배 차이다. 같은 런들의 p99는 1.5ms 안에서 움직였다.

백분위수 통계에 적은 규율이 여기서 그대로 필요하다. 최대값은 순위를 정하는 데 쓸 수 없다. 이 글에서 최대값을 쓴 곳은 하나, “가장 느린 요청을 pause로 설명할 수 있는가”를 묻는 표다. 그건 크기 비교가 아니라 인과의 대응을 보는 용도다. 수집기 사이의 판단은 전부 p99로 한다.

틀렸던 것 다섯 가지

이 실험은 네 번 만에 측정에 성공했다. 실패들이 결론보다 더 옮길 만하다.

1. 유지 버퍼를 바이트가 아니라 슬롯으로 셌다. 링 버퍼 256칸 × 3MB = 768MB인데 힙은 컨테이너 기본값인 512MB였다. 12개 런 전부가 OutOfMemoryError: GC overhead limit exceeded로 죽고, 클라이언트의 30초 타임아웃이 지연으로 기록됐다. 표는 그럴듯했다. 모든 수집기가 30,000ms였으니까. 예산을 192MB로 바꾸고 힙을 고정했다.

2. 블록 크기가 1MB였다. 1GB 힙에서 G1의 리전 크기가 정확히 1MB다. 리전의 절반 이상인 할당은 humongous로 분류되어 young 경로를 건너뛰고 연속 리전에서 바로 잡힌다. 그래서 모든 pause가 G1 Humongous Allocation으로 찍혔고 19건은 Evacuation Failure까지 달렸다. G1의 실제 동작이지만 이 글의 질문이 아니다. 제목은 일반 할당 경로를 비교한다고 하는데 데이터는 humongous 처리를 비교하고 있었다. 블록을 64KB로 줄여 12MB가 192블록이 되게 했다.

3. 워밍업과 측정 사이에 GC 로그를 비웠다. : > /opt/app/gc.log는 JVM이 열어 둔 파일에는 듣지 않는다. JVM은 원래 오프셋에 계속 쓰므로 로그가 빈 채로 돌아온다. 자르는 대신 워밍업이 남긴 줄 수를 wc -l로 세어 파서가 건너뛰게 했다.

4. pause 정규식이 종류를 최소 일치로 잡았다. Pause Mark Start 0.012ms가 종류 Mark, 시간 12ms로 파싱됐다. 1000배 오차이고, 무서운 것은 그 결과가 읽히는 방식이다. “ZGC의 pause가 10ms대”라는 표는 이상해 보이지 않는다. 줄 끝 ms 앞의 마지막 숫자를 취하도록 고쳤다.

5. 세대별 ZGC의 pause 수가 0으로 나왔다. 세대별 ZGC는 로그 줄마다 세대 태그를 붙인다(GC(0) Y: Pause Mark Start (Major) 0.012ms). 정규식은 GC(n) 바로 뒤에 Pause가 오기를 요구했으므로 3,545줄이 한 건도 매치되지 않았다. 첫 집계 표에는 “세대별 ZGC: pause 0회, 총 0.0ms”가 적혀 있었다. 0은 가장 위험한 측정값이다. 없는 것처럼 생겼지만 실은 못 본 것이기 때문이다. 태그를 선택적으로 매치하고 종류 이름에 남겨서 minor young과 major young과 old를 구분했다.

5번은 런을 다시 돌리지 않고 고쳤다. 런마다 GC 로그 원본을 gc.log.gz로 남겨 두었고 파싱이 별도 단계이기 때문이다(텍스트 25MB, 압축 1.7MB). 파서에서 두 번 틀렸다는 것이 요약이 아니라 로그를 보관해야 하는 이유다.

한계

• CPU가 2개다. 코어가 많으면 동시 수집이 요청 스레드와 덜 경쟁한다. 그 항이 이 실험에서 분리되지 않은 항이므로, 11%는 작은 컨테이너의 숫자다.
• 할당 모양이 한 점이다. 12MB, 1/4 유지, 64KB 블록. 할당률·객체 크기·생존율을 훑지 않았고, 다른 점에서 G1과 ZGC의 순서가 같다고 보장할 수 없다.
• 힙이 1GB다. 여유 공간이 수집기가 pause와 맞바꾸는 자원이다. 4GB에서 같은 할당률은 다른 문제다.
• 튜닝하지 않았다. MaxGCPauseMillis 기본값, 리전 크기 지정 없음, SoftMaxHeapSize 없음. 기본값 비교이고 튜닝된 구성의 비교가 아니다.
• pause가 아닌 꼬리를 귀속하지 못했다. ZGC에서 가장 느린 요청은 GC로 설명되지 않은 채 남아 있다. 런큐 시간과 DB 시간과 할당 비용을 쪼개는 것은 off-CPU 프로파일링의 일이다.
• 3회다. p99가 안정적이라고 말할 만큼이고, 분포를 말할 만큼은 아니다.

정리

• ZGC의 최악 pause는 G1의 300분의 1인데, 조용한 엔드포인트의 p99는 11% 좋아졌다. pause 시간의 배수는 p99의 배수가 아니다.
• 저지연 수집기의 이득은 할당하는 엔드포인트에서 세 배 이상 컸다(37% 대 11%). pause와 동시 수집의 CPU를 둘 다 내는 쪽이 그쪽이다.
• Parallel만 “가장 느린 요청 = 가장 긴 pause”가 성립했다. Full GC 113ms가 요청 118ms로 나온다. 이때는 수집기를 바꾸는 것이 정확한 조치다.
• ZGC에서 최악 요청은 최악 pause의 30만 배다. 이 구간에서 GC 튜닝을 더 하는 것은 없는 원인을 고치는 일이다.
• 세대별 ZGC는 p99가 아니라 최대값을 낮췄다. 구별되는 개선을 p99에서 주장할 근거는 이 데이터에 없다.
• 수집기 선택 이전에 확인할 것이 있다. stop-the-world가 벽시계의 1.6%인지 0.002%인지. 0.002%라면 남은 꼬리는 GC 밖에 있다.

참고

• spring-ops-lab — 원본은 reports/data/t3-*, 표는 reports/01-scenario-report.md, 집계는 scenarios/t3/aggregate.py
• GC 알고리즘 비교 — 이 실험의 개념 짝
• 백분위수 통계 — max를 순위에 쓰지 않는 이유
• 자바 메모리 모델
• JEP 439: Generational ZGC