ThreadLocal 동기화 적용 및 주의사항

ThreadLocal을 사용하여 동기화를 적용하여 개발하기 위해 기존 인스턴스 변수의 참조타입을 ThreadLocal<참조타입>으로 변경할 수 있다.

 

이를 적용하여 필드 대신에 ThreadLocal을 사용하여 데이터를 동기화하는 ThreadLocalLogTrace 클래스를 만들면 다음과 같다.

package hello.advanced.trace.logtrace;

import hello.advanced.trace.TraceInfo;
import hello.advanced.trace.TraceStatus;
import lombok.extern.slf4j.Slf4j;

@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 ThreadLocal<TraceInfo> traceInfoHolder = new ThreadLocal<>();

    @Override
    public TraceStatus begin(String message) {
        syncTraceInfo();
        TraceInfo traceInfo = traceInfoHolder.get();
        long startTimeMs = System.currentTimeMillis();
        log.info("[{}] {}{}", traceInfo.getId(), addSpace(START_PREFIX, traceInfo.getLevel()), message);
        return new TraceStatus(traceInfo, startTimeMs, message);
    }

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

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

    private void syncTraceInfo() {
        TraceInfo traceInfo = traceInfoHolder.get();
        if (traceInfo == null) {
            traceInfoHolder.set(new TraceInfo());
        } else {
            traceInfoHolder.set(traceInfo.createNextLevelInfo());
        }
    }

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

    private void complete(TraceStatus status, Exception e) {
//        TraceInfo traceInfo = status.getTraceInfo();
        TraceInfo traceInfo = traceInfoHolder.get();
        long stopTimeMs = System.currentTimeMillis();
        long resultTimeMs = stopTimeMs - status.getStartTimeMs();

        if (e == null) {
            log.info("[{}] {}{} time={}ms", traceInfo.getId(), addSpace(COMPLETE_PREFIX, traceInfo.getLevel()), status.getMessage(), resultTimeMs);
        } else {
            log.info("[{}] {}{} time={}ms ex={}", traceInfo.getId(), addSpace(EX_PREFIX, traceInfo.getLevel()), status.getMessage(), resultTimeMs, e.toString());
        }

        releaseTraceInfo();
    }

    private void releaseTraceInfo() {
        TraceInfo traceInfo = traceInfoHolder.get();
        if (traceInfo.isFirstLevel()) {
            traceInfoHolder.remove();
        } else {
            traceInfoHolder.set(traceInfo.createPreviousLevelInfo());
        }
    }
}

 

위 코드를 보면 traceHolder가 ThreadLocal 변경되었으며, 값을 저장할 때는 set()을 사용하고, 조회할 때는 get()을 사용하는 것을 볼 수 있다.

 

주의사항

ThreadLocal을 모두 사용하고 나면 꼭 ThreadLocal.remove()를 호출해서 ThreadLocal에 저장된 값을 제거해줘야 한다.

ThreadLocal의 값을 사용 후 제거하지 않고, 그냥 WAS(톰캣)처럼 Thread Pool을 사용하는 경우에 심각한 문제가 발생할 수 있다. 예를들어, 아래의 예처럼 사용자B가 사용자A의 데이터를 확인하게 되는 문제가 발생할 수도 있다는 것이다.

1. 사용자A의 HTTO 응답이 끝난다.
2. WAS는 사용이 끝난 threadA를 Thread Pool에 반환한다.
3. threadA는 Thread Pool에 아직 살아있다. 따라서 ThreadLocal의 threadA 전용 보관소에 사용자A 데이터도 함께 살아있게 된다.

이런 문제를 예방하려면 사용자A의 요청이 끝날 때, ThreadLocal의 값을 ThreadLocal.remove()를 통해서 꼭 제거해야 한다.

 

실행결과

동시성 문제가 있는 기존 FieldLogTrace 대신에 문제를 해결한 ThreadLocalLogTrace를 스프링 빈으로 등록하여 실행한 결과는 다음과 같다.

2023-09-21T22:32:19.796+09:00  INFO 15031 --- [nio-8080-exec-7] h.a.trace.logtrace.ThreadLocalLogTrace   : [744d6e1c] OrderController.request()
2023-09-21T22:32:19.797+09:00  INFO 15031 --- [nio-8080-exec-7] h.a.trace.logtrace.ThreadLocalLogTrace   : [744d6e1c] |-->OrderService.orderItem()
2023-09-21T22:32:19.797+09:00  INFO 15031 --- [nio-8080-exec-7] h.a.trace.logtrace.ThreadLocalLogTrace   : [744d6e1c] |  |-->OrderRepository.save()
2023-09-21T22:32:19.974+09:00  INFO 15031 --- [nio-8080-exec-8] h.a.trace.logtrace.ThreadLocalLogTrace   : [dab36d88] OrderController.request()
2023-09-21T22:32:19.974+09:00  INFO 15031 --- [nio-8080-exec-8] h.a.trace.logtrace.ThreadLocalLogTrace   : [dab36d88] |-->OrderService.orderItem()
2023-09-21T22:32:19.974+09:00  INFO 15031 --- [nio-8080-exec-8] h.a.trace.logtrace.ThreadLocalLogTrace   : [dab36d88] |  |-->OrderRepository.save()
2023-09-21T22:32:20.802+09:00  INFO 15031 --- [nio-8080-exec-7] h.a.trace.logtrace.ThreadLocalLogTrace   : [744d6e1c] |  |<--OrderRepository.save() time=1005ms
2023-09-21T22:32:20.803+09:00  INFO 15031 --- [nio-8080-exec-7] h.a.trace.logtrace.ThreadLocalLogTrace   : [744d6e1c] |<--OrderService.orderItem() time=1007ms
2023-09-21T22:32:20.804+09:00  INFO 15031 --- [nio-8080-exec-7] h.a.trace.logtrace.ThreadLocalLogTrace   : [744d6e1c] OrderController.request() time=1008ms
2023-09-21T22:32:20.977+09:00  INFO 15031 --- [nio-8080-exec-8] h.a.trace.logtrace.ThreadLocalLogTrace   : [dab36d88] |  |<--OrderRepository.save() time=1003ms
2023-09-21T22:32:20.978+09:00  INFO 15031 --- [nio-8080-exec-8] h.a.trace.logtrace.ThreadLocalLogTrace   : [dab36d88] |<--OrderService.orderItem() time=1004ms
2023-09-21T22:32:20.978+09:00  INFO 15031 --- [nio-8080-exec-8] h.a.trace.logtrace.ThreadLocalLogTrace   : [dab36d88] OrderController.request() time=1004ms

로그를 분리해서 확인해보면, 각각의 쓰레드 nio-8080-exec-7, nio-8080-exec-8 별로 로그가 정확하게 나누어진다.