slf4j을 활용한 로깅시 놓치기 쉬운 실수 한가지, 그리고 Logback 내부 동작 과정

slf4j을 활용한 로깅시 놓치기 쉬운 실수 한가지 그리고 Logback 내부 동작 과정

해당 포스트에선 java 8, logback 1.3, slf4j 2.0를 바탕으로 코드 제공 및 설명한다.

요약: slf4j의 로깅 메서드 호출 시 formatted string이 필요하다면 무조건 {} 쓰자.

개발을 하다 보면 디버깅 및 에러감지를 위해 필수적으로 코드 사이사이에 로그를 쌓게 된다.
자바에서는 로깅 기능을 위해 활용되는 프레임워크가 크게 logback, log4j, log4j2 정도가 있다.
보통 애플리케이션 단에서는 이 프레임워크들을 직접 사용하진 않고(굳이 사용하고 싶다면 뭐..), 이들을 추상화시켜 뒷단에 두며 구현체를 선택할 수 있는 퍼사드를 제공하는 프레임워크를 사용한다.
퍼사드의 종류엔 apache commons logging(JCL: Jakarta Commons Logging), SLF4J(Simple Logging Facade for Java)가 있으며 거의 SLF4J 대세라고 한다.

SLF4J 활용해 로깅을 할 때 부끄럽지만, 미처 관심을 둬 주지 않았던, 하지만 심플한 내용을 적어보려고 한다.
(구현체가 logback이던 log4j던 동일한 인터페이스를 활용할 테니 아마 얼추 비슷하겠지만, 팀 내에서 logback을 쓰고 있어서 상세 코드는 logback을 까볼 것임.)

---

로깅 시 메시지 전달

우리는 로깅을 할 때 파라미터 정보나 key등과 같은 데이터를 보고 싶어 하고, 이를 문자열에 포함시켜 로깅을 한다.
이런 경우 작업을 하면서 아래와 같은 방식으로 로깅을 하는 걸 자주 봤다. (내 주관적인 경험 기반)

log.debug("Writing to AMQP with " + items.size() + " items."); // (1) Concatenation operator
log.debug(String.format("Writing to AMQP with %s items.", items.size())); // (2) String Building Methods(기타 등등)
log.debug("Writing to AMQP with {} items.", items.size())); // (3) SLF4J Parameterized Message

내가 실수하고 있다는 생각 없이 위 3방식의 로깅 코드를 봤을 때 내 느낌은 아래와 같았다.

• (1) +연산자의 경우 뭔가 딱 봐도 느낌이 좋지 않아 보이지만, Java 5 이후로 바이트코드 변환 시에 StringBuilder로 처리를 해주니 사실 성능상 이슈는 없어 보인다.
• (2) String 생성 메서드들(뭐 util의 종류에 따라 다른 종류들도 사용될 듯하다)의 경우도 나쁘지 않아 보인다. 생각보다 이렇게 작성된 걸 자주 봤다.
• (3) 로깅 퍼사드에서 제공하는 파라미터 치환 기능. 뭔가 로깅 메서드내에 별도 문자열 building을 위한 호출이 필요 없어서 좋다. 이렇게도 많이 작성한다.

나의 경우 사실 현업에서 별 생각 없이 (2)와 (3)의 형태를 혼용해서 쓰곤 했다. 그냥 무의식적으로 뭐 크게 다르겠어? 라고 생각했던 것 같은데, logback 프레임웤의 내부 동작을 확인하고 나서 "아, 내가 정말 잘못 생각했었구나(2번 케이스);" 라고 깨닫게 되었다. (그런데 은근히 2번 방식의 코드가 꽤 존재한다. 사람들이 미처 인지하지 못하는 듯)

문제점

(1)이던 (2)던 내부에서 StringBuilder로 String을 생성하기에 내부의 로직적인 성능은 차이는 없지 싶다.

우선 (1)과 (2) 방식은 경우에 따라 성능에 영향을 줄 수 있으므로 잘 보고 써야 한다.(사실 이번에 공부하면서 웬만하면 사용하고 싶지 않단 생각이 들었다.)

그 이유는 다음과 같다.
❗ 우리는 logger를 정의 및 생성할 때 로깅 level(실제로 로깅을 하는 시작 level)을 지정하는데, 위의 경우 DEBUG 로그를 찍는 코드이고 현재 애플리케이션의 로깅 레벨이 INFO 이상이라면 사실 로깅 메서드 내부에서 걸러지게 된다.

❗ 이게 문제다. 실제로 로그 레벨에는 미달해서 로그는 남기지 않는데 메서드 호출 시점에 String concatenation 작업이 이뤄지고 있다.
의미 없는 String concatenation 비용에, 아주 잠깐 후 unreachable 해지긴 하지만 heap 낭비에 gc비용까지 든다.

☠️☠️실제로 (1), (2)와 같이 적용된 일부 코드때문에 대규모 트래픽을 처리하는 시스템에서 이슈가 발생하였다. 트래픽이 몰리는 구간에 size가 큰 객체의 toString()으로 인해 문자열이 계속 생성됬고, 반복되는 gc와 그에 동반되는 stop the world로 인해 응답이 지연됬다. 사소하지만 조심하자.

(1), (2)와 같이는 웬만하면 지양하는 것이 좋다.
아래와 같이 해당 logger의 로깅 level을 사전에 체크하는 코드를 쓴다면 상관없다.

if (log.isDebugEnabled()) {
    log.debug("Writing to AMQP with " + items.size() + " items.");
}

하지만 이것도 설정 부류의 클래스나 로직이 별로 없는 모듈에서는 쓸만하나, 비즈니스 로직이 복잡한 메서드에 로깅이 이곳저곳 퍼져있을 때는 쉽지 않아서, 개인적으로는 별로인 것 같다.

---

Parameterized Message (of SLF4J)

로깅 시 문자열 formatting을 하고 싶다면 (3) 번과 같이 호출하자. slf4j의 로깅 인터페이스는 위의 비용을 막기 위해 formated 되는 값을 파라미터로 받을 수 있게 했다. 그래야 해당 로그 레벨이 disabled 됐을 때 불필요한 파라미터 생성 비용을 피할 수 있다.

아래는 애플리케이션에서 로깅을 요청했을 때 logback의 동작 흐름이다.

참조: http://logback.qos.ch/manual/underTheHood.html

애플리케이션에서 로깅 요청을 하면, 실제 로깅을 수행하는 역할은 logger랑 매핑되어있는 appender list에서 일어난다.
Logger의 역할은 필터링(TurboFilter, log level 체크), LoggingEvent 오브젝트(들어온 데이터를 기반으로) 생성, 그리고 appender list로의 실제 로깅 위임까지이다.
그래서 logger의 최소 level이 INFO인데 해당 logger로 .debug() 호출이 들어오게 되면 위의 step4(check effective level)에서 걸려 해당 invocation을 끝낸다. format과 파라미터를 통해서 실제 메시지를 구성하는 단계는 step8(doLayout())인데, Appender 구현체에 따라 메시지 생성 방식이나 상세 위치는 달라질 수 있다. (해당 메소드 내에서 별도 template method로 추출한 메소드에서 형성한다든가.)

Logback Under the Hook Code

아래에 sequence diagram 상의 내부 구현 코드를 간략히 추출했다. 최대한 심플하게 추리기 위해 Appender는 ConsoleAppender, PatternLayoutEncoder를 기반으로 예시로 넣었다.
ref: https://github.com/qos-ch/logback

package ch.qos.logback.classic;

public final class Logger implements org.slf4j.Logger, LocationAwareLogger, AppenderAttachable<ILoggingEvent>, Serializable {

  /**
    * Logger에 적용되어 있는 Appender 리스트를 참조하고 잇는 프로퍼티.
    * AppenderAttachableImpl is thread safe
    */
  transient private AppenderAttachableImpl<ILoggingEvent> aai;

  ...

  public void info(String format, Object arg) { // --------------------------STEP-[1]
    filterAndLog_1(FQCN, null, Level.INFO, format, arg, null);
  }

  private void filterAndLog_1(final String localFQCN, final Marker marker, final Level level, final String msg, final Object param, final Throwable t) {

  final FilterReply decision = loggerContext.getTurboFilterChainDecision_1(marker, this, level, msg, param, t); // STEP--------------------------[2],[3]

    if (decision == FilterReply.NEUTRAL) {
      if (effectiveLevelInt > level.levelInt) { // STEP--------------------------[4]
        return;
      }
    } else if (decision == FilterReply.DENY) {
      return;
    }

    buildLoggingEventAndAppend(localFQCN, marker, level, msg, new Object[] { param }, t);
  }
  ...

  private void buildLoggingEventAndAppend(final String localFQCN, final Marker marker, final Level level, final String msg, final Object[] params, final Throwable t) {
    LoggingEvent le = new LoggingEvent(localFQCN, this, level, msg, t, params); // STEP--------------------------[5]
    le.setMarker(marker);
    callAppenders(le);
  }

  /**
    * Invoke all the appenders of this logger.

    * @param event
    *          The event to log
    */
  public void callAppenders(ILoggingEvent event) {
      int writes = 0;

      // STEP--------------------------[6]
      for (Logger l = this; l != null; l = l.parent) {
        writes += l.appendLoopOnAppenders(event);
        if (!l.additive) {
            break;
        }
      }
      // No appenders in hierarchy
      if (writes == 0) {
          loggerContext.noAppenderDefinedWarning(this);
      }
  }

  private int appendLoopOnAppenders(ILoggingEvent event) {
    if (aai != null) {
      return aai.appendLoopOnAppenders(event);
    } else {
      return 0;
    }
  }

}

// -------------------------------------------------------------------------------------

public class AppenderAttachableImpl<E> implements AppenderAttachable<E> {

  final private COWArrayList<Appender<E>> appenderList = new COWArrayList<Appender<E>>(new Appender[0]);

  /**
    * Call the doAppend method on all attached appenders.
    */
  public int appendLoopOnAppenders(E e) {
    int size = 0;
    final Appender<E>[] appenderArray = appenderList.asTypedArray();
    final int len = appenderArray.length;
    for (int i = 0; i < len; i++) {
      appenderArray[i].doAppend(e); // STEP--------------------------[7]
      size++;
    }
    return size;
  }
}

// -------------------------------------------------------------------------------------

abstract public class UnsynchronizedAppenderBase<E> extends ContextAwareBase implements Appender<E> {

  public void doAppend(E eventObject) {
    ...
    // ... sychronization 처리 
    // ... Filter 체크
    this.append(eventObject);
    ...
  }

}

// -------------------------------------------------------------------------------------

/**
 * ConsoleAppender의 superclass
 */
public class OutputStreamAppender<E> extends UnsynchronizedAppenderBase<E> {
  @Override
  protected void append(E eventObject) {
    if (!isStarted()) {
      return;
    }

    subAppend(eventObject);
  }

  /**
    * Actual writing occurs here.
    * Most subclasses of WriterAppender will need to override this
    * method.
    */
  protected void subAppend(E event) {
    ...
    byte[] byteArray = this.encoder.encode(event);
    ...
  }

} 

// -------------------------------------------------------------------------------------

public class LayoutWrappingEncoder<E> extends EncoderBase<E> {
  public byte[] encode(E event) {
    String txt = layout.doLayout(event); // STEP--------------------------[8]
    return convertToBytes(txt);
  }
}

// -------------------------------------------------------------------------------------

public class PatternLayout extends PatternLayoutBase<ILoggingEvent> {
  public String doLayout(ILoggingEvent event) {
    if (!isStarted()) {
      return CoreConstants.EMPTY_STRING;
    }
    return writeLoopOnConverters(event);
  }

}

// -------------------------------------------------------------------------------------

/**
 * PatternLayoutEncoder를 사용하는 ConsoleAppender의 string 결합은 여기서 일어나게 된다.
 */
abstract public class PatternLayoutBase<E> extends LayoutBase<E> {
  protected String writeLoopOnConverters(E event) {
    StringBuilder strBuilder = new StringBuilder(INTIAL_STRING_BUILDER_SIZE);
    Converter<E> c = head;
    while (c != null) {
      c.write(strBuilder, event);
      c = c.getNext();
    }
    return strBuilder.toString(); // STEP--------------------------[9]
  }

}

parameterized message (파라미터가 3개 이상인 경우)

아래를 보면 특정 레벨의 로깅에 대해 파라미터를 받는 메서드는 3개가 있다.

1. 파라미터 1개(arg)
2. 파라미터 2개(arg1, arg2)
3. 가변인자 형태.(argArray) - 파라미터 3개 이상

package ch.qos.logback.classic;
public final class Logger implements org.slf4j.Logger, LocationAwareLogger, AppenderAttachable<ILoggingEvent>, Serializable {

  ...
public void debug(String msg) {
    filterAndLog_0_Or3Plus(FQCN, null, Level.DEBUG, msg, null, null);
  }

  public void debug(String format, Object arg) {
    filterAndLog_1(FQCN, null, Level.DEBUG, format, arg, null);
  }

  public void debug(String format, Object arg1, Object arg2) {
    filterAndLog_2(FQCN, null, Level.DEBUG, format, arg1, arg2, null);
  }

  public void debug(String format, Object... argArray) {
    filterAndLog_0_Or3Plus(FQCN, null, Level.DEBUG, format, argArray, null);
  }

  public void debug(String msg, Throwable t) {
    filterAndLog_0_Or3Plus(FQCN, null, Level.DEBUG, msg, null, t);
  }
  ...
  // 그외 Marker가 포함된 메소드는 일단 생략.
}

3과 같이 가변인자로 받을 때에 Object Array 생성 비용이 들긴 하지만 앞선 String concatenation이 먼저 일어나는 것보단 상대적으로 비용이 적다고 한다

---

Logback 코드 분석 (slf4j 기반 logger 생성부터 로깅 수행까지)

소스코드 압박 주의

• 관련 내용
  • ServiceProvider
  • logger parent-children architecture
  • logger-appender

coming soon

---

Reference

• http://logback.qos.ch/manual/underTheHood.html
• https://logback.qos.ch/manual/architecture.html
• https://spring.io/blog/2009/12/04/logging-dependencies-in-spring/
• https://github.com/qos-ch/slf4j
• https://github.com/qos-ch/logback
• http://dveamer.github.io/backend/HowToUseSlf4j.html
• http://www.slf4j.org/faq.html