kotlin-logging을 사용하여 효과적으로 로깅하기

서론

어플리케이션을 만들고 제대로 동작하는 것을 확인하려면 단순히 DB에 값이 변한 것을 보는 것이 아니라, 특정 시간에 어떤 작업이 어떻게 수행되었는지 확인할 수 있어야한다.

즉, 로그를 남겨 확인할 수 있어야 한다.

또한, 로그를 남기는 작업은 System.out.println()와 같은 표준 출력을 사용하지 않고 주로 잘 만들어진 로그 프레임워크를 사용한다.

Java 진영에서 로깅을 제공하는 대표 프레임워크는 다음과 같다.

• Logback - Log4j 보다 향상된 성능, 필터링 제공
• Log4j2 - Logback 보다 향상된 성능, 람다 표현식, 사용자 정의 로그 레벨 지원
• Logging - java.util.logging

여기서 스프링을 사용한다면 기본적으로 활성화된 로그 프레임워크는 Logback을 사용한다.

Kotlin을 사용하여도 Java 진영의 로그 프레임워크를 사용할 수 있다.

게다가 직접 사용하는 것은 Slf4j를 사용하기 때문에 어떤 로그 프레임워크를 사용할지 사용자는 알 필요가 없고, 그저 Slf4j가 제공하는 로그 API를 사용하면 된다.

이것은 추후 새로운 로그 구현체를 사용하더라도 변경에 유연하게 대응할 수 있게 해준다.

하지만 Slf4j에는 문제점이 존재한다.

이것은 Kotlin을 사용하고, 전용 라이브러리를 사용하면 해결할 수 있다.

본론

Slf4j를 통한 로깅

Slf4j를 사용하면 다음과 같이 로그 인스턴스를 생성할 수 있다.

class MyClass {
    // LoggerFactory.getLogger(this::class.java)
    // LoggerFactory.getLogger(MyClass::class.java)
    // 클래스 내부에 선언한다면 javaClass로 간단하게 클래스를 가져올 수 있다.
    private val logger = LoggerFactory.getLogger(javaClass)
}

그리고 사용은 다음과 같다.

logger.info("Hello World!")

이때 Slf4j의 메서드는 info() 외에 debug(), warn(), error(), trace() 메서드도 제공한다.

이러한 메서드들은 로그 레벨 수준에 따라 출력이 된다.

로그 수준은 낮은 순에서 높은 순으로 나열하면 다음과 같다.

TRACE < DEBUG < INFO < WARN < ERROR

스프링을 사용할 때 기본 로그 수준은 INFO이다.

즉, DEBUG, TRACE 수준의 레벨은 기본 설정에서는 로그로 출력되지 않는다.

logger.info("Hello World!") // 로그로 남는다.
logger.debug("Hello World!") // 로그로 남지 않는다.
logger.trace("Hello World!") // 로그로 남지 않는다.

또한, 로그 메서드에는 파라미터를 남길 로그 문자열과 Object 타입(코틀린에서는 Any)의 변수들을 넘길 수 있다.

public interface Logger {
    ...
    
    public void info(String msg);
    
    public void info(String format, Object arg);
    
    public void info(String format, Object arg1, Object arg2);
    
    public void info(String format, Object... arguments);
    
    ...
}

해당 메서드는 다음과 같이 사용할 수 있다.

logger.info("Hello {} {} {}", person, person, person) 

{} 문자열이 뒤의 매개변수로 넘어온 객체의 toString() 메서드를 호출하고, 치환되어 최종적으로 로그로 남게 된다.

Hello Glen Glen Glen

하지만 이렇게 로그를 남기는 방법은 문제를 유발할 수 있다.

Slf4j의 문제점

Slf4j를 사용하여 로그를 남기면 로그 수준에 따라 로그가 남겨진다.

하지만 이것은 눈에 보이지 않는 문제를 유발한다.

logger.debug("{}", foo.veryExpensiveMethod())

현재 로그 수준이 INFO 일때 위의 로그는 남겨지지 않는다.

하지만 로그에서 호출하는 객체의 메서드는 그대로 호출이 된다.

만약, 해당 메서드가 비용이 있는 메서드라면?

곧바로 성능의 저하로 이어진다.

또한 가변 인자를 가진 로그 메서드는 다음과 같이 Javadoc으로 설명되어 있다.

Log a message at the INFO level according to the specified format and arguments.
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 Object[] before invoking the method, even if this logger is disabled for INFO. The variants taking one and two arguments exist solely in order to avoid this hidden cost.

간단히 해석하면 특정 레벨에 대해 로그 메서드가 비활성화되어도, 메서드를 호출하기 전 Object 배열을 생성하는데 비용이 발생한다는 것이다.

로그는 상대적으로 빈번한 호출이 발생하기 때문에 적은 비용이라도, 큰 결과를 초래할 수 있다.

이것을 해결하기 위해 Slf4j는 다음과 같은 메서드를 추가로 제공한다.

public interface Logger {
    ...
    public boolean isTraceEnabled();
    ...
    public boolean isDebugEnabled();
    ...
    public boolean isInfoEnabled();
    ...
    // WARN, ERROR도 존재
}

그리고 다음과 같이 사용하면 성능의 저하를 피할 수 있다.

if (logger.isDebugEnabled()) { // 로그 수준이 되지 않으면 코드 블럭은 실행되지 않는다.
    logger.debug("{}", foo.veryExpensiveMethod())
    logger.debug("Hello {} {} {}", person, person, person)
}

하지만 이러한 방법은 코드에 보일러 플레이트를 유발하고, 매번 조건문을 작성해야 하는 귀찮음이 발생한다.

이것은 Java 8에서 추가된 람다를 사용할 수 있다면 다음과 같이 개선할 수 있을 것이다.

Slf4j(2.0.9) 기준, 파라미터로 Object 가변인자만 받을 수 있기에, 밑에서 설명할 람다를 사용한 방법은 사용할 수 없다.

logger.debug(() -> "Hello " + person + " " + person + " " + person)
logger.debug(() -> foo.veryExpensiveMethod().toString())

해당 로그 메서드는 파라미터로 Supplier<Object> 하나만 받는다.

따라서 로그에 비싼 메서드를 호출하거나, 로그로 남길 변수가 많아도 성능에 영향을 주지 않는다.

하지만 이 방법은 문자열을 연결하는 번거로운 과정이 필요하다.

이 작업은 코틀린을 사용한다면 쉽게 해결할 수 있다.

왜냐하면 코틀린에는 문자열 템플릿 기능을 제공하기 때문이다.

logger.debug { "${foo.veryExpensiveMethod()}" }
logger.debug { "Hello ${person} ${person} ${person}" }

코틀린의 문자열 템플릿 기능은 내부적으로 최적화되어 수행된다.
1.5.20 이전에는 StringBuilder를 사용했지만, 이후에는 StringConcatFactory.makeConcatWithConstants()를 통해 수행된다.

Java 21의 String Interpolation 기능인 STR Template 기능을 사용하면 코틀린과 유사한 방법으로 문자열 템플릿 기능을 사용할 수 있다!

따라서 람다를 사용하면 조건문을 사용하지 않고도, 성능에 영향 없이 로그를 남길 수 있지만, slf4j에서 람다를 파라미터로 받는 메서드를 제공하지 않기 때문에 결국 조건문을 사용할 수 밖에 없다..

하지만 코틀린에서는 이러한 Slf4j의 단점을 해결한 로그 프레임워크가 있다.

kotlin-logging

바로 kotlin-logging이라는 프레임워크이다.

kotlin-logging은 Slf4j와 같이 Facade이며, Slf4j를 래핑하는 프레임워크이다.

즉, Slf4j가 의존성으로 등록이 되어야 사용 가능하다.

스프링 부트를 사용한다면 Slf4j 의존성이 등록되어 있으므로 그저 Gradle에 의존성을 추가하면 된다.

dependencies {
    // 작성하는 시점의 최신 버전이 5.1.1 이어서 사용함
    implementation("io.github.oshai:kotlin-logging-jvm:5.1.1")
}

사용은 다음과 같다.

import io.github.oshai.kotlinlogging.KotlinLogging

// 클래스 최상단에 정의한다.
private val logger = KotlinLogging.logger {}

class MyClass {

    fun myFun() {
        ...
        logger.debug { "${foo.veryExpensiveMethod()}" }
        logger.debug { "Hello ${person} ${person} ${person}" }
        ...
    }
}

끝이다.

성능 저하를 피하기 위해 조건문을 사용할 필요도, 문자열의 연산을 사용할 필요도 없다.

그저 람다에 코틀린의 문자열 템플릿을 사용한 문자열을 넣으면 된다.

예외를 로깅 하려면 다음과 같이 예외를 매개변수로 넣고, 람다를 그대로 사용하면 된다.

logger.debug(e) { "Exception! ${person}" }

자세한 사용법은 위키를 참고하면 된다.

결론

로깅은 어플리케이션이 제대로 작동하는 것을 확인하기 위해 필수적이다.

하지만 단순히 사용하게 된다면 눈에 보이지 않는 성능 저하가 발생할 수 있다.

이를 피하려면 귀찮은 작업이 필요하다.

이때 코틀린의 문자열 템플릿 기능과 kotlin-logging 프레임워크를 사용한다면 번거로운 작업을 하지 않고 문제를 피할 수 있다.