스프링 핵심 원리 - 고급편_쓰레드 로컬(쓰레드 로컬 동기화 개발, 적용)

쓰레드 로컬 동기화 - 개발

기존 FieldLogTrace에서 발생한 동시성 문제를 ThreadLocal을 통해 해결하자
TraceId traceIdHolder 필드를 쓰레드 로컬을 사용하도록 ThreadLocal<TraceId> traceIdHolder 로 변경하면 된다.

ThreadLocalLogTrace

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

    }

    @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(); // end 에서 호출 되면 마지막이라는 뜻이기 때문에 traceHolder 제거함
    }

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

    private void releaseTraceId() {
        TraceId traceId = traceIdHolder.get();
        if (traceId.isFirstLevel()) {
            traceIdHolder.remove(); // destroy >> 여기서 해당 쓰레드에서 사용한 데이터는 모두 제거 (다른 쓰레드에 영향 X)
        } 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() 을 사용한다.

ThreadLocal.remove()

추가로 쓰레드 로컬을 모두 사용하고 나면 꼭 ThreadLocal.remove() 를 호출해서 쓰레드 로컬에 저장된 값을 제거해야 한다.
쉽게 이야기해서 다음의 마지막 로그를 출력하고 나면 쓰레드 로컬의 값을 제거해야 한다.

 [3f902f0b] hello1
 [3f902f0b] |-->hello2
 [3f902f0b] |<--hello2 time=2ms
 [3f902f0b] hello1 time=6ms //end() -> releaseTraceId() -> level==0, 
 ThreadLocal.remove() 호출

여기서는 releaseTraceId() 를 통해 level 이 점점 낮아져서 2 -> 1 -> 0이 되면 로그를 처음 호출한 부분으로 돌아온것
따라서 이 경우 연관된 로그 출력이 끝난 것이다.
이제 더 이상 TraceId 값을 추적하지 않아도 된다.
그래서 traceId.isFirstLevel() (level==0)인 경우 ThreadLocal.remove() 를 호출해서 쓰레드 로컬에 저장된 값을 제거해준다.

remove()를 하지 않으면 메모리 누수가 발생할 수도 있고, Thread Pool을 사용하는 경우 이전 Thread의 영향으로 데이터가 오염될 수 있다. (데이터 오염은 GPT 질문 결과)

ThreadLocalLogTraceTest

public class ThreadLocalLogTraceTest {

    ThreadLocalLogTrace trace = new ThreadLocalLogTrace();

    @Test
    void begin_end_level2() {
        TraceStatus status1 = trace.begin("hello1");
        TraceStatus status2 = trace.begin("hello2");
        trace.end(status2);
        trace.end(status1);
    }

    @Test
    void begin_exception_level2() {
        TraceStatus status1 = trace.begin("hello");
        TraceStatus status2 = trace.begin("hello2");
        trace.exception(status2, new IllegalStateException());
        trace.exception(status1, new IllegalStateException());
    }
}

• 정상
• [ed2639e0] hello1 [ed2639e0] |-->hello2 [ed2639e0] |<--hello2 time=0ms [ed2639e0] hello1 time=6ms
• 예외
• [8e6d44a2] hello [8e6d44a2] |-->hello2 [8e6d44a2] |<X-hello2 time=1ms ex=java.lang.IllegalStateException [8e6d44a2] hello time=1ms ex=java.lang.IllegalStateException

쓰레드 로컬 동기화 - 적용

LogTraceConfig - 수정

동시성 문제가 있는 FieldLogTrace 대신에 문제를 해결한 ThreadLocalLogTrace 를 스프링 빈으로 등록하자.

@Configuration
public class LogTraceConfig {
    @Bean
    public LogTrace logTrace() {
        //return new FieldLogTrace();
        return new ThreadLocalLogTrace();
    }
}

로그

• 정상
• [c6e04666] OrderController.request() [c6e04666] |-->OrderService.orderItem() [c6e04666] | |-->OrderRepository.save() [c6e04666] | |<--OrderRepository.save() time=1001ms [c6e04666] |<--OrderService.orderItem() time=1002ms [c6e04666] OrderController.request() time=1003ms
• 예외
• [793adac7] OrderController.request() [793adac7] |-->OrderService.orderItem() [793adac7] | |-->OrderRepository.save() [793adac7] | |<X-OrderRepository.save() time=0ms ex=java.lang.IllegalStateException: 예외 발생 [793adac7] |<X-OrderService.orderItem() time=1ms ex=java.lang.IllegalStateException: 예외 발생 [793adac7] OrderController.request() time=1ms ex=java.lang.IllegalStateException: 예외 발생 Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed: java.lang.IllegalStateException: 예외 발생] with root cause

java.lang.IllegalStateException: 예외 발생

## 동시 요청
동시성 문제를 확인해보자.

- 실행 결과

[0a1256f6] OrderController.request()
[0a1256f6] |-->OrderService.orderItem()
[0a1256f6] | |-->OrderRepository.save()
[7a24d329] OrderController.request()
[7a24d329] |-->OrderService.orderItem()
[7a24d329] | |-->OrderRepository.save()
[0a1256f6] | |<--OrderRepository.save() time=1004ms
[0a1256f6] |<--OrderService.orderItem() time=1005ms
[0a1256f6] OrderController.request() time=1007ms
[7a24d329] | |<--OrderRepository.save() time=1000ms
[7a24d329] |<--OrderService.orderItem() time=1001ms
[7a24d329] OrderController.request() time=1001ms

- 로그 분리하여 확인하기

[0a1256f6] OrderController.request()
[0a1256f6] |-->OrderService.orderItem()
[0a1256f6] | |-->OrderRepository.save()
[0a1256f6] | |<--OrderRepository.save() time=1004ms
[0a1256f6] |<--OrderService.orderItem() time=1005ms
[0a1256f6] OrderController.request() time=1007ms

[7a24d329] OrderController.request()
[7a24d329] |-->OrderService.orderItem()
[7a24d329] | |-->OrderRepository.save()
[7a24d329] | |<--OrderRepository.save() time=1000ms
[7a24d329] |<--OrderService.orderItem() time=1001ms
[7a24d329] OrderController.request() time=1001ms

~

정상적으로 찍혔다.

 

출처: 김영한 지식공유자의 스프링 핵심 원리 고급편