어느날 응답 속도가 너무 느려졌다.

들어가면서

회사 내부 사정으로 개발을 멈추고 최소한의 운영 업무만 대응하는 레거시 애플리케이션이 있었다.
해당 서버의 코드를 개발하셨던 분들은 전부 퇴사하셨고, 팀 개발자가 나와 5년차 선배 이렇게 두명이었기 때문에, 진짜 운영에 필요한 개발만 돌아가면서 작업했다.

아무튼, 가장 많이 호출되는 가격 조회 API가 있는데 몇 주 전부터 응답 속도가 갑자기 너무 느려졌다걸 알게되었고, 스프린트 시간이 쪼금 남던 내가 맡을 수 있는 기회가 왔다!

속도 개선

기존 상황

응답 시간은 평균 약 5.7초였고, 응답 중 70%가 4초를 넘어갔다.

문제 로직

디버깅 로그를 통해 구간 별로 측정한 시간에서 Redis에서 조회하는 부분에 병목이 있었다.
Redis 조회 부분에서 8초 씩 소요되는 것을 확인했다.

결제API와 가격 조회 API가 있는데, 전부 외부 API를 호출에 의존하고 있는 구조다.
여기서 Redis를 쓰는 로직은 다음과 같다.

• 결제 API
  • 외부 서버에 결제 요청을 했을 때 실패한 경우, 해당 상품의 id와 실패 횟수를 1씩 증가시키며 저장
  • TTL 1시간 설정
• 가격 조회 API
  • 외부 서버에 호출해 받아온 상품들 중, 이전에 결제 실패가 특정 횟수를 넘어간 상품은 응답에서 제외
  • 최근 예약 실패 건을 Redis에서 전체 조회하여 애플리케이션 단에서 필터링 작업

예약 실패가 빈번하지 않아서, 실제로도 Redis에 저장된 건도 2~3개 밖에 없는데 조회가 O(N) 이라고 해도 3건을 조회하는데 시간이 이렇게 많이 소요되는 것이 이해가 되지 않았다.

java spring으로 redis crud를 이전에 해보지 않아서, RedisHash가 어떻게 Redis에 CRUD 동작을 만들어내는지 구체적으로는 몰랐다.

findAll() 이 어떻게 동작하는지를 알아야 할 것 같은데, 문서를 찾아보며 공부 하고 개선을 시키기에는 자꾸 느려서 빨리 해결하달라는 재촉이 엄청나게 들어와서 임시 조치라도 할 수 있는 방법을 찾아야했다.

Prod Redis에 직접 접속해서 Data를 확인해보기에는 접근 권한 신청하고 설치해야하는게 한 두개가 아니였고, 주변 다른 팀도 직접 접근해본 분이 없어서 셋팅 작업이 만만치 않았지만, 검색해보다가 시간을 쓰기보다는 직접 눈으로 보는게 더 확실할 것 같아서 오랜 삽질 끝에 접근을 해봤다.

Redis 명령과 자료구조 파헤치기

코드를 간략하게 나타내면 다음과 같다.

@RedisHash(value = "failed_product", timeToLive = 60 * 60)
public class FailedProduct {
  // field
}

public interface FailedProductRepository extends CrudRepository<FailedProduct, Long> {

  List<FailedProduct> findAll();
}

public class Service {

  public Map<Long, FailedProduct> findAllFailedProducts() {
    return failedProductRepository.findAll().stream()
            .filter(Objects::nonNull)
            .filter(entity -> entity.getCount() >= exceptCount)
            .collect( // collect to map 
            );

      }
}

Redis에 직접 확인해봤을 때도 저장되어 있는 건은 2개 밖에 없었고, 생각했던 대로 자료구조도 Hash를 사용하고 있었다.

$ redis-cli > keys failed_product*
failed_product
failed_product:id1
failed_product:id3

$ redis-cli > type failed_product:id1
hash

저장과 조회 명령어들을 직접 확인하는게 제일 정확할 것 같아 monitor 를 실행했는데 엄청나게 많은 명령어들이 실행되고 있었다..

monitor 명령을 실행하기 전에 뇌피셜로 keys failed_product* 로 id를 가져오고, 여기서 하나 씩 hash key 별로 조회하지 않을까 생각했었다.

여기서 이상한 점은 hash로 저장된 건이 2개인데, 없는 id들까지 몇 천개를 계속 조회하고 있었다.

$ redis-cli > monitor

HGETALL failed_product:id1
HGETALL failed_product:id2
HGETALL failed_product:id3
...
HGETALL failed_product:id2452

@RedisHash 동작 과정

아무튼 수집한 명령들을 기반으로 동작 과정을 역으로 알아냈다.

결론만 말하면, HASH는 Application 단에서 설정한 TTL 이후 사라지지만, SET에서 삭제하는 명령이 따로 수행되지 않았다.

1. 현재 저장된 상태
   • set에는 hash의 id들을 저장
   • {RedisHash value} : {id} 형태로 hash 저장

2. 새로운 데이터 저장
   • set에 id를 추가한다.
     • SADD failed_product {id}
   • hash 자료형에 failed_product:id 를 key로 하여 저장 및 TTL 시간 설정
     • HSET failed_product:id field1 value1 ..
     • expire failed_product:id ttl시간

3. TTL이 만료되었을 때
   • 2번에서 hash 자료형만 ttl을 설정했기 때문에 hash만 삭제되고, set에는 id1이 계속 남아있다.

4. repository.findAll() 수행

• 이때까지 저장된적있는 데이터의 수 : n, failed_product 필드 수 : m
• set 자료형에 있는 id를 조회 : O(n)
  • SMEMERS failed_product
• id들을 하나 씩 hash 조회 : O(n*m)
  

HGETALL failed_product:id1
HGETALL failed_product:id2
HGETALL failed_product:id3
…

해결하기

set의 데이터가 지워지지 않고, 이를 계속 조회하는 것 때문에 이때까지 계속 쌓인 내용을 조회하면서 진짜로 O(N)이 되어버렸던 것이였다. (m=4여서 크지 않음)

우선 TTL이 만료된 id들은 set에서 전부 지우니, 응답 시간은 평균 약 1.4초였고 (307% 개선), 4초를 넘어가는 응답의 비율이 70%에서 6%로 엄청나게 줄었다.

정확한 수치는 공개할 수 없지만, X 축이 응답 시간이고 Y축이 갯수로 파란색 -> 초록색으로 변했다고 보면 된다.

개선하기

원인이 되는 지점을 알고나니 해당 키워드로 찾았더니 대응 방안을 알아낼 수 있었는데 개선 방안은 크게 두가지가 있었다.

1. RedisTemplate 으로 직접
   • RedisTemplate 학습 필요
   • save 구현이 오래걸림
2. HASH TTL이 만료되는 것을 Application에서 구독 설정
   • spring data redis에서 expire를 받으면 set의 내용도 지우도록 되어있음 (srem)
   • spring-data-redis 코드
   • 하나의 Application에서만 Redis에 요청해도 충분한데 API application 에서 구독하면 분산된 인스턴스 전체가 구독하게됨
   • Pub/Sub을 사용하면 RedisStaticMasterReplicaConfiguration 을 사용할 수 없음

맨 처음에 말했듯이 내부 사정때문에 해당 프로젝트의 코드를 오래 작업할 수 없어, 윗 분들께 현상을 공유하고 두 가지 중에 어떤 방식으로 작업할지 여쭤봤다.

1번으로 하는게 나도 새로운걸 배우면서 개발할 수 있어서 좋겠지만, 2번으로 빨리 대응하고 다른 티켓을 또 처리하는게 낫다고 결정되어 2번으로 진행했다.

enableKeyspaceEvents

2번의 동작은 다음과 같다.

대신 2번에도 Pub/Sub으로 인한 단점이 위의 내용과 같이 있었기때문에 1개의 인스턴스만 있는 Batch Server에서만 구독하고 만료된 key를 지우도록 설정했다.

  @Configuration
  @Profile("prod|dev")
  @EnableRedisRepositories(enableKeyspaceEvents = RedisKeyValueAdapter.EnableKeyspaceEvents.ON_STARTUP, keyspaceNotificationsConfigParameter = "")
  @ConditionalOnProperty(name = "spring.application.name", havingValue = "구독 할 어플리케이션 이름")
  public static class RedisPubSubConfig {
  }

AWS ElastiCache를 사용한다면, 코드에서 keyspaceNotificationsConfigParameter를 설정할 수 없기 때문에 코드는 빈 문자열을 넣어두고
실제로 콘솔에 들어가서 아래 작업을 해줘야한다.

• 파라미터 그룹 신규 생성
• notify-keyspace-events 값 추가 : Ex

이렇게 설정해두고 Redis에 다시 들어가서 monitor로 명령들을 빠안히 쳐다보고 있으면 원하는 대로 srem 명령이 날라오는 것을 볼 수 있다.

느낀점

라이브러리 문서의 전체를 다 읽어보고 개발을 시작할 수는 없기에, 나도 그렇고 초기 개발을 하셨던 분도 간단한 well known practice code를 찾아서 개발하고 동작하면 다음 구현으로 넘어가는 상황이 많을거라 생각한다.

라이브러리에서 알아서 잘 해주겠거니~ 하고 넘겼던 부분들에서 내가 설정을 다르게 해야하거나, 빠트리는 부분이 생길 수도 있단걸 몸소 느낄 수 있었던 작업이었다.

코드 버그나 설계의 문제점을 찾는 개선과는 다른 개선 작업이었어서 중간에 고통스러운 지점도 있었으나, 개선된 수치를 딱 확인하고 신나게 퇴근 후 다음날 다른분들께 공유하는 자리의 즐거움 때문에 백엔드가 재미있는 것같다.

이 글을 쓰는 지금도 또 삽질 작업 중이라 고통스럽긴하지만

---

참고

https://repost.aws/ko/knowledge-center/elasticache-redis-keyspace-notifications
https://redis.io/docs/manual/keyspace-notifications/
https://jybaek.tistory.com/930
http://redisgate.kr/redis/command/pubsub_config.php
https://zorba91.tistory.com/354