[Spring] 스프링 부트에서 로그(Log) 사용하기2 - Log4j2 (Sync, Async Appender, Async Logger)

스프링 부트에서 Log4j2 사용하기

Log4j2는 Apache의 log4j의 다음 버전이며 가장 최근에 등장한 프레임워크이다. 이는 Logback와 동일하게 자동 리로드와 필터링 기능을 제공하고 이 외에도 Java8부터 도입된 람다식 지원과 Lazy Evalutaion, 가비지 프리 기능들을 제공하고 있다. Logback과 가장 큰 차이는 Log4j2는 멀티스레드 환경에서 비동기 로거를 사용할 경우 10배 가까운 처리량을 처리할 수 있다는 것이다. 

 

개인적으로 Log4j2와 Logback의 가장 큰 차이는 비동기 로거(Async Logger)의 차이인 것 같다. 그리고 이는 멀티 쓰레드 환경에서 더 많은 쓰레드를 다룰수록 엄청난 성능 격차를 불러일으킨다고 Log4j2 문서에서 설명하고 있다. 그래서 정말 그런지 직접 로깅하는 로직을 만들어 성능을 비교해보려고 한다.

 

Log4j2 의존성 추가하기

스프링 부트 spring-boot-starter-web 라이브러리를 보면 다음과 같이 spring-boot-starter-logging 라이브러리에 기본적으로 설치되어 있다. 그래서 기본적으로 Logback이 설정되어 있다. 

 

default: Logback 라이브러리

 

Log4j2를 사용하기 위해서는 build.gradle 파일에서 해당 라이브러리를 삭제하고 Log4j2 라이브러리 의존성을 추가해줘야 한다.

dependencies {
	// ...

	// log4j2
	implementation 'org.springframework.boot:spring-boot-starter-log4j2'
}

// stater-logging 라이브러리 삭제하기
configurations {
	all {
		exclude group: 'org.springframework.boot', module: 'spring-boot-starter-logging'
	}
}

 

의존성 변경이 끝났으면 재빌드를 하고 다시 설치된 라이브러리를 확인해보면 다음과 같이 log4j2 라이브러리 의존성이 추가된 것을 확인할 수 있다. 

 

Log4j2 라이브러리

 

1. Sync Logger

Sync Logger 가장 기본적인 로깅 방식이다. 

 

RollingFileAppender

로그가 한 파일에 계속 저장된다면 계속해서 쌓이는 로그를 견뎌낼 수 없다. 자칫하면 기록된 로그가 전부 날라갈 수 도 있다. 이러한 문제를 해결하기 위해 RollingFileAppender를 사용한다. 이는 파일에 로그를 기록하고 특정 기준에 따라 압축하여 저장해준다. (참고)

 

Triggering Policies

File Rolling Up에 따른 기준을 살펴보자.

• OnStartupTriggeringPolicy : jvm start시점을 기준으로 roll up
• TimeBasedTriggeringPolicy : time을 기준으로 roll up, 파일 패턴 날짜 최소 단위를 기준으로 설정됨
• SizeBasedTriggeringPolicy : file size에 따라 roll up
• CronTriggeringPolicy : Cron Expression(시간에 관한 표현)설정에 따라 roll up
• Trigger Policies 참고

 

DefaultRolloverStrategy

DefaultRolloverStrategy는 datetime 패턴과 파일 패턴의 int값을 받아서 결정된다. datetime은 현재 시간으로 대체되고, 파일 패턴 숫자는 db의 autoincrement처럼 rollover마다 1씩 증가한다. 

• fileIndex : max로 설정시 높은 index가 더 최신 파일이 되고 min으로 설정 시 작은 index가 최신 파일이 된다. 기존의 파일들을 rename하는 방식으로 동작한다.
• min : fileIndex 최솟값을 설정한다. 기본값은 1이다.
• max : fileIndex 최댓값을 설정한다. 만약 최댓값에 도달하면 오래된 파일을 삭제한다. 기본값은 7이다.
• DefaultRolloverStrategy 참고

 

다음 RollingFile 예제는 dd(일)을 기준으로 설정되어 하루가 지나는 시점과 100MB가 되는 시점을 기준으로 logs/app-%d{yyyy-MM-dd}-%i.log 패턴으로 압축되어 저장된다.

• DefaultRolloverStrategy는 filePattern %d{yyyy-MM-dd}가 날짜 패턴, %i가 파일 패턴의 int이다. 

<?xml version="1.0" encoding="UTF-8" ?>
<Configuration status="INFO">
    <Properties>
        <Property name="LOG_PATH">logs/app</Property>
        <Property name="FILE_PATTERN">%d{yyyy-MM-dd}-%i</Property>
        <Property name="LOG_PATTERN">[%d{yyyy-MM-dd HH:mm:ss}:%-3relative] %-5level ${PID:-} --- [%15.15thread] %-40.40logger{36} : %msg%n</Property>
    </Properties>
    <Appenders>
        <Console name="console" target="SYSTEM_OUT">
            <PatternLayout pattern="${LOG_PATTERN}"/>
        </Console>

        <RollingFile name="File"
                     fileName="${LOG_PATH}.log"
                     filePattern="${LOG_PATH}-${FILE_PATTERN}.log"
                     append="false">
            <PatternLayout pattern="${LOG_PATTERN}"/>
            <Policies>
                <TimeBasedTriggeringPolicy interval="1" modulate="true"/>
                <SizeBasedTriggeringPolicy size="100MB" />
            </Policies>
            <DefaultRolloverStrategy max="20" fileIndex="min" />
        </RollingFile>

    </Appenders>
    <Loggers>
        <logger name="com.example.springlog4j2" level="info" additivity="false" includeLocation="false">
            <!--   Sync 7.8t/s-->
            <AppenderRef ref="File"/>-
        </logger>
        <Root level="info" includeLocation="false">
            <AppenderRef ref="console"/>
        </Root>
    </Loggers>
</Configuration>

 

로그를 엄청나게 많이 찍어보면 다음과 같이 100KB단위로 롤링이 되는 것을 확인할 수 있다.

 

 

2. AsyncAppender

이는 Sync 로깅 방식과 크게 다를 게 없다. RollingFIleAppender를 <Async> 태그 안에 넣어 AsyncAppender를 입혀준다.

• includeLocation : Logback의 includeCallerData 옵션과 동일하다. 호출자 데이터를 조회해주는 데 성능만 잡아먹는다.
  • 기본값은 false이고, 사용하게 될 경우 속도가 5 ~ 20배 정도 느려진다.
• bufferSize : 기본값은 1024이다.
• blocking : true(기본값)면 로그 발생시 Queue에 넣을 공간이 없으면 빈 공간이 생길 때 까지 block 상태로 기다리며, 로그를 유실하지 않는다. false면 로그 발생시 Queue가 꽉 찼다면 로그를 유실하고, Error Appender에 이벤트를 기록한다.

<?xml version="1.0" encoding="UTF-8" ?>
<Configuration status="INFO">
    <Properties>
        <Property name="LOG_PATH">logs/app</Property>
        <Property name="FILE_PATTERN">%d{yyyy-MM-dd}-%i</Property>
        <Property name="LOG_PATTERN">[%d{yyyy-MM-dd HH:mm:ss}:%-3relative] %-5level ${PID:-} --- [%15.15thread] %-40.40logger{36} : %msg%n</Property>
    </Properties>
    <Appenders>
        <Console name="console" target="SYSTEM_OUT">
            <PatternLayout pattern="${LOG_PATTERN}"/>
        </Console>

        <RollingFile name="AsyncFile"
                     fileName="${LOG_PATH}.log"
                     filePattern="${LOG_PATH}-${FILE_PATTERN}.log"
                     immediateFlush="false" append="false">
            <PatternLayout pattern="${LOG_PATTERN}"/>
            <Policies>
                <TimeBasedTriggeringPolicy interval="1" modulate="true"/>
                <SizeBasedTriggeringPolicy size="100MB" />
            </Policies>
            <DefaultRolloverStrategy max="20" fileIndex="min" />
        </RollingFile>

        <Async name="AsyncAppender" >
            <AppenderRef ref="AsyncFile" />
        </Async>

    </Appenders>
    <Loggers>
        <logger name="com.example.springlog4j2" level="info" additivity="false" includeLocation="false">
            <!--   Async Appender 15.9 t/s -->
            <AppenderRef ref="AsyncAppender"/>
        </logger>
        <Root level="info" includeLocation="false">
            <AppenderRef ref="console"/>
        </Root>
    </Loggers>
</Configuration>

 

3. All AsyncLogger

이는 모든 로깅을 Async로 처리하는 방법이다. 이는 엄청나게 빠른 처리량을 내고 응답 시간 지연을 최소화 해준다는 장점을 가지고 있다. 하지만 주의해야 할 점도 있다.

1. 로깅 프로세스 중 문제가 발생하고 예외가 발생하면 AsyncLogger 또는 Appender가 이 문제를 애플리케이션에 알리는 것이 쉽지 않다. ExceptionHandler가 있지만 모든 경우를 다 캐치할 수 없다.
2. 드물지만 race condition을 조심해야 한다. log.debug("My obeject is {}", myObejct);와 같은 로깅을 할 때 변경 가능한 메시지는 비동기로 기록하는 것이 안전하다.

<?xml version="1.0" encoding="UTF-8" ?>
<Configuration status="INFO">
    <Properties>
        <Property name="LOG_PATH">logs/app</Property>
        <Property name="FILE_PATTERN">%d{yyyy-MM-dd}-%i</Property>
        <Property name="LOG_PATTERN">[%d{yyyy-MM-dd HH:mm:ss}:%-3relative] %-5level ${PID:-} --- [%15.15thread] %-40.40logger{36} : %msg%n</Property>
    </Properties>
    <Appenders>
        <Console name="console" target="SYSTEM_OUT">
            <PatternLayout pattern="${LOG_PATTERN}"/>
        </Console>

        <!-- Async Loggers will auto-flush in batches, so switch off immediateFlush. -->
        <RandomAccessFile name="RandomAccessFile"
                          fileName="${LOG_PATH}-async.log"
                          immediateFlush="false" append="false">
            <PatternLayout pattern="${LOG_PATTERN}"/>
        </RandomAccessFile>
    </Appenders>
    <Loggers>
        <logger name="com.example.springlog4j2" level="info" additivity="false" includeLocation="false">
            <!--    All Async Logger 147.8 t/s-->
            <AppenderRef ref="RandomAccessFile"/>
        </logger>
        <Root level="info" includeLocation="false">
            <AppenderRef ref="console"/>
        </Root>
    </Loggers>
</Configuration>

 

성능 비교

Jmeter를 사용하여 각 Logger 방식(Sync, AsyncAppender, AsyncLogger) 성능 비교를 해봤다.

• Thread: 8
• ramp-up time: 1
• API Request 1개 당 Log 10,000개 기록

 

SyncLogger 테스트 결과

• 처리량 7.8 t/s

SyncLogger

AsyncAppender 테스트 결과

• 처리량 15.9 t/s (Sync보다 약 2배 더 빠름)

AsyncAppender

 

AsyncLogger 테스트 결과

• 처리량 147.8 t/s (Sync보다 약 19배 더 빠름, AsyncAppender보다 약 9.3배 더 빠름)

AsyncLogger

 

 

실습한 내용은 github에서 확인이 가능합니다.

---

참고

https://logging.apache.org/log4j/2.x/manual/appenders.html

https://logging.apache.org/log4j/2.x/manual/async.html