feat: add system-out-println-vs-logger.mdx

Author: eottabom

posts/java/system-out-println-vs-logger.mdx

@@ -0,0 +1,213 @@
+---
+title: "Logger vs System.out.println"
+date: "2024-09-29"
+tags: ["Java"]
+summary: "Compare loggers with System.out.println, and find out why System.out.println should not be used in production code."
+description: "로거와 System.out.println 를 비교해보고, 왜 System.out.println 을 프러덕션 코드에서 사용하면 안되는지에 대해서 알아보자."
+---
+
+:::info
+운영 중인 Application 에서는 System.out.print 대신에 Logger 를 사용해야하는데,
+쓰지 말아야 하는 이유와 어떻게 동작하는지에 대해서 알아보자. (jdk 21 기반으로 작성됨)
+:::
+
+
+### System.out.println
+
+---
+
+`System.out.print` 에서 `out` 은 static 변수로 `PrintStream` 클래스로 할당되고, 이 변수는 JVM 이 초기화 될 때 설정된다.
+
+<div style={{ textAlign: 'center' }}>
+    <img src="/img/post/java/print/print-stream-out.png" alt="print-stream-out"  style={{ display: 'inline-block' }} />
+</div>
+
+`PrintStream` 은 매개변수로 전달받은 값을 console 에 출력하게 되고,
+
+```java
+    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(경쟁 조건)** 을 막아주만, 성능 상의 문제를 일으킬 수 있다.
+
+<br/>
+
+### System.out.println 장단점
+
+---
+
+|장점|단점|
+|--|--|
+|사용이 간단하고 직관적|Thread-safe 를 위해 동기화를 사용하므로 성능 저하가 발생|
+|별도의 설정이나 라이브러리가 필요 없음|로그 레벨 구분이나 파일 출력 등 고급 기능이 없음|
+|즉시 콘솔에 출력되어 디버깅에 유용|프러덕션 환경에서 사용하기 어려움|
+
+
+<br/>
+
+### Logback
+
+---
+
+`Logback` 의 `AsyncAppenderBase` 는 비동기적으로 로그 이벤트를 처리하는 클래스이다.
+이 클래스는 `AppenderBase` 를 상속 받아 구현되어 있는데, 비동기 처리 방식으로 로그를 쌓고 치리하는 기능을 제공한다.
+
+<div style={{ textAlign: 'center' }}>
+    <img src="/img/post/java/print/async-appender-base.png" alt="async-appender-base"  style={{ display: 'inline-block' }} />
+</div>
+
+
+위의 코드에서 `BlockingQueue<E> blockingQueue`, `worker`, `discardedCount` 가 비동기처리를 위한 중요한 역할을 하는데,
+* `BlockingQueue<E> blockingQueue`
+* 로그 이벤트를 임시로 저장하는 Queue
+* `BlockingQueue` 는 이벤트가 처리되지 않았을 때 스레드가 대기 할 수 있도록 설계됨
+* `worker`
+* 실제로 이벤트를 처리하는 `worker` 스레드로 `AsyncAppenderBase` 가 시작 되면 **백그라운드**에서 실행되며, `blockingQueue` 에서 이벤트를 꺼내서 로그로 출력한다.
+* `discardedCount`
+* Queue 가 꽉 차서 더 이상 이벤트를 추가하지 못할 때, 버려진 로그 이벤트의 수를 기록하는 필드
+
+<br/>
+
+#### `AsyncAppenderBase` 의 주요 동작 흐름
+
+---
+
+1) 로그 이벤트 추가
+* `append()` 메서드가 호출되면 로그 이벤트를 `blockingQueue` 에 추가
+* Queue 가 가득 찼을 때의 동작은 설정에 따라 다르다 (blocking or 이벤트 폐기)
+
+2) 이벤트 처리
+* `worker` 스레드가 지속적으로 `blockingQueue` 에서 이벤트를 가져와 처리
+* 이 과정은 main thread 와 별개로 동작하여 성능 향상의 이점
+
+3) 종료 처리
+* `stop()` 메서드 호출시 남은 이벤트를 모두 처리하고 `worker` 스레드를 안정하게 종료
+
+
+따라서, Logback 의 `AsyncAppender` 를 이용하면, 로그 메시지를 비동기적으로 처리하여 I/O 작업이 메인 스레드의 성능에 영향을 미치지 않도록 하고, <br/>
+Queue 를 사용하여 메인 스레드가 로그 출력에 시간을 소비하지 않도록 하여 동시성 문제를 방지한다.
+
+:::warning
+비동기 처리로 인해서 로그의 순서가 약간 뒤바뀔 수도 있고, Application 비정상 종료시에 마지막 로그가 손실 될 수도 있다.
+:::
+
+
+### System.out.println vs java.util.logging vs logback Benchmark
+
+---
+
+`System.out.println` 과 `java.util.logging` 그리고 `logback` 을 이용해서 멀티스테드 환경에서 JMH(Java Microbenchmark Harness) 로 로깅 성능 비교를 해보았다. <br/>
+logger 는 logger 를 켰을 때와 OFF 시켰을 때, 그리고 `logback` 의 `AsyncAppender` 설정을 추가하여, 로그 메시지를 비동기적으로 처리하여 테스트 하였다.
+
+:::note
+<b>Q. logback 에서 AsyncAppender 를 사용하면?</b>
+메인 쓰레드의 부하 감소 : 로그 이벤트는 즉시 처리되는 대신, 큐에 저장되었다가 별도의 쓰레드가 처리해서 메인 쓰레드의 작업은 빠르게 된다.
+쓰레드 간 I/O 경쟁 감소 : 동기적인 로깅은 많은 쓰레드가 동시에 출력하려고 할 때 I/O 작업에서 병목이 발생할 수 있는데, 이를 완화해준다.
+:::
+
+
+logback 의 `AsyncAppender` 설정 예시
+
+```java
+<configuration>
+    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
+        <encoder>
+            <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n </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>
+
+```
+
+아래와 같은 결과를 얻을 수 있는데,
+
+| Benchmark                               |Mode|Cnt| Score    | Error           | Units |
+|-----------------------------------------|--|--|----------|-----------------|-------|
+| LoggingBenchmark.benchmarkJavaLoggerDisabled | thrpt| 10 | 2618.238 | ±  90.077  | ops/s |
+| LoggingBenchmark.benchmarkJavaLoggerEnabled  | thrpt| 10   | 2.986 | ±   0.711  | ops/s |
+| LoggingBenchmark.benchmarkLoggerDisabled     | thrpt| 10 | 2480.615 | ± 272.262 | ops/s |
+| LoggingBenchmark.benchmarkLoggerEnabled      | thrpt| 10 | 1419.497 | ± 221.123 | ops/s |
+| LoggingBenchmark.benchmarkSystemOutPrintln   | thrpt| 10  |    6.468 | ±   0.692 | ops/s |
+
+
+#### 1) LoggerDisabled vs LoggerEnabled
+  * Logger 를 비활성화 했을 때 성능이 우수한 것을 볼 수 있는데, Logging 작업 자체가 어느 정도의 오버헤드를 가지고 있다는 것을 알 수 있다.
+#### 2) JavaLoggerEnabled vs LoggerEnabled
+  * `Logback` 이 `java.util.logging` 보다 훨씬 높은 성능을 보여주는데, Logback 의 효율적인 구현과 비동기 처리 때문이다.
+#### 3) SystemOutPrintln
+  * 동기적 처리와 I/O 작업의 직접적인 수행 때문에 가장 낮은 성능을 보여주고 있다.
+
+따라서, 프러덕션 환경에서 `System.out.println` 을 사용하는 경우 성능에 치명적인 영향을 줄 수 있다.
+
+:::warning
+java.util.logging 도 비동기 로깅을 하기 위해서 별도로 커스텀 핸들러를 구현하면 비동기처리가 가능하긴하다.
+:::
+
+:::tip
+<a href="https://github.com/eottabom/lego-piece/tree/main/benchmark">벤치 마크 결과 보기 (클릭)</a>
+<a href="https://github.com/eottabom/lego-piece/tree/main/benchmark/src/main/java/lego/benchmark/logger">벤치 마크 코드 보러가기 (클릭)</a>
+:::
+
+
+:::success
+<b>요약</b>
+✔ System.out.println 와 같은 방법은 사용이 간단하지만, 동기적 처리로 인해 <b>성능 저하</b> 와 <b>스레드 블로킹</b> 문제가 있다.
+✔ 비동기 로깅 방식은 별도의 스레드와 큐를 사용해서 어플리케이션 성능 향상을 도모한다.
+:::
+
+---
+
+### 📚 Reference
+
+* [10. 로그는 반드시 필요한 내용만 찍자](https://velog.io/@jsj3282/10.-%EB%A1%9C%EA%B7%B8%EB%8A%94-%EB%B0%98%EB%93%9C%EC%8B%9C-%ED%95%84%EC%9A%94%ED%95%9C-%EB%82%B4%EC%9A%A9%EB%A7%8C-%EC%B0%8D%EC%9E%90)
+* [코드로 뜯어보는 System.out.println 대신 logger 를 사용해야 하는 이유](https://liltdevs.tistory.com/180)
+* [System.out.println() 동작원리 native method까지 까보기](https://code-run.tistory.com/8)
+