캐시 히트율 6%와 오해(1)

About this offer

캐시 히트율에 대한 장애 회고를 읽고 관심이 생겨 실험해 보았다 테스트를 위해 상품(product) 300만 개와 카테고리별 판매 랭킹(ranking) API가 있는 쇼핑몰을 만들고, 둘 다 Redis 캐시를 적용했다. 상품 조회는 상품 한 건을 찾는 가벼운 쿼리다. 랭킹 조회는 한 카테고리의 상품을 판매량 순으로 정렬해 상위 10개를 뽑는데, 이 과정에서 상품 300만 행을 모두 훑는 무거운 쿼리다. 그래서 상품 조회가 전체 요청의 97%, 랭킹 조회는 3%로 설정했다 사용자는 상품 상세는 계속 넘겨 보지만 랭킹은 카테고리 화면에 들어갈 때 한 번 보는 정도라고 생각해서, 요청의 97%는 상품 조회이고 랭킹 조회는 3%로 잡았다. 구성 내용 애플리케이션 Spring Boot 4.1 (Java 21), 커넥션 풀(HikariCP) 20개 DB MySQL 8.4, CPU 2코어 제한, 버퍼 풀 1GB(다른 기능의 쿼리도 같은 DB의 CPU를 나눠 쓰기 때문에, 이 API가 쓸 수 있는 CPU는 그중 일부라고 가정하고 DB를 2코어로 제한했다) 캐시 Redis 7.4, @Cacheable (상품 TTL 10분, 랭킹 TTL 5분) 모니터링 Prometheus + Grafana, MySQL·Redis exporter 부하 k6, 초당 200건 고정 (상품 조회 97%, 랭킹 조회 3%) 데이터 상품 300만 개, 카테고리 24개 캐시를 붙이기는 했는데 실제로 도움이 되나 확인 하기 위해 모니터링 대시보드를 열었다. 캐시별 조회수와 히트율 패널은 있었지만 값이 비어 있었다. 요청은 초당 200건씩 들어오고 있는데 조회수는 0이고, 히트율은 선조차 없어서 확인할 게 없었다. 볼 수 있는 건 Redis 서버 전체의 hits와 misses뿐이었다. 노란 선은 Misses, 초당 약 180번이다. 캐시에 데이터가 없어서 DB까지 갔다. 초록 선은 Hits, 초당 약 11번 캐시에서 바로 조회했다. 초당 조회수는 200번이고, 그중 히트는 약 11번이므로 캐시 히트율은 약 6%정도이다. 수치를 봤을 때는 캐시가 성능을 올린다고 생각되지 않았고, 걷어내도 될 것 같다고 판단했다. 캐시를 걷어내자, DB가 무너졌다 캐시는 한 번에 걷어내지 않고 단계적으로 걷어냈다. 0% → 25% → 50% → 75% → 100%로 캐시 우회 비율(이하 우회율)을 올렸다. 0%에서 5분, 이후 단계마다 3분씩, 모두 17분이다. 트래픽은 처음부터 끝까지 초당 200건으로 같다. 우회율 상품 조회 p99 랭킹 조회 p99 0% 18ms 6ms 25% 54ms 1.2s 50% 5.5s 15.4s 75% 6.7s 16.6s 100% 8.1s 22.2s 25%에서 랭킹 조회가 1초 이상으로 불안했지만 견딜만 했다. 문제는 50%로 넘어가면서 시작됐다. 우회율은 조금씩 늘렸는데, 어느 지점을 넘는 순간 상품 조회는 5초를 넘겼고 랭킹은 15초 이상이 걸리면서 한꺼번에 무너졌다. 이상한 점은 상품 조회까지 느려진 것이다. 상품 조회는 기본키로 한 건만 찾으면 되는 가벼운 쿼리다. 무거운 랭킹 조회가 느려지는 건 이해가 되지만, 상품 조회가 300배 가까이 느려질 이유가 없어 보였다. 무엇이 DB를 무너뜨렸나 바뀐 것은 우회율을 올린 것 말고는 없다. 캐시를 뺀 뒤 DB에서 무슨 일이 일어났는지 하나씩 확인해 보았다. 예상 원인 의심하는 이유 1 Redis에 문제가 생겼다 캐시를 건드린 이후 문제가 터졌다 2 DB로 가는 쿼리 수가 늘었다 캐시를 빼면 그만큼 DB로 간다 3 특정 쿼리 하나가 DB를 잡고 있다 느린 쿼리 하나가 전체를 막는 경우도 있다 Redis 장애 주황색= 캐시 조회 , 초록색= 캐시 저장 Redis가 초당 처리한 명령 수는 우회율이 올라갈수록 389 → 293 → 76 → 36 → 1.6으로 줄었다. 캐시를 건너뛰는 요청이 늘었으니 당연하다. DB로 가는 쿼리 수 증가 캐시를 걷어냈으니 DB로 가는 쿼리가 늘었을 거라고 생각하기 쉽다 DB가 받은 SQL 문장 수인데 25%에서는 2% 늘었을 뿐이고, 50%로 넘어가는 순간에는 오히려 뚝 떨어진다. 요청이 줄어서가 아니라 부하는 그대로 초당 200건이었고, DB가 그만큼 처리하지 못해 실행된 문장 수가 줄어든 것이다. 캐시를 걷어냈는데 DB로 가는 쿼리 수가 거의 늘지 않았다는 건, 캐시가 있을 때도 대부분의 조회가 이미 DB까지 가고 있었다는 뜻이다. 히트율 6%와 같은 이야기다. MySQL 안에서 동시에 실행 중인 쿼리 수(Threads Running)는 0%에서 평균 2였다. 50%로 넘어가자 평균 13.5로 뛰었고, 최대 19까지 올라갔다. 반면 파란 선(Threads Connected)은 처음부터 끝까지 21(커넥션 풀 20개 + 지표 수집용 1개)로 일정하다. 커넥션이 새로 늘어난 게 아니라, 같은 커넥션 안에서 쿼리가 끝나지 않고 있었다. 앞의 Questions 그래프와 같이 보면, 들어오는 쿼리 수는 그대로이거나 줄었는데 동시에 실행 중인 쿼리만 6배 넘게 늘었다. 쿼리 1건이 오래 걸리니, 끝나기 전에 다음 쿼리가 들어와 계속 쌓인 것이다. 바뀐 건 건수가 아니라 무게라고 생각했다. 쿼리 하나의 독점 무거운 쿼리를 찾으려면 쿼리별로 DB 시간을 얼마나 썼는지 봐야 한다. MySQL은 쿼리 종류별 실행 횟수와 누적 시간을 performance_schema에 기록하고, sys.statement_analysis 뷰로 보여 준다. 이 값은 서버가 켜진 뒤로 계속 쌓이는 누적값이라, 단계마다 초기화(TRUNCATE)한 뒤 측정했다. 아래는 우회율 0% 단계(5분)와 50% 단계(3분)가 끝난 직후의 결과다. 쿼리 우회율 초당 실행 횟수 평균 DB 시간 비중 랭킹 집계 쿼리 0% 0.06 0.50s 45% 랭킹 집계 쿼리 50% 1.45 7.33s 98.6% 상품 기본키 조회 0% 188 0.07ms 20% 상품 기본키 조회 50% 78 0.73ms 0.5% 랭킹 쿼리는 1건에 300만 행을 훑는 무거운 쿼리다. 우회율 0%일 때는 캐시가 막아 줘서 초당 0.06건만 DB에 도달했다. 그러나 50%에서는 초당 1.45건, 약 24배가 DB에 도달했다. 무거운 쿼리가 한꺼번에 몰리자 2코어 CPU를 서로 나눠 써야 했고, 1건이 걸리는 시간이 0.50초에서 7.33초로 약 15배 늘었다. 앞에서 동시 실행 수가 13.5까지 뛰었던 이유가 이것이다. 그 결과 50%에서는 DB 시간의 98.6%를 랭킹 쿼리 하나가 썼다. 상품 조회는 초당 78건으로 훨씬 많이 실행됐지만, DB 시간은 0.5%뿐이다. 랭킹 쿼리가 붙잡은 건 DB 시간만이 아니었다. 앱은 쿼리를 보낼 때마다 커넥션 풀에서 커넥션을 하나 빌리고, 쿼리가 끝나야 돌려준다. 이 앱의 커넥션 풀은 20개다. 1건에 7초씩 걸리는 쿼리가 커넥션을 쥐고 있으면, 다른 요청은 커넥션이 돌아올 때까지 기다려야 한다. 50%로 넘어가는 순간 커넥션 풀 20개가 가득 차고, 커넥션을 기다리는 요청이 179개까지 쌓였다. 상품 조회는 DB 안에서 0.73ms면 끝나지만, 커넥션을 얻으려고 풀 앞에서 몇 초씩 기다렸다. 상품 조회가 같이 느려진 이유가 이것이다. 상품 조회 자체는 아무 문제가 없었다. 랭킹 쿼리가 커넥션을 쥐고 있는 동안 대기 했어야 했기 때문이다.