핵심 문제는 널리 사용되던 Rails 캐싱 패턴인 Rails.cache.fetch(key, race_condition_ttl: 5.minutes) { expensive_query }에서 비롯되었습니다. 이 패턴은 캐시 데이터 생성 시 경합 조건을 방지하기 위해 설계되었지만, 의도치 않게 전역적이고 조용한 뮤텍스를 생성했습니다.
문제 발생 원인: 숨겨진 뮤텍스
-
race_condition_ttl옵션은 동일한 캐시 키에 대한 동시 요청 시 하나의 스레드만 캐시를 생성하고 나머지는 대기하도록 합니다. -
이는 이론적으로 캐시 스탬피드를 방지하지만, 실제 트래픽이 몰릴 때 전역 뮤텍스처럼 작동하여 애플리케이션의 주요 경로를 직렬화시키는 ‘숨겨진 큐’가 되었습니다.
-
예를 들어, ‘최근 아티클’과 같이 여러 컴포넌트에서 공유되는 키는 전체 시스템의 병목 현상을 유발했습니다.
문제 발견 과정: 지표의 거짓말
-
대시보드는 ‘정상’이었으나, 로그에서는 데이터베이스 작업 5ms에 비해 전체 요청 완료 시간이 10초 이상으로 늘어나는 현상이 관찰되었습니다.
-
간단한 동시성 테스트(20개 스레드 중 15개 즉시 멈춤)를 통해
race_condition_ttl이 최적화가 아닌 대기열 역할을 했음을 입증했습니다. -
Redis CPU는 미미했고 Rails 로그는 대기 스레드 정보를 제공하지 않아 문제 파악이 어려웠습니다.
해결책 및 얻은 교훈
-
단일 공유 키를 네임스페이스별 키(예:
recent_articles:#{user.id})로 교체하고, 캐시 잠금에 300ms 타임아웃 래퍼를 추가했습니다. -
캐시 자체에 대한 계측을 강화하여 지연 시간, 잠금 대기 카운터 등을 모니터링하기 시작했습니다.
-
이러한 개선으로 평균 지연 시간이 70% 감소하고 500 에러가 사라졌습니다.
-
이번 사건은 지표가 현실의 전부가 아니며, ‘검증된’ 패턴도 맥락 없이 적용될 경우 예상치 못한 문제를 야기할 수 있다는 중요한 교훈을 주었습니다.