코드로 뜯어보는 System.out.println 대신 logger 를 사용해야 하는 이유

https://www.geeksforgeeks.org/system-out-println-in-java/

 

System.out.println()

System 에서 out 은 static 변수로 PrintStream 클래스로 할당됩니다.

out 은 jvm 이 시작될 때 intializeSystemclass 함수를 사용하여

jvm 의 standard outputstream(os 로 부터 받은 standard output 을 PrintStream 으로 구현한 것) 으로부터 생성되어 할당됩니다.

고로, 우리는 PreamStream.println() 을 사용하고 있는 것이 됩니다.

 

혹시 initializeSystemclass() 함수가 궁금하다면 더보기를 참고해주세요...

private static void initializeSystemClass() {
    props = new Properties();
    initProperties(props);

    String s = props.getProperty("line.separator");
    if (s != null)
        lineSeparator = s;
    sun.misc.Version.init();

    FileInputStream localFileInputStream = new FileInputStream(FileDescriptor.in);
    FileOutputStream localFileOutputStream1 = new FileOutputStream(FileDescriptor.out);
    FileOutputStream localFileOutputStream2 = new FileOutputStream(FileDescriptor.err);

    setIn0(new BufferedInputStream(localFileInputStream));
    setOut0(new PrintStream(new BufferedOutputStream(localFileOutputStream1, 128), true));
    setErr0(new PrintStream(new BufferedOutputStream(localFileOutputStream2, 128), true));
}

이 함수는 jdk 를 decompile 하여 확인하실 수 있습니다.

 

println 은 다음과 같이 구현됩니다.

 

 

public void println(String x) {
    synchronized (this) {
        print(x);
        newLine();
    }
}

// print
public void print(String s) {
    write(String.valueOf(s));
}

// write
private void write(String s) {
    try {
        synchronized (this) {
            ensureOpen();
            textOut.write(s);
            textOut.flushBuffer();
            charOut.flushBuffer();
            if (autoFlush && (s.indexOf('\\n') >= 0))
                out.flush();
        }
    }
    catch (InterruptedIOException x) {
        Thread.currentThread().interrupt();
    }
    catch (IOException x) {
        trouble = true;
    }
}

// textOut(BufferedStream).write
public void write(String s, int off, int len) throws IOException {
    synchronized (lock) {
        ensureOpen();

        int b = off, t = off + len;
        while (b < t) {
            int d = min(nChars - nextChar, t - b);
            s.getChars(b, b + d, cb, nextChar);
            b += d;
            nextChar += d;
            if (nextChar >= nChars)
                flushBuffer();
        }
    }
}

뭔가 어지러운 느낌이 들지만 중요한 것은 곳곳에 lock 이 걸려 있다는 점입니다.

(아마도, PrintStream 이 BufferedStream 을 사용하고 BufferedStream 은 fd 의 standard output 을 사용하므로 결국 printstream 은 write system call 을 사용한다고 말할 수 있겠습니다.)

 

spring 을 실행하며 tomcat 은 max thread 200 개를 갖게 됩니다.

만약 thread 1 에서 lock 을 획득하여 print 하게 된다면,

나머지 199개는 print 를 하기 위해 lock 을 획득할 때 까지 기다려야 할 것입니다.

이러한 성능 저하 때문에 운영환경에서는 절대 사용해서는 안되며, logger 를 사용해야 할 것입니다.

 

Logger

대표적인 logging framework 인 logback 은 println 의 한계를 극복하기 위해 여러가지 기능을 제공합니다.

로그 레벨 설정에 대한 출력 형식 필터링이나 출력 자체를 제어하거나

logging 을 위한 스레드를 따로 두어 전체 애플리케이션의 성능이 저하되지 않도록 합니다.

 

내부적으로 ConsoleAppender 를 통해 특정 스레드에서만 log 를 쓰게합니다.

아래에서 ConsoleAppender 의 구현을 살펴보겠습니다.

 

public class ConsoleAppender<E> extends OutputStreamAppender<E> {
		// ...
    private Lock lock;
    
    public ConsoleAppender() {
        // ...
        this.lock = new ReentrantLock();
    }
    
    // ...

    private void writeWithJansi(E event) {
        if (!this.lock.tryLock()) {
            return;
        }
        try {
            byte[] byteArray = this.encoder.encode(event);
            int length = byteArray.length;
            for (int i = 0; i < this.codeLength; i++) {
                JansiOutput.write(this.codes[i]);
            }
            JansiOutput.write(byteArray, 0, length);
            JansiOutput.write(0);
            if (this.immediateFlush) {
                JansiOutput.flush();
            }
        } catch (IOException ioe) {
            this.inError = true;
        } finally {
            this.lock.unlock();
        }
    }
}

멀미가 날 것 같은 기분입니다만…

중요한 것은 내부적으로 reentrantlock 을 사용하여 동기화 하여

기존 println 에서 synchronized block 보다 동기화의 cost 를 낮추고,

OutputStreamAppender 를 extends 한다는 점입니다.

 

 

public void start() {
    // ...
    started = false;
    OutputStream os = openOutputStream();
    try {
        setOutputStream(os);
    } catch (IOException e) {
        // ...
    }

    if (encoder == null) {
        addError("No encoder set for the appender named \\"" + name + "\\".");
        return;
    }

    encoderInit();

    writeHeader();

    synchronized (this) {
        this.outputStreamReady = true;
        this.notifyAll();
    }

    super.start();

    started = true;
    if (immediateFlush) {
        encoderInit();
        writeFooter();
    }
    // ...
}

위의 코드는 OutputStreamAppender 의 start 메서드의 일부이고,

outputstream 을 할당한 후 encoder 라는 인스턴스를 가지고 thread 시작하게 됩니다.

실제로 스레드가 시작되는 메서드가 encoderInit() 내부에 있습니다.

 

 

protected void encoderInit() {
    if (encoder == null) {
        addWarn("Encoder has not been set. Cannot invoke its init method.");
        return;
    }

    if (encoderStarted) {
        return;
    }

    // ...
    encoder.start(outputStream, this);
    // ...
}

encoder.start() 가 스레드의 시작부입니다.

 

따라서 logger 는 println 에서의 잦은 I/O 작업을 제어하거나

한 스레드에서 lock 을 독점하는 것을 막아 시스템의 전체 응답 속도를 낮추는 것을 피하기 위해

하나의 스레드에 I/O 작업을 독점적으로 하게 하여 성능적 저하를 회피할 수 있게 됩니다.

 

 

끝!