스프링 핵심 원리 - 고급편 - 섹션2. 쓰레드 로컬 - ThreadLocal

이제 인터페이스를 만들어가며 본격적으로 해보자.

 

@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 동기화, 동시성 이슈 발생

    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);
    }

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

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

    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 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();
    }
}

 

사실 전과 거의 똑같지만, trace는 주입받아 하나의 인스턴스만 있다는 점을 이용, 처음부터 시작하면 TraceId를 가지고 있고 더 들어가면 그대로 +1하고.. 하는 작업을 한다.

 

 

테스트 해보니 되니까 적용해보자.

config로 logtrace를 싱글톤으로 두어 된다는게 포인트.

 

 

이대로 끝난것 처럼 보이지만, 동시성 문제가 있다. 1년에 한번은 꼭 일어나니 알아두어야 한다.

 

 

짧은 시간 내에 두번 동시에 실행하면, 즉 이미 한 쓰레드가 요청을 받아 처리중인데 요청이 또 들어와 다른 쓰레드가 다시 실행되면 tracelog의 인스턴스가 configure에서 만든 인스턴스 하나인 싱글톤을 사용하기 때문에 꼬이게 된다.

 

이게 어떻게 된 일인지 테스트 코드로 작성해보자.

 

차라리 지역변수면 쓰레드마다 로컬 변수가 달라서 문제가 안발생할텐데, 싱글톤으로써 하나만 사용하는 인스턴스에 멤버변수를 변경하니 생기는 문제이다. 그렇다고 이것 때문에 스프링 빈에 등록해서 잘 쓰는 방식을 다시 파라미터를 받는 방식으로 다시 바꿀 수도 없고..

 

그래서 해결방법이 쓰레드 로컬(Thread Local)을 사용하는 것이다.

 

 

쓰레드 로컬은 기존에도 있던 멀티쓰레드를 사용하여 생긴 문제를 해결하기 위해 만든 것이고 자바가 공식으로 채택한 것. 같은 멤버변수를 접근해도 각 쓰레드마다 저장소를 만들어서 쓰레드마다 저장해둔 그 다른걸 주는 것.

 

자바가 채택해서 사용하는거라 사용법도 쉽다.

 

이제 뭔지 알았으니 LogTrace에도 적용하자.

@Slf4j
public class ThreadLocalLogTrace 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 동기화, 동시성 이슈 발생
    private ThreadLocal<TraceId> traceIdHolder = new ThreadLocal<>();

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

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

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

    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 releaseTraceId() {
        TraceId traceId = traceIdHolder.get();
        if (traceId.isFirstLevel()) {
            traceIdHolder.remove(); // destroy. 이제 추적할 필요가 없으니 제거
        } else {
            traceIdHolder.set(traceId.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();
    }
}

 

=로 할당했던 것들을 set으로 바꾸고, get으로 가져온다. 그리고 끝날 때 remove로 제거한다.

 

실제 상황에서도 실험해보자.

 

똑같은 인터페이스를 상속하며 만들었기 때문에 설정만 바꾸면 된다.

결과는 쓰레드별로 잘 나오는걸 볼 수 있다.

 

다만 이 쓰레드로컬을 사용할 때 주의할 점이 있다. 다 썼으면 반드시 remove()로 꼭 제거해줄 것. 왜냐하면 db 커넥션풀 처럼 쓰레드풀도 존재하는데, 다음 쓰레드로 꺼내 쓸 때 기존의 것이 남아있을 수 있다. 언뜻 보면 이게 큰 문젠가 싶지만 만약 심각한 개인정보라도 저장되어 있다면...