서비스를 개발하다보면 자신이 만든 API가 잘 동작하는지 확인해야 합니다.

물론 꼼꼼한 슬라이스 테스트를 통해서 잘 동작하는 지 검증할 수 있습니다.
성능 또한 테스트가 수행되는 시간, 발생하는 쿼리 등을 보며 확인할 수 있죠.

하지만 실제 돌아가는 환경처럼 디버깅이 힘든 환경에서는 어떨까요?
테스트를 돌리는 것도 아니고 확인하기 까다롭습니다.

이 글에서는 API 성능을 로깅하는 방법에 대해서 다뤄보고자 합니다.
예시로 로깅하고자 하는 Metrics는 다음과 같습니다.

• 요청 URI, Method
• 요청이 들어온 순간부터 응답까지 걸리는 시간(ms)
• 발생한 쿼리 횟수

서블릿의 Filter를 사용해서 위의 정보들을 로깅해보겠습니다.
순서대로 하나씩 적용해봅시다.

요청 URI

어떤 URI로 요청이 왔는지 로깅해두면 여러모로 유용합니다.
예외가 발생한 API, 유저의 행동 패턴, API 요청 빈도 수 등 다양하게 활용할 수 있습니다.

public class LoggingFilter extends OncePerRequestFilter {

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

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

스프링에서 제공하는 OncePerRequestFilter를 상속해서 필터를 구현합니다.
GenericFilterBean이나 Filter 등을 사용해서도 구현할 수 있습니다.

다만,
다른 필터를 사용하면 서블릿마다 doFilter가 호출됩니다.
서블릿 간 포워딩이 발생하면 의도치 않게 같은 필터가 여러 번 호출될 수 있습니다.

저는 요청 당 한 번만 사용되는 필터를 쉽게 구현하기 위해 사용하기로 했습니다.

혹시 응답 이후 로깅을 하고 싶으면 doFilter() 호출 이후 로깅하면 됩니다.
위의 FilterChain이 여러 필터를 거치고 서블릿이 핸들링해서 응답하는 과정으로 볼 수 있습니다.
따라서 doFilter()를 호출해주지 않으면 현재의 필터에 들어온 요청 및 응답은 거기서 더이상 진행되지 않습니다.

@Configuration
public class FilterConfiguration {

    @Bean
    FilterRegistrationBean<LoggingFilter> logging() {
        return new FilterRegistrationBean<>(new LoggingFilter());
    }
}

그리고 FilterRegistrationBean을 사용해서 필터를 등록해줬습니다.

위에서 구현한 필터를 @Component 를 통해 스프링 빈으로 등록해줘도 잘 동작합니다.
다만 여러 필터가 추가됐을 때는 @Order 등으로 순서를 지정해줘야 의도대로 동작할 수 있습니다.

근데 그렇게 되면 각 필터를 들어가보며 순서를 봐야 하기 때문에 한 눈에 볼 수 있도록 @Configuration으로 빈 등록을 해줬습니다.
FilterRegistrationBean으로 순서를 지정해주려면 setOrder() 세터를 사용하면 됩니다.

@Configuration
public class FilterConfiguration {

    private static final int FIRST = 0;

    private final LatencyLoggingFilter latencyLogging;

    public FilterConfiguration(final LatencyLoggingFilter latencyLogging) {
        this.latencyLogging = latencyLogging;
    }

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

    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;
    }
}

실제로 요즘카페 프로젝트에서도 위와 같이 setOrder로 필터를 관리하고 있습니다.

실제로 테스트 해보면 잘 동작하는 군요!

만약 정적 자원(JS, CSS 등)은 로깅하고 싶지 않다면, 해당 확장자가 포함된 요청은 제외해주면 되겠죠?

하지만 저는 모니터링 툴(Grafana)의 대시보드에서만 안 보이게 해두고 실제 로깅은 되도록 놔뒀습니다.
언제 어떻게 쓰일 지 모르는 귀중한 자원이라고 생각해서요!

요청이 들어온 순간부터 응답까지 걸리는 시간(ms)

다음으로 API의 요청부터 응답까지의 시간을 로깅해보겠습니다.
어떻게 할 수 있을까요??

요청이 들어왔을 때의 시각을 저장해두고, 응답할 때의 시각에서 빼면 될 것 같은데요.
다만 문제는 어떻게 유저 별로 시간을 관리하느냐 입니다.

두 가지 방법을 생각해봤어요.
1. @RequestScope 사용해서 요청 별로 처리하기
2. ThreadLocal 사용해서 스레드 별로 처리하기

어떻게 요청 별 처리 == 스레드 별 처리 가 가능한 지 궁금하신 분들 위해 간단하게 첨언하자면,

Spring Boot는 Embadded Tomcat을 사용합니다.
유저의 요청이 들어오면 톰캣의 nio 커넥터를 사용해서 TCP 커넥션을 맺어준 뒤 스프링 컨테이너로 보내주죠.
커넥션 풀에서 idle 상태의 스레드 하나에 요청 하나를 할당해서 응답까지 처리하게 됩니다.

앞에서 봤던 로그에서 nio-8080-exec-x 형태의 스레드 이름을 볼 수 있는데, 스레드 풀의 몇 번 스레드가 처리했는지 알 수 있습니다.

이제부터 @RequestScope와 ThreadLocal 두 방법을 사용해서 구현해보겠습니다.

1. @RequestScope

@RequestScope
@Component
public class Timer {

    private final long startMillis = System.currentTimeMillis();

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

우선 시간을 관리하기 위한 Timer 객체를 만들고 빈으로 등록했습니다.
그리고 스프링에서 제공하는 @RequestScope를 통해 빈의 생명 주기를 HTTP 요청 ~ 응답으로 설정했습니다.

그럼 생성될 때 startMillis가 초기화되고 getLatencyMillis()를 호출하면 그때까지의 시간을 얻을 수 있겠죠??

@Component
public class LoggingFilter extends OncePerRequestFilter {

    private static final Logger LOGGER = LoggerFactory.getLogger(LoggingFilter.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("요청 : {} {}, {}ms", request.getMethod(), request.getRequestURI(), timer.getLatencyMillis());
    }
}

그리고 만들어둔 Timer를 생성자 주입 받기 위해 필터도 스프링 빈으로 등록했습니다.

Timer는 Request Scope인데 요청 별로 new Timer()가 호출되지 않나요?
필드 final Timer는 재참조가 불가능한데 요청 별로 객체를 갈아끼울 수 있나요?

스프링에서 CGLIB 기반의 프록시 객체를 대신 주입해주기 때문에 가능합니다.
실제 객체는 프록시에게 명령을 전달 받아서 수행하죠.

잘 동작하네요!!

2. ThreadLocal

앞서 만들어본 Timer를 ThreadLocal을 사용해서 리팩토링 해보겠습니다.
ThreadLocal은 각 스레드별로 저장 공간을 사용할 수 있는 컨테이너입니다.

@Component
public class Timer {

    private static final ThreadLocal<Long> THREAD_LOCAL = new ThreadLocal<>();

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

    public long getLatencyMillis() {
        final long latencyMillis = System.currentTimeMillis() - THREAD_LOCAL.get();
        THREAD_LOCAL.remove();

        return latencyMillis;
    }
}

위와 같이 정적 필드로 선언을 해줬습니다.
Thread-Safe한 저장 공간이기 때문에 모든 스레드가 공유해도 각자의 영역을 사용할 수 있기 때문입니다.

생성 시점에 초기화 시켜줄 수 없기 때문에 start() 메서드를 만들었습니다.
그리고 오용될 수 있으므로 사용한 이후에는 remove()를 통해 저장된 값을 제거했습니다.

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

필터에서는 timer.start() 하나만 추가해줬습니다.

마찬가지로 잘 동작합니다!

시간이 조금 더 걸리는 이유는 ThreadLocal 내부 동작 때문일 것 같군요.
하지만 변인 통제가 되기 때문에 API별 시간 측정용으로 충분히 쓸 수 있을 것 같습니다.

발생한 쿼리 횟수

이제 발생한 쿼리 횟수를 카운팅해보려고 합니다.

요청을 처리할 때 보통 시간이 오래 걸리는 부분은 외부 시스템과의 통신입니다.
외부 API 호출, DB 호출, …

여러 외부 시스템 중 DB는 충분히 건드릴 수 있는 영역이고, 최적화를 통해서 서비스를 고도화시킬 수 있습니다.
그리고 최적화할 쿼리를 찾을 때 써볼 만한 지표라고 생각합니다.
N+1 총 정리의 내용을 프로젝트에 적용해보려고 할 때도 써볼 수 있지 않을까요?? ㅎㅎ..

Spring Data JPA를 사용하신다면 JPA의 구현체로 Hibernate를 사용하고 계실 것입니다.
그리고 Hibernate에서는 발생하는 SQL 마다 액션을 취할 수 있도록 StatementInspector 인터페이스를 제공합니다.

위의 인터페이스를 들어가서 보면, Thread-Safe하게 사용해야 하고 파라미터로 받은 SQL문 대신 리턴 값을 사용한다고 나와있습니다. (null을 리턴하면 파라미터를 그대로 사용)

저희는 SQL 문을 변경시키거나 할 계획이 없기 때문에 파라미터는 쓸 일이 없습니다.

요청 별로 횟수를 관리해야 하기 때문에 이번에도 RequestScope나 ThreadLocal을 사용하면 될 것 같습니다.
저는 동적으로 인스턴스를 생성(Reflection)해서 사용하는 RequestScope 대신 ThreadLocal으로 구현하겠습니다. JVM에게 부하를 덜 주거든요.

@Component
public class QueryCountInspector implements StatementInspector {

    private static final ThreadLocal<Integer> COUNTER = new ThreadLocal<>();

    @Override
    public String inspect(final String sql) {
        final Integer currentCount = COUNTER.get();

        if (isNull(currentCount)) {
            COUNTER.set(1);
            return sql;
        }

        COUNTER.set(currentCount + 1);
        return sql;
    }

    public int getCount() {
        final Integer count = COUNTER.get();

        if (isNull(count)) {
            return 0;
        }
        return count;
    }

    public void clear() {
        COUNTER.remove();
    }
}

앞서 소개한 StatementInspector를 구현했습니다.

• sql이 들어올 때마다 null 체크와 함께 카운팅을 해줬습니다.
• 카운팅된 값을 얻기 위한 getter를 구현했습니다.
• ThreadLocal을 정리해주기 위한 clear를 구현했습니다.

@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를 구현하기만 한다고 해서 아무도 inspect()를 호출해주지 않습니다.

스프링에서 제공하는 HibernatePropertiesCustomizer를 통해 Hibernate 관련 설정을 할 수 있는데요.
그 중 hibernate.session_factory.statement_inspector 에 만들어뒀던 QueryCountInspector를 등록해주면 됩니다.

이제 SQL이 발생할 때마다 inspect()가 호출되고 카운팅이 될 것입니다.
마지막 남은 일은 로깅용 필터에서 사용하는 것이군요.

@Component
public class LoggingFilter extends OncePerRequestFilter {

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

    private final Timer timer;
    private final QueryCountInspector queryCountInspector;

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

    @Override
    protected void doFilterInternal(final HttpServletRequest request,
                                    final HttpServletResponse response,
                                    final FilterChain filterChain) throws ServletException, IOException {
        timer.start();

        filterChain.doFilter(request, response);

        LOGGER.info("요청 : {} {}, {}ms, count: {}",
                request.getMethod(), request.getRequestURI(), timer.getLatencyMillis(), queryCountInspector.getCount());
        queryCountInspector.clear();
    }
}

QueryCountInspector를 주입 받아서 카운트 값을 로깅하도록 했습니다.
사용한 뒤에는 잊지 않고 clear()를 호출해줬습니다.

실제로 쿼리 횟수만큼 카운팅 하는지 테스트 하기 위해 show_sql을 사용했습니다.
1개의 SELECT 쿼리가 나가는 POST 요청은 1이 찍히고,
아무 쿼리도 나가지 않는 GET 요청은 0이 찍히는 군요.

잘 동작합니다👍

정리

지금까지 성능 로깅하는 예시를 살펴봤습니다.
필요한 Metrics를 자유롭게 로깅해서 사용하시면 됩니다!

추가적으로 참고할 만한 키워드들을 마지막으로 글을 마무리할게요!
봐주셔서 감사합니다😃

• AOP
• Filter
  • GenericFilterBean
  • OncePerRequestFilter
  • FilterRegistrationBean
• Servlet
  • FilterChain
  • NIO Connector
• RequestScope
  • Proxy(CGLIB)
• ThreadLocal
• Hibernate
  • StatementInspector
  • HibernatePropertiesCustomizer