실행 속도 관련 로그만 파일로 관리하기(feat. Logback)

김유정·2023년 12월 23일
0

배경

모임 관리 서비스 제작 중 중간 위치를 추천해주는 기능이 유독 속도가 느렸다. 그래서 해당 기능을 구성하는 단계 각각의 속도를 파악하고, 개선하고자 했다.

뿐만 아니라 앞으로도 속도가 느린 메서드가 발생할 수 있으니 실행 속도를 로그로 남기고, 관련 로그만 파일로 관리해야겠다고 결심했다.

어떻게 구현하냐에 따라 다르겠지만, 나는 아래와 같이 구성하여 구현했다.

  1. [필수] logback-spring.xml: 어떤 로그를 어떻게 남길지 설정하는 설정 파일
  2. [필수] TimeCheckFilter.java: 로그가 실행 속도에 해당하는 로그인지 아닌지를 판별해줄 필터
  3. [선택] PerformanceAspect.java: 실행 속도를 측정하여 로그를 남겨주는 aspect
  4. [선택] TimeCheck.java: 실행 속도를 측정하고자 하는 메서드를 쉽게 구별하기 위한 어노테이션

!!!!dependency 알아보기!!!

실행 속도를 측정해보자

코드의 반복을 줄이고, 가독성을 높이기 위해 AOP를 적용했다.

import lombok.extern.slf4j.Slf4j;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.springframework.stereotype.Component;

@Aspect
@Component
@Slf4j
public class PerformanceAspect {
    @Around("execution(* com.moim.backend.domain..controller.*.*(..)) || @annotation(com.moim.backend.global.aspect.TimeCheck)")
    public Object measureClassMethodExecutionTime(ProceedingJoinPoint joinPoint) throws Throwable {
        long startTime = System.currentTimeMillis();
        Object returnValue = joinPoint.proceed();
        long totalTime = System.currentTimeMillis() - startTime;

        String methodName = joinPoint.getSignature().getName();
        String className = joinPoint.getTarget().getClass().getSimpleName();
        log.info("[" + className + "." + methodName + "] took " + totalTime + " ms.");

        return returnValue;
    }
}

주요 코드 설명

@Around("execution(* com.moim.backend.domain..controller.*.*(..)) || @annotation(com.moim.backend.global.aspect.TimeCheck)")
  • @Around 어노테이션을 활용하여 메서드가 실행되기 전 후에 모두 적용되도록 했다.
  • execution(* com.moim.backend.domain..controller.*.*(..))
    매칭 조건 1: controller 내에 존재하는 모든 메서드
    • 접근제어자: 생략
    • 반환 타입: * | (모든 타입)
    • 패키지 경로: com.moim.backend.domain..controller
    • 클래스 이름: * | (모든 클래스)
    • 메서드 이름: * | (모든 메서드)
    • 파라미터: (...) | (파라미터 상관없이)
  • @annotation(com.moim.backend.global.aspect.TimeCheck)"
    매칭 조건 2: TimeCheck 어노테이션이 붙은 모든 메서드

로그를 남길 메서드를 구분해보자

로그를 남길 메서드를 구분할 때 패키지나 클래스를 지정하기보다 어노테이션을 쓰면, 서비스나 컨트롤러 그리고 유틸 다양한 계층에서 특정 메서드에만 aspect를 적용할 수 있도록 어노테이션을 만들었다.

import java.lang.annotation.ElementType;
import java.lang.annotation.Retention;
import java.lang.annotation.RetentionPolicy;
import java.lang.annotation.Target;

@Target(ElementType.METHOD)
@Retention(RetentionPolicy.RUNTIME)
public @interface TimeCheck {
}

로그를 어떻게 어디에 남길지 설정해보자

logback이라는 로깅 시스템을 사용할 건데, logback.xml은 spring이 구동되기 전이라 application.properties 값들을 불러올 수 없다고 한다.

그래서 logback-spring.xml을 사용하여 설정했다. Spring-boot-starter-data-jpa에 logging 관련 의존성이 포함되어 있기 때문에, 해당 의존성이 존재한다면 추가할 필요가 없다.

Logback 아키텍처는 Logger, Appender, Layout 3가지로 구성된다.

설정파일에서 springProfile 태그를 사용하면, 프로필 별로 다른 설정 파일을 사용할 수 있지만, 나는 로그 파일 경로나 로그 형식만 좀 달라서 프로필 별 application.yaml 파일에 값을 설정하여 사용했다.

  • 파일 위치: main > resources > logback-spring.xml
  • 로그 레벨: TRACE  <  DEBUG  <  INFO  <  WARN  <  ERROR
  • logback-spring.xml의 설정 옵션 참고: https://goddaehee.tistory.com/206

코드 패턴 정의

<property name="CONSOLE_LOG_PATTERN" value="%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %highlight(%-5level) %cyan(%logger) - %msg%n"/>
<property name="FILE_LOG_PATTERN" value="%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger - %msg%n"/>

property로 변수를 정할 수 있다.

여기서 CONSOLE은 인텔리제이 환경에서 애플리케이션 실행시 로그가 나오는 콘솔 화면이다. 이 때는 색상을 지정해놓으면 보기 편하다. 예시 화면은 아래와 같다.

파일의 경우, 서버에 접속해서 vi 에디터로 열었을 때, 색상을 지정해놓으면 색상은 안보이고 이상한 특수문자만 추가돼서 파일의 로그 패턴에는 색상 관련한 옵션들을 모두 뺐다.

환경별 property 파일 정의

<springProfile name="local">
  <property resource="application.yml" />
</springProfile>
<springProfile name="dev">
  <property resource="application-dev.yml" />
</springProfile>
<springProfile name="prod">
  <property resource="application-prod.yml" />
</springProfile>
<springProperty name="LOG_PATH" source="log.config.path"/>

환경별로 로그 파일 위치를 다르게 하기 위해 파일 경로를 property에 정의해두고, springProfile 태그로 환경에 맞는 파일을 선택해서 값을 가져올 수 있도록 설정했다.

springProperty 태그를 사용하게 되면, property 에 설정해놓은 값을 가져올 수 있다.

콘솔 로그 설정

<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
  <encoder>
    <pattern>${CONSOLE_LOG_PATTERN}</pattern>
  </encoder>
</appender>

appender는 로그의 형태와 출력될 위치를 정한다. appender의 name 옵션은 말 그대로 별명을 정해주는 거기 때문에, 원하는대로 정해주면 된다.

콘솔은 별다른 설정 없이 지정해놓은 패턴에 맞게 로그가 남겨지도록 encoder를 추가했다.

여기서 encoder는 지정한 로그 패턴에 맞게 메시지를 변환하는 역할을 한다.

파일 로그 설정

<appender name="TIME-CHECK" class="ch.qos.logback.core.rolling.RollingFileAppender">
  <filter class="com.moim.backend.global.filter.TimeCheckFilter"/>
  <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
    <pattern>${FILE_LOG_PATTERN}</pattern>
  </encoder>
  <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
    <fileNamePattern>${LOG_PATH}/time-check/%d{yyyy-MM-dd}_%i.log</fileNamePattern>
    <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
      <!-- 파일당 최대 용량 -->
      <maxFileSize>10MB</maxFileSize>
    </timeBasedFileNamingAndTriggeringPolicy>
    <!-- 일자별 로그파일 최대 30일 동안 보관-->
    <maxHistory>30</maxHistory>
  </rollingPolicy>
</appender>

드디어 핵심! 시간 관련된 로그를 파일로 남기기 위해 필수인 부분이다.

시간 관련된 로그인지 아닌지를 판단하기 위해서 필터가 필요하다. 필터는 아래에서 정리하고 우선은 넘어가자.

지정한 용량이 넘어가면, 파일을 추가로 만들고 넘버링 할 수 있도록 RollingFileAppender 를 사용했다.

그렇다면, 이와 관련된 정책도 필요하기 때문에 rollingPolicy 태그를 사용하여 옵션을 지정했다. 여기서는 파일의 위치와 이름, 파일당 최대 용량, 보관 기간을 설정할 수 있다.

출력할 로그 레벨 기준과 사용할 appender 지정하기

<root level="DEBUG">
	<appender-ref ref="CONSOLE"/>
	<appender-ref ref="TIME-CHECK"/>
</root>

모든 로거는 루트 로거의 자손으로 별다른 설정을 하지 않으면, 하위 로거는 루트의 설정을 상속받는다.

로거별 설정은 어떻게 하는지 잘 모르겠지만, 다 똑같이 사용할거라 root 태그에 레벨과 사용할 appender를 지정했다.

여기서 appender-ref의 ref 속성에는 위에서 만든 appender의 name을 그대로 써주면 된다. 이름이 다르거나 추가해주지 않으면 해당 appender는 작동하지 않으니 왜 파일이 안만들어지지..? 헤매지 말고 반드시 이 부분을 잘 확인하자!

전체 코드

해당 주제와 관련이 없어서 설명을 생략했는데, 디버그 레벨이 warn과 error인 로그도 파일로 남길 수 있도록 설정했다. 여기서는 훨씬 간단하게 이미 만들어진 LevelFilter를 사용해서 해당 레벨에 맞는 로그만 찍을 수 있도록 했다.

<?xml version="1.0" encoding="UTF-8" ?>
<configuration>
    <property name="CONSOLE_LOG_PATTERN" value="%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %highlight(%-5level) %cyan(%logger) - %msg%n"/>
    <property name="FILE_LOG_PATTERN" value="%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger - %msg%n"/>
    <springProfile name="local">
        <property resource="application.yml" />
    </springProfile>
    <springProfile name="dev">
        <property resource="application-dev.yml" />
    </springProfile>
    <springProfile name="prod">
        <property resource="application-prod.yml" />
    </springProfile>
    <springProperty name="LOG_PATH" source="log.config.path"/>
    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>${CONSOLE_LOG_PATTERN}</pattern>
        </encoder>
    </appender>
    <appender name="TIME-CHECK" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <filter class="com.moim.backend.global.filter.TimeCheckFilter"/>
        <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
            <pattern>${FILE_LOG_PATTERN}</pattern>
        </encoder>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>${LOG_PATH}/time-check/%d{yyyy-MM-dd}_%i.log</fileNamePattern>
            <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
                <!-- 파일당 최대 용량 -->
                <maxFileSize>10MB</maxFileSize>
            </timeBasedFileNamingAndTriggeringPolicy>
            <!-- 일자별 로그파일 최대 30일 동안 보관-->
            <maxHistory>30</maxHistory>
        </rollingPolicy>
    </appender>
    <appender name="WARNING-FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <filter class="ch.qos.logback.classic.filter.LevelFilter">
            <level>warn</level>
            <onMatch>ACCEPT</onMatch>
            <onMismatch>DENY</onMismatch>
        </filter>
        <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
            <pattern>${FILE_LOG_PATTERN}</pattern>
        </encoder>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>${LOG_PATH}/warning/warning.%d{yyyy-MM-dd}_%i.log</fileNamePattern>
            <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
                <maxFileSize>10MB</maxFileSize>
            </timeBasedFileNamingAndTriggeringPolicy>
            <maxHistory>30</maxHistory>
        </rollingPolicy>
    </appender>
    <appender name="ERROR-FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <filter class="ch.qos.logback.classic.filter.LevelFilter">
            <level>error</level>
            <onMatch>ACCEPT</onMatch>
            <onMismatch>DENY</onMismatch>
        </filter>
        <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
            <pattern>${FILE_LOG_PATTERN}</pattern>
        </encoder>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>${LOG_PATH}/error/error.%d{yyyy-MM-dd}_%i.log</fileNamePattern>
            <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
                <maxFileSize>10MB</maxFileSize>
            </timeBasedFileNamingAndTriggeringPolicy>
            <maxHistory>30</maxHistory>
        </rollingPolicy>
    </appender>
    <root level="DEBUG">
        <appender-ref ref="CONSOLE"/>
        <appender-ref ref="TIME-CHECK"/>
        <appender-ref ref="WARNING-FILE"/>
        <appender-ref ref="ERROR-FILE"/>
    </root>
</configuration>

이 로그가 시간을 체크한 것이 맞는가?

실행 속도 관련 로그만 파일로 관리하려는 게 나의 목적이기 때문에, 어떤 로그가 그에 해당하는지 판단이 필요하다.

로그 레벨별로 구분하는 필터는 이미 있지만, 내가 원하는 필터는 존재하지 않기에 직접 만들었다.

import ch.qos.logback.classic.spi.ILoggingEvent;
import ch.qos.logback.core.filter.Filter;
import ch.qos.logback.core.spi.FilterReply;

public class TimeCheckFilter extends Filter<ILoggingEvent> {
    @Override
    public FilterReply decide(ILoggingEvent event) {
        return (event.getLoggerName().equals("com.moim.backend.global.aspect.PerformanceAspect"))
                ? FilterReply.ACCEPT
                : FilterReply.DENY;
    }
}

AOP를 적용하여 PerformanceAspect에서 로그가 찍히도록 구현했기 때문에, 로거의 이름이 해당 패키지와 동일하다면, 시간 관련 로그가 맞는 것으로 판단하도록 작성했다.

드디어 짧고도 길었던 여정이 끝났다.

피드백은 언제나 환영합니다. 틀린 부분이 있다면 말씀해주세요😀

참고

profile
김유정
이전 포스트

백엔드 개발자 4개월차 회고

다음 포스트

[Java + Spring] JWT 로 카카오 로그인 로직 구현하기

0개의 댓글