이번주 월요일에 슬랙에 지속적으로 같은 로그가 되게 많이 떴었다.
사실 redis를 다른 팀에서도 사용을 하고 있기에 좀 더 주의깊게 확인해봐야 했지만 전체가 태그되는 바람에 잘 모니터링 하지는 못했던 것 같다.
이게 갑자기 alert log가 뜨게 되니까 되게 이상했다. 그리고 latency가 그래프 상으로 기하급수적으로 증가한게 보일 것이다.
이 로그가 문제는 내가 배포했던 시간부터 쭉 나왔다는 것이다.
신규 기능을 해당 시간에 오픈을 진행했었고, 그 이후로 로그가 지속적으로 찍혔었다. 😭😭😭
퇴근길에 놓치고 있었던 스레드에 같은 팀의 백엔드 개발자분이 먼저 남겨주셨다.
말씀주신 기능보다는 다른 기능에서 문제가 있긴 했다. 저쪽은 캐시도 사용하지 않으며 문제될것이 전혀 없던 곳이었다.
아래 제보된 것부터는 이제 점점 이상해지기 시작했다.
나는 분명히 하나의 key를 잡아주고 Spring Framework의 @Cacheable 을 사용해서 관리를 해주고 있는데 keys * 라니?
당연히 코드를 까봤는데 저 캐시를 사용하거나 캐시를 갱신하는 로직에서 문제가 있다고 alert을 자꾸 보내주고 있었다.
뭐가 문제였을까?
문제가 되었던 부분은 3가지였다.
- Cacheable을 사용하면서 key를 명시적으로 잡아주지 않았던 점
- CacheEvict를 사용하면서 allEntries=true 옵션을 아무생각 없이 붙였던 점
- RedisCacheManager 설정을 제대로 확인하지 않은점
이 3가지가 복합적으로 물리면서 문제가 되었다.
SimpleKeyGenerator
1번에서 봤던 key를 명시적으로 잡아주지 않은 문제는 spring cache 자체가 Cacheable을 선언한 순간에 별도의 key 가 없다면 value + key를 하는 과정에서 key가 없기 때문에 Spring 에 임의 기본값인 SimpleKeyGenerator가 SimpleKey.EMPTY 라는 object를 반환해서 그 키값으로 해당 캐시를 넣어주게 된다. 그래서 아래처럼 키가 생성된다.
value 키 문자열 + ::SimpleKey []
SimpleKey로 들어갔기 때문에 이제 임의 키로 저장되게 된다.
CacheEvict allEntries 속성
이제 캐싱을 했으니까 조회되는데에는 기본적으로 계속 잘 읽힐텐데, 캐시 데이터를 수정해야될 때가 반드시 있을 것 아닌가?
이 때 CacheEvict를 수행하는데 위에서 key를 설정하지 않았으니 이 부분에서도 evict은 value로만 해야지 ~ 하면 이제 문제가 발생한다.
절대 안지워진다 !!!
그래서 이제 이때부터 아 그럼 SimpleKey 하나만 있는데 value 하위에 있는 데이터들 모두 삭제해주면 되겠지? 라는 생각으로 allEntries=true를 적어줬다.
javadoc을 번역해서 가져와봤다.
설명 되어있는거 보면 key 아래의 값만 제거된다고 써있다
이게 진짜 웃긴데 이래놓고선 막상 동작해보면 value로 구성된 key들이 있는지 전부 탐색 한다는것이다.!!
그래서 이 부분에서 keys * 를 사용하게 된다. 탐색해서 앞 부분이 value와 같으면 전부 삭제한다는 성능적으로 엄청 위험한 기능이었다 ㅋㅋㅋㅋㅋ 🤣
사실 운영환경에서 keys * 를 사용할게 아니니까 redis를 연결한 계정의 권한 자체에서도 keys 를 사용할 수 없게 막았어야 할 것이다.
아무튼 이쯤하고 1등에 대한 당첨 결과를 계속해서 db를 읽는건 불필요하다고 판단해서 저장하게 되었는데 여기서 1등만 저장하는것이 아니라 모든 등수 결과에 대해서 redis에 캐싱을 하고 있었다.
그래서 트래픽 유입이 계속해서 되고 있었기에 그들이 뽑는 개수만큼 반복적으로 CacheEvict가 호출됐고, 그에 따라서 keys *호출 도 계속 증가하는 방식으로 구성이 된 것이다.
그래서 어떻게 해결했는데?
우선 keys를 왜 사용하게 되는지를 찾았다.
여기서 위의 3번에 대한 설정이 잘못됐다는걸 깨닫게 되었다.
RedisCacheManager의 BatchStrategies 를 변경했다.
기존 default 로 설정하면 scan이 아닌 keys를 주입하게 된다.
그래서 scan으로 변경해줬고 1회당 최대 탐색개수를 25개로 설정해주었다.
이렇게 해서 해결을 해주었고 key값에는 SimpleKey가 들어가지 않게 rank별로 key를 가져 적재될 수 있도록 구성했고 조회시에는 rank별로 별도 캐시 데이터를 읽어올 수 있게 구성해서 수정하였다.
결론
앞으로는 뭔가 잘 모르거나 실제로 데이터를 조회하거나 수정함에 있어서 이상한 명령어가 날아가지 않게 확인하려면 해당 라이브러리의 debug 로그를 로컬환경에서 찍어보면서 해야될까? 하는 생각도 잠시 들었다.
그리고 오히려 이런 상황이 좋았던것 같은건 이렇게 포스팅하면서 설정이 어떻게 들어가는지 확실하게 기억하고 넘어갈 수 있어서 좋은 것 같다.
올해 계속 새로운 이슈들 발견하고 또는 개발하면서 생기는 여러가지 동시성이슈에 대한 생각들로 많이 배우고있다!!
당장에 신규 서비스들을 개발하는 부서이기 때문에 빠르게 트래픽이 많이 유입되어 성장해서 더 깊은 고민을 많이 하는 경험도 얼른 해봤으면 좋겠다 🔥🔥🔥