로그 패턴도 병목이 될 수 있답니다 | Logback

 

혹시 로그를 아래와 같이 남기고 있지 않나요?

<pattern>%d{HH:mm:ss.SSS} %-5level %thread - %C{1}:%L - %msg%n</pattern>

 

`%C`는 로그를 호출한 클래스의 전체 이름을 출력합니다.

 

예를 들어 로그를 찍은 클래스가

package com.example.order.service; public class OrderService { }

 

위와 같다면 `%C`의 출력은 아래와 같습니다.

com.example.order.service.OrderService

 

`%C`에는 {length} 옵션을 지정해 클래스 이름을 축약해서 출력할 수 있습니다.

예를 들어

• `%C` -> com.example.order.service.OrderService
• `%C{0}` -> OrderService
• `%C{1}` -> c.e.o.s.OrderService

 

 

`%L`은 로그 호출이 발생한 소스 코드의 라인 번호를 출력하는 conversion word입니다.

만약 아래와 같은 로그 코드가

public void process() { log.info("start"); }

 

57번째 줄에 있다면 `%L`은 57을 출력합니다.

 

그래서 보통 디버깅을 위해 로그백 패턴에서 `%C`와 `%L`과 같은 conversion word를 종종 사용하는 경우가 있습니다.

 

그런데 사실 트래픽이 유의미하게 많은 상황에서 이러한 형태는 로그백에서  피해야 하는 패턴으로 소개합니다.

 

https://logback.qos.ch/manual/layouts.html

“Generating the caller class information is not particularly fast. Thus, its use should be avoided unless execution speed is not an issue.”

“Generating the line number information is not particularly fast. Thus, its use should be avoided unless execution speed is not an issue.”

 

`%C`, '%L'은 모두 caller data를 필요로 합니다.

Logback은 caller data를 얻기 위해 현재 호출 스택 정보를 생성하고 조사해야 하므로 호출 스택 트레이스를 조회하게 됩니다.

로그 한 건에서는 작은 비용일 수 있지만, 초당 수만~수십만 건의 로그가 발생하는 환경에서는 이 비용 역시 무시하기 어렵습니다.

 

 

이를 객체가 들고 있던 정보 그대로 찍는 방식으로 해결할 수 있습니다.

logger name은 로그를 찍을 때 이미 로그 이벤트에 담겨있습니다.

이를 `%logger` 패턴으로 호출 스택 트레이스 조회 비용 없이 로그에 남길 수 있습니다.

 

다만, 기존 `'%L`'은 `'%logger`'처럼 싸게 대체할 수 있는 기본 필드가 없습니다.

 

 

이론은 이론인거고, 로그에 line number 남기는 것을 포기하면서 `'%C`, `%L` 패턴을 `%logger`로 대체하는 것이 얼마나 유의미한 성능 차이를 발생시키는지 테스트해 보기 위해 소소하게 부하를 걸어보겠습니다.

 

각각 

 

먼저, 호출 스택 트레이스를 조회하는 방식에 대한 테스트입니다.

로그백 설정은 아래와 같습니다.

<?xml version="1.0" encoding="UTF-8"?>
<configuration>

    <appender name="FILE_NULL" class="ch.qos.logback.core.FileAppender">
        <file>/dev/null</file>
        <append>true</append>
        <encoder>
            <pattern>%d{HH:mm:ss.SSS} %-5level %thread - %C{1}:%L - %msg%n</pattern>
        </encoder>
    </appender>

    <root level="INFO">
        <appender-ref ref="FILE_NULL"/>
    </root>

</configuration>

 

초당 1,000 요청을 30초간 발생시킨 결과 평균 응답시간 0.580ms, 중위 응답시간 0.342ms를 확인할 수 있습니다.

 

 

Flame Graph로 프로파일링 샘플 확인 결과 21.72%의 호출 스택에 `LoggingEvent.getCallerData()`가 포함되어 있습니다.

 

 

다음으로, `%logger` 패턴으로의 개선 후의 로그백 설정으로 실험을 진행해 보았습니다.

<?xml version="1.0" encoding="UTF-8"?>
<configuration>

    <appender name="FILE_NULL" class="ch.qos.logback.core.FileAppender">
        <file>/dev/null</file>
        <append>true</append>
        <encoder>
            <pattern>%d{HH:mm:ss.SSS} %-5level %thread - %logger{1} - %msg%n</pattern>
        </encoder>
    </appender>

    <root level="INFO">
        <appender-ref ref="FILE_NULL"/>
    </root>

</configuration>

 

 

같은 조건에서 실험 결과 이번에는 평균 응답속도 0.433ms, 중위 응답속도 0.292ms를 확인할수 있습니다.

 

전후 결과를 비교해보면 응답시간 감소율이 평균 약 25.3% 감소, 중앙값 약 14.6% 감소가 일어났습니다.

이번 테스트는 로깅 비용을 비교하기 위해 최소한의 컨트롤러만 구성한 로컬 실험입니다.

실제 서비스에서의 영향은 로그 발생량, 애플리케이션 로직, CPU 사용률 등의 환경에 따라 달라질 수 있습니다.

---

 

로그와 성능을 고려했을때 사실 appender를 비동기 appender 사용하냐 아니냐 정도만 고려할 수 있을 것이라 생각했는데, 로그 패턴으로도 이 정도 결과가 나오다니... 놀랍고도 재밌군요.

 

📚 References

• https://logback.qos.ch/manual/layouts.html