ThreadLocal

김영한님의 스프링 핵심 원리 - 고급편의 ThreadLocal 내용을 정리하였습니다.

FieldLogTrace

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

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

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

FieldLogTrace를 수동으로 스프링 빈으로 등록한다.

@Configuration
public class LogTraceConfig {

    @Bean
    public LogTrace logTrace() {
        return new FieldLogTrace();
    }
}

OrderControllerV3

@RestController
@RequiredArgsConstructor
public class OrderControllerV3 {
    private final OrderServiceV3 orderService;
    private final LogTrace trace;

    @GetMapping("/v3/request")
    public String request(String itemId) throws InterruptedException {

        TraceStatus status = null;
        try {
            status = trace.begin("OrderController.request()");
            orderService.orderItem(itemId);
            trace.end(status);
            return "ok";
        } catch (Exception e) {
            trace.exception(status, e);
            throw e; //예외 다시 던져줘야 함
        }
    }
}

연속으로 실행시 예상과 다르게 로그 추적기가 작동하지 않았다.

원인은 동시성 문제이다.
스프링 빈으로 등록한 FieldLogTrace는 싱글톤으로 어플리케이션에 딱 하나만 존재한다. 이로 인해 여러 쓰레드가 동시에 접근하기 때문에 문제가 발생한다.

Thread-A가 namestore에 UserA를 등록한다.

이와 거의 동시에 Thread-B가 namestore에 보관한다. 이때 기존의 UserA는 지워지고 UserB가 저장된다.

Thread-A의 호출이 끝나면서 결과를 반환받을 때 입력한 UserA값이 UserB값으로 대체된다.

이처럼 여러 쓰레드가 동시에 같은 인스턴스에 필드 값을 변경하면서 발생하는 문제를 동시성 문제라고 한다.
이러한 문제는 싱글톤이나 static 같은 공용 필드에 여러 쓰레드가 접근하려 할 때 발생한다.

이러한 문제는 ThreadLocal로 해결할 수 있다.
ThreadLocal을 사용하면 각 Thread마다 별도의 내부 저장소를 제공해준다.

필드 대신 쓰레드 로컬을 사용하여 데이터를 동기화하는 ThreadLocalTrace를 새로 만든다.

@Slf4j
public class ThreadLocalLogTrace implements LogTrace{

	...

    private ThreadLocal<TraceId> traceIdHolder = new ThreadLocal<>();
    
    @Override
    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());
        }
    }

    @Override
    public void end(TraceStatus status) {
        complete(status, null);
    }
    ...
    
    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(); //해당 쓰레드의 내용 싹다 삭제
        } else {
            traceIdHolder.set(traceId.createPreviousId());
        }
    }

이때 주의해야 할 점은 쓰레드 로컬을 모두 사용하면 ThreadLocal.remove();를 호출하여 쓰레드 로컬에 저장된 값을 제거해주어야 한다.

스프링 빈으로 ThreadLocalTrace를 등록시켜준다.

@Configuration
public class LogTraceConfig {

    @Bean
    public LogTrace logTrace() {
        return new ThreadLocalLogTrace();
    }
}

실행 결과 의도한대로 작동하는 것을 확인할 수 있다.