[Trouble Shooting] 로그 조회 성능 개선하기

🎯 끔찍한 현재의 조회 성능

---

초기 MVP 를 개발할때 성능에 대해서 크게 신경쓰지 않고 기능 구현에 집중해 로그 조회 기능을 만들었습니다. 로그 저장 기능을 개선했으니 이제 로그 조회 기능을 개선할 시기인 것 같습니다. (두근두근)

 

일단 현재 로그 조회 기능은 다음과 같이 설계 되어 있습니다.

 

1. 사용자가 발급한 REST API KEY 를 쿼리 로그 객체에 함께 저장한다.

2. 사용자가 자신의 쿼리 로그를 조회할때 REST API KEY 를 Header 에 넣고 이를 기준으로 DB 에서 필터링 한다.

 

 

부하 테스트 결과

 

Trace 추적 결과

 

 

현재 MongoDB 에는 약 600,000 건의 로그 데이터가 저장되어 있습니다. 예상은 했지만 생각보다 너무 느린 조회 속도 입니다. 당연(?)하게 쿼리쪽이 병목 지점이라 생각했고 하나의 요청에 대한 Trace 로 추적 확인해본결과 역시나 페이지 번호가 커질수록 Repository 에서 호출할때 9s 정도의 시간이 소요됨을 확인했습니다.

 

 

 

페이징 조회 메서드

    @Override
    public Page<QueryLogResponse> findLogsByPageable(String key, Pageable pageable) {
        Query query = new Query()
                .addCriteria(Criteria.where("key").is(key))
                .with(pageable)
                .with(Sort.by(Sort.Direction.DESC, "created_at"));

        List<QueryLog> logs = mongoTemplate.find(query, QueryLog.class);

        long total = mongoTemplate.count(Query.of(query).limit(-1).skip(-1), QueryLog.class); // 전체 카운트

        List<QueryLogResponse> content = logs.stream()
                .map(log -> QueryLogResponse.builder()
                        .id(log.getId().toHexString())
                        .methodName(log.getMethodName())
                        .sqlQuery(log.getSqlQuery())
                        .executionPlan(log.getExecutionPlan())
                        .duration(log.getDuration())
                        .createdAt(log.getCreatedAt())
                        .build())
                .toList();

        return new PageImpl<>(content, pageable, total); // Page 객체로 래핑
    }

 

 

그러면 어떻게 조회 성능을 개선할까? 가장 먼저 생각난 키워드는 역시 [ 인덱스 ] 입니다. 로그 객체를 조회할때 key 를 이용해 조건을 걸고 create_at 을 통해 정렬하고 있습니다. key 와 created_at 을 통해 복합 인덱스를 만들건데 이때 순서가 중요 합니다. key 가 첫번째 필드여야만 key 조건으로 인덱스 범위를 좁힐 수 있습니다. 그 다음 created_at 을 내림차순으로 지정해 조건에 맞는 데이터들을 created_at 내림차순으로 바로 가져올 수 있습니다. ( 만약 순서가 바뀌면 인덱스 활용도가 느려질 수 있습니다. )

 

 

 

[ 복합 인덱스 생성 ] 

@Getter
@Builder
@AllArgsConstructor
@NoArgsConstructor
@Document(collection = "query_log")
@CompoundIndex(def = "{'key': 1, 'created_at': -1}", name = "key_createdAt_idx")
public class QueryLog {

    @Id
    private ObjectId id;

    @Field("key")
    private String key;

    @Field("method_name")
    private String methodName;

    @Field("sql_query")
    private String sqlQuery;

    @Field("execution_plan")
    private String executionPlan;

    @CreatedDate
    @Field("created_at")
    private LocalDateTime createdAt;

    @Field("duration")
    private long duration;

    public static QueryLog from(String key, QueryLogRequest request) {
        return QueryLog.builder()
                .key(key)
                .methodName(request.getMethodName())
                .sqlQuery(request.getSqlQuery())
                .executionPlan(request.getExecutionPlan())
                .duration(request.getDuration())
                .createdAt(request.getCreatedAt())
                .build();
    }
}

 

 

@CompoundIndex(def = "{'key': 1, 'created_at': -1}", name = "key_createdAt_idx")

 

@CompoundIndex 애노테이션을 사용해 key 와 created_at 을 이용한 복합 인덱스를 만들었습니다. 바로 성능 테스트를 해보면 다음과 같은 결과를 얻을 수 있습니다.

 

 

[ 복합 인덱스 추가 후 부하 테스트 결과 ]  

 

눈에 띄게 속도가 빨라졌지만 여전히 평균 응답 시간으 5.42s 로 느린편에 속합니다.. 그러면 병목지점이 어디일까? 이전에 RDBMS 에서 페이징 조회 기능을 개선할때 페이지 번호가 뒤로 갈 수록 버려지는 데이터가 많았던 기억이 떠올라 페이징 조회로 쏘는 쿼리가 병목지점일 수 있겠다는 의심을 가지게 되었습니다. 

 

 

 

🎯 쿼리 튜닝

---

 

MongoDB 의 페이지네이션 구현 방식은 skip + limit + count() 로 구성되어 있습니다. 예를 들어 10개 씩 페이지 조회를 하면

PageRequest.of(2,10) // 3 페이지

 

위와 같이 요청하면 MongoDB 는 다음과 같이 실행됩니다.

 

db.query_log.fing({ key : 'api_key'})
	.sort({ created_at : -1 })
    .skip(20) // 앞에서 20개 건너뜀
    .limit(10); // 10개를 가져온다.

 

여기서 skip(n) 은 MongoDB 가 무조건 n 개의 문서를 스캔하고 건너 뛰기 때문에 페이지 번호가 높아질수록 skip() 속도가 느려집니다. 즉, 60만 건의 데이터가 있을때 만약 skip 되는 양이 50만건이면 느려지는 것이 당연합니다.

 

또한 countDocuments 도 모든 문서를 뤃ㅌ어서 개수를 세기 때문에 데이터가 수십만 건 이상이면 굉장이 느려질 수 있습니다. 이러한 문제를 해결할 수 있는 커서 기반 페이징 이라고 합니다. 즉 이전까지 조회된 쿼리의 created_at 을 기억하고 [ created_at < 이전 커서 ] 처럼 조건으로 건너뛰면 skip() 없이 효율적으로 조회할 수 있습니다.

 

 

커서 기반 페이징으로 튜닝된 쿼리 

    @Override
    public QueryLogCursorResponse findLogsByCursor(String key, LocalDateTime cursorCreatedAt, int size) {
        Criteria criteria = Criteria.where("key").is(key);

        if (cursorCreatedAt != null) {
            Date cursorCreatedAtDate = Date.from(cursorCreatedAt.toInstant(ZoneOffset.UTC));
            criteria = criteria.and("created_at").lt(cursorCreatedAtDate);
        }

        Query query = new Query()
                .addCriteria(criteria)
                .with(Sort.by(Sort.Direction.DESC, "created_at"))
                .limit(size + 1);

        List<QueryLog> logs = mongoTemplate.find(query, QueryLog.class);
        boolean hasNext = logs.size() > size;
        if (hasNext) {
            logs.remove(size);
        }

        List<QueryLogResponse> content = logs.stream()
                .map(log -> QueryLogResponse.builder()
                        .id(log.getId().toHexString())
                        .methodName(log.getMethodName())
                        .sqlQuery(log.getSqlQuery())
                        .executionPlan(log.getExecutionPlan())
                        .duration(log.getDuration())
                        .createdAt(log.getCreatedAt())
                        .build())
                .toList();

        LocalDateTime nextCursor = hasNext
                ? logs.get(logs.size() - 1).getCreatedAt()
                : null;

        return new QueryLogCursorResponse(content, hasNext, nextCursor);
    }

 

key 에 해당하는 로그만 조회하도록 조건을 걸었습니다.

Criteria criteria = Criteria.where("key").is(key);

 

created_at < cusorCreatedAt 라는 커서 조건을 추가해 마지막으로 조회된 시간의 로그보다 오래된 로그를 조회하는 조건 입니다.

if (cursorCreatedAt != null) {
    Date cursorCreatedAtDate = Date.from(cursorCreatedAt.toInstant(ZoneOffset.UTC));
    criteria = criteria.and("created_at").lt(cursorCreatedAtDate);
}

 

그리고 요청된 개수보다 1개 더 조회해서 다음 페이지가 있는지 여부(hasNext) 를 판단합니다. 이렇게 조회된 쿼리 로그들을 DTO 로 감싼 뒤 반환해줍니다.

 

 

이렇게 구현된 커서 기반 페이징 방법은 기존 페이징 조회 방식에서의 skip() 과정 과 전체 페이지수를 조회하는 과정이 생략돼 수십만 건의 데이터가 쌓였을때도 빠른 조회 속도를 확보할 수 있습니다. 자! 이제 성능이 잘 개선되었는지 확인해볼까염

 

 

 

개선된 쿼리 페이징 조회 부하 테스트 결과

 

총 60만 건의 데이터가 DB 에 적재 되어 있고, 부하 테스트를 실행해본 결과 기존의 페이징 조회 기능 평균 응답 시간이 5.42s -> 409.59ms 로 향상되었으며 약 92% 정도 응답 시간이 개선되었습니다. RPS 도 13 에서 125 로 향상되어 10개 가까이 증가해 훨씬 더 많은 트래픽을 처리할 수 있게 되었습니다. 

 

 

지금까지 복합 인덱스 + 커서 기반 페이징 조회 방법을 적용해 대용량 데이터가 적재된 DB 에서 조회 성능을 개선해 보았습니다.