JFR 로 자바 정산 배치를 연다

목표

자바로 옮긴 정산 배치(Settle)를 JDK Flight Recorder 로 녹화해 CPU·할당·잠금 대기를 각각 읽고, 떠 있는 JVM 에 jcmd 로 녹화를 켜 보고, 원인을 고친 뒤 같은 인자로 다시 녹화해 견줍니다. Go 에서 익힌 읽는 법이 런타임이 바뀌어도 그대로 통하는지 확인합니다.

왜 중요한가

JFR 은 JDK 에 처음부터 들어 있는 기록기라서 따로 설치할 것이 없고, 운영 중인 JVM 에도 켤 수 있으며, 부담이 작게 설계되어 있습니다. 한 녹화 안에 CPU 표본(jdk.ExecutionSample), 할당 표본(jdk.ObjectAllocationSample), 잠금 대기(jdk.JavaMonitorEnter), GC, 그리고 그 JVM 을 어떤 인자로 띄웠는지(jdk.JVMInformation)까지 함께 담깁니다. 그래서 「같은 조건이었나」를 녹화 자체로 확인할 수 있습니다.

한계도 알아 둡니다. JFR 의 CPU 표본은 자바 코드를 실행 중인 스레드만 찍습니다. 네이티브 코드나 잠금을 기다리는 시간은 다른 이벤트로 봐야 합니다. 자바 바깥까지 한 그림으로 보고 싶을 때 쓰는 도구가 async-profiler 이고, 그 이야기는 읽기에서 다룹니다.

단계

/opt/lab/fixtures/prof/Settle.java 를 /root/jfr/Settle.java 로 복사하고 컴파일해 /root/jfr/Settle.class 를 만드세요.
java -XX:StartFlightRecording=filename=/root/jfr/run1.jfr,settings=profile Settle 100000 으로 녹화하세요.
CPU 표본에서 가장 많이 나온 Settle 안쪽 메서드와 그 비율을 /root/jfr/answers/hot.json 에 적으세요.
할당 표본의 무게(weight)로 가장 많이 할당한 Settle 안쪽 메서드와 비율을 /root/jfr/answers/alloc.json 에 적으세요.
잠금 대기를 가장 오래 일으킨 Settle 메서드와 jdk.JavaMonitorEnter 이벤트 수를 /root/jfr/answers/contention.json 에 적으세요.
녹화 옵션 없이 java Settle --serve 40 을 띄우고, jcmd 로 10초 녹화를 켜 /root/jfr/live.jfr 를 받으세요.
정규식을 한 번만 컴파일하도록 /root/jfr/Settle.java 를 고치고 같은 인자로 /root/jfr/run2.jfr 를 녹화한 뒤, 두 녹화의 couponPattern 비율을 /root/jfr/answers/jfr-compare.json 에 적으세요.

참고

jfr summary <파일> 은 이벤트 종류별 개수를, jfr view hot-methods <파일>·jfr view allocation-by-site <파일>·jfr view contention-by-site <파일> 은 표를 보여 줍니다. 표의 첫 줄은 잎(JDK 내부)일 때가 많으니, 스택을 따라 올라가 Settle 의 메서드를 찾습니다.
스택까지 보려면 jfr print --events jdk.ExecutionSample --stack-depth 64 <파일>, 기계로 읽으려면 --json 을 붙입니다.
「Settle 안쪽 메서드」는 스택을 잎부터 올라가며 처음 만나는 Settle 클래스의 메서드입니다.
떠 있는 JVM 목록은 jcmd -l 입니다. JFR 을 켜는 명령은 jcmd <pid> JFR.start name=live duration=10s filename=/root/jfr/live.jfr 입니다.
이 파드에는 capability 가 하나도 없습니다. 그래도 JFR 과 jcmd 는 됩니다. JVM 안의 기록기와 JVM 자신의 attach 통로를 쓰기 때문입니다.

정산 배치를 컴파일한다

/opt/lab/fixtures/prof/Settle.java 를 /root/jfr/Settle.java 로 복사하고 javac 로 /root/jfr/Settle.class 를 만드세요.

원본은 고치지 않습니다. 7단계에서 고칠 사본을 작업 자리에 둡니다.

시작부터 녹화한다

/root/jfr 에서 java -XX:StartFlightRecording=filename=/root/jfr/run1.jfr,settings=profile Settle 100000 을 실행하세요. 끝나면 /root/jfr/run1.jfr 가 남습니다.

settings=profile 은 표본을 더 촘촘히 받는 설정입니다(default 보다 부담이 조금 큽니다). 프로그램이 끝나면 녹화가 파일로 써집니다.

CPU 를 쓴 메서드

run1.jfr 의 jdk.ExecutionSample 에서 가장 많이 나온 Settle 안쪽 메서드를 settle_method(예: Settle.render), 그 비율(%)을 share 로 /root/jfr/answers/hot.json 에 적으세요.

jfr view hot-methods 의 첫 줄은 정규식 내부 같은 JDK 메서드일 수 있습니다. 그 비용을 만든 것은 그것을 부른 이 프로그램의 메서드입니다. Go 실습의 「잎에서 가장 가까운 main 함수」와 같은 읽기입니다.

메모리를 할당한 메서드

run1.jfr 의 jdk.ObjectAllocationSample 을 weight 로 더해 가장 큰 Settle 안쪽 메서드를 settle_method, 비율(%)을 share 로 /root/jfr/answers/alloc.json 에 적으세요.

할당 표본은 개수가 아니라 무게(weight, 바이트 추정치)로 더해야 큰 할당이 제 몫을 합니다. CPU 1위와 할당 1위가 같은지 견줘 보세요.

잠금을 기다린 곳

run1.jfr 의 jdk.JavaMonitorEnter 를 대기 시간(duration)으로 더해 가장 큰 Settle 메서드를 settle_method, 이벤트 개수를 events 로 /root/jfr/answers/contention.json 에 적으세요.

이 이벤트는 synchronized 블록에 들어가려고 일정 시간(profile 설정은 10ms) 넘게 기다렸을 때 남습니다. 기다리는 동안은 CPU 를 쓰지 않으니 CPU 표본에는 거의 보이지 않습니다.

떠 있는 JVM 에 녹화를 켠다

녹화 옵션 없이 java Settle --serve 40 & 로 띄운 뒤, jcmd <pid> JFR.start name=live duration=10s filename=/root/jfr/live.jfr 로 녹화를 켜고 끝날 때까지 기다리세요. /root/jfr/live.jfr 가 남아야 합니다.

운영 중인 서비스는 다시 띄울 수 없는 경우가 많습니다. jcmd 는 같은 사용자의 JVM 에 붙어 명령을 보냅니다. duration 이 지나면 JVM 이 스스로 파일을 씁니다.

고치고 같은 인자로 다시

/root/jfr/Settle.java 의 couponPattern 이 패턴을 한 번만 컴파일하도록 고쳐 다시 컴파일하고, 2단계와 같은 인자로 /root/jfr/run2.jfr 를 녹화한 뒤, 두 녹화의 CPU 표본에서 Settle.couponPattern 비율을 before_pct·after_pct 로 /root/jfr/answers/jfr-compare.json 에 적으세요.

static final Pattern 으로 한 번 만들어 두면 됩니다. 채점기는 두 녹화의 jdk.JVMInformation 에서 프로그램 인자가 같은지 봅니다.