Redis는 왜 빠르고, 언제 느려질까?

Q: Redis는 왜 빠르고, 언제 느려질까?

명령을 실행하는 스레드는 메인 스레드 하나라서, 키 100만 개에서 KEYS가 도는 동안 다른 클라이언트의 GET이 최대 68.4ms까지 늦어졌다.

이번 시간에는 Redis와 Python 클라이언트로 Redis의 응답 시간이 어디서 늘어나는지 직접 재 보며 배워가는 시간입니다.

재 볼 건 세 가지예요. 명령을 실행하는 스레드가 몇 개인지, 느린 명령 하나가 다른 클라이언트를 얼마나 붙잡는지, 메모리에 있는데도 지연 스파이크가 생기는 경우가 무엇인지입니다.

Redis가 빠른 이유를 물으면 보통 "메모리에 데이터를 두니까"라는 답이 먼저 나오죠. 틀린 말은 아니에요. 그런데 그것만으로는 같은 Redis가 어떤 날은 0.1ms에 응답하고 어떤 날은 수십 ms씩 멈추는 이유를 설명하지 못합니다.

왜 그럴까요? 애플리케이션이 느끼는 응답 시간에는 명령을 실행하는 시간 말고도, 앞선 명령이 끝나기를 기다리는 시간과 네트워크를 오가는 시간이 함께 들어 있기 때문이에요.

실습 준비

이 글의 명령은 모두 실습 코드의 redis-why-fast/ 디렉터리에서 실행합니다.

compose.yaml: Redis와 Python 클라이언트 컨테이너(지연을 넣는 netem 컨테이너도 들어 있지만 이 글에서는 쓰지 않아요)
probe.py: 다른 연결이 명령을 실행하는 동안 GET 응답 시간을 재는 스크립트

DEBUG 명령은 테스트 데이터를 만들 때 쓰려고 로컬 접속에서만 허용했어요. 운영 서버에서는 켜지 마세요.

compose 프로젝트 이름은 rfast로 두고, 자주 쓰는 명령은 셸 함수로 만들어 놓을게요.

아래 블록은 파일로 만들지 말고 실습 디렉터리에서 연 터미널에 그대로 붙여 넣어 주세요. 이후 명령은 모두 이 터미널에서 실행하고, 터미널을 새로 열면 다시 붙여 넣으시면 됩니다.

export COMPOSE_PROJECT_NAME=rfast
docker compose up -d
rcli() { docker compose exec -T redis redis-cli --no-raw "$@"; }

py() { docker compose exec -T app python "$@"; }

실습 1: 명령은 이벤트 루프 하나가 차례로 실행합니다

Redis는 이벤트 루프 하나가 여러 클라이언트의 소켓을 지켜보다가, 요청이 들어온 순서대로 명령을 하나씩 실행해요. Redis 서버 프로세스의 스레드 목록을 볼게요.

rcli INFO server | grep -E "redis_version|multiplexing_api|io_threads_active"
rcli CONFIG GET io-threads
docker compose exec -T redis sh -c 'cat /proc/1/task/*/comm'

redis_version:8.10.2
multiplexing_api:epoll
io_threads_active:0
1) "io-threads"
2) "1"
redis-server
iou-sqp-75938
bio_close_file
bio_aof
bio_lazy_free
jemalloc_bg_thd
jemalloc_bg_thd

출력을 보면 스레드는 여러 개지만, 명령을 실행하는 건 redis-server 메인 스레드 하나예요. 나머지는 이런 일을 맡습니다.

bio_close_file, bio_aof, bio_lazy_free: 파일 닫기, AOF(쓰기 명령을 파일에 이어 적는 영속화 방식) 파일의 fsync, UNLINK 같은 지연 해제처럼 메인 스레드를 오래 붙잡을 수 있는 일을 뒤에서 처리합니다.
jemalloc_bg_thd: 메모리 할당자 jemalloc의 백그라운드 스레드입니다.
iou-sqp-...: 커널이 io_uring 요청을 처리하려고 만든 스레드입니다. 명령을 실행하지는 않습니다.

반대로 만료된 키를 지우는 작업은 메인 스레드에서 돌아갑니다. 그래서 키가 한꺼번에 대량으로 만료되면 그 처리가 끝날 때까지 다른 명령도 기다려요.

io-threads는 기본값이 1이라 지금은 I/O 스레드가 꺼져 있습니다(io_threads_active:0). 이 값을 올리면 소켓 읽기, 프로토콜 파싱, 응답 쓰기를 여러 스레드가 나눠 맡지만, 명령 실행은 여전히 메인 스레드 하나에서 일어나요. redis.conf도 CPU 사용률이 높아 실제로 성능 문제가 있을 때만, 코어가 4개 이상인 서버에서 켜라고 권합니다.

명령을 하나씩 차례로 실행하니 자료구조에 잠금을 걸 필요가 없고, 명령 하나가 실행되는 동안 다른 명령이 끼어들지 못해요.

평소에는 명령 하나가 마이크로초 단위로 끝나서 기다리는 명령이 쌓이지 않아요. 하지만 오래 걸리는 명령이 하나 끼면 사정이 달라집니다.

실습 2: 느린 명령 하나가 모두를 세웁니다

키 100만 개를 만들고 확인해 볼게요.

rcli DEBUG POPULATE 1000000 user 20

OK

다른 클라이언트가 받는 영향은 probe.py로 잽니다. 한 연결은 1ms 간격으로 GET을 계속 보내며 응답 시간을 기록하고, 다른 연결은 중간에 인자로 받은 명령을 실행해요.

먼저 가벼운 PING으로 평소 상태를 보고, 이어서 KEYS를 실행해 볼게요. nomatch*에 맞는 키는 하나도 없지만, KEYS는 패턴을 확인하려고 키 100만 개를 모두 훑어요.

py probe.py PING
py probe.py KEYS 'nomatch*'

PING 실행 시간: 0.8 ms
그동안 다른 클라이언트의 GET 294회: 중간값 0.10 ms, 최대 0.5 ms
KEYS nomatch* 실행 시간: 69.3 ms
그동안 다른 클라이언트의 GET 301회: 중간값 0.10 ms, 최대 68.4 ms

출력을 보면 평소 0.5ms를 넘지 않던 GET이 KEYS가 도는 동안 최대 68.4ms까지 늦어졌어요.

여기서 눈여겨볼 건 늘어난 시간이 KEYS가 끝나기를 기다린 시간이라는 점이에요. GET을 처리하는 시간은 그대로입니다.

GET 자체는 0.1ms 안팎이지만, 먼저 들어온 명령이 끝날 때까지 기다려야 합니다.

어떤 명령이 오래 걸렸는지는 SLOWLOG에 남아요.

rcli SLOWLOG GET 1

1) 1) (integer) 1
   2) (integer) 1790824424
   3) (integer) 68236
   4) 1) "KEYS"
      2) "nomatch*"
   5) "172.26.0.3:35798"
   6) ""
   7) (integer) 2

세 번째 값이 실행 시간(마이크로초)이에요. 68236은 약 68ms로, 다른 클라이언트가 기다린 최대 시간과 거의 같습니다.

SLOWLOG가 재는 건 명령 실행 시간뿐이고, 네트워크로 응답을 보내는 시간은 들어가지 않아요. 관련 설정은 두 가지입니다.

slowlog-log-slower-than: 이 값(마이크로초)보다 오래 걸린 명령을 기록합니다. 기본값은 10000, 즉 10ms입니다.
slowlog-max-len: 보관할 항목 수입니다. 기본값은 128이고 넘치면 오래된 것부터 지워집니다.

KEYS 말고도 원소가 많은 컬렉션에 쓰는 SMEMBERS, HGETALL, LRANGE 0 -1, SUNION 같은 O(N) 명령과 오래 도는 Lua 스크립트도 같은 방식으로 다른 명령을 세웁니다.

실습 3: 메모리에 있어도 지연 스파이크는 생깁니다

평소에는 빠르다가 가끔 튀는 지연은 원인이 명령 하나에 있지 않은 경우가 많아요. Redis는 이런 순간을 기록하는 latency monitor를 제공합니다.

기본값은 꺼짐(0)이고, 기준 시간(ms)을 넣으면 그보다 오래 걸린 이벤트를 종류별로 기록해요.

rcli CONFIG SET latency-monitor-threshold 10

OK

원소 100만 개짜리 Set을 만들어 볼게요.

rcli EVAL "for i = 1, 1000000 do redis.call('SADD', KEYS[1], 'member:' .. i) end" 1 big:set
rcli MEMORY USAGE big:set

(nil)
(integer) 39277586

약 39MB짜리 키예요. 만드는 동안 기록된 이벤트를 지우고(LATENCY RESET), DEL로 지우면서 다른 클라이언트의 응답 시간을 재 보겠습니다.

rcli LATENCY RESET
py probe.py DEL big:set

(integer) 1
DEL big:set 실행 시간: 68.9 ms
그동안 다른 클라이언트의 GET 286회: 중간값 0.10 ms, 최대 67.3 ms

DEL은 키를 지우면서 원소 100만 개의 메모리를 하나하나 해제해요. 공식 문서의 복잡도도 키 하나에 대해 O(M), M은 원소 수입니다.

그 67ms 동안 다른 클라이언트는 기다렸어요. latency monitor에도 기록이 남았습니다.

rcli LATENCY LATEST
rcli LATENCY HISTORY command

1) 1) "command"
   2) (integer) 1790824517
   3) (integer) 67
   4) (integer) 67
1) 1) (integer) 1790824517
   2) (integer) 67

LATENCY LATEST는 이벤트 이름, 마지막 발생 시간(유닉스 시간), 마지막 지연(ms), 최대 지연(ms)을 보여 줘요. command는 일반 명령이 기준을 넘었다는 뜻입니다.

같은 Set을 다시 만들고, 이번에는 UNLINK로 지워 볼게요.

rcli EVAL "for i = 1, 1000000 do redis.call('SADD', KEYS[1], 'member:' .. i) end" 1 big:set > /dev/null
rcli LATENCY RESET > /dev/null
py probe.py UNLINK big:set
rcli LATENCY LATEST
rcli INFO memory | grep lazyfree

UNLINK big:set 실행 시간: 1.2 ms
그동안 다른 클라이언트의 GET 280회: 중간값 0.10 ms, 최대 1.1 ms
(empty array)
lazyfree_pending_objects:0
lazyfreed_objects:1

UNLINK는 키를 키 공간에서 떼어 내기만 하고 바로 응답해요. 메모리 해제는 앞에서 본 bio_lazy_free 스레드가 뒤에서 처리하고, lazyfreed_objects가 그렇게 해제된 객체 수입니다.

출력을 보면 다른 클라이언트의 최대 지연은 1.1ms였고, latency monitor에도 아무것도 남지 않았어요.

애플리케이션 코드의 DEL을 모두 고치기 어렵다면 lazyfree-lazy-user-del yes로 DEL이 UNLINK처럼 동작하게 할 수 있어요. 기본값은 no입니다.

만료나 축출로 지워지는 큰 키는 각각 lazyfree-lazy-expire, lazyfree-lazy-eviction이 같은 역할을 해요. 메모리가 찼을 때 어떤 키를 축출하는지 더 궁금하면 Redis eviction을 다룬 글을 참고하세요.

정리

범위: Redis 8.10.2(redis:8.10.2 이미지), Python redis 6.4.0, 노트북 Docker의 같은 가상 머신.

Redis 프로세스의 스레드는 여러 개였지만 명령을 실행하는 건 메인 스레드 하나였고, io-threads를 올려도 명령 실행은 메인 스레드에 남아요. 명령 하나가 오래 걸리면 다른 모든 명령이 기다린다고 보고 설계하세요.
키 100만 개에서 KEYS nomatch*가 도는 동안 평소 0.5ms를 넘지 않던 다른 클라이언트의 GET이 최대 68.4ms까지 늦어졌고, SLOWLOG에는 68236µs로 남았어요. 오래 걸린 명령은 SLOWLOG GET으로 찾아 보세요.
이 글에 싣지 않은 추가 측정에서는 한 번 호출할 때 일부만 보고 커서를 돌려주는 SCAN으로 같은 키를 훑자 전체 시간은 KEYS보다 4배 넘게 걸렸지만 그동안 GET은 최대 0.8ms였어요. 전체 키나 큰 컬렉션을 훑을 때는 KEYS 같은 O(N) 명령 대신 SCAN 계열을 쓰세요.
원소 100만 개 Set을 DEL로 지우자 다른 클라이언트가 67ms 기다렸고, UNLINK로 지우자 최대 지연이 1.1ms였어요. 큰 키는 UNLINK로 지우고, 코드를 고치기 어려우면 lazyfree-lazy-user-del yes를 켜 주세요.