학습 배경
우테코 레벨3 팀프로젝트 3차 데모데이 요구사항 중 하나는 ‘디버깅할 수 있는 로그 파일 출력’ 이다. 이전까지는 로깅에 대해 전혀 신경쓰지 않고 있었는데, 슬슬 로깅에도 신경써야할 것 같다. 로깅의 목적, SLF4J, Logback, 어디서 어느 수준으로 무엇을 로깅해야하는지 깊게 공부하기 이전에 사람들이 System.out.println() 대신 로깅 프레임워크를 통해 로깅하는 이유가 궁금해졌다.
왜 편하게 표준 출력이 가능한 System.out.println() 메소드를 놔두고 사람들은 로깅 프레임워크를 사용하는 것 일까? 더 나아가 왜 System.out.println() 을 프로덕션 코드에서 사용하면 안되는 것 일까?
휘발된다
System.out.println() 은 로그가 표준 출력으로 출력된다. 즉, 파일로 저장되지 않고 휘발된다는 의미이다. 로그는 에러가 발생한 상황을 기록하고, 추후 확인하여 문제를 진단하고, 재현하고, 고치기 위해 사용된다. 하지만 표준 출력으로 한번 출력되고 어디에도 저장되지 않으면 로그의 제 역할을 할 수 없다.
로그된 데이터는 실제로 기록되어야 한다. 하지만 System.out.println() 만으로는 불가능하다.
에러 발생 시 추적할 수 있는 최소한의 정보가 남지 않는다
System.out.println() 은 인자로 전달한 문자열만을 출력한다. 문제가 발생한 날짜, 시각 그리고 문제의 수준, 로그가 발생한 위치 등 최소한의 정보가 기록되지 않는다는 것 이다. 이런 제한적인 정보만으로는 문제를 해결하기 어려울 것 이다. 물론 이런 정보도 함께 인자로 전달한다면 충분히 에러와 장애를 추적할 수 있는 정보를 남길수야 있지만… 매번 그런 정보를 일일히 남기기엔 번거로울 것 이다.
로그 출력 레벨을 사용할 수 없다
로컬에서 개발할 때에는 디버깅을 위한 아주 상세한 정보가 출력되어 확인할 수 있어야한다. 하지만, 프로덕션에서 동작하는 코드는 에러/장애가 발생할 때 문제를 진단할 수 있는 정보만을 남겨야한다. 개발시에만 사용되는 정보와 문제 상황에 대한 정보가 함께 로깅된다면 문제 해결을 위한 정작 중요한 정보를 얻기 힘들 뿐더러, 민감한 정보를 로그로 남길수도 있기 때문이다. 또한 의미없는 로그가 쌓여 서버 용량을 차지할 수도 있다.
따라서 로깅 라이브러리는 환경에 맞게(로컬 개발 환경, 개발 서버, 프로덕션 서버 등) 로그가 출력될 수 있도록 로그 출력 레벨이라는 기능을 제공한다. 많이 사용되는 Logback이라는 라이브러리에서는 TRACE, DEBUG, INFO, WARN, ERROR, FATAL 와 같은 레벨을 제공한다. 하지만 System.out.println() 은 이런 기능을 제공하지 않는다. 어떤 환경에서든 동일한 로그가 출력된다. 프로덕션에서 이런 로그를 제거하려면 코드를 일일히 제거하거나 주석처리하거나 별도의 조건문을 설정하는 등 번거로운 일들을 해야한다.
성능저하의 원인이 될 수 있다
System.out.println() 의 구현을 한번 살펴보자.
/**
* Terminates the current line by writing the line separator string. The
* line separator string is defined by the system property
* {@code line.separator}, and is not necessarily a single newline
* character ({@code '\n'}).
*/
public void println() {
newLine();
}println() 은 newLine() 을 호출한다. newLine() 의 구현도 살펴보자.
private void newLine() {
try {
synchronized (this) {
ensureOpen();
textOut.newLine();
// ...synchronized 키워드가 붙어있다. 이때 newLine() 메소드는 임계영역(critical section)이 된다. 멀티 쓰레드 환경에서 A 쓰레드가 newLine() 메소드를 실행하면, 메소드는 잠기게 된다. 다른 쓰레드는 A 쓰레드가 모두 사용하고 잠금을 풀어준 뒤에서야 newLine() 메소드를 실행할 수 있다. 오버헤드가 발생하게 되는 것 이다.
스프링을 실행하는 톰캣은 멀티 쓰레드로 동작한다. 요청이 오면 쓰레드 풀에서 쓰레드를 하나 가져와 요청을 처리한다. 그런데, System.out.println() 을 여러 쓰레드가 사용하면 그만큼 위에서 이야기한 오버헤드가 발생하고 처리가 느려질 것 이다. 따라서 실제 프로덕트의 코드에서는 System.out.println() 을 절대 사용해서는 안된다.
한 번 요청 시 5000명의 사용자를 요청하고, 처리 과정에서 응답시간이 20초 걸리는 사이트가 있는데, 원인을 알아보니 5000명의 정보를 다 System.out.println()으로 처리하고있던 것이다. 이는 System.out.println()을 줄임으로써 응답시간이 6초까지 줄었다. - 이상민, 자바 성능 튜닝이야기, 인사이트, 2013