자바 성능 튜닝 - JMH 벤치마크와 병목 찾는 순서 (자바 고급 22단원)

이 단원에서 배우는 것

19단원에서 GC 로그로 메모리 상태를 읽었고, 20단원에서는 리플렉션 비용을 대충 재 봤다. "대충"이라고 쓴 이유가 있다. System.nanoTime() 으로 감싸는 측정은 자릿수 비교에는 쓸 수 있어도 "A가 B보다 12% 빠르다" 같은 판단에는 못 쓴다. JIT 컴파일, 죽은 코드 제거, GC가 결과를 흔들기 때문이다. 이번 단원은 믿을 수 있는 숫자를 만드는 방법과, 그 숫자를 근거로 어디를 고칠지 정하는 순서를 다룬다. 앞 단원들과 같은 재고·주문 도메인을 계속 쓴다.

단순 nanoTime 측정이 왜 틀리는지 실행 결과로 확인한다
JMH로 마이크로벤치마크를 작성하고 Score ± Error 를 해석한다
실무 병목의 실제 분포를 알고, 프로파일러로 후보를 좁히는 순서를 익힌다

왜 필요한가

성능 개선 요청은 대개 "느려요"로 시작한다. 여기서 코드를 읽고 "이 부분이 비효율적이니 고치자"로 바로 가면 거의 항상 헛수고가 된다. 스트림을 for문으로 바꾸고, String 연결을 StringBuilder 로 바꾸고, 며칠 뒤 응답 시간을 재 보면 800ms가 795ms가 되어 있다. 진짜 원인은 N+1 쿼리 하나였기 때문이다.

반대 방향의 실수도 있다. 눈으로 봐서 명백히 빨라 보이는 변경이 실제로는 느려지는 경우다. 사람의 직관은 메모리 접근 패턴, JIT 인라이닝, 분기 예측 앞에서 자주 틀린다. 그래서 규칙은 하나다.

측정 → 가장 큰 병목 하나 → 고침 → 다시 측정. 이 순서를 벗어난 최적화는 코드만 복잡하게 만든다.

문법과 예제

1. 단순 측정이 틀리는 것을 눈으로 보기

public class NaiveBench {
    static int work(int n) {
        int s = 0;
        for (int i = 0; i < n; i++) s += i % 7;
        return s;
    }

    public static void main(String[] args) {
        for (int round = 1; round <= 5; round++) {
            long t = System.nanoTime();
            work(1_000_000);                          // 결과를 안 쓴다
            System.out.println("round " + round + " : " + (System.nanoTime() - t) / 1000 + "us");
        }
    }
}

round 1 : 2155us
round 2 : 3963us
round 3 : 1766us
round 4 : 700us
round 5 : 697us

같은 코드, 같은 입력인데 최대 5.7배 차이가 난다. 1~3라운드는 인터프리터로 실행되다가 JIT가 컴파일하는 중이고, 2라운드가 오히려 느린 것은 컴파일 작업 자체가 끼어들었기 때문이다. 4라운드부터가 실제 성능이다. 여기서 얻을 교훈은 둘이다.

워밍업 없는 측정은 컴파일 과정을 측정한 것이다. 서버 애플리케이션은 몇 분씩 도는 것이 정상이므로, 우리가 알고 싶은 것은 워밍업 이후 값이다.
work() 의 결과를 쓰지 않았다. JIT는 결과가 안 쓰이는 계산을 통째로 없앨 수 있다. 이 예제는 루프가 남았지만, 조금만 단순해지면 측정 대상이 사라져 0ms 가 찍힌다. "최적화했더니 0ms가 나왔다"는 대개 이 경우다.

2. JMH — 마이크로벤치마크의 표준

JMH(Java Microbenchmark Harness)는 OpenJDK 팀이 만든 도구로, 워밍업·별도 JVM 포크·죽은 코드 방지·통계 처리를 대신해 준다. 메이븐 의존성은 다음과 같다(24단원에서 빌드 구성을 자세히 다룬다).

<dependency>
  <groupId>org.openjdk.jmh</groupId>
  <artifactId>jmh-core</artifactId>
  <version>1.37</version>
</dependency>
<dependency>
  <groupId>org.openjdk.jmh</groupId>
  <artifactId>jmh-generator-annprocess</artifactId>
  <version>1.37</version>
  <scope>provided</scope>
</dependency>

주문 처리에서 "이 SKU가 취급 품목인가"를 확인하는 코드를 List 로 하는 경우와 Set 으로 하는 경우를 비교해 본다.

package bench;

import org.openjdk.jmh.annotations.*;

import java.util.*;
import java.util.concurrent.TimeUnit;

@BenchmarkMode(Mode.AverageTime)
@OutputTimeUnit(TimeUnit.MICROSECONDS)
@State(Scope.Benchmark)
@Warmup(iterations = 3, time = 1)
@Measurement(iterations = 3, time = 1)
@Fork(1)
public class LookupBenchmark {

    @Param({"1000", "10000"})
    public int size;

    private List<String> skuList;
    private Set<String> skuSet;
    private String target;

    @Setup(Level.Trial)
    public void setUp() {
        skuList = new ArrayList<>();
        for (int i = 0; i < size; i++) skuList.add("SKU-" + i);
        skuSet = new HashSet<>(skuList);
        target = "SKU-" + (size - 1);           // 최악의 경우: 맨 끝
    }

    @Benchmark
    public boolean listContains() {
        return skuList.contains(target);        // 반환하면 죽은 코드로 제거되지 않는다
    }

    @Benchmark
    public boolean setContains() {
        return skuSet.contains(target);
    }
}

Benchmark                     (size)  Mode  Cnt   Score    Error  Units
LookupBenchmark.listContains    1000  avgt    3   2.227 ±  2.036  us/op
LookupBenchmark.listContains   10000  avgt    3  17.796 ± 13.868  us/op
LookupBenchmark.setContains     1000  avgt    3   0.008 ±  0.011  us/op
LookupBenchmark.setContains    10000  avgt    3   0.008 ±  0.005  us/op

읽는 법이 중요하다.

Score 는 연산 하나당 평균 시간이다. listContains 는 크기가 10배가 되자 시간도 8배가 됐다. 선형이다. setContains 는 크기와 무관하게 0.008µs다. 상수 시간이다. 알고리즘 복잡도 차이는 이렇게 "입력을 바꿔 가며" 재야 보인다. 한 크기로만 재면 "둘 다 빠르다"로 끝난다.
Error 는 신뢰 구간이다. 위 결과는 17.796 ± 13.868 로 오차가 너무 크다. 반복이 3회뿐이라 그렇다. 실제 판단에 쓰려면 @Warmup(iterations = 5), @Measurement(iterations = 10), @Fork(3) 정도로 올려야 한다. Error 범위가 겹치는 두 결과로 우열을 말하면 안 된다. 위 예에서 List와 Set은 자릿수가 세 개나 차이 나므로 결론은 분명하지만, 5% 차이를 다투는 상황이라면 Error를 먼저 봐야 한다.
@Fork 는 벤치마크마다 새 JVM을 띄운다. 한 JVM에서 두 구현을 연달아 돌리면 먼저 실행된 쪽 때문에 JIT의 프로파일이 오염되어, 나중 것이 부당하게 느려지거나 빨라진다. @Fork(0) 은 디버깅용이지 결과용이 아니다.

측정 결과를 버리지 않으려면 반환하거나 Blackhole 에 넣는다. void 메서드에서 계산만 하고 끝내면 JMH도 죽은 코드 제거를 막지 못한다.

3. 실제 병목의 분포

마이크로벤치마크는 "두 구현 중 어느 쪽"을 정할 때 쓴다. 하지만 실무 성능 문제의 원인은 대개 훨씬 위층에 있다. 경험적인 빈도 순으로 적으면 이렇다.

순위	병목	전형적인 증상	조치
1	N+1 쿼리	목록 100건에 쿼리 101번. CPU는 한가한데 응답이 느림	페치 조인, `IN` 절 일괄 조회
2	인덱스 없는 조회	데이터가 늘수록 선형으로 느려짐	실행 계획 확인 후 인덱스 추가
3	외부 API 순차 호출	응답 시간이 각 호출의 합	18단원의 `CompletableFuture` 병렬화
4	잘못된 자료구조	건수가 늘면 제곱으로 느려짐	`List.contains` → `Set`/`Map`
5	과도한 객체 생성	Young GC가 초당 수십 회	불필요한 복사·박싱 제거
6	락 경합	CPU 사용률은 낮은데 처리량이 안 오름	17단원의 락 범위 축소

4번은 자바 코드만으로도 쉽게 재현된다. 5만 건짜리 주문을 취급 품목 목록과 대조하는 코드다.

import java.util.*;

public class LookupBench {
    public static void main(String[] args) {
        int n = 50_000;
        List<String> skus = new ArrayList<>();
        for (int i = 0; i < n; i++) skus.add("SKU-" + i);
        List<String> orders = new ArrayList<>(skus);

        long t1 = System.nanoTime();
        int hit1 = 0;
        for (String o : orders) if (skus.contains(o)) hit1++;      // O(n^2)
        long listMs = (System.nanoTime() - t1) / 1_000_000;

        Set<String> index = new HashSet<>(skus);
        long t2 = System.nanoTime();
        int hit2 = 0;
        for (String o : orders) if (index.contains(o)) hit2++;     // O(n)
        long setMs = (System.nanoTime() - t2) / 1_000_000;

        System.out.println("List.contains : " + listMs + "ms (hit " + hit1 + ")");
        System.out.println("Set.contains  : " + setMs  + "ms (hit " + hit2 + ")");
    }
}

List.contains : 1898ms (hit 50000)
Set.contains  : 2ms (hit 50000)

900배다. 이 정도 차이는 JMH가 필요 없다. 복잡도가 다르면 대충 재도 보이고, 복잡도가 같으면 JMH가 필요하다는 것이 두 도구를 나누는 기준이다. 그리고 이 코드가 개발 환경에서는 아무 문제가 없다는 점이 중요하다. 데이터 500건이면 두 방식 다 1ms 미만이다. 성능 테스트는 운영 규모의 데이터로 해야 한다.

4. 어디를 볼지 모를 때 — 프로파일러

JMH는 후보가 정해진 뒤에 쓰는 도구다. 후보를 찾을 때는 프로파일러를 쓴다. JDK에 기본 포함된 JFR(Java Flight Recorder)이 오버헤드 1% 수준이라 운영에서도 켤 수 있다.

# 60초간 기록
jcmd <pid> JFR.start name=prof settings=profile duration=60s filename=/tmp/prof.jfr

# 기동부터 기록하려면
java -XX:StartFlightRecording=duration=60s,filename=/tmp/prof.jfr -jar order-service.jar

생성된 .jfr 파일은 JDK Mission Control이나 IntelliJ로 연다. 볼 순서는 (1) Hot Methods — CPU를 쓰는 곳, (2) Allocation — 객체를 만드는 곳, (3) Java Blocking — 락에서 기다리는 곳, (4) Socket/File I/O — 밖에서 기다리는 곳 이다. 응답은 느린데 CPU가 한가하다면 (1)이 아니라 (3)(4)를 봐야 한다. 이 구분만 해도 헛다리 짚는 일이 크게 준다.

실무에서 자주 틀리는 것

1. 평균만 보고 판단한다

"평균 응답 200ms"는 대부분 아무 의미가 없다. 사용자가 불만을 갖는 것은 느린 쪽 5%이고, 그 5%가 평균에 묻힌다. 반드시 p95, p99 를 함께 본다. GC 정지, 커넥션 풀 대기, 캐시 미스는 전부 꼬리 지연으로만 나타나는 현상이다. 평균 200ms에 p99가 4초인 서비스와 평균 250ms에 p99가 400ms인 서비스라면 후자가 훨씬 좋은 서비스다.

2. 벤치마크 결과를 실서버 성능이라고 믿는다

마이크로벤치마크는 CPU 캐시에 데이터가 다 들어가 있고, 네트워크도 DB도 없고, 스레드도 하나다. 여기서 30% 빠른 코드가 실서버에서 0.1% 개선일 수 있다. 전체의 5%를 차지하는 부분을 두 배 빠르게 해도 전체는 2.5% 빨라진다. 개선 대상을 고를 때는 항상 "이게 전체의 몇 퍼센트인가"를 먼저 확인한다. 그 비중이 10% 미만이면 손대지 않는 편이 낫다.

3. 스트림과 for문 같은 것으로 다툰다

스트림은 요소당 수 나노초 정도의 오버헤드가 있다. 백만 건 이상을 도는 뜨거운 루프에서는 의미가 있지만, DB 100건을 가공하는 코드에서는 측정조차 안 된다. parallelStream() 은 더 조심해야 한다. 18단원에서 본 것처럼 ForkJoinPool.commonPool() 을 쓰므로 웹 요청 스레드에서 호출하면 서로를 굶기고, I/O가 섞이면 오히려 느려진다. 가독성을 희생하는 최적화는 측정으로 이득을 증명한 뒤에만 한다.

4. 캐시를 넣어 문제를 덮는다

느린 쿼리 앞에 캐시를 붙이면 즉시 빨라진다. 그리고 (a) 데이터 정합성 문제, (b) 19단원에서 본 상한 없는 캐시로 인한 OOM, (c) 캐시가 비었을 때 요청이 한꺼번에 DB로 몰리는 현상(cache stampede)이 새로 생긴다. 캐시는 정당한 도구지만 쿼리 자체를 고칠 수 있는데 캐시로 덮는 것은 부채다. 인덱스 하나로 해결될 일인지 먼저 확인한다.

5. 측정 환경을 통제하지 않는다

노트북에서 IDE, 브라우저, 도커를 켜 놓고 벤치마크를 돌리면 결과가 20%씩 흔들린다. 전원 관리 때문에 CPU 클럭이 오르내리기도 한다. 최소한 같은 조건에서 A와 B를 번갈아 여러 번 재고, 결과가 재현되는지 확인해야 한다. JMH의 @Fork(3) 이 이 문제를 어느 정도 완화해 준다.

스스로 확인하기

다음 JMH 결과로 "새 구현이 더 빠르다"고 말할 수 있는가?

oldImpl  avgt  5  120.4 ± 31.2  us/op
newImpl  avgt  5  103.7 ± 28.9  us/op

주문 목록 API 응답이 1,200ms다. JFR로 재 보니 CPU 사용률은 15%이고 Hot Methods 상위에 특별한 것이 없다. 다음에 볼 곳은 어디인가?
전체 응답 시간 1,000ms 중 JSON 직렬화가 40ms를 차지한다. 더 빠른 직렬화 라이브러리로 바꾸면 두 배 빨라진다고 한다. 이 작업의 기대 효과는?

정답

말할 수 없다. 두 결과의 신뢰 구간이 크게 겹친다(89.2~151.6 과 74.8~132.6). 차이 16.7µs 보다 오차 30µs가 더 크므로, 이 데이터로는 두 구현의 성능이 다르다는 근거가 없다. 할 일은 두 가지다. 하나는 @Fork 와 @Measurement 반복을 늘려 오차를 줄이는 것, 다른 하나는 왜 오차가 이렇게 큰지 보는 것이다. @Setup(Level.Invocation) 에서 무거운 작업을 하거나, 벤치마크 안에서 GC가 도는 경우가 흔한 원인이다.
CPU가 한가한데 느리다는 것은 기다리고 있다는 뜻이다. 순서대로 (1) DB — 쿼리 개수와 실행 시간. N+1이면 쿼리 수가 목록 건수에 비례해 늘어난다. 애플리케이션 로그에서 SQL 개수를 세는 것이 가장 빠르다. (2) 외부 API 호출 — 순차 호출이면 합산 시간이 그대로 응답 시간이다. (3) 커넥션 풀 대기 — 풀이 작으면 획득 대기가 생긴다. (4) 락 대기 — JFR의 Java Blocking 이벤트를 본다. Hot Methods만 보고 "최적화할 게 없다"고 결론 내리는 것이 가장 흔한 오진이다.
2% 개선, 즉 1,000ms → 980ms 다. 40ms의 절반인 20ms만 줄어들기 때문이다. 라이브러리 교체에는 호환성 검증, 직렬화 결과 차이(날짜 포맷, null 처리) 확인, 전 구간 회귀 테스트가 따라온다. 그 비용을 생각하면 2%는 대개 정당화되지 않는다. 나머지 960ms가 어디에 쓰이는지부터 찾는 것이 옳은 순서다. 다만 이 계산은 어디까지나 "전체가 1,000ms일 때"의 이야기다. 나머지를 100ms까지 줄인 뒤에는 같은 40ms가 전체의 40%가 되어 최우선 과제가 된다. 최적화 대상은 절대 시간이 아니라 그때그때의 비중으로 정한다.