[SWYP] 메서드 성능 측정을 위한 AOP 적용기

[Version]
⦁ 2024.05.20 / [SWYP] 메서드 성능 측정을 위한 AOP 적용기

프로젝트를 진행하던 중 클라이언트에서 서버의 API를 호출했을 때 성능이 좋지 않은 메서드를 확인하고 싶었다. 컨트롤러의 메서드마다 시작 시간과 종료 시간을 측정하여 확인할 수 있지만 이 요구사항은 비기능적인 요구사항이기 때문에 코드를 분리하는 것이 좋다고 생각했다.

이 글은 AOP의 정의부터 실제 프로젝트에 적용한 과정까지 작성한 일대기이다. 한번 같이 확인해 보자!

AOP(Aspect Oriented Programming)란?

먼저, 관점 지향 프로그래밍을 알아보기 전 기존에 우리가 알고 있던 객체 지향 프로그래밍의 정의를 떠올려보자. 객체 지향 프로그래밍에서 모듈 단위는 클래스이다. 그럼 관점 지향 프로그래밍에서 모듈 단위는 무엇일까? 바로 관점이다. 관점도 역시 클래스로 작성하기 대문에 두 방식이 차이가 없어 보일 수 있지만 클래스와 관점은 개념과 공통 모듈을 처리하는 방식이 다르므로 두 프로그래밍 방식은 같다고 볼 수 없다.

관점은 여러 클래스에 걸쳐 공통으로 실행되는 기능을 모듈로 분리한 것이다. 따라서 관점 지향 프로그래밍을 사용하면 의존으로 발생하는 복잡도를 낮출 수 있다. 관점 지향 프로그래밍은 프레임워크를 통해 객체를 생성하거나 메서드를 호출하기 때문이다.

이와 같이 클래스 외부에서 관점이 기능이 실행되므로 서로 분리가 되고 이러한 형태를 관심의 분리라고 한다. 관점은 애플리케이션에서 특정 메서드가 실행될 때 함께 실행된다. 따라서 관점 지향 프로그래밍은 객체 지향 프로그래밍을 보완하는 관계로 동작한다.

AOP 용어 목록

대상 객체(Target Object): 공통 모듈을 적용할 대상을 의미한다.
관점(Aspect): AOP 프로그래밍으로 작성한 공통 모듈과 적용될 위치 정보의 조합을 의미한다.
어드바이스(Advice): 애플리케이션의 공통 로직이 작성된 모듈을 의미한다. 스프링 AOP에서 어드바이스는 메서드의 형태로 구성되어 있다.
포인트 컷(Point Cut): 어드바이스를 적용할 위치를 선정하는 설정을 의미한다. 어드바이스는 포인트 컷으로 위치가 결정되고 해당 시점에 어드바이스가 실행된다. 포인트 컷은 표현식을 사용하거나 애너테이션을 사용하여 표현할 수 있다.
조인 포인트(Join Point): 어드바이스가 적용될 위치를 의미한다.
위빙(Weaving): 조인 포인트에 실행할 코드인 어드바이스를 추가하는 과정을 위빙이라 한다.
프록시 객체(Proxy Object): 스프링 AOP는 관점 클래스와 대상 클래스의 기능을 조합하기 위해 동적으로 프록시 객체를 생성한다. 생성된 프록시 객체가 관점 클래스와 대상 클래스의 기능을 실행한다.

메서드 성능 측정을 위한 AOP 적용

@Slf4j
@Component
@Aspect
public class ElapseLoggingAspect {

    @Around("execution(* com.swyg.oneului.controller..*(..))")
    public Object loggingElapseTime(ProceedingJoinPoint proceedingJoinPoint) throws Throwable {
        StopWatch stopWatch = new StopWatch();
        stopWatch.start();

        Object result;
        try {
            result = proceedingJoinPoint.proceed();
        } finally {
            stopWatch.stop();
            String className = proceedingJoinPoint.getTarget().getClass().getName();
            String methodName = proceedingJoinPoint.getSignature().getName();
            long elapsedTime = stopWatch.getLastTaskTimeMillis();

            if (elapsedTime > 2000) {
                log.info("ClassName: {}, MethodName: {}, elapsed time: {} ms", className, methodName, elapsedTime);
            }
        }

        return result;
    }
}

모든 컨트롤러 클래스에 대해 메서드 시간 측정이라는 횡단 관심사를 분리하기 위해 `ElapseLoggingAspect` 클래스를 생성했다. 컨트롤러에서 실행하는 API에서 2초 이상 걸리는 메서드가 있다면 로그를 기록하는 기능을 구현하였다.

AOP는 다양한 어드바이스 타입을 제공한다. 나는 API의 호출되기 전부터 호출이 끝난 후까지의 시간을 측정해야 하기 때문에 Around 어드바이스 타입을 사용하였다. 포인트 컷으로는 컨트롤러 패키지 아래에 있는 모든 클래스에 대해 적용이 되도록 하였다.

관점에 대한 로직은 비교적 간단하다. StopWatch 객체를 생성하여 시작한 후 실제 대상 메서드를 호출하고 메서드의 실행이 완료되면 StopWatch 객체를 멈춘다. 만약 실행시간이 2초 이상일 경우 로그를 기록하는 작업이다.

로그 파일 생성

AOP를 적용한 이후 컨트롤러의 API를 호출할 때마다 실행 시간이 2초 이상인 메서드의 경우 로그가 기록되는 것을 확인하였다. 하지만 실시간으로 내가 로그를 눈으로 확인하는 것은 비효율적이라 생각되었다. 때문에 관점 메서드가 실행될 때 로그가 기록된다면 일자별로 파일을 남기도록 개선하였다.

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <property name="LOG_PATTERN" value="%d{yyyy-MM-dd HH:mm:ss} [%thread] %-5level %logger{36} - %msg%n"/>

    <appender name="CONSOLE_LOG" class="ch.qos.logback.core.ConsoleAppender">
        <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
            <pattern>${LOG_PATTERN}</pattern>
        </encoder>
    </appender>

    <appender name="FILE_LOG" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>./logs/MethodElapseTime.log</file>
        <filter class="ch.qos.logback.classic.filter.LevelFilter">
            <level>INFO</level>
            <onMatch>ACCEPT</onMatch>
            <onMismatch>DENY</onMismatch>
        </filter>
        <encoder>
            <pattern>${LOG_PATTERN}</pattern>
        </encoder>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>./logs/MethodElapseTime.%d{yyyy-MM-dd}.%i.log.gz</fileNamePattern>
            <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
                <maxFileSize>100MB</maxFileSize>
            </timeBasedFileNamingAndTriggeringPolicy>
            <maxHistory>180</maxHistory>
        </rollingPolicy>
    </appender>

    <root level="INFO">
        <appender-ref ref="CONSOLE_LOG"/>
    </root>

    <logger name="com.swyg.oneului.aspect" level="INFO" additivity="false">
        <appender-ref ref="FILE_LOG"/>
    </logger>
</configuration>

위 XML 파일은 Logback 라이브러리의 설정 파일이다. 각 항목에 대해 한번 알아보자!

로그 패턴 설정

<property name="LOG_PATTERN" value="%d{yyyy-MM-dd HH:mm:ss} [%thread] %-5level %logger{36} - %msg%n"/>

LOG_PATTERN이라는 이름의 속성을 설정한다.
value에 정의되어 있는 문자열은 로그 메시지가 어떻게 표기될지를 표현한다.
- % d {yyyy-MM-dd HH:mm:ss}: 로그를 남긴 시간을 표시한다.
- [% thread]: 로그를 남긴 스레드 이름을 표시한다.
- %-5 level: 로그의 레벨(INFO, DEBUG 등)을 표시한다.
- % logger {36}: 로거의 이름을 표시한다.
- % msg: 로그 메시지를 표시한다.

콘솔 출력 설정

<appender name="CONSOLE_LOG" class="ch.qos.logback.core.ConsoleAppender">
    <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
        <pattern>${LOG_PATTERN}</pattern>
    </encoder>
</appender>

로그 메시지를 콘솔에 출력한다.
위에서 정의한 LOG_PATTERN을 사용하여 로그 메시지를 포맷팅 한다.

파일 출력 설정

<appender name="FILE_LOG" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>./logs/MethodElapseTime.log</file>
    <filter class="ch.qos.logback.classic.filter.LevelFilter">
        <level>INFO</level>
        <onMatch>ACCEPT</onMatch>
        <onMismatch>DENY</onMismatch>
    </filter>
    <encoder>
        <pattern>${LOG_PATTERN}</pattern>
    </encoder>
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
        <fileNamePattern>./logs/MethodElapseTime.%d{yyyy-MM-dd}.%i.log.gz</fileNamePattern>
        <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
            <maxFileSize>100MB</maxFileSize>
        </timeBasedFileNamingAndTriggeringPolicy>
        <maxHistory>180</maxHistory>
    </rollingPolicy>
</appender>

로그 메시지를 `./logs/MethodElapseTime.log`파일에 기록한다.
로그 레벨이 INFO인 로그만 기록한다.
로그 파일은 날짜와 크기에 따라 분할된다.
- fileNamePattern: 파일 이름 패턴이다. 날짜(yyyy-MM-dd)와 파일 인덱스(%i)를 포함한다.
- maxFileSize: 각 로그 파일의 최대 크기(100MB)
- maxHistory: 로그 파일을 최대 180일 동안 보관

특정 로거 설정

<logger name="com.swyg.oneului.aspect" level="INFO" additivity="false">
    <appender-ref ref="FILE_LOG"/>
</logger>

com.swyg.oneului.aspect 패키지의 로그 설정입니다.
로그 레벨을 INFO로 설정하여 INFO 이상의 로그 메시지를 기록한다.
additivity="false"는 이 로거가 상위 로거의 설정을 상속받지 않도록 한다. 즉, 콘솔에는 기록하지 않고 파일에만 기록한다.

파일 생성 결과

2024-05-20 14:25:30 [http-nio-8080-exec-1] INFO  c.s.o.aspect.ElapseLoggingAspect - ClassName: com.swyg.oneului.controller.SurveyController, MethodName: getAllSurveys, elapsed time: 20 ms
2024-05-20 14:25:35 [http-nio-8080-exec-1] INFO  c.s.o.aspect.ElapseLoggingAspect - ClassName: com.swyg.oneului.controller.SurveyController, MethodName: getAllSurveys, elapsed time: 3 ms
2024-05-20 14:25:52 [http-nio-8080-exec-1] INFO  c.s.o.aspect.ElapseLoggingAspect - ClassName: com.swyg.oneului.controller.SurveyController, MethodName: getAllSurveys, elapsed time: 7 ms
2024-05-20 14:25:59 [http-nio-8080-exec-1] INFO  c.s.o.aspect.ElapseLoggingAspect - ClassName: com.swyg.oneului.controller.SurveyController, MethodName: getAllSurveys, elapsed time: 21 ms

자! 이제 로그가 기록된 파일을 확인해보자. 현재는 로그에 기록하기 위해 2초 이상이라는 제한 조건을 해제하였으나 실제 서비스를 운영할 때 2초 이상 걸리는 API가 존재한다면 해당 파일을 확인 후 로직을 수행할 수 있게 될 것이다.

EVERYTHING'S GONNA BE FINE