[Spring] 로그 추적기와 쓰레드 로컬

 

 

 

public 접근제어자가 붙은 모든 메서드가 실행될 때 마다 로그를 찍어보자.

로그는 애플리케이션 로직에 영향을 끼쳐서는 안되고, 각 HTTP 요청을 구분할 수 있어야 한다.

 

 

@Slf4j
public class FieldLogTrace implements LogTrace {
    private static final String START_PREFIX = "-->";
    private static final String COMPLETE_PREFIX = "<--";
    private static final String EX_PREFIX = "<X-";
    private TraceId traceIdHolder; //traceId 동기화, 동시성 이슈 발생

    @Override
    public TraceStatus begin(String message) {
        syncTraceId();
        TraceId traceId = traceIdHolder;
        Long startTimeMs = System.currentTimeMillis();
        log.info("[{}] {}{}", traceId.getId(), addSpace(START_PREFIX,
                traceId.getLevel()), message);
        return new TraceStatus(traceId, startTimeMs, message);
    }

    @Override
    public void end(TraceStatus status) {
        complete(status, null);
    }

    @Override
    public void exception(TraceStatus status, Exception e) {
        complete(status, e);
    }

    private void complete(TraceStatus status, Exception e) {
        Long stopTimeMs = System.currentTimeMillis();
        long resultTimeMs = stopTimeMs - status.getStartTimeMs();
        TraceId traceId = status.getTraceId();
        if (e == null) {
            log.info("[{}] {}{} time={}ms", traceId.getId(),
                    addSpace(COMPLETE_PREFIX, traceId.getLevel()), status.getMessage(),
                    resultTimeMs);
        } else {
            log.info("[{}] {}{} time={}ms ex={}", traceId.getId(),
                    addSpace(EX_PREFIX, traceId.getLevel()), status.getMessage(), resultTimeMs,
                    e.toString());
        }
        releaseTraceId();
    }

    private void syncTraceId() {
        if (traceIdHolder == null) {
            traceIdHolder = new TraceId();
        } else {
            traceIdHolder = traceIdHolder.createNextId();
        }
    }

    private void releaseTraceId() {
        if (traceIdHolder.isFirstLevel()) {
            traceIdHolder = null; //destroy
        } else {
            traceIdHolder = traceIdHolder.createPreviousId();
        }
    }

    private static String addSpace(String prefix, int level) {
        StringBuilder sb = new StringBuilder();
        for (int i = 0; i < level; i++) {
            sb.append((i == level - 1) ? "|" + prefix : "| ");
        }
        return sb.toString();
    }
}

public interface LogTrace {
    TraceStatus begin(String message);

    void end(TraceStatus status);
    void exception(TraceStatus status, Exception e);
}

 

 

로그 전용 클래스를 만들어서 로그를 출력하자.

조건을 모두 만족하는 듯 하지만... 한 작업이 끝나기 전에 새로운 작업을 수행해 로그를 출력하도록 하면 문제가 발생한다.

 

스프링이 관리하는 빈들은 기본적으로 싱글톤으로 관리된다.

따라서 빈으로 등록한 로그 서비스는 싱글톤이고, 여러 쓰레드에서 해당 서비스를 사용하는 경우 동시성 문제가 발생한다.

 

해당 문제를 해결하기 위해 쓰레드 로컬이 도입됐다.

 

쓰레드 로컬은 특정 쓰레드만 접근할 수 있는 특별한 저장소로, 각 쓰레드에게 고유한 로컬 변수를 제공한다. (쓰레드와 지역 변수를 매핑한다)

일종의 디자인 패턴으로, 자바에서는 ThreadLocal 클래스를 통해 쓰레드 로컬 기능을 제공한다.

 

쓰레드 로컬을 모두 사용한 후 remove 메서드를 호출해서 쓰레드 로컬에 저장된 값을 제거해 메모루 누수를 방지하자.

쓰레드 풀을 사용하는 경우 쓰레드가 재사용되기에 해당 변수가 계속 유지되니 제대로 제거하지 않으면 메모리 사용량이 계속 증가한다. 

 

스프링 부트는 HTTP 요청 정보를 저장하고 추출할 때 쓰레드 로컬을 사용한다.

RequestContextHolder 클래스를 통해 현재 쓰레드의 HttpServletRequest와 HttpServletResponse 객체를 저장하고 추출한다.

 

따라서 개발자가 직접 HTTP 관련 쓰레드 로컬을 관리할 필요는 없고, 특별한 로직을 구현해야 하는 경우에는 직접 쓰레드 로컬을 사용해야 할 수도 있다.