Study · JDK · STEP 8 / 8 · 실행할 때

JIT는 자주 도는 코드만 골라, 실행 도중에 기계어로 갈아 끼운다

장면

같은 반복을 20구간 돌렸더니 첫 구간과 마지막 구간의 시간이 18배 가까이 달랐다. 코드는 하나도 안 바뀌었는데?

public class Warm3 {
    static int add(int a, int b) { return a + b; }

    public static void main(String[] args) {
        long sum = 0;
        for (int c = 1; c <= 20; c++) {                  // 구간 20개
            long t0 = System.nanoTime();
            for (int n = 0; n < 200_000; n++) {          // 구간마다 20만 번 (밑줄은 읽기 쉽게 끊는 표기)
                sum = add((int) (sum & 0xFFFF), n & 7);  // 계산 내용보다 add를 많이 부르는 것이 목적이다
            }
            System.out.println("chunk " + c + " us=" + (System.nanoTime() - t0) / 1000);
        }
    }
}

아래 재생기의 ▶를 누르면 한 스텝씩 진행된다. 금색 테두리가 방금 바뀐 곳이고, 캡션이 무슨 일이 일어났는지 말해 준다. 굵게 밑줄 친 말은 누르면 뜻이 나온다.

장면 · 자주 도는 코드 번역 0 / 20

add를 부르는 반복을 20만 번씩 20구간 돌린다. ▶를 누를 때마다 한 구간씩 막대가 쌓이고, 번역 로그가 함께 찍힌다. 괄호 안 「단계」는 번역 단계 번호다(0 인터프리터 · 3 C1 · 4 C2).

키보드 · ← → 한 스텝 · Space 재생/멈춤 · Home 처음

그래서 성능을 잴 때 처음 몇 구간(워밍업)의 숫자는 나중 구간과 다르게 본다.

어떻게 확인했나

• 시간은 System.nanoTime으로 잰 한 번의 실행값이다. 컴퓨터마다 다르므로 비율과 순서만 읽는다.
• 번역 시점은 -XX:+PrintCompilation으로 확인했다. 두 번 돌려 순서가 같았다.
• PrintCompilation 로그 시각은 번역을 시작한 때다(compileBroker.cpp L2198–L2200). 끝난 때는 -XX:+LogCompilation으로 따로 두 번 쟀다 — 반복문의 C2 번역은 시작 약 4ms 뒤 끝났고, 같은 순간 C1 번역본이 폐기됐다(instanceKlass.cpp L3570–L3575). 장면의 로그는 그 전 실행의 것이라 시작 40ms → 폐기 43ms로 약 3ms다.
• add가 반복문 번역본 안에 복사돼 들어간 것은 -XX:+PrintInlining 출력(@ 36 Warm3::add inline)으로 확인했다.

‹ 이전 목차로 ›