본문으로 건너뛰기
개발 머꼬
개발 노트Redis
hohyeon.dev39

전날 방문자 키 하나를 지울 때마다 Redis가 0.6초씩 멈춘 이유

  • #Engineering Note
  • #Performance
  • #Redis

문제 발생

일별 순방문자 수를 Redis set으로 세고 있었습니다. 요청이 들어올 때마다 기기 ID를 그날 키에 넣고, 대시보드는 SCARD로 개수만 읽었습니다. 새벽 4시에 도는 배치가 전날 숫자를 DB로 옮긴 다음 전날 키를 지웠습니다.

r.sadd(f"visitors:{today}", device_id)

count = r.scard(f"visitors:{yesterday}")
save_daily_count(yesterday, count)
r.delete(f"visitors:{yesterday}")

비회원까지 기기 ID로 세다 보니 하루치가 300만 개를 넘겼고, 그즈음부터 매일 새벽 4시 정각에 API 타임아웃 알람이 몇 건씩 울렸습니다. Redis CPU도 메모리도 멀쩡했습니다. SLOWLOG GET을 열어 보고 나서야 배치가 보낸 DEL 한 건이 600ms 넘게 걸렸다는 걸 알았습니다. 키 하나 지우는 데 0.6초라니, 처음엔 잘못 본 줄 알았습니다.

그래서 배치에서 DEL을 빼고, 키를 처음 만들 때 이틀짜리 TTL을 걸어 Redis가 알아서 지우게 했습니다. 그랬더니 알람이 새벽 4시에서 자정 언저리로 옮겨 갔을 뿐이고, 이번에는 SLOWLOG에 아무것도 남지 않았습니다.

원인 분석

DEL은 지우는 값이 클수록 오래 걸립니다. DEL 문서의 시간 복잡도는 지우는 키 개수에 대한 O(N)인데, 바로 뒤에 단서가 붙어 있습니다. 문자열이 아닌 값을 가진 키라면 그 키 하나의 복잡도가 O(M)이고, M은 list, set, sorted set, hash에 든 요소 개수라고요. O(1)인 건 문자열 키 하나를 지울 때뿐입니다. 300만 개짜리 set을 지우는 건 300만 개를 하나씩 해제하는 일이었습니다.

그동안 Redis는 다른 명령을 처리하지 않습니다. redis.conf의 LAZY FREEING 절 주석이 이걸 그대로 설명합니다. DEL은 블로킹 삭제라서 객체에 딸린 메모리를 동기적으로 회수하는 동안 새 명령 처리를 멈추고, 요소가 수백만 개인 값이면 길게는 몇 초까지 멈출 수 있다고요. 같은 크기의 set을 만들어 재현해 보니 DEL 한 번에 631ms가 걸렸고, 옆에서 계속 보내던 PING은 최대 624ms를 기다렸습니다. 그 0.6초 사이에 들어온 API 요청이 전부 같이 기다린 겁니다.

Redis가 스스로 지울 때도 똑같이 멈춥니다. 같은 주석은 사용자가 지우라고 하지 않아도 Redis가 키를 지우는 경우를 넷 꼽습니다. maxmemory 정책에 따른 eviction, TTL 만료, 이미 있는 키를 덮어쓰는 명령(RENAME, SUNIONSTORE, STORE를 붙인 SORT, 그리고 SET), 레플리카의 전체 재동기화입니다. 그리고 이 경우들도 기본값은 DEL을 부른 것처럼 블로킹으로 지운다고 적어 둡니다. TTL로 바꿨더니 시각만 옮겨 간 이유가 이거였습니다. 재현에서도 300만 개짜리 키가 만료되는 순간 PING이 640ms 넘게 멈췄습니다.

RENAME 문서에는 따로 경고가 있습니다. 대상 키가 이미 있으면 덮어쓰면서 암묵적으로 DEL을 하기 때문에, RENAME 자체는 보통 상수 시간이어도 지워지는 값이 아주 크면 지연이 커질 수 있다고요. 임시 키에 새로 만든 다음 RENAME으로 바꿔치기하는 흔한 패턴이 여기에 걸립니다. 재현해 보니 SLOWLOG에 rename이 612ms로 찍혀서, O(1) 명령이 왜 느리냐고 한참 헤매기 딱 좋았습니다.

만료로 지워진 건 SLOWLOG에 남지 않습니다. SLOWLOG 문서에 따르면 slow log가 재는 건 명령을 실행하는 시간입니다. 만료 삭제는 클라이언트가 보낸 명령이 아니니 기록될 자리가 없습니다. 재현에서도 만료로 640ms가 멈췄는데 slow log에는 한 줄도 늘지 않았습니다.

해결 방안

  1. 큰 키는 UNLINK로 지웁니다. UNLINK 문서에 따르면 키를 키 공간에서 떼어 내는 건 값 크기와 상관없이 키당 O(1)이고, 실제 메모리 회수는 다른 스레드에서 합니다. 문서 표현 그대로 DEL은 블로킹이고 UNLINK는 아닙니다. Redis 4.0부터 있는 명령입니다.
r.unlink(f"visitors:{yesterday}")

같은 300만 개짜리 set을 UNLINK로 지우니 8ms에 끝났고, 그동안 PING도 8ms 넘게 기다리지 않았습니다.

  1. Redis가 알아서 지우는 경로도 백그라운드로 돌립니다. 경우마다 따로 켜는 설정이 있습니다. 코드 곳곳의 DEL을 다 바꾸기 어렵다면 lazyfree-lazy-user-del을 켜서 DEL이 UNLINK처럼 동작하게 할 수도 있습니다.
lazyfree-lazy-eviction yes
lazyfree-lazy-expire yes
lazyfree-lazy-server-del yes
lazyfree-lazy-user-del yes

최신 redis.conf에서도 이 값들의 기본은 전부 no입니다. 지금 값은 CONFIG GET lazyfree*로 봅니다. CONFIG SET으로 바꾼 값은 재시작하면 사라지니 redis.conf에 적거나 CONFIG REWRITE로 파일에 남겨 둡니다. 재현에서 lazyfree-lazy-expire와 lazyfree-lazy-server-del을 켜자 만료와 RENAME 때 멈추던 시간이 10ms 안쪽으로 줄었습니다.

이름 그대로 메모리를 나중에 돌려받는 방식이라, 지운 직후에는 used_memory가 바로 줄지 않을 수 있습니다. 해제를 기다리는 객체 수는 INFO memory의 lazyfree_pending_objects에 나옵니다.

  1. 개수만 필요하면 set 대신 HyperLogLog를 씁니다. 이 키는 처음부터 SCARD 말고는 쓴 적이 없었습니다. Redis 문서는 HyperLogLog를 메모리와 정확도를 맞바꾼 구조로 소개합니다. 최대 12KB만 쓰고 표준 오차는 0.81%이며, 페이지별·기간별 순방문자 수 세기가 문서가 드는 대표적인 쓰임입니다.
r.pfadd(f"uv:{today}", device_id)
count = r.pfcount(f"uv:{yesterday}")

기기 ID 300만 개를 넣어 보니 PFCOUNT는 3,024,300을 돌려줬고(오차 0.8%), 키 크기는 14KB였습니다. 같은 데이터를 담은 set은 170MB였습니다. 이 정도 키는 언제 지워도 아무 일이 없습니다. 대신 누가 왔는지 목록을 꺼내거나 특정 사용자가 왔는지 확인할 수는 없으니, 그게 필요하면 set을 두고 1, 2번으로 지웁니다.

  1. 큰 키가 어디 있는지 먼저 찾아 둡니다. redis-cli --bigkeys는 자료형별로 요소가 가장 많은 키를, --memkeys는 메모리를 가장 많이 쓰는 키를 찾아 줍니다. 문서에 따르면 SCAN으로 훑기 때문에 바쁜 서버에 돌려도 운영에 영향을 주지 않고, -i 옵션으로 간격을 주면 부하를 더 줄일 수 있습니다.
redis-cli --bigkeys -i 0.01
redis-cli --memkeys -i 0.01

키 하나만 볼 때는 MEMORY USAGE를 씁니다. 문서에 따르면 중첩 자료형은 기본으로 요소 5개를 샘플링해 추정하고, SAMPLES 0이면 전부 셉니다. 전부 세는 쪽은 큰 키에서 그 자체가 오래 걸려서, 300만 개짜리 set에서 기본값은 9ms, SAMPLES 0은 312ms였습니다. 운영 서버에서는 기본값으로 봅니다.

  1. 확인은 latency monitor로 합니다. SLOWLOG에 안 남는 멈춤은 latency monitor가 잡습니다. 문서에 따르면 기본으로 꺼져 있고(임계값 0), 밀리초 단위 임계값을 주면 켜집니다. 감시하는 이벤트에 만료 사이클(expire-cycle)과 eviction 중 삭제(eviction-del)도 들어 있습니다.
CONFIG SET latency-monitor-threshold 100
LATENCY LATEST

재현 환경(Redis 7.0)에서 큰 키를 만료시키자 LATENCY LATEST에 expire-cycle과 expire-del이 각각 695ms, 696ms로 찍혔습니다. lazyfree-lazy-expire를 켜고 같은 실험을 다시 돌리니 아무 이벤트도 남지 않았습니다. 설정을 바꾼 뒤에는 이렇게 한 번 직접 확인해 두는 게 마음이 편합니다.

공식 문서

마지막 수정

좋아요북마크

댓글3