직접 만든 마이크로벤치마크는 얼마나 틀리는가 - 결함 넷을 하나씩 재봤다

JIT 컴파일에 측정이 틀어지는 세 가지를 적고 “JMH가 이 셋을 다룬다”로 끝냈다. 문서를 근거로 쓴 문장이고, 각각이 몇 배짜리인지는 재지 않았다.

이 글이 그 측정이다. 그리고 질문을 하나 더 붙였다. 언제는 손으로 재도 되는가.

저장소는 jvm-bench-lab이고 재실행은 한 줄이다.

./scenarios/t5/run.sh 1

설계: 결함마다 대조군을 둔다

두 하네스가 같은 클래스(Work)를 호출한다. 하나는 nanoTime 두 번과 나눗셈으로 만든 순진한 하네스, 하나는 JMH(OpenJDK의 마이크로벤치마크 도구)다. 같은 컨테이너에서 같은 고정 힙(-Xms1g -Xmx1g)으로 돌린다. 그러면 답의 차이는 하네스의 성질이다.

그런데 “순진한 하네스가 JMH보다 25배 빠르게 나왔다”만으로는 아무것도 분리되지 않는다. 손으로 만든 하네스는 한 번에 여러 가지가 틀려 있기 때문이다. 그래서 결함마다 순진한 하네스 자신의 교정판을 대조군으로 뒀다.

• 제거 ↔ 같은 루프인데 결과를 필드에 누적
• 상수 접힘 ↔ 같은 호출인데 인자가 런타임 값
• 워밍업 없음 ↔ 같은 루프인데 컴파일된 뒤
• 반복마다 타이머 ↔ 루프 전체에 타이머 한 쌍

vs 대조군이 결함 하나의 값이다.

JMH가 잰 것

3회 중앙값이다.

벤치마크	ns/op
mix (splitmix64, 컴파일러가 모르는 값)	1.07
monomorphic (인터페이스 하나의 구현 하나)	1.09
megamorphic (한 자리에서 구현 셋이 번갈아)	3.52
sumArray (int 1,024개)	616.25
blackholeOverhead	1.08

순진한 하네스가 잰 것

결함	ns/op	vs JMH	vs 대조군
죽은 코드 제거	0.043	25.5배 빠름	21.4배 빠름
상수 접힘	0.079	13.8배 빠름	12.3배 빠름
워밍업 없음	18.166	16.9배 느림	19.9배 느림
반복마다 타이머	20.592	19.0배 느림	14.8배 느림
배열 합(1,024개), 워밍업함	606.906	1.0배	-

대조군, 즉 같은 루프를 제대로 쓴 것들:

대조군	ns/op	vs JMH
static 필드에 누적	0.946	1.1배 빠름
상수 대신 런타임 인자	0.968	1.1배 빠름
같은 루프, 워밍업함	0.913	1.2배 빠름
루프 전체에 타이머 한 쌍	1.395	1.3배 느림

결과를 지우는 결함은 당신에게 유리한 방향으로 틀린다

죽은 코드 제거는 1.07ns짜리 일을 0.043ns로 보고한다. 결과를 아무도 쓰지 않으므로 컴파일러가 계산을 지울 수 있고, 남은 0.043ns는 대략 루프 카운터 값이다.

“The downfall of many benchmarks is Dead-Code Elimination (DCE): compilers are smart enough to deduce some computations are redundant and eliminate them completely.” (JMHSample_08_DeadCode)

JMH는 반환값을 Blackhole(값을 소비한 것처럼 만드는 객체)에 넘겨 이 제거를 막는다.

상수 접힘은 0.079ns다. 인자가 리터럴이라 호출이 컴파일 시점에 한 번 계산됐다.

두 결함의 공통점이 문제다. 둘 다 “우리 코드가 엄청 빠르다”는 결론을 준다. 벤치마크를 짜는 사람은 보통 빠르기를 바라고 있고, 기대와 맞는 숫자는 의심받지 않는다. 20배 느리게 나오면 뭔가 잘못됐나 들여다보지만, 20배 빠르게 나오면 커밋한다.

일을 더하는 결함은 반대 방향으로 그만큼

워밍업 없이 재면 18.166ns, 같은 루프를 데우면 0.913ns다. 19.9배. 인터프리터와 C1(계층 컴파일의 첫 단계 컴파일러)을 재고 있고, 그것은 운영에서 도는 코드가 아니다.

반복마다 nanoTime을 부르면 20.592ns, 루프 전체에 한 쌍이면 1.395ns다. 14.8배. 타이머가 재려는 것의 열 배쯤 든다. 1ns짜리를 재면서 20ns짜리 자를 대고 있는 셈이다. Aleksey Shipilev도 유닉스 계열에서 nanoTime 호출 지연을 25~30ns로 쟀다(Nanotrusting the Nanotime).

제대로 쓴 순진한 루프도 15% 빠르다

대조군 셋이 0.913~0.968ns인데 JMH는 1.07ns다.

결함 넷을 다 고쳐도 같아지지 않는다. 예측 가능한 인덱스를 도는 맨 루프는 JMH가 만들어 주는 하네스보다 최적화하기 쉽다. JMH는 호출마다 반환값을 소비하고 벤치마크 메서드 경계를 넘어야 한다. 그래서 결함을 고치면 자릿수는 맞지만 JMH와 같아지지는 않는다.

반복 횟수도 값을 움직인다. 타이머 대조군은 500만 번이라 1.395ns가 나왔고, 같은 루프를 5,000만 번 돌린 워밍업 대조군은 0.913ns다. 짧은 창일수록 램프 구간(컴파일이 끝나기 전의 느린 구간)의 비중이 크다.

그리고 연산이 크면 이 모든 게 사라진다

순진한 배열 합은 606.906ns, JMH는 616.25ns다. 1.5% 차이, 잡음 안이다.

이 줄이 실무에 가장 직접 옮겨진다. 위의 결함들은 절대량으로 몇 나노초짜리다. 그래서 1ns 연산에서는 20배지만 600ns 연산에서는 보이지 않는다.

그러면 물어야 할 것은 “내 벤치마크가 순진한가”가 아니라 “내 오차가 내 효과보다 작은가”다. 리스트 구현 두 개를 비교하는데 각각 수백 마이크로초가 걸린다면 nanoTime 두 번으로 충분하다. 해시 함수 두 개를 비교한다면 JMH 없이는 아무것도 알 수 없다.

재현되지 않은 결함 하나

다섯 번째 결함으로 프로파일 오염을 넣었다. 한 JVM에서 구현 여러 개를 재면 호출 자리의 타입 프로파일(그 자리에서 본 구체 타입의 기록)이 더러워져서 나중 측정이 틀어진다는 것이다. 재현되지 않았다. 한 타입만 본 자리에서 0.670ns, 셋이 지나간 뒤 0.640ns다.

재현되지 않은 이유가 더 쓸모 있다. 측정 루프 하나 안에서 op는 5,000만 번 내내 같은 구체 타입을 쥔다. 그러면 인라인 캐시(호출 자리의 타입별 분기)가 더러워져 있어도 CPU의 분기 예측이 100% 맞는다. 디스패치가 값을 하는 것은 타입이 실제로 번갈아 들어올 때이고, 그것이 JMH의 megamorphic(3.52ns 대 1.09ns, 3.2배)이 하는 일이며 내 루프가 하지 않는 일이다.

지우지 않고 “재현 못 함”으로 남겼다. 어떤 설계에서 결함이 재현되지 않았다는 것도 그 설계에 대한 사실이기 때문이다.

틀렸던 것 넷, 전부 내 하네스 안에서

1. 측정하는 자리가 아닌 다른 자리를 오염시켰다. F5의 첫 판은 plus.apply(i) 루프를 재면서 all[i%3].apply(i)라는 다른 루프를 오염시켰다. 효과가 0으로 나왔고 깨끗한 음성 결과처럼 보였다. 그런데 타입 프로파일은 클래스나 인터페이스가 아니라 호출 자리에 붙는다. 둘을 공용 헬퍼 하나로 통과시켜 고쳤다.

2. 공용 헬퍼로 고쳤더니 벡터화를 재고 있었다. 루프가 acc += op.apply(i)이고 Plus가 x+1이라 전체가 i+1의 합으로 환원되고, HotSpot이 이것을 벡터화(여러 반복을 SIMD 명령 하나로 묶어 실행)한다. 그 결과 오염된 자리가 깨끗한 자리보다 빨라졌다(0.372 대 0.717ns). 루프 반송 의존성(이번 반복이 이전 반복의 결과를 써야 하는 관계, acc = op.apply(acc) ^ i)을 넣어 호출을 임계 경로에 묶었다.

3. 그러고도 F5는 아무것도 안 보여 줬다. 위에 쓴 이유다. 재현 못 함으로 기록했다.

4. scoreError를 숫자로 파싱했다. 포크가 하나면 JMH가 문자열 "NaN"을 쓰는데 요약 생성이 거기서 죽었다.

1·2·3번은 옷만 다른 같은 실수다. 하네스가 자기 이름과 다른 것을 재고 있었다. 그게 이 실험의 주제이므로, 실험 자신의 계측기 안에서 세 번 난 것이 여기서 제일 쓸모 있는 재료다. T6에서도 패턴이 조용히 아무것도 매치하지 않은 일이 두 번 있었다.

한계

• 호스트 하나, CPU 고정 없음. Docker Desktop은 VM으로 돌고 물리 코어 핀닝도 주파수 제어도 없으며 다른 컨테이너도 떠 있었다. 절대 ns/op는 이 기계의 성질이고, 다른 환경으로 옮길 수 있는 것은 배수뿐이다.
• JDK 하나. aarch64의 Temurin 21이다. 제거·접힘·벡터화는 컴파일러의 판단이고 다른 JDK나 아키텍처에서 달라진다.
• 결함 다섯 개지 목록이 아니다. false sharing, 측정 창 안의 할당과 GC, 정렬된 입력이 만드는 분기 예측, @State 스코프 실수는 다루지 않았다.
• 연산이 일부러 작다. 하네스 오차가 지배하는 구간이고, 배열 합 줄이 그 바깥을 보여 준다. 10ms짜리 연산을 어떻게 재는지는 여기 없다.
• JMH를 기준으로 두고 JMH 자체는 검증하지 않았다. 다만 @State 필드를 일부러 final이 아니게 뒀다. 거기에 static final을 쓰면 JMH 안에서도 상수 접힘이 그대로 재현된다. JMH 샘플도 입력을 final이 아닌 필드에서 읽으라고 적는다(JMHSample_10). 도구가 벤치마크를 자기 상수로부터 지켜 주지는 않는다.
• 3회다. 배수가 재현된다고 말할 만큼이고 분포를 말할 만큼은 아니다.

정리

• 결과를 지우는 결함은 유리한 방향으로 한 자릿수 배 틀린다. 제거 21.4배, 상수 접힘 12.3배. 기대와 맞는 숫자라 의심받지 않는다.
• 일을 더하는 결함은 반대 방향으로 그만큼. 워밍업 없음 19.9배, 반복마다 타이머 14.8배.
• 타이머가 재려는 것보다 열 배 비쌀 수 있다. 1ns를 20ns 자로 재는 일이 된다.
• 결함을 다 고쳐도 순진한 루프는 JMH보다 약 15% 빠르다. 자릿수를 맞추는 것이지 같아지는 것이 아니다.
• 620ns 연산에서는 차이가 1.5%다. 질문은 “순진한가”가 아니라 “오차가 효과보다 작은가”다.
• 프로파일 오염은 이 설계에서 재현되지 않았고, 이유는 루프 안에서 타입이 하나라 분기 예측이 맞기 때문이다. 디스패치 비용은 타입이 번갈아야 나타난다(3.52 대 1.09ns).
• 계측기가 자기 이름과 다른 것을 재는 일은 이 실험 안에서만 세 번 났다.

참고

• jvm-bench-lab — 원본은 reports/data/t5-*, 표는 reports/01-benchmark-report.md
• JIT 컴파일 — 이 실험의 개념 짝
• CPU 프로파일러가 1순위로 지목한 코드를 고쳤더니 — 계측기가 틀리는 다른 방식
• JMH
• JMHSample_08_DeadCode, JMHSample_10_ConstantFold — 죽은 코드 제거와 상수 접힘에 대한 JMH 1.37 샘플
• Aleksey Shipilev, Nanotrusting the Nanotime — System.nanoTime의 지연과 해상도