인프런 커뮤니티 질문&답변

저는 컴터 사양이 꽤나 좋아서 인지? 항상 표준출력이 더 빠르더군요.

알아보니 로깅 프레임워크가 느린 이유에는 대략 이런 이유들이 있네요.

• 로그 출력에 여러 과정을 거침. Logger → Appender → Encoder → Layout → OutputStream

• 레벨 설정에 의한 필터링

• 로그 포맷팅 처리

분명 표준출력이 synchronized에 의해서 멀티 스레드 환경에서 취약한건 맞으나 현재 테스트에서는 그 부분이 로깅 프레임워크의 처리 과정보다는 빨랐던 것 같습니다.

테스트 환경 변경

그래서 테스트 환경을 바꿔서 테스트 해보았습니다.

멀티스레드 환경. 스레드 10개. 각 스레드별 100000번 출력

package kr.co.shortenurlservice.log;

import lombok.extern.slf4j.Slf4j;

import java.util.concurrent.CountDownLatch;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;

@Slf4j
public class SoutVsAsyncLoggingTest {

    private static final int THREAD_COUNT = 10;
    private static final int LOG_COUNT = 100_000;

    public static void main(String[] args) throws InterruptedException {
        // 1. System.out.println() 테스트
        long sysoutTime = runTest(i ->
            System.out.println("[SYSOUT][" + Thread.currentThread().getName() + "] " + i)
        );

        // 2. log.info() (AsyncAppender + Console) 테스트
        long asyncLogTime = runTest(i ->
            log.info("[LOGGER][{}] {}", Thread.currentThread().getName(), i)
        );

        // 결과 출력
        Thread.sleep(5000);
        System.out.printf("System.out: %,d ms%n", sysoutTime);
        System.out.printf("Async log : %,d ms%n", asyncLogTime);
    }

    private static long runTest(StringConsumer task) throws InterruptedException {
        long start = System.currentTimeMillis();

        ExecutorService executor = Executors.newFixedThreadPool(THREAD_COUNT);
        CountDownLatch latch = new CountDownLatch(THREAD_COUNT);

        for (int t = 0; t < THREAD_COUNT; t++) {
            executor.submit(() -> {
                for (int i = 0; i < LOG_COUNT; i++) {
                    task.accept(i);
                }
                latch.countDown();
            });
        }

        latch.await();
        executor.shutdown();

        long end = System.currentTimeMillis();
        return end - start;
    }

    @FunctionalInterface
    interface StringConsumer {
        void accept(int value);
    }
}

또한 test/resources/logback.xml 설정으로 포맷을 날짜 같은것 제외하고 표준출력과 똑같이 맞춰주고 AsyncAppender를 통해 멀티 스레드 환경에서 차별점이 있도록 비동기 Appender를 추가해줌.

<configuration>
    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%msg%n</pattern>
        </encoder>
    </appender>

    <appender name="ASYNC_CONSOLE" class="ch.qos.logback.classic.AsyncAppender">
        <appender-ref ref="CONSOLE"/>
        <queueSize>10240</queueSize>
    </appender>

    <root level="info">
        <appender-ref ref="ASYNC_CONSOLE"/>
    </root>
</configuration>

이렇게 하니까 표준출력보다 빠르더군요.

꼭 성능문제뿐 아니라 로그 관리체계 자체가 로깅 프레임워크가 넘사이기 때문에 안쓸 비교불가겠지만..

성능적으로 보더라도 실무 환경이라면 메시지 출력 전후로 비즈니스 로직들이 있기 때문에 임계영역을 통해 스레드를 대시시키는 표준출력을 사용하는것보다는 로깅 프레임워크가 더욱 성능적으로 이점이 있을 것 같습니다.