글을 작성하게 된 이유
실시간 트래픽이 몰리는 서비스에서 Stop-The-World(STW)가 400ms 이상 걸리면서, 모듈 사이 통신이 끊기고 라우팅이 꼬이는 상황을 겪고 나서야 깨달았다.
이 글은 그때 겪었던 장애 상황부터, GC 원인 분석, 그리고 ParallelGC에서 G1GC로 튜닝하면서 실제로 STW를 줄였던 과정을 정리해보려고 쓴다.
GC가 뭐길래?
Java에서는 개발자가 직접 free() 같은 걸 호출해서 메모리를 해제하지 않는다.
대신 GC가 주기적으로 돌아다니면서 더 이상 참조되지 않는 객체를 찾아서 메모리에서 치워준다.
이 덕분에 메모리 관리가 편해지는 대신, GC가 도는 동안 애플리케이션의 모든 쓰레드가 멈춘다. 이것을 Stop-The-World(STW) 라고 부른다.
서비스 간략 설명
내가 튜닝했던 서비스는 시민 ↔ 소방서 실시간 콜 통신 서비스였다.
- 시민이 소방서에 전화를 걸면
- 실시간 콜 시스템에서 약 200명 규모의 일반 대기 큐를 가지고 콜을 컨트롤하고
- 호 폭주가 일어나면 비상대기 큐로 라우팅해서 별도로 처리하는 구조였다.
즉, "비상대기 큐로 라우팅됐다”는 건
그 자체로 비정상 상황 또는 재난 상황일 수 있는 시그널이라 괜히 잘못 울리면 안 되는, 꽤 민감한 시스템이었다.
문제가 처음 정의된 이유
호 폭주도 아닌 평상시인데, 간헐적으로 콜이 비상대기 큐로 라우팅되는 현상.
- 비상대기 연락망 입장에서는 “혹시 국가 재난 수준의 사고가 터진 건가?” 라고 오인할 수 있고
- 진짜 비상 상황이 발생했을 때 올바른 우선순위로 콜을 처리하지 못할 가능성이 생긴다.
그래서 이 문제는 단순 성능 이슈가 아니라
업무 프로세스·알림 체계까지 흔드는 장애였다.
문제를 처음 직면하고, 실행 했던 행동
SI 성격의 사업이라, 언제든 바로 서버에 붙어서 로그를 볼 수 있는 환경은 아니었다.
(로그를 특정 시간대로 요청하면 2~3일 뒤에 받아볼 수 있는 구조였다.)
제일 먼저 했던 건
- “어디를 봐야 할지” 범위를 줄이는 것 관제 모듈이 문제인지, 인프라(L4, 네트워크, 서버)가 문제인지 위치를 먼저 좁히는 것 이었다.
초기 가설들
- 일반 대기 큐 쪽에 장애가 있었던 건 아닐까?
- 일반 대기 콜 서비스가 진짜 장애였다면, 비상대기 큐로 라우팅되는 건 오히려 정상 동작일 수도 있다.
- 근데 사용자 측 확인 결과,
일반 대기 콜 서비스는 그 시점에 멀쩡했다.
- 코드 레벨 버그로 잘못 라우팅하는 건 아닐까?
- 보통 개발자는 본능적으로 “코드 버그인가?”를 먼저 떠올리는데,
- 일부러 처음엔 코드 보면서 생각하지 않으려고 했다.
→ 로그·인프라 관점에서 먼저 봐야 편견이 덜 생긴다.
- 라우팅 시점에 DB를 쓰고 있는데, 그 과정에서 타임아웃·락 등이 걸렸나?
- 라우팅 직전에 DB를 쓴다면:
- DB 레이턴시 문제
- 데드락
- 트랜잭션 대기
- 이런 것들로 인해 응답 지연 → 상위 모듈이 서버를 죽었다고 판단 → 비상대기 큐로 라우팅
이런 흐름이 가능하다.
- 라우팅 직전에 DB를 쓴다면:
로그를 분석하고, 들었던 생각
CTI Gateway(L4 역할)가 서버가 죽었다고 판단하고 교환기로 콜을 넘긴 기록이 있었다.
실제 서버는 죽지 않았는데, L4가 “얘 죽은 것 같음” 하고 판정한 상황.
이 지점에서 STW를 강하게 의심하게 됐다.
- 서버는 살아있고, CPU도 그렇게 높지 않은데 짧은 순간 동안 모든 요청이 멈춘 것처럼 보이는 상황
→ GC로 인한 STW 말고는 설명이 잘 안 된다.
그래서 그 다음에는 해당 시점의 JVM 로그 / GC 로그 / jstat 기록 확보 및 비슷한 부하를 재현할 수 있는 개발계 환경 구성
이었다.
1번 서버
6~10분 간격으로 Minor GC가 발생
한 번에 300~400ms 수준의 STW
jstat -gcutil 형태의 로그에서 YGCT, GCT 누적 시간 증가를 보면 특정 구간에서 튀는 값이 있었다.
S0 S1 E O M CCS YGC YGCT FGC FGCT GCT
39.56 0.00 88.74 11.23 94.50 91.83 1024 417.252 5 0.600 417.852
0.00 99.91 2.77 11.23 94.50 91.83 1025 417.712 5 0.600 418.312
0.00 99.91 16.36 11.23 94.50 91.83 1025 417.712 5 0.600 418.312
0.00 99.91 27.53 11.23 94.50 91.83 1025 417.712 5 0.600 418.312
0.00 99.91 38.97 11.23 94.50 91.83 1025 417.712 5 0.600 418.312
0.00 99.91 49.04 11.23 94.50 91.83 1025 417.712 5 0.600 418.312
0.00 99.91 63.37 11.23 94.50 91.83 1025 417.712 5 0.600 418.312
0.00 99.91 79.78 11.23 94.50 91.83 1025 417.712 5 0.600 418.312
0.00 99.91 96.65 11.23 94.50 91.83 1025 417.712 5 0.600 418.312
77.04 0.00 14.08 11.23 94.50 91.83 1026 418.142 5 0.600 418.742
77.04 0.00 33.33 11.23 94.50 91.83 1026 418.142 5 0.600 418.742
77.04 0.00 50.76 11.23 94.50 91.83 1026 418.142 5 0.600 418.742
77.04 0.00 68.35 11.23 94.50 91.83 1026 418.142 5 0.600 418.742
77.04 0.00 80.21 11.23 94.50 91.83 1026 418.142 5 0.600 418.742
0.00 54.06 1.44 11.23 94.50 91.83 1027 418.473 5 0.600 419.0722번 서버
2~3분 간격으로 Minor GC발생 100~200ms 수준\
L4가 트래픽을 2번 서버 쪽으로만 몰고 있는 상황이라,
1번/2번 서버 간에 GC 패턴도 다르게 나왔다.
S0 S1 E O M CCS YGC YGCT FGC FGCT GCT
0.00 99.90 79.37 41.15 94.07 91.14 2589 469.886 5 0.624 470.510
85.52 0.00 26.93 41.16 94.07 91.14 2590 470.101 5 0.624 470.726
85.52 0.00 82.76 41.16 94.07 91.14 2590 470.101 5 0.624 470.726
0.00 48.58 29.38 41.16 94.07 91.14 2591 470.230 5 0.624 470.854
0.00 48.58 63.80 41.16 94.07 91.14 2591 470.230 5 0.624 470.854
0.00 48.58 98.52 41.16 94.07 91.14 2591 470.230 5 0.624 470.854
62.11 0.00 27.73 41.17 94.07 91.14 2592 470.399 5 0.624 471.023
62.11 0.00 59.12 41.17 94.07 91.14 2592 470.399 5 0.624 471.023
62.11 0.00 95.62 41.17 94.07 91.14 2592 470.399 5 0.624 471.023
0.00 99.82 45.36 41.17 94.07 91.14 2593 470.591 5 0.624 471.215
45.62 0.00 15.16 41.18 94.07 91.14 2594 470.699 5 0.624 471.323
45.62 0.00 86.90 41.18 94.07 91.14 2594 470.699 5 0.624 471.323
0.00 39.24 37.71 41.19 94.07 91.14 2595 470.788 5 0.624 471.412
0.00 39.24 72.52 41.19 94.07 91.14 2595 470.788 5 0.624 471.412
61.73 0.00 19.08 41.20 94.07 91.14 2596 470.945 5 0.624 471.569
61.73 0.00 66.15 41.20 94.07 91.14 2596 470.945 5 0.624 471.569
0.00 59.89 5.42 41.21 94.07 91.14 2597 471.092 5 0.624 471.716
0.00 59.89 47.92 41.21 94.07 91.14 2597 471.092 5 0.624 471.716
0.00 59.89 91.42 41.21 94.07 91.14 2597 471.092 5 0.624 471.716
60.39 0.00 40.56 41.21 94.07 91.14 2598 471.233 5 0.624 471.857
60.39 0.00 76.65 41.21 94.07 91.14 2598 471.233 5 0.624 471.857
0.00 65.46 15.70 41.21 94.07 91.14 2599 471.390 5 0.624 472.014
어떤 GC를 사용하고 있는가
환경: Java 8 / Heap 16GB / 기본 GC = ParallelGC
ParallelGC는 Throughput(전체 처리량)을 최적화하는 데 초점이 맞춰져 있어서
- Young 영역을 모아서 한 번에 크게 처리하고
- 그 과정에서 STW가 상대적으로 길어질 수 있는 구조다.
왜 200콜인데도 150–400 ms STW가 나왔나
200 동시통화는 소켓 200개라는 뜻일 뿐이고, 실제로는 이벤트 변환/검증/로그로 짧은 객체가 쏟아짐 → Eden 급팽창
ParallelGC는 Young을 덩어리째 치우는 경향이 있기에 → 간헐적이지만 긴 STW가 발생한다.
생각했던 해결방법
이때 고민했던 방법은 대략 세 가지였다.
- 거대 객체 리팩토링
- 콜 컨텍스트나 세션에서 오래 들고 있는 큰 객체들을 쪼개거나
- 불필요한 보관을 줄이는 방식으로 메모리 압박을 완화하는 방법
- 관제 모듈의 타임아웃/판단 로직 조정
- 관제 시스템이 “죽었다고 판단하는 기준 시간”을
STW를 어느 정도 포용할 수 있을 만큼 늘리는 방법 - 다만 이건 “GC 때문에 멈춘 걸 그냥 못 본 척하는 것”에 가깝다.
- 관제 시스템이 “죽었다고 판단하는 기준 시간”을
- GC 튜닝 (알고리즘 변경 + 옵션 조정)
- STW 자체를 줄이거나
- STW 양상을 “가끔 길게”에서 “자주 짧게”로 바꾸는 접근
선택한 방법 : GC 튜닝
최종적으로는 3번, GC 튜닝을 선택했다.
- ParallelGC의 구조적인 한계
- Throughput에는 유리하지만
- 한 번 Young GC가 돌 때 STW가 길게 나오는 패턴을 근본적으로 피하기 어렵다.
- 실시간성, 짧은 응답을 요구하는 서비스에는 잘 안 맞는 경우가 많다.
- 코드 리팩토링은 영향 범위가 너무 큼
- 콜 처리 로직, 세션 구조를 건드리면
서비스 전체 QA·리그레션 테스트 범위가 너무 넓어진다. - 장애 대응 관점에서 “지금 당장 할 수 있는” 해법은 아니었다.
- 콜 처리 로직, 세션 구조를 건드리면
- 타임아웃 조정은 근본 해결이 아님
- STW가 400ms인데 타임아웃을 1초로 늘리면
당장 눈앞의 장애는 줄어들 수 있다. - 근데 GC 때문에 응답이 밀리는 구조 자체는 그대로라서
나중에 트래픽이 더 커지면 다시 터진다.
- STW가 400ms인데 타임아웃을 1초로 늘리면
그래서,
“GC 알고리즘을 바꾸는 것이 이 서비스 특성상 가장 영향 범위는 적으면서 효과는 확실한 방법”이라고 판단했다.
| SerialGC | 단일 쓰레드, 단순 | 작은 앱에 적합 |
| ParallelGC | 병렬 처리, Throughput 우선 | pause time 예측 어려움 |
| CMS (deprecated) | Old 영역 동시 수집 | Full GC 무거움 |
| G1GC | Region 기반, pause 제어 가능 | 실시간 서비스에 추천 |
| ZGC/ Shenandoah | 저지연 설계, JDK 11+ | 대규모 시스템에 적합 |
튜닝 이후 로그
1번 서버 gc 평균 - 208ms
S0 S1 E O M CCS YGC YGCT FGC FGCT GCT
0.00 100.00 12.90 7.26 93.87 90.90 53 6.040 0 0.000 6.040
0.00 100.00 68.92 7.26 93.87 90.90 53 6.040 0 0.000 6.040
0.00 100.00 52.44 5.83 93.89 90.98 54 6.318 0 0.000 6.318
0.00 100.00 61.00 6.25 93.92 90.98 56 6.477 0 0.000 6.477
0.00 100.00 59.86 6.95 93.95 90.99 57 6.550 0 0.000 6.550
0.00 100.00 8.89 6.26 93.99 90.99 58 6.783 0 0.000 6.783
0.00 100.00 0.00 6.60 93.89 91.00 59 6.952 0 0.000 6.952
0.00 100.00 26.42 6.62 93.96 91.04 61 7.095 0 0.000 7.095
0.00 100.00 9.09 7.13 93.87 91.27 63 7.255 0 0.000 7.255
0.00 100.00 75.62 7.13 93.87 91.27 63 7.255 0 0.000 7.255
0.00 100.00 60.00 7.10 93.82 90.74 65 7.516 0 0.000 7.516
0.00 100.00 65.65 7.26 93.74 90.77 66 7.621 0 0.000 7.621
0.00 100.00 1.87 7.01 93.84 90.82 68 7.881 0 0.000 7.8812번 서버 gc 평균 - 70ms
S0 S1 E O M CCS YGC YGCT FGC FGCT GCT
0.00 100.00 56.87 7.26 93.87 90.90 53 6.040 0 0.000 6.040
0.00 100.00 21.95 5.83 93.89 90.98 54 6.318 0 0.000 6.318
0.00 100.00 8.00 6.25 93.92 90.98 56 6.477 0 0.000 6.477
0.00 100.00 47.40 6.95 93.95 90.99 57 6.550 0 0.000 6.550
0.00 100.00 89.97 6.95 93.95 90.99 57 6.550 0 0.000 6.550
0.00 100.00 77.78 6.26 93.99 90.99 58 6.783 0 0.000 6.783
0.00 100.00 53.12 6.60 93.95 91.04 60 7.046 0 0.000 7.046
0.00 100.00 83.40 7.11 93.85 91.26 62 7.148 0 0.000 7.148
0.00 100.00 62.40 7.13 93.87 91.27 63 7.255 0 0.000 7.255
0.00 100.00 30.56 7.10 93.82 90.74 65 7.516 0 0.000 7.516
0.00 100.00 46.52 7.26 93.74 90.77 66 7.621 0 0.000 7.621최종 적용 결과
g1gc 적용
.env added
-XX:+UseG1GC -XX:maxGCPauseMillis=100
davinci@davinci-dvp:/$ jmap -heap 7 | grep GC
Garbage-First (G1) GC with 8 thread(s)
davinci@davinci-dvp:/$
davinci@davinci-dvp:/$ jmap -heap 7
Attaching to process ID 7, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.332-b09
using thread-local object allocation.
Garbage-First (G1) GC with 8 thread(s)
Heap Configuration:
MinHeapFreeRatio = 40
MaxHeapFreeRatio = 70
MaxHeapSize = 3221225472 (3072.0MB)
NewSize = 1363144 (1.2999954223632812MB)
MaxNewSize = 1932525568 (1843.0MB)
OldSize = 5452592 (5.1999969482421875MB)
NewRatio = 2
SurvivorRatio = 8
MetaspaceSize = 21807104 (20.796875MB)
CompressedClassSpaceSize = 1073741824 (1024.0MB)
MaxMetaspaceSize = 17592186044415 MB
G1HeapRegionSize = 1048576 (1.0MB)
Heap Usage:
G1 Heap:
regions = 3072
capacity = 3221225472 (3072.0MB)
used = 501219312 (477.99998474121094MB)
free = 2720006160 (2594.000015258789MB)
15.55989533662796% used
G1 Young Generation:
Eden Space:
regions = 159
capacity = 2003828736 (1911.0MB)
used = 166723584 (159.0MB)
free = 1837105152 (1752.0MB)
8.320251177394034% used
Survivor Space:
regions = 25
capacity = 26214400 (25.0MB)
used = 26214400 (25.0MB)
free = 0 (0.0MB)
100.0% used
G1 Old Generation:
regions = 294
capacity = 1191182336 (1136.0MB)
used = 308281328 (293.99998474121094MB)
free = 882901008 (842.0000152587891MB)
25.88028034693758% used마무리
이번 케이스를 정리하면서 다시 느낀 건, “서버가 잠깐 멈춘다”는 것이 단순히 JVM 내부의 GC 문제로 끝나는 게 아니라
L4, 관제 시스템, 라우팅, 비상 프로세스까지 전부 연쇄적으로 흔들 수 있다는 거였다.
그래서 앞으로는, 성능 이슈나 타임아웃을 볼 때 “DB만 의심하지 말고 GC도 같이 본다” 개발계에서도 jstat, GC 로그를 습관적으로 좀 더 챙겨본다.
실시간/콜/메시지 같은 서비스는 기본 GC부터 한 번 더 확인하고 시작한다 이 정도를 개인적인 체크리스트로 가져가려고 한다.
'JAVA' 카테고리의 다른 글
| 시큐리티(미완성) (1) | 2023.08.08 |
|---|---|
| JAVA Object 클래스 란? (0) | 2023.04.27 |
| JAVA 캐스팅을 하는 이유 (0) | 2023.04.24 |
| JAVA 변수의 종류 (0) | 2023.04.23 |
| JAVA 클래스란? (0) | 2023.04.22 |