Log를 찍을 때 고려할 것

게시 2024/05/06 업데이트 2024/12/31

By RPhi 15 분읽는 시간

우리가 sysout을 사용하지 않는 이유

보통 java에서 로그를 찍을 때 System.out.println이라는 함수 대신 log.debug(log는 때때로 대문자이거나 LOGGER 등으로 다를 수 있다.) 함수를 쓰라는 이야기를 들곤 한다.
sysout 함수 대신 log.debug라는 함수를 쓰는 이유는 여러 가지가 있다.
첫 번째는 sysout으로는 로그 레벨을 2가지밖에 사용하지 못한다는 점일 것이다.
System.out.println과 System.err.println이 바로 그것인데, 각각 표준 출력과 오류 출력에 대응한다.(linux를 조금 하다보면 나오는 &1과 &2가 바로 이것이다.)(물론 윈도우도 마찬가지지만)
그리고 두 번째는 위와 같은 맥락에서 출력이 따로 파일로 저장되지 않는다는 점이다.
물론 표준 출력 or 오류 출력을 리다이렉션할 수 있지만, OS마다 리다이렉션 방법을 고민하는 것이 결코 쉽지는 않을 것이다.
세 번째로 따로 신경쓰지 않는 이상 로그 내용과 관련된 메타데이터(시간, 패지키 위치, 실행 스레드 등)가 남지 않는다는 점을 들 수 있을 것이다.
그리고 네 번째로 제일 중요한 부분으로서 성능 저하가 일어날 가능성이 있다는 점을 들 수 있겠다.
보통 웹 어플리케이션 서버의 경우 멀티 스레드 환경이기 때문에, sysout을 사용하면 해당 부분이 병목 현상으로 막힐 가능성이 있다.
이런 이유로 sysout 대신 log.debug라는 함수를 이용하는 것이지만, 사실 이 log에 해당하는 구현체를 무엇으로 사용하느냐도 중요한 문제일 것이다.
실제로 찾아보면 sysout을 대체하기 위한 여러 로그 구현체가 존재하고 있다.

log4j2? logback? slf4j?

여러 대체제가 있겠지만 중요하다고 생각되는 몇 가지만을 간단히 살펴보자.
아마 엔터프라이즈급 어플리케이션에서 제일 많이 사용되는 것은 log4j2일 것이다.
설정 부분이 까다롭긴 해도 log4j2는 다양한 로그 레벨과 훌륭한 성능, async 로거 등의 기능들을 갖추고 있으며, 한번 익혀두기만 하면 로그 관련에 대해서는 그리 신경쓸 필요가 없을 정도다.

한편, 모두가 사용하는 스프링의 경우는 기본 로그 라이브러리를 log4j2가 아닌 logback으로 사용한다.
그래서 log4j2를 사용하기 위해 build.gradle(혹은 maven이라면 pom.xml)에서 일부러 logback을 제거하는 설정을 해야 하곤 한다.
logback도 나쁘지는 않겠지만 부하가 많을 때는 자원을 많이 소모할 수도 있다는 모양이다.
그래서 logback을 제거하고 log4j2로 구현체를 바꾸는 경우도 많다.

slf4j의 경우는 위와는 결이 조금 다르다.
원래 이름인 Simple Logging Facade for Java에서도 알 수 있지만, 해당 라이브러리는 그 자체로 로깅 기능을 구현해주기보다는 그보다 앞단에서 interface 역할을 하는 라이브러리이다.
스프링에서 로깅을 사용할 때 보통 다음과 같은 코드를 사용하곤 한다.

  
package com.mycompany.app;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class App {
    private static Logger LOGGER = LoggerFactory.getLogger(App.class);

    public static void main(String[] args) {
        LOGGER.info("Hello from Slf4j logger!");
    }
}

혹은 lombok을 사용한다면 다음과 같은 코드를 추가한다.
달라진 점이라면 물론 선언된 LOGGER 대신 lombok에 의해 자동 생성된 log 객체를 사용한다는 점일 것이다.

  
package com.mycompany.app;

import lombok.extern.slf4j.Slf4j;

@Slf4j
public class App {
    public static void main(String[] args) {
        log.info("Hello from Slf4j logger!");
    }
}

import된 패키지명을 보면 알겠지만, 스프링에서 logger를 사용할 때는 Slf4j를 사용한다.
그리고 내부적으로 Slf4j는 내부에 들어 있는 구현체의 종류에 따라 log4j2를 사용할지, logback을 사용할지 혹은 다른 라이브러리를 사용할지를 결정짓는다.
그래서 이미 로그가 온갖 곳에 박혀 있는 기존의 프로젝트에서 logback을 log4j2로 교체하자 라는 이야기가 나올 때, 내부 코드까지는 건드릴 필요 없이 build.gradle과 관련 설정 파일을 조금 손보는 것만으로도 손쉽게 구현체를 교체할 수가 있는 것이다.

이렇듯 다양한 구현체가 있기는 한데, 사실 로직을 쓰는 개발자 입장에서는 log.debug나 log.info, log.error 중 하나를 쓰면 그만이다.
물론 그것도 퍼포먼스를 생각한다면 완전히 막 쓸 수는 없다.
퍼포먼스를 높이기 위한 약간의 팁이 존재한다.

퍼포먼스를 위한 팁

log4j2 공식 문서에서는 String에 변수를 대입할 때 “Hello “ + str + “ World!”처럼 String을 +로 이어붙이는 것보다 “Hello {} World!”의 형식으로 사용하는 것을 권장한다.
예를 들면 다음과 같은 코드는 퍼포먼스적인 문제가 존재한다.

  
logger.debug("Logging in user " + user.getName() + " with birthday " + user.getBirthdayCalendar());

만약 해당 코드가 실행되는 시점에 로그 레벨이 debug 이하라면 상관이 없을 수도 있다.
그러나 info, error 등 상위의 레벨이라면 해당 함수는 실행되지 않아야만 할 것이다.
하지만 실제로는 logger.debug라는 함수가 실행되는 시점에 로그 레벨과 상관 없이 “Logging in user “ + user.getName() + “ with birthday “ + user.getBirthdayCalendar() 라는 파라미터는 이미 계산이 된 상태로 실행이 된다.(프로그래밍 언어의 stack 구조상 이를 막는 것은 불가능하다)
로그 레벨이 info라서 해당 문장이 출력되지 않는 상황에서도 CPU는 이미 해당 구문을 의미도 없이 계산해버린 것이다.
String concat이 상당한 CPU 자원을 요구한다는 걸 생각하면 해당 구문이 길어질수록, 많아질수록 퍼포먼스가 떨어지게 된다는 것은 당연한 사실일 것이다.
그러므로 우리는 다음과 같은 구문을 사용할 수 있다.

  
if (logger.isDebugEnabled()) {
    logger.debug("Logging in user " + user.getName() + " with birthday " + user.getBirthdayCalendar());
}

logger.isDebugEnabled()를 체크함으로써 로그 레벨이 debug보다 상위라면 logger.debug 함수는 실행되지 않는다.
함수 자체가 실행되지 않으므로 로그 레벨이 info 이상일 때 String concat을 방지할 수 있어 이는 퍼포먼스의 향상으로 이루어지는 것이다.
log4j 시절에는 위와 같은 코드를 짜는 것이 최선이었다고 한다.
하지만 여전히 문제점이 존재한다.
if 구문을 써야 하므로 코드 양이 쓸데없이 늘어났고, logger.isDebugEnabled와 logger.debug 양쪽에서 로그레벨을 체크하므로 쓸데 없는 연산이 중복된 것이다.
이에 공식 문서는 다음과 같은 코드를 권장한다.

  
logger.debug("Logging in user {} with birthday {}", user.getName(), user.getBirthdayCalendar());

위 예시는 간단하지만 두 번째 예시와 달리 로그 레벨을 한 번만 확인한다.
게다가 보기도 좋고 깔끔하니 코드 내용을 복기할 때에도 장점이 있는 셈이다.

한편, 위 예시 역시도 문제점이 남아 있다.
String의 concat이 매번 일어나지는 않게 되었지만, 그럼에도 user.getName() 함수를 호출할 때와 user.getBirthdayCalendar() 함수를 호출할 때 로그 레벨에 관계 없이 연산이 일어나게 된다.
물론 위 예시에서는 해당 연산은 그리 복잡하지 않은 연산일 것이다.
하지만 만약에 해당 위치에 값을 구해야 하는 좀 더 복잡한 연산을 필요로 한다면?
logger.debug 함수 이전에 값을 미리 구해 놓는다는 것은 답이 되지 않는다.
만약 그 값이 로그를 찍기 위한 단 한 가지의 목적으로 구해지는 것이라면, 로그 레벨이 info든 error든 해당 값을 구하기 위한 연산은 몇 번이고 이루어질 것이기 때문이다.

간단하게 생각하면, 중복 연산이 이루어지는 것을 고려하더라도 logger.isDebugEnabled()를 체크할 수 있을 것이다.
중복 연산이 일어난다 하더라도 복잡한 연산이 로그 레벨에 관계 없이 매번 이루어지는 것보다는 훨씬 싸게 먹힐 것이기 때문이다.
하지만 log4j2에서는 다음과 같은 문법을 제공한다.

  
// Java-8 style optimization: no need to explicitly check the log level:
// the lambda expression is not evaluated if the TRACE level is not enabled
logger.trace("Some long-running operation returned {}", () -> expensiveOperation());

Java 8의 람다식을 사용한 lazy logging이 바로 그것이다.
위의 예시에서 parameter는 expensiveOperation()의 결과가 아닌, expensiveOperation()을 결과로서 반환하는 무명 함수 () -> expensiveOperation()를 제공한다.
logger.trace가 실행되는 시점에 trace 함수는 expensiveOperation()의 결과가 아닌 해당 무명 함수를 지닌 상태로 로그 레벨을 확인한다.
만약 로그 레벨이 합당하다면 trace 함수는 자신이 받은 무명 함수를 실행시켜 복잡한 연산 끝에 원하는 값을 얻어낼 것이다.
하지만 로그 레벨이 debug나 그 위라면, trace 함수는 파라미터로 받은 무명 함수를 실행시키지 않으면 그만이다.
그래서 효율적인 로깅이 가능하다.

물론 마지막 네 번째의 예시까지 가는 경우는 일반적인 개발자 레벨에서는 그리 많지 않을 수도 있다.
보통은 세 번째 예시의 단계에서 로그를 사용하는 것이 일반적이고 효율적일 것이다.

그 외 고려해볼 만한 것들

위와 같은 상황 이외에도 몇 가지를 고려해볼 수 있다.
예를 들면 일반적인 로그는 sync 모드로 실행되기 때문에, 로그 코드 다음 코드가 실행되려면 로깅이 끝날 때까지 기다려야만 한다.
그러나 경우에 따라서는 로그보다 비즈니스 로직 코드의 실행이 더 중요할 때가 있을 것이다.
이러한 경우 async 로거를 사용하여 중요한 코드의 실행을 우선시하는 방법이 있을 수 있을 것이다.

참고 사이트

https://hudi.blog/do-not-use-system-out-println-for-logging
https://liltdevs.tistory.com/180
https://betterstack.com/community/guides/logging/best-java-logging-libraries
https://logging.apache.org/log4j/2.x/manual/api.html

Java