GC 로그를 읽는다

목표

작은 자바 프로그램으로 실제 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 로 끝나는 줄만 센다.

단계 8개

재료를 컴파일한다
GC 로그를 켠다
세부 로그에서 정지를 센다
힙이 작으면 정지가 잦다
평균이 아니라 최대 정지
살아 있는 프로세스를 jstat 으로
Serial 과 G1 을 같은 부하로
jcmd 로 힙 정보와 실제 플래그