Reading the GC log

목표

작은 자바 프로그램으로 실제 GC 로그를 만들고 읽는다 — 정지 횟수·정지 시간·힙 크기의 영향·컬렉터 비교·jstat·jcmd.

왜 중요한가

"서비스가 느리다" 를 받았을 때 첫 갈림길은 GC 인가 아닌가다. GC 로그에 긴 정지가 없으면 범인은 다른 곳(잠금·풀 고갈)이다. 로그를 켜는 법과 읽는 법, 그리고 힙 크기와 컬렉터가 정지에 어떻게 영향을 주는지를 실제 숫자로 본다. 재료 Churn.java 는 java Churn <초> <유지MB> [반복당KB] 로 돌며, 유지MB 만큼은 붙들고 나머지는 계속 버린다.

단계

1. mkdir -p /root/jvm/gc && cd /root/jvm/gc && javac -d . /opt/lab/fixtures/jvm/Churn.java 로 컴파일한다. /root/jvm/gc/Churn.class 가 생기고 java -cp /root/jvm/gc Churn 1 0 이 done 을 찍는다.
2. java -Xmx256m -Xlog:gc:file=/root/jvm/gc/gc.log -cp /root/jvm/gc Churn 5 24 로 GC 로그를 만든다. 로그에 Using 으로 시작하는 컬렉터 줄과 Pause Young 줄이 있어야 한다.
3. -Xlog:gc*:file=/root/jvm/gc/gc-detail.log 로 세부 로그를 만든다(같은 부하 5초·24MB). Pause Young 을 포함하고 ms 로 끝나는 줄(정지 완료 줄)의 수를 세어 /root/jvm/gc/answer.txt 에 young_pauses=<n> 한 줄로 적는다.
4. 같은 부하를 -Xms64m -Xmx64m 으로 돌려 /root/jvm/gc/gc-64.log(-Xlog:gc*)를, -Xmx256m 으로 돌려 /root/jvm/gc/gc-256.log 를 만들고, /root/jvm/gc/compare.txt 에 xmx64_pauses=<n> 과 xmx256_pauses=<n> 두 줄(3단계와 같은 세는 법)을 적는다. 64M 쪽이 더 많아야 한다.
5. gc-256.log 에서 가장 긴 정지(Pause 줄의 마지막 ms 값)를 찾아 /root/jvm/gc/pause.txt 에 max_pause_ms=<x> 로 적는다(소수 셋째 자리까지, 로그 값 그대로).
6. java -Xmx128m -cp /root/jvm/gc Churn 12 24 를 백그라운드로 띄우고 jstat -gc <pid> 1000 5 > /root/jvm/gc/jstat.txt 로 1초 간격 5번을 남긴다. 헤더(S0C·EC·YGC·FGC…)와 데이터 5행이 있어야 한다.
7. -XX:+UseSerialGC -Xlog:gc:file=/root/jvm/gc/gc-serial.log 와 -XX:+UseG1GC -Xlog:gc:file=/root/jvm/gc/gc-g1.log 로 같은 부하(-Xmx128m, 5초·24MB)를 돌리고, 각각의 최대 정지를 /root/jvm/gc/collector.txt 에 serial_max_pause_ms=<x> 와 g1_max_pause_ms=<x> 두 줄로 적는다.
8. Churn 을 다시 백그라운드로 띄운 채 jcmd <pid> GC.heap_info > /root/jvm/gc/heap_info.txt 와 jcmd <pid> VM.flags > /root/jvm/gc/vm_flags.txt 를 남긴다. heap_info 에 total 과 used 가, vm_flags 에 -XX:MaxHeapSize= 가 있어야 한다.

참고

• 최대 정지 뽑기: awk '/Pause/ && match($0,/[0-9.]+ms$/){v=substr($0,RSTART,RLENGTH-2)+0; if(v>m)m=v} END{print m}' gc-256.log
• 백그라운드 pid: java ... & PID=$! 뒤 jstat -gc $PID 1000 5. 프로그램은 스스로 끝난다.
• 흔한 실수: -Xlog:gc* 에서 Pause Young 을 세면 시작 줄과 완료 줄이 둘 다 잡힌다 — ms 로 끝나는 줄만 센다.

재료를 컴파일한다

/root/jvm/gc 에 Churn.java 를 컴파일해 Churn.class 를 만든다. java -cp /root/jvm/gc Churn 1 0 이 done 을 찍는다.

javac -d <출력디렉터리> <소스> 입니다. 클래스는 패키지가 없으므로 -cp 에 디렉터리만 주면 됩니다.

GC 로그를 켠다

-Xmx256m -Xlog:gc:file=/root/jvm/gc/gc.log 로 Churn 5 24 를 돌린다. 로그에 Using 줄과 Pause Young 줄이 있어야 한다.

-Xlog:gc:file=<경로> 가 GC 이벤트를 파일로 보냅니다. 첫 줄이 어떤 컬렉터를 쓰는지 말해 줍니다.

세부 로그에서 정지를 센다

-Xlog:gc*:file=/root/jvm/gc/gc-detail.log 로 같은 부하를 돌리고, Pause Young 을 포함하며 ms 로 끝나는 줄 수를 /root/jvm/gc/answer.txt 에 young_pauses= 으로 적는다.

gc* 는 정지 하나를 [gc,start] 와 [gc] 두 줄로 남깁니다. 완료 줄만 세려면 ms 로 끝나는 줄을 고르세요: grep -E 'Pause Young.*ms$' | wc -l

힙이 작으면 정지가 잦다

-Xms64m -Xmx64m 으로 gc-64.log 를, -Xmx256m 으로 gc-256.log 를(둘 다 -Xlog:gc*) 만들고 compare.txt 에 xmx64_pauses= 과 xmx256_pauses= 을 적는다. 64M 쪽이 많아야 한다.

같은 할당량을 작은 힙에 넣으면 에덴이 빨리 차서 Young GC 가 잦아집니다. 세는 법은 3단계와 같습니다.

평균이 아니라 최대 정지

gc-256.log 에서 Pause 줄의 마지막 ms 값 중 최댓값을 /root/jvm/gc/pause.txt 에 max_pause_ms= 로 적는다.

참고 절의 awk 한 줄이 최댓값을 뽑습니다. 값은 로그의 소수 셋째 자리 그대로입니다.

살아 있는 프로세스를 jstat 으로

Churn 12 24 (-Xmx128m) 를 백그라운드로 띄우고 jstat -gc 1000 5 > /root/jvm/gc/jstat.txt 를 남긴다. 헤더와 데이터 5행이 있어야 한다.

java ... & PID=$! 로 pid 를 잡고 jstat -gc $PID 1000 5 입니다. 프로그램이 12초 뒤 스스로 끝나므로 그 안에 5번을 찍습니다.

Serial 과 G1 을 같은 부하로

-XX:+UseSerialGC 로 gc-serial.log 를, -XX:+UseG1GC 로 gc-g1.log 를(-Xmx128m, -Xlog:gc, Churn 5 24) 만들고 collector.txt 에 serial_max_pause_ms= 와 g1_max_pause_ms= 를 적는다.

각 로그의 첫 줄이 Using Serial / Using G1 이어야 합니다. 최대 정지는 5단계의 awk 를 파일만 바꿔 씁니다.

jcmd 로 힙 정보와 실제 플래그

Churn 을 백그라운드로 띄운 채 jcmd GC.heap_info > /root/jvm/gc/heap_info.txt 와 jcmd VM.flags > /root/jvm/gc/vm_flags.txt 를 남긴다.

jcmd -l 로 pid 를 확인할 수 있습니다. VM.flags 는 JVM 이 실제로 적용한 값(-XX:MaxHeapSize=…)을 보여 줍니다 — 설정 파일이 아니라 이것이 진실입니다.