Audit Log 조회 API 성능 개선기 - 1

들어가며

프로젝트 관리 시스템 프로젝트를 진행하면서

유저, 회사, 프로젝트, 댓글 등 여러 엔티티의 생성, 수정, 삭제 내역을 조회하는 API를 개발해야 했다.

 

ERD는 위와 같이 구성되어 있었다.

만약 수정의 경우 audit_log_detail을 통해 수정 전과 수정 후 데이터를 저장하고자 했다.

최초 구상시에는 Spring AOP를 활용해 구현하고자 했지만

AOP를 적용하기 위해선 현재 작동하는 비즈니스 로직들을 수정해야하는 상황이 발생해서

결국 AOP를 사용하지 않고 비즈니스 로직에 AuditLog에 데이터를 기록하는 로직을 추가했다.

 

로직 설명

예시로 프로젝트 생성 로직의 경우

createProjcet -> createAuditLog -> auditLogFactory

식의 의존 방향을 통해 생성 로그가 DB에 저장되는 방식이다.

프로젝트 수정의 경우

간단히 설명하자면

수정전과 수정후 스냅샷 비교를 통해 변경된 데이터를 auditLogDetail 에 저장하는 방식이다.

 

발생한 문제

해당 로직을 구현하고 10,000개의 데이터를 바탕으로 테스트하는 과정에서

조회 API가 비정상적으로 느린 현상을 발견하였다.

Spring AOP 를 활용해 응답시간을 확인해본 결과

2025-04-25 11:58:29.609 [https-jsse-nio-443-exec-6]  INFO com.welcommu.moduleapi.aop.ExecutionTimeLogger - ⏱️ List com.welcommu.moduleservice.logging.AuditLogSearchService.searchLogs(ActionType,TargetType,String,String,Long) executed in 2812 ms
2025-04-25 11:58:29.609 [https-jsse-nio-443-exec-6]  INFO com.welcommu.moduleapi.aop.ExecutionTimeLogger - ⏱️ ResponseEntity com.welcommu.moduleapi.logging.AuditLogController.searchAuditLogs(ActionType,TargetType,String,String,Long) executed in 2812 ms

요청에서 응답까지의 시간을 확인해본 결과 평균적으로 2800ms의 시간이 소요되는 것을 확인하였다.

 

원인 분석

콘솔 로그에 뜨는 sql 쿼리문을 분석한 결과

현재 aduditLog ↔ audiltLogDetail 간의 연관 관계에서

audiltLog를 통해 테이블 데이터를 조회할경우 audiltLogDetail의 정보도 필요하기에

aduditLog ↔ audiltLogDetail

1 + N 개의 쿼리가 나가고 있는 현상을 발견하였다.

N + 1 문제 발생!

2025-04-25 12:01:57.679 [https-jsse-nio-443-exec-9]  INFO com.welcommu.modulecommon.filter.JwtAuthenticationFilter - 유효한 JWT 토큰으로 인증된 사용자: admin@naver.com
2025-04-25 12:01:57.679 [https-jsse-nio-443-exec-9] DEBUG org.springframework.security.web.FilterChainProxy - Secured GET /api/auditLog/search?
Hibernate: 
    select
        al1_0.id,
        al1_0.action_type,
        al1_0.actor_id,
        al1_0.logged_at,
        al1_0.target_id,
        al1_0.target_type 
    from
        audit_log al1_0 
    where
        1=1
Hibernate: 
    select
        d1_0.audit_log_id,
        d1_0.id,
        d1_0.field_name,
        d1_0.new_value,
        d1_0.old_value 
    from
        audit_log_detail d1_0 
    where
        d1_0.audit_log_id=?
Hibernate: 
    select
        d1_0.audit_log_id,
        d1_0.id,
        d1_0.field_name,
        d1_0.new_value,
        d1_0.old_value 
    from
        audit_log_detail d1_0 
    where
        d1_0.audit_log_id=?
        ...

문제가 발생한 dto

public class AuditLogResponse {

    private Long id;
    private Long actorId;
    private String targetType;
    private Long targetId;
    private String actionType;
    private LocalDateTime loggedAt;
    private List<AuditLogDetailResponse> details;

    public static AuditLogResponse from(AuditLog log) {
        return new AuditLogResponse(
            log.getId(),
            log.getActorId(),
            log.getTargetType().name(),
            log.getTargetId(),
            log.getActionType().name(),
            log.getLoggedAt(),
            log.getDetails().stream().map(AuditLogDetailResponse::from).toList()  <- 문제 발생 부분
        );
    }
}

logDetail을 불러오는 과정에서 N + 1 이 발생하는 것을 확인했다.

해결과정

기존에는 audlitLog 조회시

커스텀 쿼리를 통해 여러개의 쿼리문을 보냄으로서 N + 1 문제가 발생했다. 

package com.welcommu.moduleinfra.logging;

import com.welcommu.moduledomain.logging.AuditLog;
import com.welcommu.moduledomain.logging.enums.ActionType;
import com.welcommu.moduledomain.logging.enums.TargetType;
import jakarta.persistence.EntityManager;
import jakarta.persistence.TypedQuery;
import java.time.LocalDateTime;
import java.util.HashMap;
import java.util.List;
import java.util.Map;
import lombok.RequiredArgsConstructor;
import org.springframework.stereotype.Repository;

@Repository
@RequiredArgsConstructor
public class AuditLogRepositoryImpl implements AuditLogRepositoryCustom {

    private final EntityManager em;

    @Override
    public List<AuditLog> findByConditions(
        ActionType actionType,
        TargetType targetType,
        LocalDateTime startDate,
        LocalDateTime endDate,
        Long userId
    ) {
        StringBuilder sb = new StringBuilder("SELECT a FROM AuditLog a WHERE 1=1");
        Map<String, Object> params = new HashMap<>();

        if (actionType != null) {
            sb.append(" AND a.actionType = :actionType");
            params.put("actionType", actionType);
        }
        if (targetType != null) {
            sb.append(" AND a.targetType = :targetType");
            params.put("targetType", targetType);
        }
        if (startDate != null) {
            sb.append(" AND a.loggedAt >= :startDate");
            params.put("startDate", startDate);
        }
        if (endDate != null) {
            sb.append(" AND a.loggedAt <= :endDate");
            params.put("endDate", endDate);
        }
        if (userId != null) {
            sb.append(" AND a.actorId = :userId");
            params.put("userId", userId);
        }

        TypedQuery<AuditLog> query = em.createQuery(sb.toString(), AuditLog.class);
        params.forEach(query::setParameter);

        return query.getResultList();
    }
}

 

전송하는 쿼리의 수를 줄이기 위해 fetch join을 적용하여 N + 1 문제를 해결하고자 했다.

다른 해결책(예: @BatchSize, @EntityGraph)도 있지만, fetch join은 개발자가 데이터 로딩 시점을 명확하게 제어할 수 있다는 장점이 있기에 fetch join으로 해결하고자 했다.

fetch join은 JPQL 쿼리 내에서 즉시 로딩(EAGER)할 연관 관계를 명시적으로 선언하는 방식이다.

이를 통해 개발자는 데이터가 필요한 특정 상황에서만 함께 조회하도록 직접 제어할 수 있고, 이는 애플리케이션의 동작을 예측 가능하게 만들고, 다른 곳에서 발생할 수 있는 잠재적인 성능 문제를 방지하는 효과가 있기에 이 방식을 선택했다.

복잡한 동적 쿼리이기도 했고 쿼리의 동작을 명확하게 제어하고 싶었기에 이러한 방식이 더 좋다고 생각했다.

package com.welcommu.moduleinfra.logging;

import com.welcommu.moduledomain.logging.AuditLog;
import com.welcommu.moduledomain.logging.enums.ActionType;
import com.welcommu.moduledomain.logging.enums.TargetType;
import jakarta.persistence.EntityManager;
import jakarta.persistence.TypedQuery;
import java.time.LocalDateTime;
import java.util.HashMap;
import java.util.List;
import java.util.Map;
import lombok.RequiredArgsConstructor;
import org.springframework.stereotype.Repository;

@Repository
@RequiredArgsConstructor
public class AuditLogRepositoryImpl implements AuditLogRepositoryCustom {

    private final EntityManager em;

    @Override
    public List<AuditLog> findByConditions(
        ActionType actionType,
        TargetType targetType,
        LocalDateTime startDate,
        LocalDateTime endDate,
        Long userId
    ) {
        StringBuilder sb = new StringBuilder("SELECT DISTINCT a FROM AuditLog a LEFT JOIN FETCH a.details WHERE 1=1");
        Map<String, Object> params = new HashMap<>();

        if (actionType != null) {
            sb.append(" AND a.actionType = :actionType");
            params.put("actionType", actionType);
        }
        if (targetType != null) {
            sb.append(" AND a.targetType = :targetType");
            params.put("targetType", targetType);
        }
        if (startDate != null) {
            sb.append(" AND a.loggedAt >= :startDate");
            params.put("startDate", startDate);
        }
        if (endDate != null) {
            sb.append(" AND a.loggedAt <= :endDate");
            params.put("endDate", endDate);
        }
        if (userId != null) {
            sb.append(" AND a.actorId = :userId");
            params.put("userId", userId);
        }

        TypedQuery<AuditLog> query = em.createQuery(sb.toString(), AuditLog.class);
        params.forEach(query::setParameter);

        return query.getResultList();
    }
}

 

변경된 내용 요약

BEFORE
StringBuilder sb = new StringBuilder("SELECT a FROM AuditLog a WHERE 1=1");

AFTER        
StringBuilder sb = new StringBuilder("SELECT DISTINCT a FROM AuditLog a LEFT JOIN FETCH a.details WHERE 1=1");

문제 해결

fetch join을 통해 N + 1 문제를 해결하니 응답속도가 상당히 빨라졌다.

문제 해결 후 콘솔 로그

2025-04-25 12:12:10.635 [https-jsse-nio-443-exec-8]  INFO com.welcommu.modulecommon.filter.JwtAuthenticationFilter - 유효한 JWT 토큰으로 인증된 사용자: admin@naver.com
2025-04-25 12:12:10.636 [https-jsse-nio-443-exec-8] DEBUG org.springframework.security.web.FilterChainProxy - Secured GET /api/auditLog/search?
Hibernate: 
    select
        distinct al1_0.id,
        al1_0.action_type,
        al1_0.actor_id,
        d1_0.audit_log_id,
        d1_0.id,
        d1_0.field_name,
        d1_0.new_value,
        d1_0.old_value,
        al1_0.logged_at,
        al1_0.target_id,
        al1_0.target_type 
    from
        audit_log al1_0 
    left join
        audit_log_detail d1_0 
            on al1_0.id=d1_0.audit_log_id 
    where
        1=1

쿼리문도 1개가 나가는 것을 확인했다.

수정 후 응답시간

2025-04-25 12:10:11.670 [https-jsse-nio-443-exec-1]  INFO com.welcommu.moduleapi.aop.ExecutionTimeLogger - ⏱️ List com.welcommu.moduleservice.logging.AuditLogSearchService.searchLogs(ActionType,TargetType,String,String,Long) executed in 120 ms
2025-04-25 12:10:11.670 [https-jsse-nio-443-exec-1]  INFO com.welcommu.moduleapi.aop.ExecutionTimeLogger - ⏱️ ResponseEntity com.welcommu.moduleapi.logging.AuditLogController.searchAuditLogs(ActionType,TargetType,String,String,Long) executed in 120 ms

 

응답속도는 2800ms -> 120ms로 상당히 빨라진 모습을 확인할 수 있었다.

1차 성능 개선 완료.