“MySQL CPU 는 아니다”라는 한 줄

상품 조회 API 의 처리량 천장을 찾던 측정에서 병목 후보를 아래처럼 정리했습니다.

후보판정근거
product-service CPU아니다천장 상태에서 354~690m / 3000m
MySQL CPU아니다207~356m
Hikari 풀 10아니다maximum-pool-size=50 으로 올려도 322.9 rps, 개선 없음

(측정 기록에서 발췌)

세 행 모두 숫자가 붙어 있습니다. 애플리케이션 CPU 는 한도의 4분의 1에도 못 미쳤고 MySQL 은 0.4코어를 넘지 않았습니다. 커넥션 풀은 다섯 배로 늘렸는데 처리량이 오히려 조금 줄었습니다. 이 표를 근거로 “2차 병목은 CPU 도 커넥션 풀도 아니다. MySQL 내부가 남았다”라고 결론 내렸고, 다음 측정의 1순위를 InnoDB wait event 같은 DB 내부 계측으로 잡았습니다.

이 글에서는 그 결론의 근거를 다시 따져 봅니다. “아니다”나 “0건”이라는 관찰은 실제로 무엇을 배제했을까요? 이 질문을 두 곳에 적용합니다. 하나는 컨테이너에 올린 MySQL 의 CPU 한도이고, 다른 하나는 재고 차감에 걸린 Redis 분산 락입니다. 마지막으로 그 과정에서 함께 드러난 캐시와 트랜잭션 범위 문제를 다룹니다.

측정한 시스템

PeekCart 는 주문, 상품, 결제, 알림 서비스와 게이트웨이로 이루어진 학습용 이커머스 백엔드입니다. 이 측정은 상품 서비스(Spring Boot, MySQL 8.0, Redis 캐시)를 GKE 에 올려 진행했습니다.

  • 노드는 e2-standard-4 2대였습니다. load generator(k6)는 앱과 CPU 를 다투지 않도록 클러스터 밖 e2-medium VM 에 따로 두었습니다.
  • 상품 100개를 넣고 상품마다 재고를 100,000 으로 두었습니다.
  • 상품 상세(/api/v1/products/{id})와 목록(/api/v1/products)을 각각 캐시를 켜고 끈 채 400 VU(가상 사용자)로 포화시켰습니다.
  • 애플리케이션 CPU 가 먼저 막히지 않도록 product-service 의 CPU 한도를 기본값 1000m 에서 3000m 으로 올렸습니다.
엔드포인트캐시 OFF캐시 ON
상세378.1 rps463.6 rps
목록380.0 rps767.1 rps

캐시를 끈 상세 조회에서 VU 를 100, 200, 400 으로 올리는 동안 처리량은 285.8, 353.9, 378.1 rps 로 거의 멈췄고, 지연은 348ms, 559ms, 1.03s 로 늘었습니다. 이 램프는 설정을 되돌리느라 Pod 를 다시 띄운 직후 워밍업 없이 돌렸습니다. 첫 단계인 50 VU 는 요청 50건만 남아 버렸고, 100 VU 값이 워밍업 뒤에 잰 50 VU 런(358.5 rps)보다 낮은 것도 이 때문으로 보입니다(추정). 그리고 하는 일이 다른 두 엔드포인트가 캐시를 끄자 거의 같은 높이(378.1 rps 와 380.0 rps)에서 멈췄습니다. 두 경로가 함께 쓰는 자원 하나가 천장을 정하고 있다고 봤습니다. 위 후보 표는 그 자원을 찾으려고 만든 것입니다.

이 측정은 원래 서비스를 나누기 전 단일 Pod 환경에서 잰 캐시 효과가 2.31배로 목표 3배에 못 미친 이유를 찾던 것이었습니다. 캐시 배수는 CPU 여유에 따라 1.23배에서 2.39배 사이로 움직였고, 3배는 조건 없이 정한 숫자였다는 결론이 먼저 나왔습니다. 남은 질문이 “캐시를 끈 두 경로를 같은 높이에 묶어 둔 것은 무엇인가”였습니다.

표의 MySQL 행에는 한도가 빠져 있습니다. MySQL 컨테이너는 Kubernetes 매니페스트에서 requests.cpu: 250m, limits.cpu: 500m 으로 돌고 있었습니다. 노트북의 minikube(4코어) 환경을 기준으로 처음 정한 뒤 다시 보지 않은 값입니다. 207~356m 는 500m 의 절반 안팎이니 한도 아래였던 것은 맞습니다.

재고 경로의 분산 락

주문 서비스는 주문을 저장하면서 같은 트랜잭션으로 outbox 테이블에 이벤트를 남기고, 스케줄러가 그 이벤트를 Kafka 로 발행합니다. 상품 서비스의 Kafka consumer 가 이벤트를 받아 재고를 예약(차감)합니다. 이 비동기 흐름을 이 글에서는 예약 saga 라고 부릅니다.

재고 예약에는 Redis 분산 락과 JPA 낙관적 락(@Version)이 함께 걸려 있었습니다. 분산 락은 두 층입니다. Redisson 호출을 감싼 DistributedLockManager(이 글에서는 “락 관리자”)가 락을 얻고 풀고, 그 위의 InventoryLockFacade(“락 파사드”)가 락 획득, 트랜잭션 시작, 커밋, 락 해제 순서를 보장하려고 만든 클래스입니다. 여러 인스턴스가 같은 상품 재고를 동시에 고치려 하면 락 파사드가 먼저 순서대로 처리하게 만들고, 락 관리자는 Redis 가 죽으면 락 없이 진행해 @Version 이 최후 방어선이 되는 설계였습니다.

MySQL CPU 한도: 관찰만으로 내린 “아니다”

첫 번째 질문은 처음 표의 MySQL 행입니다.

세 “아니다”는 근거의 종류가 달랐습니다

기존 계획은 MySQL 안을 들여다보는 것이었습니다. CPU 와 커넥션 풀이 빠졌으니 다음은 DB 내부라고 봤습니다. SHOW ENGINE INNODB STATUS 로 row lock wait 와 buffer pool hit 를 보고, performance_schema 에서 wait event 상위 항목을 뽑고, 디스크 읽기 비율을 재서 가설에 순위를 매기는 계획이었습니다.

그 전에 후보 표의 세 “아니다”를 근거의 종류로 다시 나눠 볼 수 있습니다.

후보조건을 바꿔 봤나근거의 종류
product-service CPU1000m 에서 3000m 으로 올렸고, 캐시를 켠 목록이 325 rps 에서 715 rps 로 늘었다바꿔 보고 결과를 봤다
Hikari 풀10 에서 50 으로 올렸고, 처리량이 늘지 않았다바꿔 보고 결과를 봤다
MySQL CPU바꾼 적이 없다. 부하 중 사용량이 한도 아래로 보였다관찰만 했다

앞의 두 행은 실험입니다. 원인 후보를 직접 움직였고 처리량이 따라 움직이는지 봤습니다. 세 번째 행은 관찰입니다. MySQL 의 CPU 한도는 그 세션 내내 500m 그대로였습니다. 측정용 Kustomize overlay 의 patches 는 product-service 하나에만 걸려 있었고, product-service 의 CPU 한도와 Hikari 풀 크기도 세션 중에 직접 바꿨습니다. MySQL 매니페스트는 아무도 건드리지 않았습니다.

관찰만으로 원인을 배제하려면 관찰한 숫자가 “한도에 막혔다면 이렇게 보였을 것”이라는 모습과 분명히 달라야 합니다. CPU 사용량이 한도 아래라는 숫자가 그 조건을 채우는지는 그때 따져 보지 않았습니다. 그래서 다음 측정의 1순위가 InnoDB 내부에서 MySQL 자신의 CPU 한도로 바뀌었습니다. 이 정정은 측정을 다시 돌리기 전, 다음 세션을 준비하며 설정 파일을 열어 보다가 나왔습니다.

측정 방식은 이렇게 정했습니다.

  1. 조건을 하나만 움직입니다. MySQL limits.cpu 를 바꿀 수 있는 자리를 측정용 설정에 만들되 기본값은 이전 세션과 같은 500m 으로 둡니다. 처음부터 올려 두면 이전 천장을 같은 조건에서 다시 볼 수 없기 때문입니다.
  2. 움직인 뒤 되돌립니다. 천장이 올라간 것을 한 번 본 것만으로는 그사이의 다른 변화(Pod 재시작, 노드 상태, 캐시 워밍업 정도)와 구별되지 않습니다. 원래 값으로 돌렸을 때 천장도 원래 높이로 내려와야 그 설정의 효과라고 말할 수 있습니다.

주문 경로는 게이트웨이를 거쳐야 해서 rate limiter 도 미리 확인했습니다. 다른 측정에서 요청의 60% 가 429 로 실패해 지연 수치를 쓸 수 없었던 적이 있었기 때문입니다. 한도의 키가 IP 가 아닌 사용자(초당 40건)여서 사용자 수를 나눠 한도 아래로 부하를 걸었고, 429 가 한 건이라도 나오면 실행을 실패로 처리했습니다. 사용자 한 명으로 한도를 넘겨 429 가 실제로 나오는 것(5,152건 중 4,532건)도 먼저 확인했습니다. 그래야 본 측정의 “429 = 0” 이 한도 아래에서 쟀다는 증거가 됩니다.

MySQL 한도를 올리자 천장이 따라 올라갔습니다

주문 생성 경로에서 같은 부하(k6 로 초당 300회 주문 시도를 목표로, 사용자 200명 고정, 2분)를 두 번 걸고 MySQL limits.cpu 만 바꿨습니다.

MySQL 한도주문 생성응답 p95측정 직후 MySQL CPU
500m54.0 건/초2.38s498m
2000m158.6 건/초879ms1,259m

(측정 기록에서 발췌)

표의 주문 생성 값은 k6 의 setup(사용자 200명 로그인, 1분 가까이)까지 포함한 전체 실행 시간으로 나눈 값입니다. 부하를 건 2분만으로 나누면 500m 은 약 80건/초, 2000m 은 약 231건/초이고 처리량은 2.89배가 됐습니다. p95 는 3분의 1 남짓으로 줄었습니다. 두 런 모두 429 와 요청 실패는 0건이었습니다.

2000m 런 직후 kubectl top 을 한 번 찍었을 때 MySQL 은 1,259m 로 한도 아래였고, order-service 가 2000m 중 1,784m 를, 게이트웨이 두 Pod 가 각각 1,097m 와 1,228m 를 쓰고 있었습니다. 이 세션에서는 스로틀 카운터를 읽지 않았습니다. 다음 천장이 다른 서비스로 옮겨 갔다는 것은 이 한 번의 샘플에 기댄 추정입니다.

이 결과에는 한계가 있습니다.

  • 목표 초당 300회는 넣지 못했습니다. 반복 한 번이 장바구니 담기와 주문 생성을 한 번씩 부르는데, 500m 에서는 응답이 느려 반복 하나가 약 2.5초 걸렸고 사용자 200명으로는 초당 80회 남짓이 상한이었습니다. 2000m 에서는 응답이 빨라져 그 상한도 올라갔습니다. 두 결과 모두 200명으로 포화시킨 결과입니다.
  • 이 세션에서는 한도를 500m 로 되돌려 천장이 다시 내려오는지 보지 못했습니다. 되돌림은 뒤에서 읽기 경로를 다시 잴 때 했습니다.
  • 498m 는 부하 직후 kubectl top pods 를 한 번 찍은 값입니다.

”207~356m” 는 50 VU 런의 샘플이었습니다

같은 도구가 한 번은 “한도 아래”를, 한 번은 “한도에 닿음”을 보여 줬습니다. 그래서 처음 표의 MySQL 행이 어떻게 만들어졌는지 측정 세션 기록을 다시 열었습니다.

그 숫자는 400 VU 로 천장을 확인하기 전, 50 VU 조건(상세, 캐시 OFF)으로 70초를 돌리며 kubectl top pod 를 10초 간격으로 다섯 번 찍은 값이었고, 출력은 356m, 356m, 207m, 207m, 207m 였습니다. 바로 앞에서 같은 조건으로 잰 처리량은 358.5 rps 였습니다. 같은 세션 앞부분에서도 63m 이 네 번 연속 찍혔습니다. 10초마다 물어도 값은 그보다 드물게 바뀌었습니다.

같은 세션 바로 뒤에 50 VU 값들은 동시성에 막혀 천장에 닿지 못한 값이라고 보고 400 VU 로 다시 쟀습니다. 그런데 후보 표의 CPU 행은 다시 재지 않았습니다. 커넥션 풀 행도 같은 50 VU 조건(풀 10 에서 358.5 rps, 풀 50 에서 322.9 rps)에서 나온 값입니다. 클러스터에서 MySQL 행을 틀리게 만든 직접 원인은 천장에 닿지 않은 부하에서 잰 샘플을 그대로 쓴 것입니다. 그 세션의 MySQL 스로틀은 재지 않았습니다.

평균 사용량이 스로틀을 가린다는 것은 그 위에 겹친 두 번째 문제입니다. 컨테이너의 CPU 한도는 100ms 단위(period)마다 쓸 수 있는 CPU 시간(quota)으로 적용됩니다.

아래 장면의 두 수치는 출처가 다릅니다. 위쪽은 클러스터에서 찍힌 kubectl top 샘플이고, 아래쪽은 측정이 끝난 뒤 로컬 Docker 에서 따로 만든 재현입니다. 평균 사용량이 한도의 3분의 1 남짓일 때, 그 40초 동안 MySQL 이 한도에 막힌 적이 있었을지 먼저 예상해 보세요.

평균이 한도 아래면, 한도에 막힌 적이 없을까요?

평균 사용량은 한도 0.5코어의 3분의 1 남짓입니다. 이 40초 동안 MySQL 이 한도에 막힌 period 가 있었을지 예상한 뒤, 같은 구간을 period 별로 펼쳐 보세요.

평균 사용량 0.18코어 / 한도 0.5코어 스로틀된 period ? / 393 throttled_usec 합 ?

위쪽 "클러스터 기록"과 아래쪽 "로컬 재현"은 조건이 다른 별개의 측정이라 한 축에 놓지 않았습니다. 로컬 재현은 Docker --cpus 0.5 의 MySQL 8.0.46 에 세션 4개가 조회 3,000회 후 1초씩 쉬는 버스트 부하를 40초 동안 건 결과이며, 측정한 것은 합계 카운터(393 period 중 107 period 스로틀, throttled_usec 합 23.2초)뿐입니다. period 별 칸에서 어느 칸이 스로틀됐는지의 배치는 원리를 보이기 위한 도식이고, 실제 period 별 시계열은 기록하지 않았습니다.

평균 사용량은 CFS 스로틀을 가립니다

kubectl top 은 metrics-server 가 일정 주기로 모은 값을 돌려줍니다. metrics-server 는 기본으로 15초마다 지표를 수집하는 autoscaling 용 도구라, 정확한 자원 사용량을 재는 데는 맞지 않습니다. 이 환경(GKE)의 실제 수집 주기는 확인하지 않았습니다.

평균 사용량이라는 숫자에도 문제가 있습니다. 컨테이너의 CPU 한도는 Linux CFS 의 bandwidth control로 구현됩니다. 기본 100ms period 마다 그룹이 쓸 수 있는 CPU 시간(quota)이 정해지고, period 안에서 quota 를 다 쓰면 다음 period 에 quota 가 다시 채워질 때까지 그룹의 스레드는 실행되지 못합니다. 이것을 스로틀(throttle)이라고 부릅니다. 여러 스레드가 동시에 몰리면 quota 는 period 초반에 바닥나고 나머지 시간은 기다림이 됩니다. 수십 초를 평균 낸 사용량에는 이 기다림이 보이지 않습니다. 기다린 횟수와 시간은 cgroup 의 cpu.stat(nr_throttled, throttled_usec)에 따로 쌓입니다.

장면 아래쪽의 로컬 재현 조건은 이렇습니다. MySQL 8.0.46 컨테이너에서 저장 프로시저로 PK 조회를 반복하는 버스트 부하를 만들었고, 세션 4개가 조회 3,000회 후 1초씩 쉬게 했습니다. --cpus 0.5 에서 40초 평균 사용량은 0.18코어였지만, cpu.stat 은 393개 period 중 **107개(27%)**에서 스로틀을 기록했습니다. --cpus 2.0 에 더 센 버스트를 주자 평균 0.96코어에 period 의 25% 가 스로틀이었습니다(역시 로컬 재현). 이 로컬 수치는 클러스터 측정과 조건이 달라 직접 비교할 수 없습니다. 보여 주는 것은 “평균이 한도 아래”가 “한도에 막히지 않았다”를 뜻하지 않는다는 원리까지입니다.

”아니다”를 쉽게 내놓지 못하게 바꾼 측정 설계

읽기 경로의 공통 천장이 MySQL CPU 한도인지 다시 쟀습니다. 같은 세션에서 재고 캐시의 효과도 함께 쟀는데 그 결과는 캐시 경계를 다루는 뒷부분에서 봅니다. 이번에는 “아니다”를 쉽게 내놓지 못하도록 측정 자체를 바꿨습니다.

  • 설정 하나를 올렸다가 되돌립니다. MySQL 한도를 500m(A), 2000m(B), 다시 500m(A2) 순서로 움직이고, A2 가 A 의 ±10% 안으로 돌아오지 않으면 CPU 에 대한 결론을 쓰지 않기로 미리 정했습니다. MySQL 은 한도를 바꿀 때마다 Pod 가 새로 뜨고 buffer pool 이 식기 때문에 한 방향으로만 바꿔 봐서는 CPU 효과와 재시작 효과를 가를 수 없습니다. 되돌림 블록은 계획을 다듬는 과정에서 이 이유로 추가했습니다.
  • 평균 사용량 대신 스로틀 카운터를 봅니다. 각 런 전후로 product-service 와 MySQL 컨테이너의 cpu.stat(usage_usec, throttled_usec)을 읽어 차이를 남겼습니다. 측정을 위해 Prometheus 스택을 새로 들이는 방법은 측정 대상 시스템을 바꾸게 되므로 쓰지 않았습니다.
  • 같은 세션 안에서 비교합니다. 노드, GKE 버전, 부하 도구 버전이 이전 세션과 같다고 보장할 수 없어서 효과는 같은 세션 안에서 상세와 목록을 나란히 잰 비율(상세 ON 처리량 / 목록 ON 처리량)로 보기로 미리 정했습니다.
  • 셀마다 세 번 돌려 중앙값을 씁니다. 블록 A 와 B 는 상세와 목록에 캐시 ON 과 OFF 를 조합한 네 칸, A2 는 캐시 OFF 두 칸이라 모두 30번입니다.
  • 오염된 런을 드러냅니다. 런 전후로 Pod UID 를 대조해 도중에 재시작된 런은 버리고, 캐시를 켠 런 앞에서는 Redis 를 명령 하나로 비운 뒤 정해진 키만 채우는 워밍업을 측정 구간 밖에서 돌렸습니다.
  • 통과 기준을 미리 적습니다. 이전 세션 수치의 재현(±10%), 대조군(이번에 코드를 바꾸지 않은 캐시 ON 목록이 이전 세션 값의 ±15% 안에 드는지), 되돌림(±10%)입니다. 기준을 넘긴 항목은 통과로 적지 않기로 했습니다.

상세는 한도를 따라 돌아왔고, 목록은 기준을 넘었습니다

읽기 경로를 다시 쟀습니다. 조건은 GKE e2-standard-4 2대, 클러스터 밖 load generator(k6 v2.2.0), MySQL 8.0.46 과 Redis 7.2, product-service CPU 한도 3000m, 400 VU 로 60초, 상품 100개, 셀마다 3회 중앙값, 모두 30런입니다. 이 세션의 product-service 는 상세 조회의 재고까지 5초 TTL 캐시에 올린 버전이라, 캐시 ON 상세 값은 이전 세션보다 크게 나옵니다. 재고 캐시는 뒷부분에서 다룹니다.

블록MySQL 한도엔드포인트캐시rpsMySQL 스로틀(60초 런당 누적)
A500m상세OFF393.4147.6초
A500m상세ON906.6133.2초
A500m목록OFF367.6123.6초
A500m목록ON894.9103.0초
B2000m상세OFF903.80.1초
B2000m상세ON1,815.00.0초
B2000m목록OFF1,406.45.1초
B2000m목록ON2,249.20.0초
A2500m 복귀상세OFF392.6105.0초
A2500m 복귀목록OFF409.9113.1초

(측정 기록에서 발췌)

캐시를 끈 상세 조회는 393.4 rps 에서 903.8 rps 로 올랐다가 392.6 rps 로 돌아왔습니다. 되돌린 값이 처음 값과 0.2% 차이라 재시작이나 시간에 따른 변화와 구별되는 MySQL CPU 한도의 효과라고 말할 수 있습니다. 2000m 의 처리량은 500m 의 2.30배였습니다.

같은 셀에서 MySQL 스로틀은 147.6초에서 0.1초로 사라졌다가 되돌리자 다시 나타났습니다. 이전 측정이 “MySQL 내부”로 남겼던 공통 천장은 MySQL 자신의 CPU 한도였습니다. 주문 경로에서 본 결론이 읽기 경로에서도 같았습니다.

스로틀 열의 숫자가 60초를 넘는 이유는 이렇습니다. throttled_usec 는 CPU 마다 그 그룹의 runqueue 가 스로틀돼 있던 시간을 더한 값이라, 여러 CPU 에서 동시에 스로틀되면 wall-clock 시간을 넘습니다. 같은 런의 원본 카운터에서 MySQL 이 실제로 쓴 CPU 시간을 계산하면 500m 블록은 모든 런이 60초 동안 약 2931초, 즉 한도와 거의 같은 0.490.51코어였습니다. 이번에는 평균 사용량도 한도에 붙어 있었습니다. 다만 그것만으로는 “한도에 닿았다”와 “우연히 한도 근처였다”를 구별하기 어렵고 스로틀 카운터를 봐야 둘을 가를 수 있습니다.

목록은 결론이 갈렸습니다. 367.6 rps 에서 1,406.4 rps 로 올랐다가 409.9 rps 로 내려왔습니다. 되돌린 값이 처음과 11.5% 달라 미리 정한 ±10% 기준을 넘었습니다. 2000m 블록의 세 런도 782.7, 1,406.4, 1,408.4 rps 로 첫 런만 낮았습니다. 한도를 바꿀 때마다 MySQL Pod 가 새로 뜨면서 buffer pool 이 식는데, 블록 시작 전에 돌린 워밍업(전 상품 조회 3회)이 목록 경로까지는 충분히 데우지 못한 것으로 보입니다. 효과 크기(약 3.8배)가 오차보다 훨씬 커서 방향은 분명하지만, 목록의 배수는 확정값으로 적지 않았습니다.

한도를 되돌리면 천장도 돌아올까요?

MySQL CPU 한도를 한 단계씩 바꿔 보세요. 막대는 처리량(rps), 아래 띠는 같은 셀 3회 런의 MySQL 스로틀 누적 시간 중앙값입니다. 엔드포인트와 캐시를 바꿔 같은 왕복을 다시 볼 수 있습니다.

한도

GKE 클러스터에서 잰 셀별 3회 중앙값(400 VU, 60초)입니다. 세 번째 블록(500m 복귀)은 캐시 OFF 두 칸만 쟀습니다. 스로틀은 60초 런당 누적값이며 CPU 마다 스로틀된 시간을 더한 값이라 60초를 넘을 수 있습니다. 500m 과 2000m 사이의 한도는 재지 않았으므로 막대를 선으로 잇지 않았습니다.

이 세션에서는 측정 장치도 결과를 오염시킬 뻔했습니다. 배포 직후 Pod 목록의 첫 항목을 골랐더니 종료 중인 이전 Pod 여서 캐시 ON 목록 세 런이 전부 “런 도중 재시작”으로 걸러져 대조군 칸이 통째로 사라질 뻔했습니다. 런 전후 Pod UID 대조가 설계대로 동작해 오염된 런이 조용히 섞이지 않고 드러났고, 실행 중인 Pod 만 고르도록(--field-selector=status.phase=Running) 고쳤습니다. Kubernetes 가 2000m 을 2 로 정규화해 돌려주는 것을 문자열로 비교했다가 블록 B 가 중단된 일도 있어 millicore 로 환산해 비교하도록 고쳤습니다.

천장은 다른 자리로 옮겨 갔습니다

천장 하나를 걷어 내자 다음 천장이 보였습니다.

  • 주문 경로에서는 MySQL 2000m 에서 order-service(2000m 중 1,784m)와 게이트웨이 쪽으로 옮겨 간 것으로 보였습니다. 근거는 런 직후 kubectl top 한 번입니다.
  • 읽기 경로의 캐시 OFF 상세는 904 rps 에서 다시 멈췄는데, 그 셀의 MySQL 스로틀은 0.1초였습니다. 이번에는 MySQL CPU 한도가 원인이 아닙니다. 같은 셀에서 product-service 가 런마다 21~33초 스로틀됐으므로 3000m 한도가 후보이지만, 원인은 분리하지 않았습니다.
  • 캐시를 켜 DB 를 거의 쓰지 않는 경로도 MySQL 한도에 반응했습니다. 목록 ON 은 894.9 rps 에서 2,249.2 rps 로 올랐고 이 셀의 캐시 miss 는 0 이었습니다. 이 현상은 캐시 경계를 다루는 뒷부분에서 다시 봅니다.

비동기 경로의 천장과 스케줄러 스레드 하나

주문 경로를 잰 세션에서는 비동기 경로도 함께 봤습니다. 주문을 받은 뒤 재고를 예약하는 비동기 경로(saga)는 MySQL 한도를 4배로 올려도 초당 14.3건에서 16.3건으로 14% 늘었을 뿐입니다. 이 경로의 병목 위치는 두 숫자로 좁혔습니다.

  • Kafka consumer lag 이 3개 파티션 모두 0 이었습니다.
  • 예약 건수가 outbox 의 PUBLISHED 건수와 정확히 같았습니다(3,300 = 3,300).

consumer 는 발행되는 족족 처리하고 있었고 일감이 모자란 쪽이 consumer 였습니다. 발행 쪽은 outbox 를 5초마다 100건씩 꺼내는 폴링이라 이론 상한이 초당 20건이었습니다. 측정을 위해 0.5초마다 500건으로 완화하자 초당 77.3건이 됐지만 그 위에 새 천장이 또 남았습니다. 이벤트당 약 13ms 가 걸리는 것이 이벤트를 하나씩 보내고 응답을 기다리는 동기 발행과 맞아떨어졌지만, 그 세션에서 분리하지는 못했습니다.

측정 도중에는 발행률이 아예 0 이 되는 구간이 있었습니다.

orderOutboxPollingJob       locked_at 12:16:57.454  →  이후 실행 기록 없음
orderReservationTimeoutJob  locked_at 12:17:09.332  lock_until 12:20:14.129   (185초 실행)
orderOutboxPollingJob       locked_at 12:20:27.861  ← 형제 잡 해제 13초 후 재개

PUBLISHED: 그 구간 내내 5,500 고정 → 재개 즉시 6,717

(측정 기록에서 발췌)

스케줄러 스레드는 scheduling-1 하나뿐이었습니다. Spring Boot 에서 @Scheduled 의 기본 스레드 풀 크기는 1이고, 이 프로젝트는 그 값을 바꾼 적이 없었습니다. 그래서 주문 만료 잡이 185초 동안 스레드를 쓰는 사이 같은 스레드를 기다리던 발행 잡은 한 번도 돌지 못했습니다. 백로그가 쌓이면 만료 잡이 길어지고, 그동안 발행이 멈춰 백로그가 더 쌓입니다. 이 순환은 부하가 있을 때만 드러납니다.

스케줄러 풀은 spring.task.scheduling.pool.size 를 4로 정해 주문, 상품, 결제, 알림 네 서비스에 넣었습니다. 잡 수와 상관없이 동시 실행 상한으로 정한 값입니다. 잡이 대부분 DB 폴링과 발행 같은 블로킹 I/O 라 너무 키우면 병목이 커넥션 풀 경합으로 옮겨 갑니다. 같은 잡이 여러 Pod 에서 동시에 도는 것은 원래대로 ShedLock 이 막습니다. 고치기 전에 스레드 starvation 을 재현하는 테스트를 먼저 실패시켜 본 뒤 설정을 넣어 통과시켰습니다.

“MySQL 내부가 남았다”로 정리했던 것은 실제로 세 층이었습니다. 동기 경로에는 MySQL 의 CPU 한도, 비동기 경로에는 발행 폴링 설정, 발행이 계속 도는지에는 스케줄러 스레드 하나가 걸려 있었습니다. 셋 중 MySQL 내부(InnoDB 대기, 디스크)에 있던 것은 없었습니다. InnoDB 내부 계측은 이 세션에서 실행하지 않았습니다.

기본 한도는 2000m 으로, requests 는 그대로

측정 두 번(주문 경로, 읽기 경로)에서 천장은 모두 MySQL CPU 한도였습니다. 그래서 모든 환경이 물려받는 기본 매니페스트의 MySQL limits.cpu 를 2000m 으로 올렸습니다. 500m 과 2000m 사이의 값은 재지 않았으므로 실제로 잰 2000m 을 골랐습니다. requests.cpu 는 250m 그대로 두었습니다. 되돌림 실험이 움직인 것은 limits 하나였고, Pod 배치에 쓰이는 requests 를 올리는 비용은 노드 단위 CPU 경합을 재야 따질 수 있는데 그 경합은 재지 않았기 때문입니다. 그 대가로 실사용 최대 1,259m 중 requests 를 넘는 1,000m 남짓은 보장되지 않는 버스트로 남아, 노드가 바쁠 때 먼저 깎입니다.

이 변경 뒤에는 새 측정을 하지 않았고, overlay 8개를 렌더해 기본값을 물려받는 것만 2000m 으로 바뀌고 requests 는 그대로인지 확인했습니다.

이 검증에서 계획의 전제 하나가 틀린 것으로 드러났습니다. 기본값을 물려받는 overlay 는 계획이 센 7개보다 적은 5개였습니다. 주문 경로 측정용 overlay 는 500m 을 직접 지정하고 있었는데, 기본값도 500m 이어서 렌더 결과가 같았고 계획은 그것을 상속으로 봤습니다. 값이 같을 때는 상속과 명시를 렌더 결과로 구별할 수 없습니다. 기본값을 바꾸자 500m 에 남은 쪽이 직접 적은 쪽이었고, 기본값에서 limits 를 지워 보는 식으로 값을 일부러 다르게 만들어서 둘을 다시 확인했습니다.

2000m 기본값을 실제 클러스터에 적용한 적은 아직 없습니다. 적용하면 MySQL Pod 가 Recreate 전략으로 다시 뜨면서 buffer pool 이 식습니다. 2000m 측정용 overlay 는 이제 기본값과 같아졌지만, 목록 배수를 다시 잴 때 필요한 대조 쌍이라 지우지 않았습니다.

재고 분산 락: 원인을 구별하지 못한 “0건”

두 번째 질문은 재고 예약 경로의 “락 획득 실패 0건”입니다.

재고 경로는 코드를 먼저 읽었습니다

주문 경로 측정을 준비하며 재고 경로는 측정 전에 코드부터 읽었습니다. 읽고 나서 두 가지 이유로 측정 계획을 바꿨습니다.

하나는 잴 대상이 이미 옮겨 가 있었다는 것입니다. 분산 락이 병목일 수 있다고 처음 의심한 것은 서비스를 나누기 전이었습니다. 그때는 주문 생성 요청이 그 자리에서 재고를 차감했고, “주문 요청이 Redis 락 대기에서 timeout 된다”가 의심 대상이었습니다. 서비스를 나누면서 주문 생성은 주문을 저장하고 order.created 이벤트를 발행하는 데서 끝나게 됐습니다. 재고 차감은 상품 서비스의 Kafka consumer 가 이벤트를 받아 처리합니다. 락 실패는 이제 consumer 예외, 재시도, DLQ 순서로 이어지고, HTTP 응답에는 드러나지 않습니다. 그래서 볼 지표를 응답 p95 에서 consumer lag, 재시도, DLQ 유입, 낙관적 락 충돌 수로 바꿨습니다.

다른 하나는 락 파사드가 보장하려던 순서가 그 호출 위치에서는 지켜지지 않는다는 것입니다. consumer 메서드에 @Transactional 이 붙어 있고, 재고를 바꾸는 InventoryService 는 기본 전파인 REQUIRED 입니다. REQUIRED 는 이미 열린 트랜잭션이 있으면 새로 열지 않고 그 트랜잭션에 참여합니다. 락 파사드는 consumer 의 트랜잭션 안에서 불리므로 파사드의 finally { unlock } 은 커밋보다 먼저 실행됩니다.

이 단계에서는 고치지 않고 측정으로 드러내기로 했습니다. 결과를 읽는 기준도 미리 정했습니다. 락이 커밋까지 유지된다면 낙관적 락 충돌은 드물어야 합니다. 락 획득 실패는 거의 없는데 낙관적 락 충돌이 의미 있게 나오면, 코드에서 읽은 대로 락이 커밋 전에 풀린다는 것을 실행 중에도 확인할 수 있습니다.

락 획득 실패는 0, 낙관적 락 충돌은 7

재고 경로의 측정에서는 처음에 아무것도 나오지 않았습니다. 전 주문을 상품 하나에 몰아 2,977건을 넣었는데 락 획득 실패 0, 낙관적 락 충돌 0, DLQ 0 이었습니다.

이 0 은 구성에서 나온 숫자였습니다. product-service 는 1개였고 consumer concurrency 설정이 없어 기본값 1이었습니다. 재고 예약을 처리하는 스레드가 시스템 전체에 하나뿐이니 락을 두고 다툴 상대가 없었습니다. 부하를 얼마나 올려도 0 이 나올 수밖에 없습니다.

product-service 를 3개로 늘리고 같은 상품에 1분간 주문 9,782건을 몰았습니다.

지표값
락 획득 실패(PRD-004, 3초 대기 초과)0
낙관적 락 충돌(OptimisticLockingFailureException)7
DLQ 유입7
음수 재고 행0
품목별 차이0

(측정 기록에서 발췌)

락이 커밋까지 유지된다면 락을 거친 차감끼리는 한 번에 하나만 커밋에 도달하므로 서로 충돌할 수 없습니다. 모두가 락을 바로 얻었는데 충돌이 났으니 락이 커밋 전에 풀렸다고 읽었습니다. 다만 이 숫자만으로 증명되지는 않습니다. 같은 런에서 예약 733건이 해제됐으므로 락이 없는 복구 경로(restoreStock, 뒤에서 설명)도 같은 상품 재고를 고쳤습니다. 충돌 7건이 어느 경로끼리 부딪힌 것인지는 기록하지 않았습니다. 락 해제 시점은 코드와 뒤의 로컬 재현으로 확인했습니다. 상품 재고는 100,000 에서 시작했고 몰린 주문은 9,782건이었으므로 “음수 재고 행 0”은 처음부터 다른 값이 나올 수 없었습니다. @Version 이 막은 것은 lost update 였고, 근거는 품목별 차이 0 입니다. 그 대가가 DLQ 7건이었습니다.

아래 장면에서 같은 “락 획득 실패 0” 이 나오는 상황을 바꿔 보세요. 카운터 뒤에서 요청이 어디를 지나는지 보면 됩니다.

"락 획득 실패 0"은 무엇을 말해 줄까요?

재고 예약 요청이 consumer 인스턴스에서 Redis 락을 거쳐 재고 행으로 갑니다. 상황을 바꿔 보면서 카운터는 그대로인데 뒤에서 무엇이 달라지는지 보세요.

락 획득 실패 0 낙관적 락 충돌 0 DLQ 0 주문 2,977

카운터 값은 (가)와 (다)만 클러스터 측정값입니다. (나)는 Redis 예외가 나면 tryLock 이 true 를 돌려주는 코드 경로를 그린 것이고, "락 제거" 뒤의 부하 재측정은 하지 않아 값을 적지 않았습니다. 흘러가는 요청 수와 어느 요청이 충돌하는지는 예시이며, (다)에서 두 consumer 가 동시에 진행하는 모습은 로컬에서 재현하지 않은 도식입니다. (다)의 런에서는 락이 없는 재고 복구 경로도 함께 돌았고, 충돌 7건이 어느 경로끼리 부딪힌 것인지는 기록하지 않았습니다.

“락 획득 실패 0”은 세 경우를 구별하지 못합니다.

  • (가) 다툴 상대가 없는 경우입니다(인스턴스 하나, consumer 스레드 하나).
  • (나) Redis 가 죽은 경우입니다. 락 관리자는 Redis 예외가 나면 true 를 돌려주고 락 없이 진행하도록 짜여 있었습니다.
  • (다) 락이 너무 일찍 풀려 아무도 기다리지 않은 경우입니다.

실제 상황은 (다)였습니다. 인스턴스가 하나일 때 분산 락은 경쟁자가 없어 아무 일도 하지 않았습니다. 셋으로 늘린 뒤에는 커밋을 감싸지 못해 역시 소용이 없었습니다.

진입점의 트랜잭션 안에서 분산 락은 SELECT 만 감쌌습니다

락 파사드를 지우기 전에 코드를 다시 읽자 문제가 하나 더 나왔습니다. 락이 감싼 SQL 자체가 SELECT 하나였습니다.

// 락 파사드
boolean locked = lockManager.tryLock(lockKey, 3, 5, TimeUnit.SECONDS);
...
try {
    inventoryService.decreaseStock(productId, quantity);
} finally {
    lockManager.unlock(lockKey);
}

// InventoryService (클래스에 @Transactional)
public void decreaseStock(Long productId, int quantity) {
    Inventory inventory = inventoryRepository.findByProductId(productId)
            .orElseThrow(() -> new ProductException(ErrorCode.PRD_001));
    inventory.decrease(quantity);
}

(락 파사드 제거 직전 코드에서 발췌, 일부 생략)

decreaseStock 은 엔티티를 읽고 필드를 바꿀 뿐 save 도 flush 도 부르지 않습니다. JPA 는 바뀐 필드를 모아 두었다가 트랜잭션이 커밋되기 직전(flush)에 UPDATE 를 보냅니다. 이 메서드가 바깥 트랜잭션에 참여하면 메서드가 끝나도 트랜잭션은 끝나지 않으므로 UPDATE 는 락이 풀린 뒤 바깥 커밋 때 나갑니다. 락 안에서 실행된 SQL 은 SELECT 하나였습니다.

이 순서는 락 파사드를 제거하기 직전 코드로 로컬에서 재현했습니다(로컬 재현: Testcontainers, MySQL 8.0.46 general_log).

  • 바깥 트랜잭션 없이 파사드를 부르면 파사드가 돌아온 시점에 UPDATE 와 COMMIT 이 이미 나가 있고 다른 커넥션은 차감된 재고를 봅니다.
  • consumer 와 같은 조건으로 바깥 트랜잭션 안에서 부르면, 파사드가 돌아온 시점에 Redis 의 락 키는 이미 없고 다른 커넥션은 차감 전 재고를 봅니다. 그때까지 MySQL 이 받은 문장은 SET autocommit=0 과 SELECT 뿐이었습니다. UPDATE 와 COMMIT 은 바깥 트랜잭션이 커밋할 때 나갔습니다.

락 구간 안에는 어떤 SQL 이 있었을까요?

파란 띠가 consumer 1 이 Redis 락을 쥔 구간입니다. 띠 안에 들어간 SQL 과 밖으로 밀려난 SQL 을 보고, 바깥 트랜잭션을 걷어 냈을 때 UPDATE 와 COMMIT 이 어디로 옮겨 가는지 비교해 보세요.

클러스터 측정, 인스턴스 3개 락 획득 실패 0 낙관적 락 충돌 7 DLQ 7

consumer 1 의 SQL 순서와 DB 값은 락 파사드 제거 직전 코드로 한 로컬 재현(Testcontainers MySQL 8.0.46 general_log, 단일 스레드)에서 관찰한 것입니다. 두 구성은 각각 따로 실행해 시작 재고가 다릅니다(바깥 트랜잭션 안: 99 (v1) 에서 98 (v2), 바깥 트랜잭션 없음: 100 에서 99 (v1)). 두 consumer 의 동시 실행은 로컬에서 재현하지 않았고, consumer 2 의 진행은 코드 경로를 따라 그린 도식입니다. 막대의 길이는 실제 시간이 아닙니다.

락이 덮은 범위도 좁았습니다. 재고를 바꾸는 길은 세 갈래였습니다.

  • 예약 차감(decreaseStock)
  • 취소나 만료 때의 재고 복구(restoreStock)
  • 여러 품목을 한꺼번에 예약하기 전의 재고 사전 확인(hasSufficientStock)

락은 첫 번째에만 걸려 있었습니다. 만료 처리는 별도 스케줄러 스레드에서 consumer 와 동시에 돕니다.

락을 쥐는 시간에도 함정이 있었습니다. Redisson 은 leaseTime 을 주지 않으면 watchdog 이 락을 계속 연장하지만, 이 코드는 leaseTime 을 5초로 지정해 watchdog 이 동작하지 않았습니다. 처리가 5초를 넘기면 Redis 가 락을 먼저 풀어 버립니다. 그 뒤의 unlock 은 isHeldByCurrentThread() 가 false 라 예외도 로그도 없이 지나갑니다. 락이 사라졌다는 신호가 어디에도 남지 않습니다.

기존 동시성 테스트가 이것을 못 잡은 이유도 같은 곳에 있었습니다. 테스트는 파사드를 바깥 트랜잭션 없이 직접 불렀습니다. 파사드가 보장하려던 순서가 실제로 지켜지는 유일한 구성만 시험하고 있었습니다.

이력을 거슬러 올라가면 이 파사드는 원래 바로 이 문제를 고치려고 만든 것이었습니다. 도입 당시의 목적은 락 해제와 트랜잭션 커밋 사이의 gap 에서 생기는 오버셀링을 막는 것이었고, 그래서 락 관리를 트랜잭션 밖의 파사드로 분리했습니다. 그런데 그때 파사드를 부른 주문 생성 서비스는 이미 클래스 전체에 @Transactional 이 걸려 있었습니다. 서비스를 나누기 전에도 파사드는 바깥 트랜잭션 안에서 불렸고, 순서는 그때부터 뒤집혀 있었습니다.

이 역전은 그때도 알려져 있었습니다. 당시 분석은 주문 생성의 바깥 트랜잭션이 순서를 뒤집는다고 보고, 서비스를 나누면 주문과 재고가 다른 트랜잭션에 놓이니 결함이 자연히 사라질 것이라고 예상했습니다. 서비스는 나뉘었지만 결함은 남았습니다. 재고 차감을 넘겨받은 consumer 메서드에 @Transactional 이 있었고, 주문 생성 메서드가 하던 바깥 트랜잭션 역할을 그 메서드가 그대로 물려받았습니다. 락이 커밋을 감싸는지는 서비스를 어떻게 나눴는지와 상관없이, 락을 부르는 진입점의 트랜잭션 전파가 정하고 있었습니다.

재시도 네 번이 모두 실패했습니다

충돌 7건은 재시도를 모두 쓰고 DLQ 로 갔습니다. error handler 는 1초, 5초, 30초 간격으로 세 번 재시도했으니(처음 시도 포함 네 번), 낙관적 락 충돌이라면 대개 두 번째쯤에 풀려야 할 것 같습니다. 가능한 설명은 두 가지였습니다.

하나는 애초에 재시도 대상이 아니었다는 설명입니다. spring-kafka 의 DefaultErrorHandler 는 일부 예외를 재시도 없이 바로 실패로 보냅니다. 프로젝트가 쓰는 spring-kafka 3.3.14 jar 에서 그 기본 목록(ExceptionClassifier.defaultFatalExceptionsList)을 바이트코드로 읽었습니다. 목록은 deserialization, message conversion, argument resolution 예외와 NoSuchMethodException, ClassCastException 등 여섯 개였고, 낙관적 락 예외나 그 상위 타입은 없었습니다. 재시도는 실제로 일어났습니다.

다른 설명은 재시도가 경합을 그대로 다시 만들었다는 것입니다. 재시도 간격을 정하는 backoff 에는 무작위 성분이 없었습니다. 같은 순간에 충돌한 consumer 들은 똑같이 1초, 5초, 30초를 기다렸다가 같은 순간에 깨어나 다시 부딪힐 수 있습니다. 또 1분 내내 같은 상품으로 주문이 계속 들어오고 있었으므로, 재시도한 메시지가 새로 들어온 메시지와 부딪혔을 수도 있습니다. 측정된 7건이 어느 경로를 밟았는지는 직접 이어 보지 못했습니다.

분산 락을 걷어 내고 @Version 하나로

선택지는 세 가지였습니다.

방식남는 문제
A. 락을 트랜잭션 밖으로consumer 계층에서 상품 id 순서로 락을 먼저 모두 잡고, 트랜잭션을 열고, 커밋한 뒤 푼다트랜잭션이 lease(5초)보다 길어지면 같은 결함이 돌아온다. 이를 막으려면 lease 를 늘려 주는 watchdog 이 필요하고, 복구와 사전 확인 경로까지 락 안에 넣어야 하며, Redis 장애 시 조용히 통과하는 동작도 그대로 남는다
B. 락을 제거하고 @Version 하나로락 파사드를 지우고, 낙관적 락 충돌은 jitter 를 넣은 재시도로 흡수하고, 다 쓰면 DLQ 로 보낸다충돌 자체는 남는다. 경합이 심하면 재시도와 DLQ 가 늘어난다
C. 비관적 락(SELECT … FOR UPDATE)재고 행을 커밋까지 DB 가 잠근다커넥션과 행 락을 쥐는 시간이 트랜잭션 전체로 늘어난다. 이 트랜잭션에는 예약 레코드 저장과 outbox 기록도 들어 있다

재고 행을 UPDATE … SET stock = stock - ? WHERE stock >= ? 처럼 조건부 UPDATE 한 번으로 바꾸는 방법도 있지만, 이 결정에서는 따로 검토하지 않았습니다.

B 를 골랐습니다. A 는 측정에서 기여가 없던 수단을 제대로 동작하게 만들려고 장치를 계속 덧붙이는 방향입니다. C 는 구조적으로 가장 단순합니다. 순서를 사람이 맞출 필요 없이 DB 가 커밋까지 잠그기 때문입니다. 다만 부하에서 DB 경합이 얼마나 생길지는 재지 않았고, 측정은 이미 MySQL CPU 를 천장으로 지목한 상태였습니다. 그래서 C 는 미뤄 두었습니다. 낙관적 락 충돌률이나 DLQ 유입이 허용 범위를 넘으면 C 로 옮겨 가는 조건을 함께 정했습니다.

분산 락을 지워도 되는 근거는 측정과 코드 양쪽에 있었습니다.

  • 정합성을 지킨 것은 처음부터 @Version 이었습니다. 락이 있던 때에도 오버셀링 0 을 만든 것은 낙관적 락이었습니다.
  • 재고를 바꾸는 세 경로가 같은 규칙 아래 놓입니다. 이전에는 한 경로에만 락이 있었고 나머지는 @Version 뿐이었습니다. 사전 확인과 차감 사이에 다른 쓰기가 들어와 재고가 모자라게 될 수 있습니다. 그러면 차감에서 예외가 나 트랜잭션 전체가 되돌아가고, 재시도 때는 사전 확인이 그 주문을 막습니다.
  • 재고 정합성이 Redis 가용성과 무관해집니다. Redis 가 죽으면 락 없이 통과하던 경로와, lease 가 만료돼도 아무 신호가 없던 실패가 재고 경로에서 사라집니다.

대가도 있습니다. 락이 있을 때는 실패하기 전의 락 대기도 지표로 볼 수 있었습니다. 낙관적 락 충돌은 실패한 뒤에만 보이므로 “락 경합”이라는 지표 하나를 잃었습니다.

락 획득 실패 오류 코드(PRD-004)는 지우지 않았습니다. 전역 예외 핸들러가 낙관적 락 충돌을 409 로 바꿀 때도 같은 코드를 쓰고 있었기 때문입니다. 처음에는 grep 결과를 head 로 잘라 보다가 이 참조를 놓쳤고, 컴파일 오류로 드러났습니다. 이제 이 코드는 낙관적 락 충돌 하나만 뜻합니다.

재시도에는 jitter 를 넣었습니다. 1초, 5초, 30초라는 단계는 유지하고, 각 간격을 ±50% 범위에서 고르게 뽑습니다. 같은 순간에 충돌한 consumer 들이 서로 다른 순간에 깨어나게 하려는 것입니다. 이 변경은 상품 서비스의 error handler 에만 적용했고, 다른 서비스의 재시도에는 아직 넣지 않았습니다.

테스트도 바꿨습니다. 락 파사드를 지우기 전에는 “락 해제가 커밋보다 먼저 일어난다”를 순서로 assert 하는 재현 테스트를 먼저 만들어 현상을 재현해 두었습니다. 지운 뒤에는 그 테스트를 “재고 경로에서 락 획득과 해제 호출이 0회”라는 계약으로 바꿨습니다. 기존 동시성 테스트의 분산 락 시나리오는 consumer 와 같은 바깥 트랜잭션 구성의 오버셀링 테스트로 교체했습니다.

락을 지운 재고 경로는 부하에서 다시 재지 않았습니다. 락을 지운 뒤 jitter 가 DLQ 유입을 실제로 줄이는지, 낙관적 락 충돌률이 비관적 락으로 넘어갈 수준인지는 로컬 테스트로만 확인했고, 클러스터 결과로 주장하지 않습니다.

캐시와 트랜잭션 경계

두 질문을 따라가는 동안 상품 조회 쪽에서도 트랜잭션 범위가 만든 문제가 드러났습니다. 캐시 hit 이어도 트랜잭션은 열린다는 것과, 쓰기 트랜잭션 안에서 캐시를 지우면 커밋 전에 지워진다는 것입니다.

상세의 캐시 이득을 깎은 것은 재고 SELECT 하나였습니다

앞의 GKE 측정(400 VU)에서 캐시를 켰을 때의 이득은 목록이 2.02배, 상세가 1.23배였습니다. 처음에는 원인 후보를 두 가지로 봤습니다. 상세가 캐시 hit 이어도 재고만은 매번 DB 에서 읽는다는 것, 그리고 조회 서비스에 @Transactional(readOnly = true) 가 걸려 있어 캐시 hit 여부와 상관없이 트랜잭션이 열린다는 것입니다.

두 번째는 차이의 원인이 될 수 없었습니다. 그 선언은 클래스에 붙어 있어 목록 조회에도 똑같이 걸리는데, 목록은 그 상태로 2.02배를 냈습니다. 두 경로가 함께 내는 비용으로는 둘의 차이를 설명할 수 없습니다. Hibernate Statistics 로 캐시 hit 시 나가는 SQL 을 세자 상세 1개, 목록 0개였습니다. 차이는 재고 SELECT 하나였습니다.

캐시 hit 이어도 readOnly 트랜잭션 명령 다섯 개가 남습니다

다만 이 결론과 함께 세운 전제 하나가 틀렸습니다. 쿼리가 0이면 물리 커넥션조차 잡지 않는다고 봤던 것입니다. MySQL 이 실제로 받은 명령을 general_log 로 세어 보니(로컬 재현: Testcontainers, MySQL 8.0.46, Hibernate 6.6, Connector/J 9.6), 캐시가 전부 hit 인 상세나 목록 요청 하나에 MySQL 은 명령 다섯 개를 받았습니다.

SET SESSION TRANSACTION READ ONLY
SET autocommit=0
COMMIT
SET autocommit=1
SET SESSION TRANSACTION READ WRITE

(글 작성 중 로컬 재현 출력에서 발췌, 캐시 hit 요청 1건)

같은 구간에서 Hibernate Statistics 는 0을 셌습니다. Statistics 는 Hibernate 가 만든 PreparedStatement 를 세는데, 이 다섯 개는 트랜잭션 시작과 종료 때 Spring 과 JDBC 드라이버가 커넥션에 보내는 명령이라 거기에 잡히지 않습니다. 클래스의 @Transactional 을 지운 변형에서는 캐시 hit 요청의 명령이 0개가 됐습니다(로컬 재현).

결론(차이의 원인이 아니다)은 맞았습니다. 틀린 것은 그 공통 비용이 0이라는 근거였습니다. 그리고 이 공통 비용은 앞의 읽기 경로 재측정에서 풀지 못한 현상 하나와 이어집니다. 그 측정에서 캐시를 켠 목록 조회는 1분 동안 캐시 miss 가 0건이었는데도 같은 시간 MySQL 은 한도 500m 를 다 쓰며 스로틀을 받고 있었습니다(약 506m 사용). 한도를 2000m 로 풀자 MySQL 은 1.2코어 안팎을 썼습니다. 그 측정에서는 이것을 설명하지 못했고, 노드 단위 CPU 경합을 후보로만 들었습니다. 캐시 hit 요청마다 명령 다섯 개가 오간다면 초당 9002,200 요청은 초당 수천1만 개의 명령이 됩니다(계산값, 측정 아님). 유력한 설명이지만 클러스터에서 인과를 확인하지는 않았습니다.

재고를 캐시에 올리되, 무효화는 하지 않습니다

상세 조회의 재고 SELECT 를 없애는 방법도 네 가지를 놓고 골랐습니다.

방식고르지 않은 이유
A. 상품 정보 캐시(30분)에 합친다구현 비용이 거의 없다품절 상품을 최대 30분 동안 “재고 있음”으로 보여 준다
B. 쓰기 경로에서 캐시를 지운다평균적으로는 가장 신선하다커밋 전에 지워진다. 다음 절에서 설명
C. 재고 변경을 이벤트로 퍼뜨린다상품 변경 이벤트에 재고 필드가 이미 있다예약과 복구마다 이벤트를 발행해야 한다. 발행 경로는 이미 초당 20건에 묶인 천장이다
D. 상세 응답에서 재고를 뺀다문제 자체가 사라진다공개 API 계약을 깬다

고른 것은 재고 전용 캐시에 5초 TTL 을 걸고, 쓰기 경로에는 아무것도 하지 않는 방식입니다. TTL 은 캐시 설정 클래스의 속성(peekcart.cache.product-stock-ttl, 기본 5s)으로 둡니다.

이 결정의 출발점은 API 계약이었습니다. 상세 조회가 돌려주는 재고는 지금도 예약을 보장하지 않습니다. 응답을 받은 직후 다른 주문이 재고를 가져갈 수 있고, 주문이 되는지는 예약 saga 가 정합니다. 이 숫자는 화면에 보여 주는 힌트입니다. 5초 늦은 값은 원래 있던 어긋남을 최대 5초만큼 늘릴 뿐입니다. 상품 정보와 재고를 다른 캐시로 나눈 것도 같은 이유입니다. 둘의 변경 빈도가 크게 달라서 한 항목에 합치면 둘 중 하나는 TTL 이 맞지 않습니다.

이 결정은 테스트로 고정했습니다.

  • TTL 을 1초로 주입한 테스트입니다. 재고 100 을 캐시에 올린 뒤 DB 를 7 로 바꾸면 TTL 전에는 100 이, TTL 이 지나면 7 이 보입니다. 낡은 값의 상한이 TTL 이라는 계약입니다.
  • 예약으로 DB 재고가 70 이 돼도 TTL 안에서는 100 이 보인다는 테스트입니다. 누군가 쓰기 경로에 무효화를 슬쩍 넣으면 이 테스트가 실패해 이 결정을 다시 보게 만듭니다.

가드가 실제로 실패하는지도 결함을 주입해 확인했습니다.

주입한 결함결과
재고 조회의 @Cacheable 제거캐시 hit 시 SQL 수가 다시 1이 되어 실패
TTL 을 1시간으로낡은 값 상한 테스트만 실패
쓰기 경로에 @CacheEvict 추가쓰기 경로 테스트만 실패

구현 중에 계획에 없던 비용도 하나 드러났습니다. Redis 가 죽지 않고 응답만 멈춘 상황을 흉내 내는 기존 테스트가 상한 1.5초를 넘겨 2.05초가 나왔습니다. 상세 조회가 이제 캐시를 두 개 거치므로 조회 500ms 와 저장 500ms 타임아웃이 각각 두 번씩 걸려 최악 2,000ms 가 됩니다(이전에는 1,000ms). 응답은 여전히 돌아오고 지연의 상한만 늘어났으므로 테스트 상한을 2.6초로 올리고 비용으로 받아들였습니다. 이 지연을 줄이는 설정은 Redis 클라이언트 타임아웃(spring.data.redis.timeout)이고, TTL 과는 관계가 없습니다.

@CacheEvict 도 커밋 전에 실행됩니다

선택지 B(쓰기 경로에서 캐시 삭제)를 고르지 않은 이유는 락과 같은 곳에 있습니다. 재고를 바꾸는 서비스는 consumer 의 트랜잭션에 참여합니다. 그 메서드에 @CacheEvict 를 달면 캐시 삭제는 기본값(beforeInvocation=false)대로 메서드가 끝날 때 일어나고, 그 시점은 트랜잭션 커밋보다 앞입니다. 삭제와 커밋 사이에 조회가 들어오면 아직 커밋되지 않은 쓰기의 이전 값을 DB 에서 읽어 다시 캐시에 넣습니다. 그러면 낡은 값은 다음 쓰기까지, TTL 이 없다면 무기한 남습니다. 락이 커밋 전에 풀렸던 것과 같은 구조입니다. 락 해제도 캐시 삭제도 참여한 트랜잭션 안에서 실행되는 side effect 라 커밋보다 먼저 일어납니다. 무효화를 하려면 커밋 이후(afterCommit)에 해야 합니다. Spring 의 TransactionAwareCacheDecorator(Redis 캐시 매니저라면 transactionAware() 설정)를 쓰면 캐시 삭제가 커밋 뒤로 미뤄집니다. 그래도 삭제와 재조회 사이의 경합은 남아 낡은 값의 상한은 결국 TTL 이 정합니다. 무효화를 붙이더라도 TTL 은 함께 있어야 합니다.

아래 장면은 앞의 락 장면과 같은 시간축 배치입니다. 락 구간 대신 캐시를 지우는 시점을 옮겨 보세요.

캐시를 지웠는데 왜 낡은 값이 남을까요?

재고 100 을 99 로 바꾸는 쓰기 트랜잭션과, 그 사이에 들어오는 조회 요청이 있습니다. 캐시를 지우는 시점을 바꿔 보고, 캐시 줄에 낡은 값이 언제부터 언제까지 남는지 보세요.

글에서 검토하고 고르지 않은 선택지를 코드 경로대로 그린 도식이며, 측정한 결과가 아닙니다. 재고 값(100 에서 99)과 조회 시점은 예시이고, 막대의 길이는 실제 시간이 아닙니다. 실제로 고른 방식은 쓰기 경로에서 캐시를 지우지 않고 재고 캐시에 5초 TTL 만 두는 것입니다.

재고 캐시 뒤의 상세/목록 비율은 500m 에서 1.01, 2000m 에서 0.81

MySQL 한도를 왕복시킨 앞의 30런 표에서 캐시 이득도 다시 계산할 수 있습니다. 블록 A 에서 상세의 캐시 배수(ON 906.6 / OFF 393.4)는 2.30배로, 이전 세션의 1.23배보다 크게 나오지만 이 숫자는 쓰지 않았습니다. 대조군 기준을 통과하지 못했기 때문입니다. 코드를 바꾸지 않은 캐시 ON 목록이 이전 세션보다 16.7% 높게 나왔습니다(767.1 rps 에서 894.9 rps).

반면 캐시 OFF 두 칸은 이전 값과 ±4% 안에서 겹쳤습니다. 캐시 ON 목록도 블록 A 에서 MySQL 500m 에 런마다 96~124초 스로틀됐으므로, 캐시 OFF 만 한도에 막혀 있었고 캐시 ON 만 환경 변화의 이득을 받았다고 설명할 수는 없습니다. +16.7% 의 원인은 분리하지 않았습니다. 원인이 무엇이든 바닥은 그대로인 채 위쪽만 움직였으니 두 세션의 배수를 나누면 그 변화가 섞입니다.

그래서 미리 정한 대로 같은 세션 안의 비율을 봤습니다.

상세 ON / 목록 ONMySQL 한도
이전 세션0.604500m
블록 A1.013500m
블록 B0.8072000m

같은 MySQL 조건에서 0.60 이 1.01 이 됐습니다. 재고 DB 조회 한 번 때문에 상세는 목록의 60% 에 머물러 있었고 재고 캐시가 그 조회를 없앴습니다.

블록 B 를 보면 블록 A 의 해석이 달라집니다. MySQL 천장을 풀자 상세는 목록의 81% 로 다시 벌어졌습니다. 블록 A 의 1.01 은 두 엔드포인트가 같은 천장(약 900 rps)에 함께 막혀 있던 결과였습니다. 상세는 Redis 를 두 번(상품 정보와 재고), 목록은 한 번 거친다는 차이가 남은 20% 의 후보지만, 그 인과는 분리하지 않았습니다. 되돌림 블록이 없었다면 “상세와 목록이 동률이 됐다”고 적었을 것입니다.

재고 캐시의 동작도 숫자로 확인했습니다. 2000m 블록의 캐시 ON 상세에서 재고 캐시 miss 는 초당 10.0~11.1건, hit rate 는 99.4% 였습니다. 상품 100개에 TTL 5초라면 이론상 갱신은 초당 20건인데, 실측은 그 절반이었습니다. 만료 순간 같은 키에 요청이 몰려 DB 를 여러 번 치는 현상(stampede)은 @Cacheable 에 sync=true 가 없어 원리적으로는 생길 수 있지만, 이 부하(400 VU)에서는 나타나지 않았습니다.

돌아보면 더 나았을 방법

이 장은 일이 다 끝난 뒤 기록을 다시 읽으며 한 사후 분석입니다. 여기서 다루는 방법은 그때 검토 대상에 오르지 않았습니다.

처음 후보 표를 다르게 채웠다면

처음 측정에서 MySQL 행을 채운 것은 kubectl top 의 샘플이었습니다. 재측정 세션에서는 런 전후로 컨테이너의 cpu.stat 을 두 번 읽어 차이를 냈습니다. 비용은 Pod 마다 kubectl exec … cat /sys/fs/cgroup/cpu.stat 한 줄이 전부였습니다. 그 카운터로 본 MySQL 500m 은 캐시를 끈 런에서도, 켠 런에서도 매번 스로틀이 걸려 있었습니다(60초 런당 72~169초 누적).

처음 측정 때 이 카운터를 함께 읽었다면 MySQL 행은 “아니다”가 되기 어려웠을 것입니다. 다만 그 세션의 MySQL 스로틀은 실제로 재지 않았으므로, 이것은 같은 구성을 나중에 잰 값에서 미루어 본 추정입니다. 컨테이너의 CPU 한도를 의심할 때 평균 사용량으로는 “한도 아래”까지만 말할 수 있습니다. “한도에 막혔다”는 답은 nr_throttled, throttled_usec 같은 카운터를 읽어야 얻습니다.

같은 표의 구성도 문제였습니다. 세 행 중 조건을 실제로 움직인 것은 두 행이었습니다. CPU 두 행의 값은 천장에 닿기 전, 동시성에 묶인 50 VU 런에서 나왔습니다. 표에 “조작했나, 관찰했나”와 “어떤 부하 조건에서 쟀나”라는 두 열이 있었다면, MySQL 행은 “관찰, 50 VU” 로 적혀 결론을 내리기 전에 눈에 걸렸을 것입니다.

락 파사드를 만든 날, 실패하는 테스트가 하나 있었다면

락 파사드를 도입하며 함께 추가한 테스트는 의존성을 모두 mock 으로 바꾼 단위 테스트였습니다. 락을 얻고 서비스를 부르고 finally 에서 푸는지를 확인할 뿐, 트랜잭션이 언제 커밋되는지는 볼 수 없는 구성입니다. 통합 동시성 테스트는 파사드를 바깥 트랜잭션 없이 불렀습니다. 두 테스트 모두 파사드가 보장하려던 순서(“커밋 후 해제”)가 깨지는 구성을 시험하지 않았습니다.

당시 분석은 그 구성이 실제 코드에 있다는 것까지 알고 있었고, 주문 생성의 바깥 트랜잭션이 순서를 뒤집는다고 봤습니다. 그러고는 테스트를 만들지 않고 “서비스를 나누면 사라진다”는 예상만 남겼습니다.

그 구성을 그대로 재현하는 테스트는 만들기 어렵지 않았을 것입니다. 바깥 트랜잭션 안에서 파사드를 부르고, 파사드가 돌아온 시점에 락이 이미 풀렸는지와 다른 커넥션이 차감 전 값을 보는지를 assert 하면 됩니다. 앞의 로컬 재현이 바로 그 구성이었고, 결과는 assert 가 실패하는 쪽이었습니다. 그런 테스트가 있었다면 결함은 도입한 날 드러났을 것이고, 호출 위치가 consumer 로 옮겨 갔을 때도 그 테스트가 계속 실패해 결함이 남아 있다는 것을 보여 줬을 것입니다(추정).

순서를 보장하려고 만든 코드라면 그 순서가 깨질 수 있는 구성(여기서는 바깥 트랜잭션 안의 호출)을 그대로 만든 테스트로 그 보장을 확인할 수 있었습니다.

캐시 hit 요청의 트랜잭션 명령을 줄이는 세 방법

조회 서비스 클래스 전체에 @Transactional(readOnly = true) 를 거는 것은 흔한 기본 구성입니다. 이 구성에서는 캐시가 모두 hit 이어도 요청마다 MySQL 에 명령 다섯 개가 오갔습니다. 줄이는 방법마다 비용이 다릅니다. 아래 표의 수치는 모두 로컬 재현입니다.

방법확인한 것(로컬 재현)비용과 한계
1캐시 호출을 트랜잭션 밖에 둡니다. 조회 서비스의 클래스 레벨 선언을 빼고, DB 를 실제로 읽는 메서드에만 선언합니다클래스 레벨 선언을 지운 변형에서 캐시 hit 요청의 명령이 0개. 캐시 계층에도 클래스 레벨 readOnly 트랜잭션이 있지만, 프록시의 advisor 를 출력해 보니 캐시 인터셉터가 트랜잭션 인터셉터보다 바깥에 있어 hit 이면 트랜잭션을 열지 않았습니다. 다만 두 인터셉터의 order 값이 같아(지정 없음) 이 순서는 Spring 이 보장하지 않습니다(Advice Ordering)캐시 miss 일 때는 메서드마다 트랜잭션이 따로 열립니다(변형에서 상세 miss 요청의 명령이 8개에서 13개로). 여러 조회를 한 스냅샷으로 묶어야 하는 메서드라면 쓸 수 없습니다. 이 순서에 기대려면 @EnableCaching(order = …) 로 명시해야 합니다
2커넥션 풀의 기본 상태를 autocommit=false 로 두고(Hikari auto-commit=false), Hibernate 에 그 사실을 알립니다(hibernate.connection.provider_disables_autocommit=true)캐시 hit 요청의 명령이 5개에서 3개로 줄었습니다. SET autocommit 두 개가 빠집니다모든 커넥션의 기본 상태가 바뀝니다. 트랜잭션 밖에서 JDBC 를 쓰는 코드가 있다면 동작이 달라질 수 있는데, 전체 테스트 스위트로는 확인하지 않았습니다. READ ONLY, READ WRITE, COMMIT 은 남습니다
3무엇을 하든, contract test 가 세는 대상을 바꿉니다. Hibernate 의 SQL 수 대신 DB 서버가 받은 명령 수(general_log, Com_* 상태 변수)를 셉니다기존 contract test 는 같은 요청에서 0 을 셌고, 서버는 5 를 받았습니다테스트가 무거워지고 DB 설정에 의존합니다

첫째 방법은 효과가 가장 크지만 트랜잭션 범위 설계를 다시 해야 합니다. 둘째는 설정 두 줄로 끝나고 영향은 서비스 전체에 미칩니다. 어느 쪽이든 셋째가 없으면 고친 뒤에 다시 늘어나도 알아챌 방법이 없습니다. 이 명령들이 클러스터에서 MySQL CPU 를 얼마나 썼는지는 재지 않았으므로 방법을 고르기 전에 그것부터 재야 합니다.

아무도 고르지 않은 값

세 층의 천장은 모두 처음 정한 값이 다시 검토되지 않은 채 남은 것이었습니다.

  • MySQL CPU 한도는 노트북 환경을 기준으로 정한 뒤 다시 보지 않았습니다.
  • 스케줄러 스레드 수는 Spring Boot 기본값 1이었습니다.
  • outbox 폴링은 처음 설정한 5초마다 100건이었습니다.

부하를 걸기 전에 “이 시스템에서 처리량을 제한하는 설정값 중, 이 환경을 기준으로 정한 적이 없는 것”을 목록으로 뽑아 두었다면, 그 목록이 처음 측정의 후보 표가 됐을 것입니다.

정리하며

처음 질문은 “MySQL CPU 는 아니다”라는 한 줄이 무엇을 배제했느냐였습니다.

  • product-service CPU 와 커넥션 풀. 둘 다 직접 바꿔 봤지만 MySQL 한도가 500m 에 묶여 있던 50 VU 조건의 결과라, 그 조건에서 천장이 아니었다는 데까지만 말할 수 있습니다. 3000m 에서 product-service CPU 를 “아니다”로 본 근거도 MySQL 행과 같은 평균 사용량 샘플이었습니다. MySQL 을 2000m 으로 푼 재측정에서는 product-service 도 런마다 11~33초 스로틀됐습니다.
  • MySQL CPU. 배제되지 않았습니다. 같은 50 VU 조건에서 10초 간격의 평균 사용량 샘플이 한도 아래로 보였을 뿐, 한도는 한 번도 움직이지 않았습니다. 한도를 올리자 주문 생성은 부하 구간 기준 초당 약 80건에서 약 231건이 됐습니다. 캐시를 끈 상세 조회는 393 rps 에서 904 rps 로 한도를 따라 올라갔다가, 되돌리자 393 rps 로 돌아왔습니다. 스로틀 카운터도 같은 단계에서 사라졌다가 다시 쌓였습니다.
  • “락 획득 실패 0건”. 다툴 상대가 없는 경우, Redis 가 죽어 락을 건너뛴 경우, 락이 커밋 전에 풀린 경우를 구별하지 못하는 숫자였습니다. 실제는 세 번째였고, 락이 감싼 것은 SELECT 하나였습니다.

그 결과 바뀐 것은 다음과 같습니다.

  • MySQL 의 기본 CPU 한도를 500m 에서 2000m 으로 올렸습니다. requests 는 재지 않았으므로 그대로 두었습니다.
  • 재고 경로의 분산 락을 걷어 내고 @Version 하나로 통일했습니다. 재시도에는 jitter 를 넣었습니다.
  • 상세 조회의 재고를 5초 TTL 캐시에 올렸습니다. 같은 MySQL 500m 조건에서 상세/목록 비율이 0.60 에서 1.01 이 됐고, 한도를 2000m 로 풀면 0.81 입니다.
  • 스케줄러 스레드를 1개에서 4개로 늘렸습니다.

모르는 채로 남은 것도 있습니다.

남은 것상태
목록 경로의 CPU 배수(되돌림 기준 초과)미해결
MySQL 2000m 에서 남은 새 천장(상세 OFF 904 rps, MySQL 스로틀 0.1초, product-service 스로틀 런당 21~33초)미해결
캐시 hit 요청의 트랜잭션 명령 5개가 클러스터 MySQL CPU 를 얼마나 쓰는지로컬에서만 확인
비동기 발행 경로의 천장(기본 초당 20건, 완화 후 77건)미해결
락 제거 후 부하에서의 낙관적 락 충돌률과 DLQ 유입미측정
다른 서비스의 재시도 jitter미적용
기본 한도 2000m 의 실제 클러스터 적용렌더 검증만

다음 측정의 후보 표에는 “직접 바꿔 봤는가”와 “어떤 부하 조건이었는가”가 열로 들어가고, CPU 행은 평균 사용량 대신 스로틀 카운터로 채워질 것입니다.