로깅 성능에 대한 고민

로깅을 할 때 원하는 형태로 출력하기 위해 필요한 계산 로직들이 있을 수 있다.

출력을 꼭 해야하는 경우라면 필요한 로직이기 때문에 당연시 하겠지만, 로그 레벨에 의해 출력되지 않을 로그에도 해당 계산 로직들이 호출되곤 한다. 이 비용은 정당한 비용일까?

이번 포스팅에선 로그를 위해 호출되는 로직들에 의한 비용과 개선방안에 대해 고민한 내용을 정리해볼까 한다.

---

일단 Slf4j 의 Logger 인터페이스에선 파라미터 바인딩 방식을 제공한다. 이 방식을 사용하면 문자열을 더하는 간단한 연산같은 경우는 피할 수 있다.

문자열 더하기

log.info("안녕하세요, " + name + "님!");

파라미터 바인딩

log.info("안녕하세요, {}님!", name);

---

파라미터 바인딩 방식은 무적일까? 만약 여러 개의 파라미터를 써서 출력할 문자열을 만들어야 한다면 어떨까?

Slf4j의 Logger 인터페이스를 보면, 이 파라미터 바인딩 방식이 뒤에 인자 한개, 두개 까지는 오버로딩이 되어있다. 하지만 세개부터는 그냥 가변인자를 받는 걸 볼 수 있다.

public void info(String msg);

public void info(String format, Object arg);

public void info(String format, Object arg1, Object arg2);

/**
 * Log a message at the INFO level according to the specified format
 * and arguments.
 * <p/>
 * <p>This form avoids superfluous string concatenation when the logger
 * is disabled for the INFO level. However, this variant incurs the hidden
 * (and relatively small) cost of creating an <code>Object[]</code> before invoking the method,
 * even if this logger is disabled for INFO. The variants taking
 * {@link #info(String, Object) one} and {@link #info(String, Object, Object) two}
 * arguments exist solely in order to avoid this hidden cost.</p>
 *
 * @param format    the format string
 * @param arguments a list of 3 or more arguments
 */
public void info(String format, Object... arguments);

그리고 가변 인자를 받고 있는 메서드의 설명을 보면, 이 메서드를 사용할 경우 Object 배열을 생성하는 숨겨진 비용이 든다고 얘기하고 있다.

너무 당연한 얘기다. 가변인자는 받는 쪽에선 결국 배열을 만들어서 받으니까.

즉, 파라미터 바인딩 방식을 사용해도 출력되지 않는 레벨의 로그를 찍는 함수를 호출한다면 최소 Object배열을 만드는 쓸데없는 비용이 낭비된다는 얘기다.

 

이 Object 배열의 생성 비용을 절약하기 위해 파라미터를 2개 이하로 제한하는 방법도 있다고 한다.

하지만 이 부분은 신경쓰지 않는 것이 좋다는 것이 내 의견이다. 일단 Object 배열을 생성하는 비용이 정말 그렇게 큰 문제를 일으킬까? 싶다. 그리고 어차피 찍어야 하는 정보들이라면 찍는 것이 맞다고 생각한다. 만약 Object 배열 생성을 피하기 위해 파라미터를 제한해서 찍을 정보를 줄인다면, 그때부턴 공방이매우 사소한 비용 절약 vs 로그의 가치 가 된다. 말이 필요없이 후자다.

 

로그는 트러블 슈팅의 목적 뿐 아니라, 필터링이 가능한 데이터로써 많은 가치를 지닌다. 고작 객체 하나 생성하는 비용 때문에 중요한 가치를 상실하지 말자. 그 비용이 그렇게 중요했다면, 레이어간 데이터를 전달할 때 DTO로 포장해서 전달하는 것 조차도 불필요한 객체 생성이다. 전부 까서 전달하지 왜 객체로 포장해서 전달하나.. 너무 사소한 비용에 목숨걸지 말자.

---

Object 배열을 만드는 것만이 문제가 아니다.

현재 진행하고 있는 내편이란 프로젝트에서 찍는 로깅 코드의 일부다.

log.debug(
        "[{}] {}--> {} args={}",
        loggingStatusManager.getTaskId(),
        getDepthSpace(loggingStatusManager.getDepthLevel()),
        message,
        args
);

파라미터 바인딩을 위해 넣는 파라미터 부분에서도 메서드를 꽤 여러 개 호출하고 있다.

이 메서드를 호출하는 비용 또한 불필요한 비용이 된다.

어떻게 불필요한 비용을 최소화할 수 있을까?

Slf4j 로깅 프레임워크에는 로그 레벨을 체크할 수 있는 메서드가 존재한다. 이 메서드는 각 레벨별 로그 메서드 호출시에 메서드 내부에서 레벨을 체크해서 출력을 할지 말지를 판단하는 부분에 사용되기도 한다. 이걸 바깥으로 빼서 미리 한번 검사하면 불필요한 연산 비용을 줄일 수 있지 않을까?

if (log.isDebugEnabled()) {
    log.debug(
            "[{}] {}--> {} args={}",
            loggingStatusManager.getTaskId(),
            getDepthSpace(loggingStatusManager.getDepthLevel()),
            message,
            args
    );
}

실제 내편 프로젝트에선 다음과 같은 형태로 로깅을 하고 있다.

그럼 log.isDebugEnabled()를 호출하는 비용은 어떻게 할거냐? 싶을 수 있다. 하지만 이 조건문을 실행하는 비용은 안에서 쓰이는 연산 로직에 비하면 너무나 사소한 비용이다. 약 1천만 번 호출해야 고작 몇 나노 세컨드 정도의 비용이 드는 거의 없다시피 하는 비용이다.

---

그럼 모든 로깅문에 if 분기로 로그 레벨을 체크하면 되는걸까?

이거에 대한 고민은 또 달랐다. 모든 로깅문마다 체크한다기 보단 프로젝트 정책에서 정한 디폴트 레벨보다 높은 레벨일 경우에만 체크하는 게 좋다는 결론이 내렸다. 왜냐면 우리 프로젝트에서 디폴트 로그 레벨은 info고 로컬이나 개발서버에선 debug를 사용하는데, 굳이 info로 찍는 로깅 구문을 분기문 체크할 필요가 없다고 생각했다. info로활성화 되든 debug로 활성화 되든 info 로깅 구문은 실행되는 거기 때문에 괜히 분기문을 두번 실행하게 만드는 꼴이 된다.

그래서 debug로 호출하는 부분에만 로깅 레벨체크 분기문을 추가하도록 했다.

 

끝.

Ref

http://dveamer.github.io/backend/HowToUseSlf4j.html

https://logging.apache.org/log4j/log4j-2.3.2/performance.html