Logger vs System.out.println

System.out.println

System.out.print 에서 out 은 static 변수로 PrintStream 클래스로 할당되고, 이 변수는 JVM 이 초기화 될 때 설정된다.

PrintStream 은 매개변수로 전달받은 값을 console 에 출력하게 되고,

    private final InternalLock lock;
    
    (....)
    
    public void println(String x) {
        if (getClass() == PrintStream.class) {
            writeln(String.valueOf(x));
        } else {
            synchronized (this) {
                print(x);
                newLine();
            }
        }
    }
    
    (....)
    
    private void writeln(char[] buf) {
        try {
            if (lock != null) {
                lock.lock(); // lock 객체가 있으면 락을 걸어준다.
                try {
                    implWriteln(buf);
                } finally {
                    lock.unlock(); // lock 해제
                }
            } else {
                synchronized (this) {
                    implWriteln(buf); // lock 객체가 없으면 this 객체에 대해서 동기화 처리
                }
            }
        }
        catch (InterruptedIOException x) {
            Thread.currentThread().interrupt();
        }
        catch (IOException x) {
            trouble = true;
        }
    }

내부적으로 synchronized 와 lock (InternalLock) 으로 thread-safe 하게 동작하게 설계 되어 있다.
하지만, 메서드를 호출하는 스레드가 해당 블록 내의 작업을 단일 스레드로 처리 하게 만들기 때문에
여러 스레드가 동시에 이 메서드에 접근할 경우 병목 이 발생할 수 있다.

synchronized 나 lock 를 사용한 동기화는 Race Condition(경쟁 조건) 을 막아주만, 성능 상의 문제를 일으킬 수 있다.

System.out.println 장단점

Logback

Logback 의 AsyncAppenderBase 는 비동기적으로 로그 이벤트를 처리하는 클래스이다.
이 클래스는 AppenderBase 를 상속 받아 구현되어 있는데, 비동기 처리 방식으로 로그를 쌓고 치리하는 기능을 제공한다.

위의 코드에서 BlockingQueue<E> blockingQueue, worker, discardedCount 가 비동기처리를 위한 중요한 역할을 하는데,

• BlockingQueue<E> blockingQueue
  • 로그 이벤트를 임시로 저장하는 Queue
  • BlockingQueue 는 이벤트가 처리되지 않았을 때 스레드가 대기 할 수 있도록 설계됨
• worker
  • 실제로 이벤트를 처리하는 worker 스레드로 AsyncAppenderBase 가 시작 되면 백그라운드에서 실행되며, blockingQueue 에서 이벤트를 꺼내서 로그로 출력한다.
• discardedCount
  • Queue 가 꽉 차서 더 이상 이벤트를 추가하지 못할 때, 버려진 로그 이벤트의 수를 기록하는 필드

AsyncAppenderBase 의 주요 동작 흐름

1) 로그 이벤트 추가

• append() 메서드가 호출되면 로그 이벤트를 blockingQueue 에 추가
• Queue 가 가득 찼을 때의 동작은 설정에 따라 다르다 (blocking or 이벤트 폐기)

2) 이벤트 처리

• worker 스레드가 지속적으로 blockingQueue 에서 이벤트를 가져와 처리
• 이 과정은 main thread 와 별개로 동작하여 성능 향상의 이점

3) 종료 처리

• stop() 메서드 호출시 남은 이벤트를 모두 처리하고 worker 스레드를 안정하게 종료

따라서, Logback 의 AsyncAppender 를 이용하면,
로그 메시지를 비동기적으로 처리하여 I/O 작업이 메인 스레드의 성능에 영향을 미치지 않도록 하고,
Queue 를 사용하여 메인 스레드가 로그 출력에 시간을 소비하지 않도록 하여 동시성 문제를 방지한다.

System.out.println vs java.util.logging vs logback Benchmark

System.out.println 과 java.util.logging 그리고 logback 을 이용해서 멀티스테드 환경에서 JMH(Java Microbenchmark Harness) 로 로깅 성능 비교를 해보았다.
logger 는 logger 를 켰을 때와 OFF 시켰을 때, 그리고 logback 의 AsyncAppender 설정을 추가하여, 로그 메시지를 비동기적으로 처리하여 테스트 하였다.

logback 의 AsyncAppender 설정 예시

<configuration>
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg
 </pattern>
        </encoder>
    </appender>

    <appender name="ASYNC" class="ch.qos.logback.classic.AsyncAppender">
        <appender-ref ref="STDOUT"/>
    </appender>

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

아래와 같은 결과를 얻을 수 있는데,

1) LoggerDisabled vs LoggerEnabled

• Logger 를 비활성화 했을 때 성능이 우수한 것을 볼 수 있는데, Logging 작업 자체가 어느 정도의 오버헤드를 가지고 있다는 것을 알 수 있다.

2) JavaLoggerEnabled vs LoggerEnabled

• Logback 이 java.util.logging 보다 훨씬 높은 성능을 보여주는데, Logback 의 효율적인 구현과 비동기 처리 때문이다.

3) SystemOutPrintln

• 동기적 처리와 I/O 작업의 직접적인 수행 때문에 가장 낮은 성능을 보여주고 있다.

따라서, 프러덕션 환경에서 System.out.println 을 사용하는 경우 성능에 치명적인 영향을 줄 수 있다.

Reference

• 10. 로그는 반드시 필요한 내용만 찍자
• 코드로 뜯어보는 System.out.println 대신 logger 를 사용해야 하는 이유
• System.out.println() 동작원리 native method까지 까보기