지난 주말 밤 11시쯤 모바일 서비스 응답이 16분 정도 지연되는 이슈가 있었습니다.
방송 중에만 1+1 행사를 걸었던 터라 목표치를 240% 넘게 달성할 정도로 주문이 몰렸던 시간대였거든요.
초기 가설과 캐시 미스 확인
장애가 수습되고 1시간 이내에 제가 부랴부랴 정리했던 1차 분석에서는 원인이 꽤 명확해 보였습니다.
단일 실행에 20~30초씩 걸리는 무거운 추천·랭킹 쿼리가 병목을 일으켰고, 캐시 만료 시 동시 접근을 제어할 분산 락이 없어서 발생한 전형적인 캐시 스탬피드(Cache Stampede) 현상으로 판단했거든요.
조치 계획도 자연스럽게 쿼리 최적화와 Redisson 분산 락 도입 쪽으로 가닥을 잡았습니다.
그런데 실제 비회원 캐시 Hit/Miss 통계를 뽑아보면서 고개가 갸우뚱해졌습니다.
평소 98~99%에 달하던 캐시 방어율이 이번 피크 시간대에는 95.8%(미스 발생률 4.15%) 수준으로 떨어지면서, 40분간 총 327건의 미스가 잡히긴 했습니다. 평소보다 미스가 튄 95% 내외라 분명 이상 수치이긴 했지만, 스탬피드가 단독 원인이라고 보기에는 어려웠습니다.
8천 건 가까운 전체 인입 중 고작 300여 건 수준의 미스만으로는 DB 커넥션 풀이 완전히 고갈되고 서버가 뻗을 수가 없었거든요. 스탬피드로 서버가 터졌다고 하기에는 미스 수치가 예상보다 턱없이 적었습니다.
로그인 기록과 회원 트래픽 전수 조사
300건의 캐시 미스만으로 시스템이 마비된 진짜 이유를 찾기 위해, 상품상세 로그부터 로그인 기록과 신규 회원가입 수치까지 싹 다 살펴보기 시작했습니다.
로그를 쪼개어 대조해 보니 상황이 전혀 다르게 돌아가고 있었습니다.
전체 3만 1천 건의 상품상세 인입 중 무려 74.3%(2만 3,119건)가 로그인한 회원 트래픽이었습니다. 평소 2주 전 평시와 비교해 보니 신규 회원가입은 74명에서 396명으로 435.1%(5.35배) 폭증했고, 로그인 시도 건수도 1.8만 건에서 4.0만 건으로 121.5%나 급증했더라고요. 1+1 혜택을 챙기려는 실사용 회원들이 일시에 쏟아져 들어온 특수 케이스였던 셈입니다.
그리고 상품상세 코드에서 회원 등급별 캐시 허용 설정을 확인하면서 원인이 드러났습니다.
설정 파일 속 회원 등급별 캐시 플래그를 확인해 보니, 비회원만 캐시를 타도록 열려 있고 일반 회원 등급들은 전부 꺼져 있는 구조였습니다.
즉, 비회원의 300여 건 캐시 미스가 문제가 아니라, 순수 2만 3천 건에 달하는 상품상세 진입 요청이 캐시를 1밀리초도 거치지 않고 100% DB로 직행하고 있었던 겁니다.
상품상세 화면 하나에 물려 있는 수많은 추천 구좌부터 랭킹, 그리고 로그인 회원 상태에서 파생되는 추가 API 요청들까지 감안하면 실제로는 수십, 수백만 개의 쿼리가 DB로 한꺼번에 쏟아진 셈이었죠. 커넥션 풀이 버텨낼 리가 없었습니다.
원인을 짚고 나서
이번 이슈를 겪으면서 얻은 게 정말 많았습니다.
계속 미뤄두던 스탬피드 방어 정책이었는데 스탬피드 현상도 어느 정도 겪어보고, 시스템 설정 하나가 불러오는 파급력과 중요성도 제대로 배웠거든요.
원인을 분석하는 과정에서 300MB 분량의 로그 파일 7개와 총 18MB에 달하는 엑셀 지표 등 방대한 데이터를 전수 확인했는데, 에이전트의 도움도 많이 받았고 데이터를 파고들수록 앞뒤가 맞아떨어지는 분석 과정 자체가 나름 재미있었습니다.
특수한 유입 상황 하나가 아키텍처의 숨은 빈틈을 짚어주고, 명확한 개선 방향과 값진 트러블슈팅 경험까지 안겨주어서 엔지니어로서 참 행복한 이슈였습니다.
추가적으로 바라는 게 있다면 원인들이 해결되고 난 다음 동일 혜택 수준의 편성 한번만 해줬으면 좋겠네요.