CPU 프로파일러가 1순위로 지목한 코드를 고쳤더니 아무 일도 없었다

느린 요청을 만나면 프로파일러를 켠다. 그런데 요청이 160ms인데 CPU를 5ms만 쓴다면, CPU 프로파일러는 그 5ms 안에서 순위를 매겨 준다. 155ms에 대해서는 아무 말도 하지 않는다. 그리고 그 5ms의 1위가 155ms의 1위와 같으리라는 보장은 없다.

이 글은 그 보장이 실제로 없다는 것을 재고, 대신 무엇을 봐야 하는지를 재는 실험이다. 나머지 155ms를 보는 방법이 off-CPU 분석이다. Brendan Gregg는 이를 “off-CPU time is measured and studied, along with context such as stack traces”로 정의한다(Off-CPU Analysis). 스레드가 I/O, 락, 타이머 때문에 CPU 밖에서 기다린 시간을 스택과 함께 재는 일이다.

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

./scenarios/t6/run.sh serial 1

설계: 대기마다 다른 이벤트에 떨어지게 한다

엔드포인트 하나가 네 구간을 지난다.

구간	하는 일	남기는 것
CPU	SHA-256 1ms	아무 이벤트도 없음. CPU 프로파일에만 보인다
업스트림	100ms 블로킹 HTTP 호출	jdk.SocketRead
데이터베이스	커넥션 10개짜리 풀 뒤의 pg_sleep(0.05)	jdk.SocketRead, 풀이 밀리면 jdk.ThreadPark
공용 구간	모니터 뒤에서 2ms	jdk.JavaMonitorEnter

업스트림 호출과 DB 질의는 둘 다 jdk.SocketRead다. 이벤트 종류만 보면 구별되지 않는다. 그래서 귀속은 대기 아래 프레임으로 한다. callUpstream이 부른 소켓 읽기와 queryDb가 부른 소켓 읽기는 다른 항이다. 마찬가지로 park(스레드가 스스로 멈춰 깨워 주기를 기다리는 상태)는 여기서 HikariCP의 커넥션 bag을 기다리는 것이지만, 다른 코드에서는 다른 것을 기다린다. 이벤트 이름만으로 귀속하면 틀린다.

모드는 셋이고 각각 항을 하나씩 없앤다.

• serial: 네 구간을 순서대로
• concurrent: 서로 의존하지 않는 업스트림과 DB를 겹침
• fixed: 거기에 더해 공용 구간의 계산을 임계 구역(모니터를 쥔 채 실행하는 구간) 밖으로 빼고 변경만 안에 남김

앞의 두 모드가 요청 하나를 처리하는 모양은 이렇다.

flowchart TD
    subgraph serial
        S1["CPU 1ms"] --> S2["업스트림 100ms"] --> S3["DB pg_sleep 50ms"] --> S4["공용 구간 2ms"]
    end
    subgraph concurrent
        C1["CPU 1ms"] --> C2["업스트림 100ms"]
        C1 --> C3["DB pg_sleep 50ms"]
        C2 --> C4["공용 구간 2ms"]
        C3 --> C4
    end

세 모드를 둔 이유는 분해를 읽고 끝내지 않기 위해서다. 분해가 맞다면 어느 수정이 얼마나 듣는지 미리 맞힐 수 있어야 한다.

부하는 클라이언트 20개, 60초, closed model(클라이언트가 응답을 받아야 다음 요청을 보내는 방식)이다. 3회씩 돌린 중앙값을 적는다.

두 프로파일러가 같은 코드에 대해 다른 순위를 낸다

async-profiler를 같은 창에서 wall-clock 모드와 CPU 모드로 한 번씩 돌렸다. CPU 모드는 CPU 시간을 기준으로 스택을 모은다. wall-clock 모드는 “regardless of thread status: Running, Sleeping or Blocked”, 즉 상태와 무관하게 모든 스레드를 같은 주기로 샘플링한다(async-profiler v4.0 Profiling Modes). 비율은 핸들러 안 샘플 기준이다. 전체 프로파일 기준으로 하면 wall-clock이 같이 찍는 유휴 스레드에 희석된다.

프로파일	업스트림	데이터베이스	공용 구간	CPU
wall clock	65.4%	33.0%	1.1%	0.2%
cpu	8.3%	6.0%	56.2%	31.3%

같은 실행, 같은 창, 완전히 다른 1위다. CPU 프로파일러에게 이 서비스의 문제는 공용 구간이고, wall-clock 프로파일러에게는 업스트림이다.

둘 다 맞다. CPU 프로파일은 CPU를 정확히 잰다. 공용 구간은 실제로 이 핸들러가 CPU를 가장 많이 쓰는 곳이다. 다만 “어디서 CPU를 쓰는가”는 “요청이 어디서 시간을 쓰는가”와 다른 질문이다.

그래서 각각의 조언을 따라가 봤다

모드	rps	평균	p50	p99	요청당 CPU
serial	125.3	159.60	158.25	183.54	4.94
업스트림·DB 겹침	184.2	108.45	106.87	127.06	4.14
겹침 + 락 밖으로 계산	180.8	110.52	108.85	129.57	4.21

rps는 초당 처리한 요청 수이고, 시간은 ms다(p50과 p99는 백분위수).

CPU 프로파일러가 1순위로 지목한 것을 고친 결과가 세 번째 줄이다. 공용 구간의 모니터 대기를 완전히 없앴다(뒤 표에서 1.48 → 0.00ms). 평균은 108.45ms에서 110.52ms가 됐다. 개선이 없고, 런 간 편차 안이다.

wall-clock 프로파일러가 지목한 것을 고친 결과가 두 번째 줄이다. 평균 32% 감소, 처리량 47% 증가.

왜 그런지는 표가 말한다

요청당 밀리초, 핸들러 안에서 발생한 이벤트만 센다.

모드	업스트림	데이터베이스	공용 구간	합	평균	합/평균
serial	101.70	51.59	1.14	154.43	159.60	96.8%
겹침	101.50	51.28	1.48	154.29	108.45	142.3%
겹침 + 락 밖으로	103.15	51.97	0.00	155.20	110.52	140.4%

공용 구간은 159.60ms 중 1.14ms, 0.7%다. CPU 샘플의 56.2%를 차지하면서 지연의 0.7%다. 그래서 이 구간을 없애도 줄어들 수 있는 몫은 0.7%가 최대이고, 실제로 아무것도 줄지 않았다.

이 숫자들이 CPU 프로파일에서 그렇게 커 보인 이유는 단순하다. 공용 구간은 2ms를 CPU로 쓰고 CPU 구간은 1ms를 쓴다. 56.2 대 31.3, 비율 1.8 대 2 대 1이다. CPU 프로파일은 정확히 자기가 재는 것을 재고 있었다. 그것이 지연이 아닐 뿐이다.

분해가 개선의 크기를 미리 맞혔다

serial에서 업스트림 101.70ms와 DB 51.59ms가 순서대로 일어난다. 둘이 서로를 기다릴 이유가 없다. 그래서 겹치면 임계 경로(요청 지연을 결정하는 가장 긴 대기의 사슬)는 max(101.70, 51.59)에 CPU 약 5ms를 더한 값, 약 106.6ms가 되어야 한다.

측정값은 108.45ms다. 1.9ms 차이다.

나는 이 예측을 이 실험에서 가장 무게 있는 결과로 본다. 분해가 그럴듯해 보이는 것만으로는 그 분해를 믿을 근거가 되지 않는다. 아직 하지 않은 수정의 결과를 맞혀야 믿을 수 있다. 맞히지 못하는 분해는 사후 설명이다.

서로 다른 계측기 둘이 99.8%를 채운다

serial에서 측정된 대기가 평균의 96.8%다. 남은 3.2%는 CPU와 1ms 임계값 아래 대기와 스케줄링이어야 한다.

요청당 CPU를 따로 쟀다. process_cpu_time_ns_total 카운터의 증분을 그 사이에 처리한 요청 수로 나눈 값이고, JFR 이벤트 지속 시간과 아무 메커니즘도 공유하지 않는다. 4.94ms, 즉 3.1%다.

96.8 + 3.1 = 99.8%. 설명되지 않는 시간이 거의 남지 않는다. 계측기 두 개가 독립적으로 같은 결론에 도달할 때 비로소 표를 믿을 수 있다.

겹치는 순간 합계는 지연의 분해가 아니게 된다

위 표에서 겹침 모드의 합/평균이 142.3%다. 154.29ms의 대기를 108.45ms 요청에서 쟀다.

오류가 아니다. 업스트림 대기와 DB 대기가 서로 다른 스레드에서 동시에 일어난다. 그래서 대기의 지속 시간은 더해지지만 벽시계 시간은 더해지지 않는다. off-CPU 이벤트 지속 시간의 합은 스레드가 기다린 시간이다. 요청이 한 번이라도 분기하면 그 합은 더 이상 지연의 분해가 아니다.

이 표가 위험한 이유는 여전히 그럴듯해 보이기 때문이다. 108ms 요청에서 “154ms의 대기”를 읽고 그것을 줄일 계획을 세우게 된다. 임계 경로에 있는 대기만 클라이언트에 도달하는데, 분기 이후로는 프로파일이 어느 쪽이 임계 경로인지 말해 주지 않는다.

틀렸던 것 여섯 가지

1. CPU가 놀고 있지 않았다. 첫 시도는 요청마다 SHA-256을 5ms 태웠고 189rps에서 앱 컨테이너가 CPU 할당량 2개의 194.6%를 썼다. 유휴 CPU에 관한 시나리오가 포화된 CPU를 재고 있었고, 지연의 일부는 CPU 큐잉이었다. CPU 작업을 1ms로, 클라이언트를 20개로 줄였다.

2. 레코딩이 워밍업을 포함했다. -XX:StartFlightRecording은 JVM 시작부터 기록한다. 이벤트 총합은 워밍업을 포함하고 요청 수는 측정 창만 세니 예산이 평균의 103.7%가 됐다. 100%를 넘는 분해는 분해로 읽을 수 없다. 워밍업 뒤에 jcmd JFR.start로 시작하도록 바꿨고, 이미지에 설정 파일을 넣어 임계값 1ms를 유지했다.

3. 요청당 대기를 JVM 전체 총합에서 나눴다. jdk.ThreadPark 15,091건 중 핸들러 안은 4,665건이었고, jdk.ThreadSleep은 24건 100초인데 핸들러 안은 0건이었다. 첫 요약은 그것을 요청당 21.18ms의 sleep으로 적었다. 어떤 요청도 잔 적이 없다.

4. 순간값 게이지를 프로파일링 창으로 나눴다. process_cpu_usage의 “프로파일러 없음” 구간에 JIT 램프(JIT 컴파일이 진행되며 CPU를 더 쓰는 기동 초기 구간)가 들어가 1.4코어로 읽혔고, 정상 상태는 0.85코어 근처였다. 그대로 뒀으면 프로파일러가 공짜인 것처럼 보였을 것이다. 카운터 증분 방식으로 바꿨다.

5. docker stats가 머신의 모든 컨테이너를 찍는다. 무관한 컨테이너 12개가 표에 섞였고 그중 하나는 코어의 107%를 썼다. 이 스택과 나머지를 분리해 적는다.

6. JFR 샘플러를 끄는 정규식이 아무것도 안 바꾸고 성공했다. settings=profile은 실행 샘플러·네이티브 샘플러·할당 샘플러를 켜는데 이 시나리오는 그중 무엇도 읽지 않는다. 해당 설정에 control 속성이 붙어 있어서 패턴이 빗나갔다. 이 시나리오에서 패턴이 조용히 아무것도 매치하지 않은 것이 두 번째였다(첫 번째는 T4의 핀 귀속이다).

한계

• 커널까지 따라가지 못했다. 이 시나리오의 원래 계획은 eBPF(커널 안에서 검증된 작은 프로그램을 돌려 이벤트를 수집하는 기능)로 커널 안까지 보는 것이었다. 이 호스트에서는 불가능하다. Docker Desktop의 linuxkit VM은 perf_event_paranoid=2이고 perf도 bpftrace도 없으며 /sys/kernel/debug도 마운트하지 않는다. async-profiler의 wall-clock 모드가 되는 것은 perf 이벤트가 아니라 자체 타이머로 샘플링하기 때문이다. 여기의 모든 귀속은 JVM 경계에서 멈춘다. 소켓 읽기는 소켓 읽기로 귀속될 뿐 큐잉·시스템콜·네트워크로 쪼개지지 않는다.
• 컨테이너가 유휴하지는 않다. CPU 할당량의 약 45%를 쓴다. 이 실험이 지지하는 주장은 요청 단위다. 159.60ms 평균에 대해 CPU 4.94ms이지, 기계가 놀고 있다는 뜻이 아니다.
• 요청당 CPU 4.94ms 중 의도한 것은 3ms뿐이다. 나머지는 Spring MVC, 호출마다 새로 여는 업스트림 커넥션, JDBC, 그리고 계측기 자신이다. 더 쪼개지 않았다.
• 여기서 풀 대기는 거의 0이다. 클라이언트 20개에서 풀은 10개 중 6개만 쓰여 jdk.ThreadPark가 0.19ms다. 클라이언트 40개 스모크에서는 38.93ms였다. 풀 대기가 주제인 것은 T4 2부다.
• pg_sleep은 실제 질의가 아니다. 버퍼도 CPU도 락도 건드리지 않고 커넥션만 쥔다. 크기를 아는 대기일 뿐이다.
• wall-clock 샘플링의 비용을 분리하지 못했다. “프로파일러 없음” 창에 JIT 램프가 들어 있어 깨끗한 대조군이 아니고, 4.94ms 중 관측자 몫이 얼마인지는 모른다.
• 3회다. 재현된다고 말할 만큼이고 분포를 말할 만큼은 아니다.

정리

• 요청이 CPU를 거의 안 쓰면 CPU 프로파일러의 순위는 지연의 순위와 무관할 수 있다. 여기서는 1위가 서로 달랐다.
• CPU 샘플의 56.2%를 차지한 코드가 지연의 0.7%였다. 그것을 완전히 없앴더니 평균이 108.45 → 110.52ms였다.
• wall-clock 프로파일이 지목한 항을 고치자 평균 32% 감소, 처리량 47% 증가였다.
• 대기의 귀속은 이벤트 종류가 아니라 대기 아래 프레임으로 한다. 업스트림과 DB가 같은 jdk.SocketRead다.
• 분해를 믿으려면 아직 하지 않은 수정의 크기를 맞혀야 한다. 106.6ms 예측에 108.45ms 측정이었다.
• 메커니즘을 공유하지 않는 계측기 둘이 99.8%를 채울 때 표가 완성된다.
• 요청이 분기하면 off-CPU 합계는 지연의 분해가 아니다. 겹침 모드에서 합/평균이 142.3%였다.

참고

• spring-ops-lab — 원본은 reports/data/t6-*, 표는 reports/01-scenario-report.md, 집계는 scenarios/t6/aggregate.py
• 가상 스레드가 캐리어를 놓지 못할 때 — 같은 저장소의 T4
• SLASH 23 리뷰 - 프로파일러로 시스템 성능 향상시키기
• async-profiler
• async-profiler v4.0: Profiling Modes — wall-clock 모드가 스레드 상태와 무관하게 샘플링한다는 설명
• Brendan Gregg, Off-CPU Analysis — off-CPU 분석의 정의