필터를 사용해 API 성능 로그 만들기

들어가며

요즘카페 서비스를 개발하면서 우리가 만든 API가 잘 작동하는지 검증할 필요가 있었다. API 별로 테스트를 통해 잘 동작하는지 검증할 수는 있지만 실제 돌아가는 환경에서 확인하고자 하였다.

이를 통해 API 별로 발생할 수 있는 쿼리, 수행 시간, 성능 등을 측정하고자 하는 필요성이 느껴져 진행하게 되었다.

로그로 남기고자 하는 데이터는 요청 URI, Method, 응답까지 걸리는 시간(ms), 발생 쿼리 횟수를 남기고자 하였다.

요청 URI, Method

로그로 요청 URI를 남기면서 어떤 요청에 대해 예외가 발생했고, 요청 빈도 수는 어떻게 되는 지를 알아차릴 수 있다.

@Component
public class LatencyLoggingFilter extends OncePerRequestFilter {

    private static final Logger LOGGER = LoggerFactory.getLogger(LatencyLoggingFilter.class);

    @Override
    protected void doFilterInternal(final HttpServletRequest request, final HttpServletResponse response,
                                    final FilterChain filterChain) throws ServletException, IOException {
        LOGGER.info("Request URI: {} {]", request.getMethod(), request.getRequestURI());
        filterChain.doFilter(request, response);
    }
}

스프링에서 제공하는 OncePerRequestFilter 를 상속해서 구현하였다. 이를 통해 요청당 한번만 사용되는 필터를 구현하였다. 이를 사용하지 않을 경우에는 여러 서블릿 에서 의도치 않게 같은 필터가 호출될 수 도 있기 때문에 이를 사용하였다.

Logger를 사용하고 이후 필터를 진행하기 위해 doFilter()를 호출하였다. 이를 호출하지 않을 경우 필터의 요청,응답은 진행되지 않는다.

여러 필터가 등록되어 있다면 순서를 어떻게 해야할까?

@Order(0)
@Component
public class LatencyLoggingFilter extends OncePerRequestFilter {
	...
}

@Bean
public FilterRegistrationBean<LatencyLoggingFilter> latencyLoggingFilterFilter() {
    return registerFilter(latencyLogging, 0);
}

private <F extends Filter> FilterRegistrationBean<F> registerFilter(final F f, final int order) {
    final FilterRegistrationBean<F> filter = new FilterRegistrationBean<>(f);
    filter.setOrder(order);

    return filter;
}

여러 필터가 추가될 경우 필터의 순서를 추가해줘야 한다. Chaining 방식으로 여러개를 설정한 뒤 Order 어노테이션을 지정하지 않는다면 알파벳 순으로 진행되기 때문에 순서를 추가해줘야한다.

1. 상단 코드처럼 @Order를 이용하여 처리할 수도 있다.
2. 순서를 지정해 주기 위해 다음과 같이 Configuration에 순서와 함께 필터를 등록할 수도 있다.

응답까지 걸리는 시간(ms)

API의 요청이 들어오고 응답이 나가기 까지 걸리는 시간을 알아보고자 하였다.

단순하게 응답 시간 - 요청 시간 = 처리 시간 이라고 생각하였다. 사용자 별로 시간 관리를 하는 방법을 고민해봤다.

1. @RequestScope를 사용하여 요청별로 웹 scope를 지정
2. ThreadLocal을 사용하여 쓰레드 별로 처리

@RequestScope를 사용

@RequestScope
@Component
public class Timer {

    private final long startMillis = System.currentTimeMillis();

    public long getLatencyMillis() {
        return System.currentTimeMillis() - startMillis;
    }
}

Timer 이라는 객체를 만들고 @RequestScope 를 통해 요청부터 응답까지로 빈생명주기를 설정했다.

생성시에 startMillis가 생성되고 응답전에 getLatencyMillis 를 호출하면 응답까지 걸리는 시간이 계산 된다.

@Component
public class LatencyLoggingFilter extends OncePerRequestFilter {

    private static final Logger LOGGER = LoggerFactory.getLogger(LatencyLoggingFilter.class);

    private final Timer timer;

    public LoggingFilter(final Timer timer) {
        this.timer = timer;
    }

    @Override
    protected void doFilterInternal(final HttpServletRequest request, final HttpServletResponse response,
                                    final FilterChain filterChain) throws ServletException, IOException {
        filterChain.doFilter(request, response);        
				LOGGER.info("Request URI: {} {} {}", request.getMethod(), request.getRequestURI(), timer.getLatencyMillis());
    }
}

이후 필터가 처리된 이후에 응답시간과 함께 로그를 찍기 위해 doFilter() 순서를 변경하였다.

ThreadLocal 사용

스프링 부트에서는 다중 요청을 어떻게 처리할까? 스프링부트는 톰캣을 내장하고 있는데, 톰캣은 부팅하면서 ThreadPool을 생성한다. 이 때 요청이 들어오면 ThreadPool에서 하나씩 Thread를 할당하고 각각의 요청을 처리한다. 그렇게 요청 별 처리 가 스레드 별 처리가 될 수 있는 것이다.

@Component
public class Timer {

    private final ThreadLocal<Long> threadLocal = new ThreadLocal<>();

    public void start() {
        threadLocal.set(System.currentTimeMillis());
    }

    public double getDurationSeconds() {
        final long start = threadLocal.get();
        final long end = System.currentTimeMillis();

        threadLocal.remove();
        final double millis = (double) end - start;
        return millis / 1000;
    }
}

ThreadLocal이라는 각 쓰레드별 저장 공간 이다. 여기서 시작 시간과 종료 시간을 계산해주고 반환해준다.

@Component
public class LatencyLoggingFilter extends OncePerRequestFilter {

    private static final Logger LOGGER = LoggerFactory.getLogger(LatencyLoggingFilter.class);

    private final Timer timer;

    public LoggingFilter(final Timer timer) {
        this.timer = timer;
    }

    @Override
    protected void doFilterInternal(final HttpServletRequest request, final HttpServletResponse response,
                                    final FilterChain filterChain) throws ServletException, IOException {
				timer.start();        
				filterChain.doFilter(request, response);     
				timer.getDurationSeconds();   
				LOGGER.info("Request URI: {} {} {}", request.getMethod(), request.getRequestURI(), timer.getLatencyMillis());
    }
}

다음처럼 시간을 계산하도록 처리할 수 있다.

발생 쿼리 횟수

요청 API 별로 발생한 쿼리 횟수를 카운트 해보려고 한다. 이를 통해 직관적으로 현재 API에서 얼마나 쿼리가 발생하고 있는지 판별할 수 있다. 또한 N+1 문제를 해결하는데도 조금은 도움이 되었던 것 같다.

쿼리 횟수를 카운트 하는 이유 중에 하나로는 요청이 외부 시스템과 통신을 하면서 시간이 오래 걸릴 수 있는데 이를 최적화 하기 위해 알아볼 방법 중 하나 일 수 있다.

@Component
public class QueryInspector implements StatementInspector {

    private final QueryCounter queryCounter;

    public QueryInspector(final QueryCounter queryCounter) {
        this.queryCounter = queryCounter;
    }

    @Override
    public String inspect(final String sql) {
        if (inRequestScope()) {
            queryCounter.increase();
        }

        return sql;
    }

    private boolean inRequestScope() {
        return nonNull(RequestContextHolder.getRequestAttributes());
    }

    public int getQueryCount() {
        return queryCounter.getCount();
    }
}

StatementInspector를 구현하는 QueryInspector 를 만들었다. StatementInspector 는 Hibernate에서 제공하는 인터페이스이다. 이는 모든 Hibernate SQL문을 실행되기 전에, SQL문을 변경하여 실행할 수 있는 역할을 한다.

위의 코드는 sql이 들어올 때 Null체크를 하고 queryCounter의 개수를 늘린다. 이후 이 값을 사용하기 위해서는 getQueryCount() 를 통해 조회를 한다.

@Component
@RequestScope
public class QueryCounter {

    private int count = 0;

    public void increase() {
        count++;
    }

    public int getCount() {
        return count;
    }
}

우리는 요청 별로 횟수를 관리해야 하기 때문에 위에서 처럼 RequestScope나 ThreadLocal 을 사용할 수 있다.

@Configuration
public class HibernateConfiguration {

    private final QueryCountInspector queryCountInspector;

    public HibernateConfiguration(final QueryCountInspector queryCountInspector) {
        this.queryCountInspector = queryCountInspector;
    }

    @Bean
    HibernatePropertiesCustomizer hibernatePropertiesCustomizer() {
        return properties -> properties.put(AvailableSettings.STATEMENT_INSPECTOR, queryCountInspector);
    }
}

위의 코드를 통해서 StatementInspector가 구현 되었을 때, SQL이 발생할 때마다 inspect() 를 호출 할 수 있도록 Configuration을 설정해 주었다.

@Component
public class LatencyLoggingFilter extends OncePerRequestFilter {

    private static final Logger LOGGER = LoggerFactory.getLogger(LatencyLoggingFilter.class);

    private final Timer timer;

    public LoggingFilter(final Timer timer) {
        this.timer = timer;
    }

    @Override
    protected void doFilterInternal(final HttpServletRequest request, final HttpServletResponse response,
                                    final FilterChain filterChain) throws ServletException, IOException {
				timer.start();        
				filterChain.doFilter(request, response);     
				final double durationSeconds = timer.getDurationSeconds();   
        final int queryCount = queryInspector.getQueryCount();

				LOGGER.info("Request URI: {} {}, Latency {}s, Query Count {}", request.getMethod(), request.getRequestURI(), durationSeconds, queryCount);
    }
}

나가며

요청 URI, Method, 응답까지 걸리는 시간(ms), 발생 쿼리 횟수 를 로깅으로 찍어보았다. 이를 통해 API 빈도수, 조회수 등을 파악하고 추후 이를 지표로써 개선할 수 있지 않을까 라는 생각을 한다.