JIT 예열과 벤치마크

앞의 여러 장에서 실행 시간을 한 번 재 보고, 이 측정은 엄밀하지 않다고 덧붙인 적이 있습니다. 무엇이 엄밀하지 않은지 이 글에서 직접 확인합니다. HotSpot JVM은 바이트코드를 처음에는 인터프리터로 실행하다가, 자주 실행되는 메서드를 실행 도중에 기계어로 컴파일합니다. 이를 JIT(just-in-time) 컴파일이라고 합니다. 그래서 같은 코드라도 처음 몇 번은 느리고 나중에는 빨라집니다. 첫 실행에는 클래스 로딩과 초기화 비용도 섞이고, 그 뒤에도 GC, CPU 클럭 변화, 운영체제의 스케줄링이 측정값을 흔듭니다.

nanoTime()으로 잰 값은 숫자 하나를 줄 뿐, 그 숫자가 무엇을 쟀는지는 알려 주지 않습니다. 이 글에서는 측정을 망치는 대표적인 함정을 하나씩 재현하고, 그 함정을 체계적으로 피하도록 만든 도구인 JMH(Java Microbenchmark Harness)가 무엇을 해 주는지 정리합니다. 본문의 출력은 JDK 21(HotSpot)에서 얻은 것입니다. 시간 값은 컴퓨터와 실행마다 달라지므로 숫자 자체보다 숫자들 사이의 관계를 보세요.

속도보다 먼저 결과를 확인한다: 반복 사이에 남는 상태

벤치마크는 같은 작업을 여러 번 실행해 시간을 잽니다. 그러려면 매번 정말 같은 작업을 하는지부터 확인해야 합니다. 아래 Fixture는 매 반복에서 같은 배열을 더한다고 생각하고 만든 측정용 객체인데, 합계를 지역 변수가 아니라 필드 accumulator에 쌓습니다.

import java.util.stream.IntStream;

public final class BenchmarkStateCarryoverBug {
    private static final class Fixture {
        private long accumulator;

        long run(int[] values) {
            for (int value : values) {
                accumulator += value;
            }
            return accumulator;
        }
    }

    public static void main(String[] args) {
        int[] values = IntStream.rangeClosed(1, 100).toArray();
        Fixture fixture = new Fixture();
        long first = fixture.run(values);
        long second = fixture.run(values);
        System.out.println("first=" + first + ", second=" + second);
        System.out.println("wrong-same=" + (first == second));
    }
}

main은 같은 fixture 객체로 같은 배열을 두 번 더합니다. 둘째 줄의 wrong-same은 두 결과가 같은지 비교한 값입니다.

first=5050, second=10100
wrong-same=false

1부터 100까지의 합은 5050이므로 첫 결과는 맞습니다. 하지만 두 번째 호출은 첫 호출이 남긴 5050에서 시작해 10100을 돌려줬습니다. 반복마다 하는 일이 다르니, 이 상태로 시간을 재서 비교하는 것은 의미가 없습니다. 실제 벤치마크에서는 반복이 수천 번이고 결과를 출력하지도 않으므로, 이런 오류는 결과를 확인하는 코드가 없으면 드러나지 않습니다.

고치는 방법은 상태의 범위를 정하는 것입니다. 연산마다 새 상태가 필요한지, 측정 반복을 시작할 때마다 초기화해야 하는지, 아니면 운영 환경처럼 상태가 계속 쌓이는 것까지 재고 싶은지 먼저 정합니다. 이 예라면 합계를 run 안의 지역 변수로 두면 됩니다. 뒤에서 볼 JMH는 @State와 @Setup 애노테이션으로 상태를 언제 만들고 언제 초기화할지 코드에 적게 해 줍니다.

같은 코드가 점점 빨라지는 이유: JIT 컴파일

HotSpot은 메서드를 처음에는 인터프리터로 실행하면서 몇 번 호출됐는지, 반복문이 몇 번 돌았는지, 어떤 타입이 들어왔는지 같은 프로필(profile)을 모읍니다. 호출이 충분히 쌓이면 먼저 C1 컴파일러가 빠르게 기계어를 만들고, 더 많이 쓰이는 메서드는 C2 컴파일러가 모아 둔 프로필을 바탕으로 더 공격적으로 최적화한 기계어로 다시 컴파일합니다. 이렇게 단계를 밟아 가는 방식을 계층형 컴파일(tiered compilation)이라고 합니다. 측정 결과에는 이 과정이 그대로 묻어 납니다. 인터프리터로 실행되던 구간, 컴파일이 진행 중인 구간, 최적화된 기계어로 실행되는 구간의 시간이 모두 다르기 때문입니다.

그래서 벤치마크는 측정하기 전에 같은 작업을 미리 여러 번 실행해 두는 예열(warm-up) 단계를 둡니다. 다음 예제는 JMH를 대신할 수 없는 교육용 측정 틀이지만, 예열과 측정을 나누고 결과를 확인하는 기본 구조를 갖추고 있습니다. transform은 정수 하나에 간단한 계산을 30번 되풀이하고, operation은 원소 20,000개짜리 배열 전체에 transform을 적용해 합을 구합니다.

import java.util.Arrays;
import java.util.stream.IntStream;

public final class WarmupMeasurementHarness {
    private static long transform(int value) {
        long result = value;
        for (int round = 0; round < 30; round++) {
            result = (result * 1_664_525L + 1_013_904_223L) & 0x7fff_ffffL;
        }
        return result;
    }

    private static long operation(int[] values) {
        return Arrays.stream(values).mapToLong(WarmupMeasurementHarness::transform).sum();
    }

    public static void main(String[] args) {
        int[] values = IntStream.range(0, 20_000).toArray();
        for (int warmup = 0; warmup < 5; warmup++) {
            operation(values);
        }

        long expected = operation(values);
        for (int iteration = 1; iteration <= 5; iteration++) {
            long start = System.nanoTime();
            long checksum = operation(values);
            long elapsed = System.nanoTime() - start;
            if (checksum != expected) {
                throw new AssertionError("checksum");
            }
            System.out.println(
                    "iteration=" + iteration + ", ns=" + elapsed + ", checksum=" + checksum);
        }
    }
}

main은 같은 operation을 세 가지 목적으로 부릅니다. 처음 5번은 예열로, 반환값을 버립니다. 그다음 1번은 기준 체크섬 expected를 구하는 호출이고, 마지막 5번이 실제 측정입니다. 측정할 때마다 체크섬을 기준과 비교하므로, 앞의 Fixture처럼 반복마다 결과가 달라지면 바로 AssertionError가 납니다. 다만 기준값도 같은 구현으로 계산했으므로, 이 비교는 반복 사이의 일관성을 확인할 뿐 답이 맞는지까지 증명하지는 않습니다.

operation은 모두 11번 호출되고, 한 번 호출할 때마다 원소 20,000개에 30라운드씩 계산하므로 안쪽 계산은 호출당 600,000번입니다. 출력되는 ns는 배열 전체를 한 번 처리하는 데 걸린 시간입니다. 이 환경에서 한 번 실행한 결과는 다음과 같습니다.

iteration=1, ns=495953, checksum=21472586571056
iteration=2, ns=544665, checksum=21472586571056
iteration=3, ns=504630, checksum=21472586571056
iteration=4, ns=483225, checksum=21472586571056
iteration=5, ns=475659, checksum=21472586571056

체크섬은 언제 실행해도 같지만, 시간은 실행할 때마다 달라집니다. 예열이 얼마나 영향을 주는지 보려고 예열 반복의 조건 warmup < 5를 warmup < 0으로 바꿔 예열 없이 실행해 봤습니다.

iteration=1, ns=2738177, checksum=21472586571056
iteration=2, ns=2449385, checksum=21472586571056
iteration=3, ns=1112676, checksum=21472586571056
iteration=4, ns=789164, checksum=21472586571056
iteration=5, ns=754820, checksum=21472586571056

예열이 없으면 첫 측정이 약 2.7ms로, 예열한 뒤의 약 0.5ms보다 다섯 배쯤 느렸고, 반복이 거듭될수록 점점 빨라졌습니다. 앞쪽 반복은 아직 인터프리터나 C1 코드로 실행되던 시간과 클래스 로딩 비용까지 함께 잰 것입니다. 이 결과만 보고 '이 연산은 원소 하나에 약 137ns가 든다'고 말한다면, 실제로는 JVM의 준비 과정을 잰 셈이 됩니다. 반대로 예열한 뒤의 값을 원소 수로 나눠 약 24ns라는 숫자를 얻더라도, 그 나눗셈만으로 측정이 타당해지지는 않습니다. 실제 서비스에서 이 연산이 같은 데이터, 같은 호출 패턴으로 실행되는지는 별개의 문제이기 때문입니다.

JIT 컴파일 로그로 확인하기

언제 무엇이 컴파일됐는지는 HotSpot의 통합 로깅으로 볼 수 있습니다. jit+compilation 태그를 debug 수준으로 켜고, 예제 클래스에 해당하는 줄만 추리면 다음과 같습니다.

java -Xlog:jit+compilation=debug -cp out WarmupMeasurementHarness

[0.044s][debug][jit,compilation]   50       3       WarmupMeasurementHarness::transform (33 bytes)
[0.044s][debug][jit,compilation]   52       3       WarmupMeasurementHarness$$Lambda/0x00007f54c0000a08::applyAsLong (5 bytes)
[0.044s][debug][jit,compilation]   56       4       WarmupMeasurementHarness::transform (33 bytes)
[0.045s][debug][jit,compilation]   50       3       WarmupMeasurementHarness::transform (33 bytes)   made not entrant
iteration=1, ns=482582, checksum=21472586571056
iteration=2, ns=1566820, checksum=21472586571056
iteration=3, ns=512206, checksum=21472586571056
iteration=4, ns=502484, checksum=21472586571056
iteration=5, ns=494792, checksum=21472586571056

각 줄의 첫 숫자는 컴파일 작업 번호이고, 그다음 숫자가 컴파일 단계입니다. 3은 프로필을 모으는 코드를 넣은 C1 컴파일이고, 4는 C2 컴파일입니다. transform은 먼저 3단계로 컴파일됐다가 곧 4단계로 다시 컴파일됐고, 마지막 줄의 made not entrant는 앞서 만든 3단계 코드를 더는 쓰지 않는다는 뜻입니다. 이 실행에서는 측정이 시작되기 전에 이 과정이 끝났습니다. 눈여겨볼 것은 operation이 목록에 없다는 점입니다. operation은 11번밖에 불리지 않아 컴파일할 만큼 뜨거워지지 않았고, 실제로 시간을 쓰는 곳은 220,000번 호출된 transform과 스트림 내부의 반복문이었습니다. 이 형식은 JDK 21 기준이며, 쓸 수 있는 태그는 java -Xlog:help로 확인합니다.

로그를 켠 이 실행에서는 두 번째 측정이 혼자 약 1.6ms로 튀었습니다. 컴파일은 이미 끝난 뒤였으니, GC나 운영체제의 스케줄링처럼 측정하려는 코드와 상관없는 일이 끼어들었을 가능성이 큽니다. 한 번의 측정값을 그대로 믿으면 안 되는 이유이고, 반복을 여러 번 하고 분포를 봐야 하는 이유이기도 합니다. 또 예열을 5번 한다고 해서 언제나 컴파일이 끝난다는 보장은 없습니다. 몇 번이면 충분한지는 코드와 JVM에 따라 다르므로, 이렇게 로그로 확인하거나 측정값이 안정되는지를 보고 판단해야 합니다.

쓰지 않는 결과는 사라질 수 있다: 죽은 코드 제거

JIT 컴파일러는 결과가 어디에도 쓰이지 않는 계산을 통째로 없앨 수 있습니다. 이를 죽은 코드 제거(dead code elimination)라고 합니다. 앞의 예제에서 예열 호출은 반환값을 버리므로, 이론적으로는 그 계산의 일부가 최적화로 사라질 수 있습니다. 측정 구간에서 이런 일이 생기면 아무것도 하지 않는 시간을 재게 됩니다. 그래서 측정하는 계산의 결과는 반드시 어딘가에서 '쓰이게' 만들어야 합니다.

public final class ConsumedChecksumProbe {
    static long calculate(int limit) {
        long checksum = 0;
        for (int value = 1; value <= limit; value++) {
            checksum ^= (long) value * value * 31;
        }
        return checksum;
    }

    public static void main(String[] args) {
        long combined = 0;
        for (int iteration = 0; iteration < 10; iteration++) {
            combined ^= calculate(100_000 + iteration);
        }
        if (combined == Long.MIN_VALUE) {
            throw new AssertionError("impossible sentinel");
        }
        System.out.println("combined=" + combined);
    }
}

출력되는 combined의 값 자체에는 의미가 없고, 열 번의 계산 결과가 모두 쓰였다는 표시 역할을 합니다. 입력이 정해져 있으므로 몇 번을 실행해도 같은 값이 나옵니다.

combined=309988963567

이 프로그램은 결과를 소비하는 두 가지 습관을 보여 줍니다. 첫째, 매 반복의 결과를 combined에 XOR로 합치고 마지막에 출력하므로, 어느 반복의 계산도 '쓰이지 않는' 상태가 되지 않습니다. 둘째, 입력을 100_000 + iteration처럼 반복마다 바꿉니다. 입력이 매번 같은 상수라면 컴파일러가 결과를 미리 계산해 두거나 반복문 밖으로 끌어낼 여지가 생기기 때문입니다. Long.MIN_VALUE와 비교하는 부분은 실제로는 일어나지 않는 조건이지만, 결과를 검사하는 코드가 있다는 것을 분명히 해 둡니다.

결과를 소비하는 방법 자체가 비싸서는 안 된다는 점도 기억해야 합니다. 측정 구간 안에서 결과를 매번 출력하면 계산보다 출력 시간을 재게 됩니다. JMH는 이 문제를 위해 Blackhole이라는 객체를 제공하고, 벤치마크 메서드가 값을 반환하면 그 값을 알아서 소비해 줍니다. 벤치마크 데이터가 실제 서비스보다 지나치게 규칙적이어도 문제가 됩니다. 분기가 항상 같은 쪽으로만 가거나 만든 객체가 메서드 밖으로 나가지 않으면, JIT가 운영 환경에서는 할 수 없는 최적화를 해서 비현실적으로 빠른 숫자가 나올 수 있습니다.

호출 지점의 타입 프로필과 인라이닝

JIT가 하는 가장 중요한 최적화 가운데 하나는 인라이닝(inlining), 즉 호출되는 메서드의 본문을 호출하는 자리에 직접 펼쳐 넣는 것입니다. 인터페이스 메서드 호출은 실행 중에 어떤 구현이 불릴지 모르므로 그대로는 인라이닝하기 어렵습니다. 그래서 HotSpot은 호출 지점마다 실제로 들어온 타입을 프로필로 기록해 두고, 한 타입만 보였다면(단형, monomorphic) 그 구현을 펼쳐 넣고, 두 타입이 보였다면(이형, bimorphic) 타입을 검사해 둘 중 하나를 펼쳐 넣습니다. 세 타입 이상이 섞인 호출 지점(다형, megamorphic)은 보통 이런 인라이닝을 포기하고 일반적인 가상 호출로 남깁니다. 이 단계 구분은 HotSpot C2의 동작이며, 명세가 정한 규칙은 아닙니다.

이 때문에 벤치마크에서 어떤 타입을 어떤 순서로 넣었는지가 결과를 바꿀 수 있습니다. 다음 예제는 같은 run 메서드에 구현이 하나뿐인 배열과 두 구현이 섞인 배열을 차례로 넘깁니다. 한 라운드에 apply가 각각 1번과 2번 호출되므로 하는 일의 양부터 다르고, 시간은 재지 않습니다.

public final class PolymorphicCallProfile {
    private interface Rule {
        int apply(int value);
    }

    private static final class DoubleRule implements Rule {
        public int apply(int value) {
            return value * 2;
        }
    }

    private static final class AddRule implements Rule {
        public int apply(int value) {
            return value + 3;
        }
    }

    private static long run(Rule[] rules, int rounds) {
        long checksum = 0;
        for (int round = 0; round < rounds; round++) {
            for (Rule rule : rules) {
                checksum += rule.apply(round);
            }
        }
        return checksum;
    }

    public static void main(String[] args) {
        Rule doubleRule = new DoubleRule();
        System.out.println("mono=" + run(new Rule[] {doubleRule}, 20_000));
        System.out.println("mixed=" + run(new Rule[] {doubleRule, new AddRule()}, 20_000));
    }
}

run은 라운드마다 배열의 모든 규칙에 라운드 번호를 넣고, 돌려받은 값을 체크섬에 더합니다. 두 줄의 값은 계산이 맞았는지 확인하는 용도입니다.

mono=399980000
mixed=600030000

mono는 0부터 19,999까지 각 수에 2를 곱한 합이라 399,980,000이고, mixed는 여기에 round + 3의 합 200,050,000이 더해져 600,030,000입니다. 체크섬은 두 호출이 맞게 계산됐다는 것만 알려 줄 뿐, 인라이닝이 어떻게 됐는지는 알려 주지 않습니다. 여기서 중요한 것은 두 호출이 같은 run의 같은 호출 지점 rule.apply(round)를 공유한다는 점입니다. 첫 호출에서는 이 지점에 DoubleRule만 들어왔지만, 두 번째 호출부터는 AddRule도 들어옵니다. 만약 첫 호출 동안 C2가 DoubleRule만 있다고 가정하고 최적화했다면, 두 번째 호출에서는 그 가정이 깨져 다시 컴파일해야 합니다. 그래서 같은 프로세스 안에서 벤치마크 A를 돌린 뒤 B를 돌리면, B의 결과에는 A가 남긴 프로필이 섞입니다.

이 영향을 없애려면 벤치마크마다 새 JVM 프로세스를 띄워야 합니다. JMH는 이를 포크(fork)라고 부르며, 기본적으로 벤치마크마다 별도의 JVM에서 측정합니다. 실제로 어떤 메서드가 인라이닝됐는지는 JIT 로그나 JFR(JDK Flight Recorder) 기록에서 확인할 수 있습니다. 참고로 이 예제는 실행 시간이 짧아서, 이 환경에서 확인해 보니 run은 C1의 3단계까지만 컴파일되고 C2 컴파일은 일어나지 않았습니다. 짧은 프로그램은 위에서 말한 최적화 단계에 도달하기도 전에 끝날 수 있다는 것도 측정할 때 알아 둘 점입니다.

믿을 수 있는 측정을 위해 JMH를 쓴다

지금까지 본 함정을 손으로 모두 피하기는 어렵습니다. JMH는 OpenJDK 프로젝트에서 만든 미세 벤치마크(microbenchmark) 도구로, 예열과 측정 반복, 별도 JVM으로 포크하기, 상태의 범위 관리, 결과 소비를 애노테이션으로 정할 수 있게 해 줍니다. 앞의 배열 합계를 JMH로 옮기면 대략 다음과 같은 모양이 됩니다. JMH 라이브러리와 전용 빌드 설정이 필요하므로, 이 코드는 Maven의 JMH 프로젝트 템플릿처럼 JMH가 준비된 프로젝트에서 실행해야 합니다.

import java.util.concurrent.TimeUnit;
import java.util.stream.IntStream;
import org.openjdk.jmh.annotations.Benchmark;
import org.openjdk.jmh.annotations.BenchmarkMode;
import org.openjdk.jmh.annotations.Fork;
import org.openjdk.jmh.annotations.Level;
import org.openjdk.jmh.annotations.Measurement;
import org.openjdk.jmh.annotations.Mode;
import org.openjdk.jmh.annotations.OutputTimeUnit;
import org.openjdk.jmh.annotations.Scope;
import org.openjdk.jmh.annotations.Setup;
import org.openjdk.jmh.annotations.State;
import org.openjdk.jmh.annotations.Warmup;

@State(Scope.Thread)
@BenchmarkMode(Mode.AverageTime)
@OutputTimeUnit(TimeUnit.MICROSECONDS)
@Warmup(iterations = 5)
@Measurement(iterations = 5)
@Fork(2)
public class ArraySumBenchmark {
    private int[] values;

    @Setup(Level.Trial)
    public void prepare() {
        values = IntStream.rangeClosed(1, 1_000).toArray();
    }

    @Benchmark
    public long sum() {
        long total = 0;
        for (int value : values) {
            total += value;
        }
        return total;
    }
}

@State(Scope.Thread)는 측정하는 스레드마다 이 객체를 하나씩 둔다는 뜻이고, @Setup(Level.Trial)이 붙은 prepare는 한 번의 측정 실행을 시작하기 전에 입력을 준비합니다. 반복마다 상태를 새로 만들어야 한다면 Level.Iteration을 씁니다. @Warmup과 @Measurement는 예열과 측정의 반복 횟수를, @Fork(2)는 새 JVM을 두 번 띄워 각각 측정하라는 뜻입니다. sum은 합계를 지역 변수에 쌓으므로 반복 사이에 상태가 남지 않고, 결과를 반환하므로 JMH가 그 값을 소비해 죽은 코드 제거를 막아 줍니다.

그렇다고 JMH가 모든 것을 해결해 주지는 않습니다. JMH는 '이 코드를 이 조건에서 실행하면 얼마나 걸리는가'를 정확히 재 줄 뿐, 측정하는 작업이 실제 서비스의 작업을 대표하는지는 알려 주지 않습니다. 운영 환경과 다른 입력 크기나 분포를 쓰면 정확하게 잰 엉뚱한 숫자가 나옵니다. 그래서 미세 벤치마크의 결과는 실제 요청 단위의 응답 시간 측정과 함께 해석해야 합니다.

벤치마크 결과와 함께 적어 둘 것

벤치마크 결과는 조건이 함께 있어야 다른 사람이 다시 확인할 수 있습니다. 결과를 공유할 때는 다음 내용을 같이 남깁니다.

• JDK 공급자와 버전, JVM 옵션, 운영체제, CPU, 전원 모드
• 예열과 측정의 반복 횟수, 포크 수
• 입력 크기와 분포, 난수를 썼다면 시드, 그리고 예상 결과(체크섬)
• 측정하는 동안의 할당률, GC 일시 정지, JIT 컴파일 활동
• 평균만이 아니라 분산과 백분위수
• 여러 벤치마크를 비교했다면 실행 순서를 바꾸거나 포크를 나눠 서로 영향을 주지 않게 한 방법

정리

• HotSpot은 바이트코드를 인터프리터로 실행하면서 프로필을 모으고, 자주 쓰이는 메서드를 C1과 C2로 단계적으로 컴파일합니다. 그래서 같은 코드도 처음에는 느리고 점점 빨라집니다.
• 시간을 재기 전에 매 반복이 같은 일을 하는지 결과로 확인합니다. 필드에 쌓이는 상태는 반복 사이에 남아 결과를 바꿉니다.
• 예열 횟수만으로는 컴파일이 끝났다고 확신할 수 없습니다. -Xlog:jit+compilation=debug 같은 로그나 측정값의 안정 여부로 확인합니다.
• 쓰이지 않는 계산은 JIT가 없앨 수 있으므로 결과를 소비하되, 소비하는 비용이 측정을 지배하지 않게 합니다.
• 호출 지점의 타입 프로필은 같은 프로세스 안에서 앞의 실행에 영향을 받습니다. 벤치마크마다 별도 JVM으로 포크해 측정합니다.
• JMH는 예열, 측정, 포크, 상태 범위, 결과 소비를 체계적으로 다루지만, 측정하는 작업이 현실적인지는 직접 판단해야 합니다.

연습 문제

1. 1부터 1,000까지 담은 배열의 합을 세 번 구하되, 각 반복이 서로 독립적인 지역 누산기를 쓰고 매번 기대값과 같은지 검사하는 프로그램을 작성하세요. 기대값은 같은 구현을 다시 호출해 만들지 말고 등차수열의 합 공식으로 먼저 계산합니다. 시간은 재지 않습니다. 같은 코드에 1부터 2,000까지의 배열과 빈 배열을 넣으면 각각 얼마가 나와야 하는지도 예상하세요.
2. 앞의 BenchmarkStateCarryoverBug에서 fixture.run(values)를 세 번째로 한 번 더 호출하면 무엇이 나올지 예상하고, 그 이유를 설명하세요.
3. JIT 컴파일 로그에 transform은 나오는데 operation은 나오지 않았습니다. 왜 그런지, 그리고 이것이 '예열은 측정 대상 메서드를 몇 번 부르면 충분한가'라는 질문과 어떻게 이어지는지 설명하세요.

힌트

1. 1부터 n까지의 합은 n × (n + 1) ÷ 2입니다.
2. 두 번째 호출이 끝났을 때 accumulator에는 무엇이 남아 있나요?
3. 두 메서드가 각각 몇 번 호출되는지 세어 보세요.

해설

1. 합계를 메서드 안의 지역 변수로 계산하면 반복 사이에 남는 상태가 없습니다.

import java.util.stream.IntStream;

public final class ResetBenchmarkStateSolution {
    static long sum(int[] values) {
        long total = 0;
        for (int value : values) {
            total += value;
        }
        return total;
    }

    public static void main(String[] args) {
        int[] values = IntStream.rangeClosed(1, 1_000).toArray();
        long expected = 500_500;
        for (int iteration = 1; iteration <= 3; iteration++) {
            long result = sum(values);
            if (result != expected) {
                throw new AssertionError("iteration=" + iteration);
            }
            System.out.println("iteration=" + iteration + ", result=" + result);
        }
    }
}

각 반복은 결과가 기대값과 다르면 AssertionError를 던집니다. 그래서 세 줄이 모두 찍혔다면 세 번 모두 검사를 통과했다는 뜻입니다.

iteration=1, result=500500
iteration=2, result=500500
iteration=3, result=500500

기대값 500,500은 1,000 × 1,001 ÷ 2로 구했습니다. total은 sum을 부를 때마다 0에서 새로 시작하므로 세 반복이 모두 같은 값을 냅니다. 1부터 2,000까지의 배열이라면 2,000 × 2,001 ÷ 2 = 2,001,000이 몇 번을 반복해도 똑같이 나와야 하고, 빈 배열은 반복문이 한 번도 돌지 않으므로 언제나 0입니다. 기대값을 같은 구현으로 만들지 않고 공식으로 따로 계산한 덕분에, 이 검사는 반복 사이의 일관성뿐 아니라 답이 맞는지도 확인합니다.

2. first=5050, second=10100 다음 세 번째 호출은 15150을 돌려줍니다. accumulator는 객체의 필드라서 호출이 끝나도 사라지지 않고, 두 번째 호출이 끝났을 때 10100이 남아 있습니다. 세 번째 호출은 거기에 다시 5050을 더합니다. 호출할 때마다 결과가 5050씩 커지므로, 이 객체로 시간을 재면 반복마다 다른 작업을 재는 셈입니다.

3. operation은 예열 5번, 기준 1번, 측정 5번으로 모두 11번만 호출됩니다. 반면 transform은 operation 한 번에 20,000번씩, 모두 220,000번 호출됩니다. HotSpot은 호출 횟수와 반복 횟수가 쌓인 코드를 컴파일하므로, 실제로 뜨거운 코드는 transform과 스트림 내부의 반복문이고 operation은 컴파일할 대상이 아니었습니다. 따라서 '측정하려는 메서드를 몇 번 불렀는가'만으로는 예열이 충분한지 판단할 수 없습니다. 시간이 실제로 쓰이는 안쪽 코드가 컴파일됐는지를 로그로 확인하거나, 측정값이 안정되는지를 보고 판단해야 합니다.

다음 글

실행 시간을 흔드는 또 다른 큰 요인은 메모리 관리입니다. GC 로그로 할당률과 메모리 누수 구분하기에서는 객체를 얼마나 빨리 만들고 버리는지가 GC와 응답 시간에 어떤 영향을 주는지 로그로 확인합니다.