레디스 SCAN 커맨드와 관련된 이슈 일지

Backend/Redis

레디스 SCAN 커맨드와 관련된 이슈 일지

nowwater 2023. 8. 21. 22:40

728x90

작업한 내용을 배포하던 도중 redis 장애가 발생했다.

slowlog 를 확인해보니 SCAN 커맨드가 최대 1초까지 지연이 발생했었다. 이로 인해 다른 클라이언트들의 레디스 커맨드들도 연쇄적으로 모두 블로킹되었고, 응답 지연이 꽤나 발생하고 말았다. 일단 롤백을 바로 해서 다행히 큰 장애로 이어지지는 않았다. (이로 인해 전사 긴급 장애 대응 채널이 열렸고, 많은 개발자 분들이 모니터링 대응을 해주셨다.. 매우 죄송하고 감사합니다..😓)

그런데 SCAN 이라는 커맨드는 왜 이렇게 오래 걸렸고, 왜 발생했던 것일까? (내가 작업한 내용 중에는 SCAN 커맨드를 사용하는 부분이 없었다ㅜ) 그 이유를 찾기 위해서 여러 자료들을 찾아보았고, 그 과정들을 기록해두기 위해 글을 작성하려고 한다.

오래 걸린 이유

일단 SCAN 커맨드를 알아보기에 앞서, 레디스의 특성을 살펴보면 좋을 것 같다.

Redis 는 single thread event loop 구조로 명령을 처리한다. 따라서 먼저 호출된 커맨드에서 blocking이 발생하면, 해당 지점이 병목이 되어서 이후 들어오는 커맨드들도 모두 지연이 발생하게 된다. (물론 싱글 스레드 임에도 불구하고 get, set 명령어의 경우 초당 10만 개 이상 처리할 수 있을 만큼 빠르다.) 예를 들어 저장되어 있는 모든 키를 조회하는 KEYS 커맨드를 사용했을 때, 만약 저장된 키가 많이 있었다면 전체 데이터를 조회하는데 걸리는 시간이 오래 걸리게 된다. 그러면 당연히 그 동안 다른 커맨드를 수행하지 못하게 될 것이다.

이러한 KEYS 커맨드 대신에 사용하기 위한 방법으로 나온 것이 SCAN 이다.

SCAN 커맨드는 cursor, pattern, count 를 사용하여 전체 key 를 조회하는 방식이다.

pattern 과 일치하는 key 를 한 번에 count 만큼 반복적으로 조회하는데, 그 때 마다 cursor 를 움직이면서 작업을 수행한다.

처음 시작은 scan 번호를 0으로 지정해서 시작하며, 두 개의 값을 반환을 하는데 첫 번째 값은 다음 cursor의 번호이고 그 다음 값은 키값들이 출력된다. 다음 데이터를 찾기 위해서는 이전 결과값으로 반환된 커서 값을 이용해서 검색하면 된다. 만약 scan 후 나온 다음 cursor 의 값이 0인 경우, 그 이후에 값이 없음을 의미한다.

각각의 scan 커맨드 호출의 시간복잡도는 O(1) 이지만, KEYS 와 마찬가지로 전체 키를 조회하는 경우에는 O(N) 이 걸린다. (N = 저장되어 있는 전체 키의 개수)

O(1) for every call. O(N) for a complete iteration, including enough command calls for the cursor to return back to 0. N is the number of elements inside the collection.

그래서 왜 발생했나

이러한 위험성을 가진 커맨드인 KEYS 나 SCAN 를 안쓰면 되는 거 아닌가 ?! 라고 생각할 수 있다.

그러나 사용하기 쉽게 추상화되어 편하게 사용했었던 spring-data-redis 의 어노테이션 속에 그 위험성이 도사리고 있었다.

이슈가 발생했던 기존 프로젝트 코드를 살펴보면, spring-data-redis 의존성을 추가하여 RedisConfig 와 @Cacheable 을 사용하여 캐시를 사용하고 있었다. 그런데 RedisConfig 에서 잘 보면 BatchStrategies 라는 옵션을 사용하는 것을 확인할 수 있다.

private RedisCacheWriter getCacheWriter() {
    return RedisCacheWriter.nonLockingRedisCacheWriter(redisConnectionFactory, BatchStrategies.scan(BATCH_SCAN_SIZE));
}

이게 과연 어떤 옵션일까 ? 궁금해서 BatchStrategies 에 관해서 찾아보았더니 다음과 같이 나와있었다.

음.. 일단 KEYS 또는 SCAN 커맨드를 사용해서 배치 전략을 구현한다는 얘긴 거 같은데, 뭔가 궁금증이 해소되지 않는다.. 역시 구글링을 해보아야겠다.

The cache implementation defaults to use KEYS and DEL to clear the cache. KEYS can cause performance issues with large keyspaces. Therefore, the default RedisCacheWriter can be created with a BatchStrategy to switch to a SCAN-based batch strategy. The SCAN strategy requires a batch size to avoid excessive Redis command roundtrips:
Note: The KEYS batch strategy is fully supported using any driver and Redis operation mode (Standalone, Clustered). SCAN is fully supported when using the Lettuce driver. Jedis supports SCAN only in non-clustered modes.

RedisCacheManager cm = RedisCacheManager.build(
	RedisCacheWriter.nonLockingRedisCacheWriter(connectionFactory, BatchStrategies.scan(1000))
).cacheDefaults(defaultCacheConfig())

위 내용에 따르면, 캐시를 삭제할 때 기본 구현으로 KEYS 와 DEL 을 사용하는데, 그때 KEYS 대신 SCAN 을 사용하도록 옵션을 바꿔주는 거라고 한다 !!

즉, 해당 옵션이 포함된 RedisCacheWriter를 기본 설정으로 등록해 두었기 때문에 @CacheEvict 어노테이션을 사용해 캐시 삭제가 일어날 때 SCAN 이 사용되는 것이었다 !! (만약 설정하지 않았다면 KEYS 커맨드를 사용했을테고, 그럼 문제가 더 커졌을 듯..)

캐시 삭제가 이루어지는 곳을 찾아보았더니 두 개의 @CacheEvict 어노테이션을 발견할 수 있었다. 그 중 하나는 admin-api 모듈의 수정 API 에 붙어 있었고, 나머지 하나는 service-api 모듈의 메타 조회 API 에 붙어 있었다. 그리고 내가 작업한 내용 중에 일부분이 메타 조회 API 에서 비동기적으로 단축 URL 을 생성해내는 로직과 연관이 있었고, 일부 내용이 바뀌면서 @CacheEvict 가 비정상적으로 많이 호출되었던 것이었다..!

단축 URL 생성 메소드를 탈 때마다 캐시 eviction 이 발생하고, 아래의 SCAN 커맨드가 발생한다.

scan 0 match meta::* count 100000
scan 0 match detail::* count 100000

그런데 당시 40만 건의 데이터가 있었고, 카운트가 10만이기에 meta, detail 에 대한 스캔 쿼리가 총 5번이 발생하여 10번의 스캔이 발생하게 된다 !! 그런데 처음에 200ms 내외로 처리하던 SCAN 이 비동기 로직에 의해 순식간에 몰리게 되었고, 지연 시간이 점점 늘다가 1s 를 넘어가기 시작했다 (캐시를 evict 하는 메서드가 비동기로 동작해 단 기간에 약 150회 가량 호출됨) 이로 인해 다른 레디스 커맨드들이 모두 블로킹되어 지연시간이 급증하게 된 것이다.. (150 * 10 의 scan 쿼리 ?? 이건 레디스가 뻗지 않고 버틸 수 가 없었을 거다)

그래서 이 부분에 @CacheEvict 를 지워버리고 scan 이 발생하지 않도록 수정해주었다. 그리고 이 외에도 admin-api 에 수정 API 를 호출할 때도 해당 어노테이션이 붙어 있어서 같이 제거해주었다.

→ 문제 해완결료!!