Skip to content
hyoguoo.log
Blog

Logger 성능 저하 방지와 구조화된 로깅 설계

- Last update:
hyoguoo
Backend Engineer
SERIES

Payment Platform Project

  1. 1 결제 정보 검증을 통한 안전한 결제 연동 시스템 구현
  2. 2 트랜잭션 범위 최소화를 통한 성능 및 안정성 향상
  3. 3 결제 상태 전환 관리와 재시도 로직을 통한 결제 복구 시스템 구축
  4. 4 외부 의존성 제어를 통한 결제 프로세스 다양한 시나리오 검증
  5. 5 Logger 성능 저하 방지와 구조화된 로깅 설계 OPEN
  6. 6 결제 이력 추적 및 핵심 지표 모니터링 시스템 구현
  7. 7 보상 트랜잭션 실패 상황 극복 가능한 결제 플로우 설계
  8. 8 전략 패턴을 통한 PG 독립성 확보 및 확장 가능한 결제 시스템 설계
  9. 9 Checkout API 멱등성 보장 — Caffeine 캐시와 TOCTOU 경쟁 조건 해결
  10. 10 비동기 결제 처리 플로우 구현 — Outbox 패턴부터 LinkedBlockingQueue Worker까지
  11. 11 결제 복구 상태 모델 설계 — 장애 내성을 갖춘 상태 전이
- Last update:
hyoguoo
Backend Engineer

로그를 단순히 println()으로 찍는 건 성능 이슈와 레벨을 구분할 수 없기 때문에, 개발 초기 테스트 외엔 적절하지 않다.

  • 로그 레벨 구분이 없음 (debug, info, warn 등 불가능)
  • 시간, 클래스, 스레드 정보가 출력되지 않음
  • 로그 파일 관리 및 저장 불가
  • 멀티스레드 환경에서 병목 발생 (System.out은 synchronized I/O)

로그는 문제를 추적하고 흐름을 분석하기 위해 많은 양의 데이터를 남기기 때문에, 구조화된 출력과 불필요한 연산 제어가 반드시 필요하다.

Logger 문자열 결합과 성능 문제

Section titled “Logger 문자열 결합과 성능 문제”

로그를 남길 때는 "Hello" + "World"와 같은 문자열 결합 방식이 아닌, "Hello {}"와 같은 포맷팅 방식을 권장하는데, 이는 성능에 영향을 미치기 때문이다.

private static void concatLog(Order order) {
    logger.trace("OrderId=" + order);
}

이 방식은 로그 레벨이 trace가 아니라면 출력도 안 되지만, order.toString() 호출과 문자열 결합은 그대로 발생하여, 출력은 안 되지만 연산은 수행되는 비효율이 생긴다.

// 1. 레벨을 직접 확인하는 방식
private static void checkConditionLog(Order order) {
    if (logger.isTraceEnabled()) {
        logger.trace("OrderId= " + order);
    }
}


// 2. 파라미터 포맷팅 방식
private static void paramLog(Order order) {
    logger.trace("OrderId={}", order);
}

이를 피하기 위해 두 가지 방식을 사용할 수 있다.

  1. 로그 레벨을 직접 체크하는 방식
  2. 파라미터 포맷팅 방식 ({} 사용)

1번 방식은 조건을 직접 해야하는 조건문을 작성해야 하므로 코드가 복잡해지고 가독성이 떨어져, 보통 2번 방식인 파라미터 포맷팅 방식을 사용한다.

로깅 방식별 성능 테스트

Section titled “로깅 방식별 성능 테스트”

로깅 방식에 따른 성능 차이를 측정하기 위해, 멀티스레드 환경에서 다음과 같이 테스트를 작성하여 세 가지 방식에 대해 테스트를 진행했다.

  1. 문자열 결합 방식 (+ 사용)
  2. String.format() 방식
  3. 파라미터 포맷팅 방식 ({} 사용)
LoggerTest.java
class LoggerTest extends IntegrationTest {


    private static final Logger logger = LoggerFactory.getLogger(LoggerTest.class);
    private static final int THREAD_COUNT = 10;
    private static final int TASK_COUNT = 100000;


    private static void logWithConcat(TestData testData) {
        logger.trace("[TEST] | TEST | testData=" + testData);
    }


    private static void logWithFormat(TestData testData) {
        logger.trace(String.format("[TEST] | TEST | testData=%s", testData));
    }


    private static void logWithParam(TestData testData) {
        logger.trace("[TEST] | TEST | orderId={}", testData);
    }


    @Test
    void testLogSpeed() throws InterruptedException {
        ExecutorService executor = Executors.newFixedThreadPool(THREAD_COUNT);
        TestData testData = new TestData(100);


        // 948ms
        runTest(executor, "String concatenation (+)", () -> logWithConcat(testData));
        // 886ms
        runTest(executor, "String.format()", () -> logWithFormat(testData));
        // 19ms
        runTest(executor, "Parameterized logging ({})", () -> logWithParam(testData));


        executor.shutdown();
    }


    private void runTest(ExecutorService executor, String label, Runnable task) throws InterruptedException {
        CountDownLatch latch = new CountDownLatch(THREAD_COUNT);
        long start = System.currentTimeMillis();
        for (int i = 0; i < THREAD_COUNT; i++) {
            executor.submit(() -> {
                for (int j = 0; j < TASK_COUNT; j++) {
                    task.run();
                }
                latch.countDown();
            });
        }
        latch.await();
        long end = System.currentTimeMillis();
        System.out.println(label + ": " + (end - start) + "ms");
    }


    static class TestData {


        private final List<String> data;


        public TestData(int size) {
            this.data = new ArrayList<>();
            for (int i = 0; i < size; i++) {
                data.add(UUID.randomUUID().toString());
            }
        }


        public String getTestDataString() {
            return data.stream().sorted().collect(Collectors.joining(","));
        }


        @Override
        public String toString() {
            return this.getTestDataString();
        }
    }
}
방식소요 시간
문자열 결합 (+)948ms
String.format() 사용886ms
파라미터 포맷팅 ({})19ms
  • +, String.format() 연산자 방식은 로그 레벨에 관계없이 toString()이 호출되고 문자열 결합이 발생
  • 파라미터 포맷팅({}) 방식은 로그 레벨이 활성화된 경우에만 포맷팅이 수행되어, toString() 호출이 발생하지 않음

파라미터 포맷팅 방식이 가장 빠르며, 문자열 결합/포맷은 로그 레벨이 비활성화되어 있어도 toString() 호출과 문자열 결합이 발생해 성능이 저하된다.

메서드 호출 문제

Section titled “메서드 호출 문제”

{} 포맷팅을 사용하면 문자열 결합 비용은 줄일 수 있지만, 메서드 호출 자체는 여전히 발생한다는 점에서 성능 이슈는 완전히 사라지지 않는다.

private static String getExpensiveDetail(Order order) {
    logger.trace("OrderId={}, detail={}", order.getId(), order.getExpensiveDetail());
}

위 코드처럼 로그 레벨과 무관하게 getExpensiveDetail()이 호출된다면, 불필요한 연산이 수행되어 성능 저하가 발생할 수 있다.

private static void logWithSupplier(Order order) {
    logger.trace("OrderId={}, detail={}", () -> order.getId(), () -> order.getExpensiveDetail());
}

Log4j2는 이를 해결하기 위해 Supplier 기반 지연 평가를 지원하지만, Slf4j는 해당 기능을 제공하지 않기 때문에 isTraceEnabled() 같은 조건문을 명시적으로 사용하여 방지할 수 있다.

메서드 호출 성능 테스트(SlF4J 환경)

Section titled “메서드 호출 성능 테스트(SlF4J 환경)”

위와 동일한 테스트 환경에서 메서드 호출을 포함한 로그 성능을 측정했다.

class LoggerTest extends IntegrationTest {


    private static void logConcatWithMethodCall(TestData testData) {
        logger.trace("[TEST] | TEST | testData=" + testData.getTestDataString());
    }


    private static void logFormatWithMethodCall(TestData testData) {
        logger.trace(String.format("[TEST] | TEST | testData=%s", testData.getTestDataString()));
    }


    private static void logParamWithMethodCall(TestData testData) {
        logger.trace("[TEST] | TEST | orderId={}", testData.getTestDataString());
    }


    private static void logParamWithCheck(TestData testData) {
        if (logger.isTraceEnabled()) {
            logger.trace("[TEST] | TEST | testData={}", testData.getTestDataString());
        }
    }


    @Test
    void testLogSpeedWithMethodCall() throws InterruptedException {
        ExecutorService executor = Executors.newFixedThreadPool(THREAD_COUNT);
        TestData testData = new TestData(100);


        // 1042ms
        runTest(executor, "String concat + method call",
                () -> logConcatWithMethodCall(testData));
        // 1092ms
        runTest(executor, "String.format + method call",
                () -> logFormatWithMethodCall(testData));
        // 947ms
        runTest(executor, "Param-style logging + method call",
                () -> logParamWithMethodCall(testData));
        // 14ms
        runTest(executor, "Level check logging + method call",
                () -> logParamWithCheck(testData));


        executor.shutdown();
    }
}
방식소요 시간
문자열 결합 + 메서드 호출1042ms
String.format + 메서드 호출1092ms
파라미터 포맷팅 + 메서드 호출947ms
로그 레벨 체크 후 포맷팅 + 메서드 호출14ms
  • 파라미터 포맷팅 방식은 로그 레벨과 관계없이 메서드 호출이 발생하여 성능 저하가 발생
  • isTraceEnabled() 조건을 사용한 경우, 로그 레벨이 비활성화되어 있으면 해당 연산 자체가 수행되지 않아 성능 저하가 거의 없음

실전 대응 - 구조화된 포맷 + 연산 최소화

Section titled “실전 대응 - 구조화된 포맷 + 연산 최소화”

로그 포맷을 강제하고 싶었고, 동시에 로그 레벨이 꺼져 있을 때 불필요한 연산이 발생하지 않도록 막고 싶어, 직접 LogFmt 유틸 클래스를 만들어 사용했다.

  • 로그의 도메인과 이벤트명을 명확하게 구분
  • 로그 메시지는 Supplier<String>으로 감싸, 로그 레벨이 비활성화되었을 땐 메시지 연산 자체가 발생하지 않도록 처리
  • Slf4j 환경이므로 isInfoEnabled() 등의 레벨 체크 사용
public void example() {
    LogFmt.info(
            logger,
            LogDomain.PAYMENT,
            EventType.PAYMENT_STATUS_TO_IN_PROGRESS,
            () -> String.format("orderId=%s", orderId)
    );
}
2025-08-03 12:56:56.129 ... - [3ce5fab6] [PAYMENT] | PAYMENT_STATUS_TO_IN_PROGRESS | orderId=55996af6-e5b5-47e5-ac3c-44508ee6fd6b

LogFmt 클래스

Section titled “LogFmt 클래스”
@NoArgsConstructor(access = AccessLevel.PRIVATE)
public class LogFmt {


    private static final String INFO_LOG_FORMAT = "[{}] | {} | {}";
    private static final String INFO_LOG_FORMAT_NO_MESSAGE = "[{}] | {}";


    // ...


    public static void info(Logger logger, LogDomain logDomain, EventType event) {
        if (logger.isInfoEnabled()) {
            logger.info(INFO_LOG_FORMAT_NO_MESSAGE, logDomain.name(), event.name());
        }
    }


    public static void info(Logger logger, LogDomain logDomain, EventType event, Supplier<String> messageSupplier) {
        if (logger.isInfoEnabled()) {
            logger.info(INFO_LOG_FORMAT, logDomain.name(), event.name(), messageSupplier.get());
        }
    }


    // ...
}

불필요한 연산을 막고 도메인과 이벤트 타입을 명확히 구분해, 성능을 해치지 않으면서 흐름을 추적할 수 있는 구조화된 로그를 설계했다.

로그

Tags:

Last updated: