[Spring] Slf4j 로깅에 템플릿을 사용해야 하는 이유

Slf4j를 사용하여 로깅할 때 아래와 같이 세가지 방법을 사용할 수 있습니다.

        Logger logger = LoggerFactory.getLogger(this.getClass());
        String message1= "5";
        String message2= "20";

        logger.info("3 + 2 ="+message1+", "+message1+" + 15 = "+message2); // (1)
        logger.info(String.format("3 + 2 =%s, %s + 15 = %s",message1,message1,message2)); // (2)
        logger.info("3 + 2 ={}, {} + 15 = {}",message1,message1,message2); //(3)

slf4j에서는 로그레벨 체크 시점을 이유로 (3)번 방법을 사용하기를 권장합니다.

세가지 방법은 두가지 관점에서 차이를 가집니다.

1. 문자열 생성방법

(1) String + 연산

• Java 5 이전에는 매 +연산마다 중간단계 문자열이 생성되었지만 Java 5 이후로는 컴파일러가 자동으로 효율적인 방법으로 변환하여 컴파일String + 연산 최적화

(2) String.format 연산

• String.format은 내부적으로 Pattern.compile로 패턴을 생성하여 format 문자열을 파싱하고 파라미터를 맵핑해줍니다.

(3) MessegeFormatter.format 연산

• slf4j의 MessageFormatter를 이용하여 formatting anchor({})를 파라미터로 치환하여 문자열을 생성합니다.
• slf4j 공식문서에 따르면 jdk의 MessageFormat 클래스보다 10배정도 빠르게 동작한고 합니다.

 if (decision == FilterReply.NEUTRAL) {
            if (effectiveLevelInt > level.levelInt) {
                return;
            }
        } else if (decision == FilterReply.DENY) {
            return;
        }

2. 로그 레벨 체크 시점

logger.info를 호출하면 메서드는 내부적으로 filterAndLog~ (파라미터 갯수에 따라 메서드명 suffix가 달라짐) 를 다시 호출합니다. 이 메서드에서는 로그를 생성하기전, 해당 실행환경의 로그레벨과 Level.INFO를 비교하여 실행환경의 로그레벨이 높으면 로그를 남기지 않고 return 합니다.

(1), (2) 방법에서는 info 메서드의 파라미터로 전달할 String 문자열을 생성을 먼저 한 후에 메서드를 호출하기 때문에 실행환경 로그 레벨보다 호출 메서드의 레벨이 낮은 경우여서 로그 출력이 필요없는 상황에서도 항상 문자열을 생성하게 됩니다.

slf4j는 (3)번 방법으로 이런 비효율을 방지하기를 권장합니다.
이 방법에서는 포맷팅할 문자열과 맵핑할 파라미터를 메서드로 각각 전달하게 하여 로그 레벨을 체크한 후에 문자열을 만들기 때문에 불필요한 문자열 생성을 방지할 수 있습니다.

 

=> 세가지 방법의 문자열 생성방법에서도 성능차이가 발생할 수 있지만, 더 중요한 것은 로그 레벨 체크 시점 입니다.
문자열 생성을 지연함으로써 불필요한 문자열을 생성하지 않아 heap 메모리 사용을 절약하고 GC 처리 비용을 줄이는 등의 이점을 가질 수 있습니다.
(하나의 문자열이지만 운영시에 수천~수만 트래픽이 생성하는 비용이 합쳐지만 큰 비용이 될 것입니다.)

[참고]
slf4j을 활용한 로깅시 놓치기 쉬운 실수 한가지, 그리고 Logback 내부 동작 과정[](https://eminentstar.tistory.com/77)
slf4j - logging performance