[스프링 핵심원리 - 고급편] #3. 쓰레드 로컬 - ThreadLocal

[YuDeokRin]

섹션3. 쓰레드 로컬 - ThreadLocal

1️⃣ 필드 동기화 - 개발

섹션2. 에서 로그 추적기를 만들었다. 하지만 동기화 문제점이 있었다.

1. 트랜잭션 ID, level을 동기화하는 문제 → 문제 해결 : TraceId를 파라미터로 넘겨서 해결

동기화 문제는 해결되었지만 로그를 출력하는 모든 메서드에서 TraceId 파라미터를 다 추가해야 하는 문제가 있다.

TraceId를 파라미터로 넘기지 않고 문제를 해결 할 수 있을까 ?

• LogTrace
  • LogTrace 인터페이스에는 로그 추적기를 위한 최소한의 기능인 begin(), end(), exception()를 정의햇다. → 파라미터 TraceId 값이 필요없다.
• LogTrace

public interface LogTrace {

    TraceStatus begin(String message);

    void end(TraceStatus status);

    void exception(TraceStatus status, Exception e);
}

• FieldLogTrace → 기존의 HelloTraceV2와 기능은 비슷하다.

package hello.advanced.trace.logtrace;

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

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

    @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 releaseTraceId() {
        if (traceIdHolder.isFirstLevel()) {
            traceIdHolder = null;
        } 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();
    }

}

• FieldLogTrace 코드 분석
  • TraceId를 동기화 하는 부분만 파라미터를 사용하는 것에서 TraceId traceIdHolder 필드를 사용하도록 변경되었다.
  • 이제 직전 로그의 TraceId는 파라미터로 전달 X → FieldLogTrace의 필드인 traceIdHolder에 저장
  • syncTraceId()는 traceId를 새로만들거나 앞선 로그의 TraceId를 참고해서 동기화 시키고 level도 증가
    • 최초의 호출이면 TraceID 생성
    • 직전 로그가 있으면 해당 로그의 TraceId를 참고해서 동기화하고, level도 하나 증가 시킨다.
    • 결과는 traceIdHolder에 보관
  • releaseTraceId()
    • 메서드를 추가로 호출할 때는 level이 하나 증가해야 하지만, 메서드 호출이 끝나면 level이 하나 감소해야한다.
    • releaseTraceId()는 level을 하나 감소한다.
    • 최초 호출(level==0)이면 내부에서 관리하는 traceId를 제거한다.

[c80f5dbb] OrderController.request() [c80f5dbb] |-->OrderService.orderItem() //syncTraceId(): 최초 호출 level=0
//syncTraceId(): 직전 로그 있음 level=1
증가
[c80f5dbb] | |-->OrderRepository.save() //syncTraceId(): 직전 로그 있음 level=2
증가
[c80f5dbb] | |<--OrderRepository.save() time=1005ms //releaseTraceId():
level=2->1 감소
[c80f5dbb] |<--OrderService.orderItem() time=1014ms //releaseTraceId():
level=1->0 감소
[c80f5dbb] OrderController.request() time=1017ms //releaseTraceId():
level==0, traceId 제거

✅ 테스트

• FieldLogTraceTest

package hello.advanced.trace.logtrace;

import hello.advanced.trace.TraceStatus;
import org.junit.jupiter.api.Test;

public class FieldLogTraceTest {

    FieldLogTrace trace = new FieldLogTrace();

    @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("hello1");
        TraceStatus status2 = trace.begin("hello2");
        trace.exception(status2, new IllegalStateException());
        trace.exception(status1, new IllegalStateException());
    }
}

• 테스트 결과 - begin_end_level2

21:07:48.536 [Test worker] INFO hello.advanced.trace.logtrace.FieldLogTrace -- [1606c677] hello1
21:07:48.539 [Test worker] INFO hello.advanced.trace.logtrace.FieldLogTrace -- [1606c677] |-->hello2
21:07:48.539 [Test worker] INFO hello.advanced.trace.logtrace.FieldLogTrace -- [1606c677] |<--hello2 time=1ms
21:07:48.539 [Test worker] INFO hello.advanced.trace.logtrace.FieldLogTrace -- [1606c677] hello1 time=4ms

• 테스트 결과 - begin_exception_level2

21:11:21.437 [Test worker] INFO hello.advanced.trace.logtrace.FieldLogTrace -- [d876b62f] hello1
21:11:21.439 [Test worker] INFO hello.advanced.trace.logtrace.FieldLogTrace -- [d876b62f] |-->hello2
21:11:21.439 [Test worker] INFO hello.advanced.trace.logtrace.FieldLogTrace -- [d876b62f] |<X-hello2 time=0ms ex=java.lang.IllegalStateException
21:11:21.439 [Test worker] INFO hello.advanced.trace.logtrace.FieldLogTrace -- [d876b62f] hello1 time=3ms ex=java.lang.IllegalStateException

• 테스트를 통해 알아낸점
  • TraceId를 파라미터로 전달하지 않아도 되고, 애플리케이션의 메서드 파라미터도 변경하지 않아도된다.

2️⃣ 필드 동기화

• FieldLogTrace를 애플리케이션에 적용해보자.

• 첫 번째 작업은 LogTrace 스프링 빈 등록 → 향후 구현체를 편리하게 변경할 수 있다는 장점이 생김

package hello.advanced;

import hello.advanced.trace.logtrace.FieldLogTrace;
import hello.advanced.trace.logtrace.LogTrace;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;

@Configuration
public class LogTraceConfig {

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

}

• OrderControllerV3

package hello.advanced.app.V3;

import hello.advanced.trace.TraceStatus;
import hello.advanced.trace.logtrace.LogTrace;
import lombok.RequiredArgsConstructor;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;

@RestController // @Controller + @ResponseBody
@RequiredArgsConstructor
public class OrderControllerV3 {

    private final OrderServiceV3 orderService;
    private final LogTrace trace;

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

        TraceStatus status = null;

        try { // try-catch 하는 이유 : 예외가 터지는 경우에도 로그를 출력해주어야하기 때문에
            status = trace.begin("OrderController.request()");
            orderService.orderItem(itemId);
            trace.end(status);
            return "ok";
        } catch (Exception e) {
            trace.exception(status, e);
            throw e; // 에외를 꼭 다시 던져주어야 한다.
        }

    }

}

• OrderServiceV3

package hello.advanced.app.V3;

import hello.advanced.trace.TraceId;
import hello.advanced.trace.TraceStatus;
import hello.advanced.trace.hellotrace.HelloTraceV2;
import hello.advanced.trace.logtrace.LogTrace;
import lombok.RequiredArgsConstructor;
import org.springframework.stereotype.Service;

@Service
@RequiredArgsConstructor
public class OrderServiceV3 {

    private final OrderRepositoryV3 orderRepository;
    private final LogTrace trace;

    public void orderItem(String itemId) {
        TraceStatus status = null;

        try {
            status = trace.begin("OrderService.orderItem()");
            orderRepository.save(itemId);
            trace.end(status);
        } catch (Exception e) {
            trace.exception(status, e);
            throw e;
        }

    }

}

• OrderRepositoryV3

package hello.advanced.app.V3;

import hello.advanced.trace.TraceStatus;
import hello.advanced.trace.logtrace.LogTrace;
import lombok.RequiredArgsConstructor;
import org.springframework.stereotype.Repository;

@Repository
@RequiredArgsConstructor
public class OrderRepositoryV3 {

    private final LogTrace trace;

    public void save(String itemId) {

        TraceStatus status = null;

        try {
            status = trace.begin("OrderRepository.save()");
            //저장 로직
            if (itemId.equals("ex")) { // itemId가 ex로 넘어오면 문제 발생
                throw new IllegalStateException("예외 발생!");
            }

            sleep(1000);
            trace.end(status);
        } catch (IllegalStateException e) {
            trace.exception(status, e);
            throw e;
        }
    }

    private void sleep(int millis) {
        try {
            Thread.sleep(millis);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }
}

• 결과 출력 - 정상

[advanced] [nio-8080-exec-3] h.advanced.trace.logtrace.FieldLogTrace  : [183c3042] OrderController.request()
[advanced] [nio-8080-exec-3] h.advanced.trace.logtrace.FieldLogTrace  : [183c3042] |-->OrderService.orderItem()
[advanced] [nio-8080-exec-3] h.advanced.trace.logtrace.FieldLogTrace  : [183c3042] |   |-->OrderRepository.save()
[advanced] [nio-8080-exec-3] h.advanced.trace.logtrace.FieldLogTrace  : [183c3042] |   |<--OrderRepository.save() time=1005ms
[advanced] [nio-8080-exec-3] h.advanced.trace.logtrace.FieldLogTrace  : [183c3042] |<--OrderService.orderItem() time=1007ms
[advanced] [nio-8080-exec-3] h.advanced.trace.logtrace.FieldLogTrace  : [183c3042] OrderController.request() time=1007ms

• 결과 출력 - 예외

[advanced] [nio-8080-exec-5] h.advanced.trace.logtrace.FieldLogTrace  : [1f404ddd] OrderController.request()
[advanced] [nio-8080-exec-5] h.advanced.trace.logtrace.FieldLogTrace  : [1f404ddd] |-->OrderService.orderItem()
[advanced] [nio-8080-exec-5] h.advanced.trace.logtrace.FieldLogTrace  : [1f404ddd] |   |-->OrderRepository.save()
[advanced] [nio-8080-exec-5] h.advanced.trace.logtrace.FieldLogTrace  : [1f404ddd] |   |<X-OrderRepository.save() time=0ms ex=java.lang.IllegalStateException: 예외 발생!
[advanced] [nio-8080-exec-5] h.advanced.trace.logtrace.FieldLogTrace  : [1f404ddd] |<X-OrderService.orderItem() time=0ms ex=java.lang.IllegalStateException: 예외 발생!
[advanced] [nio-8080-exec-5] h.advanced.trace.logtrace.FieldLogTrace  : [1f404ddd] OrderController.request() time=0ms ex=java.lang.IllegalStateException: 예외 발생!

• traceIdHolder 필드를 사용한 덕분에 파라미터 추가 없이 깔금한 로그 추적기 완성

하지만 이제 실제 서비스에 위의 코드를 추가하고 배포까지한다면 문제가 있을까?

• 강의에서는 1년에 한번씩 일어나는 문제가 있다고한다.

• 바로 동시성 문제

3️⃣ 필드 동기화 - 동시성 문제

• 동시성 문제 확인 → 로직을 1초 안에 2번 실행 해보기

  • http://localhost:8080/v3/request?itemId=hello
  • http://localhost:8080/v3/request?itemId=hello

• 기대하는 결과값

[nio-8080-exec-3] [52808e46] OrderController.request()
[nio-8080-exec-3] [52808e46] |-->OrderService.orderItem()
[nio-8080-exec-3] [52808e46] | |-->OrderRepository.save()
[nio-8080-exec-4] [4568423c] OrderController.request()
[nio-8080-exec-4] [4568423c] |-->OrderService.orderItem()
[nio-8080-exec-4] [4568423c] | |-->OrderRepository.save()
[nio-8080-exec-3] [52808e46] | |<--OrderRepository.save() time=1001ms
[nio-8080-exec-3] [52808e46] |<--OrderService.orderItem() time=1001ms
[nio-8080-exec-3] [52808e46] OrderController.request() time=1003ms
[nio-8080-exec-4] [4568423c] | |<--OrderRepository.save() time=1000ms
[nio-8080-exec-4] [4568423c] |<--OrderService.orderItem() time=1001ms
[nio-8080-exec-4] [4568423c] OrderController.request() time=1001ms

• 기대하는 결과 - 로그 분리해서 확인하기

[52808e46]
[nio-8080-exec-3] [52808e46] OrderController.request()
[nio-8080-exec-3] [52808e46] |-->OrderService.orderItem()
[nio-8080-exec-3] [52808e46] | |-->OrderRepository.save()
[nio-8080-exec-3] [52808e46] | |<--OrderRepository.save() time=1001ms
[nio-8080-exec-3] [52808e46] |<--OrderService.orderItem() time=1001ms
[nio-8080-exec-3] [52808e46] OrderController.request() time=1003ms

[4568423c]
[nio-8080-exec-4] [4568423c] OrderController.request()
[nio-8080-exec-4] [4568423c] |-->OrderService.orderItem()
[nio-8080-exec-4] [4568423c] | |-->OrderRepository.save()
[nio-8080-exec-4] [4568423c] | |<--OrderRepository.save() time=1000ms
[nio-8080-exec-4] [4568423c] |<--OrderService.orderItem() time=1001ms
[nio-8080-exec-4] [4568423c] OrderController.request() time=1001ms

• 실제 결과 - 로그 분리해서 확인

[nio-8080-exec-7] h.advanced.trace.logtrace.FieldLogTrace  : [29cf4845] OrderController.request()
[nio-8080-exec-7] h.advanced.trace.logtrace.FieldLogTrace  : [29cf4845] |-->OrderService.orderItem()
[nio-8080-exec-7] h.advanced.trace.logtrace.FieldLogTrace  : [29cf4845] |   |-->OrderRepository.save()
[nio-8080-exec-7] h.advanced.trace.logtrace.FieldLogTrace  : [29cf4845] |   |<--OrderRepository.save() time=1008ms
[nio-8080-exec-7] h.advanced.trace.logtrace.FieldLogTrace  : [29cf4845] |<--OrderService.orderItem() time=1010ms
[nio-8080-exec-7] h.advanced.trace.logtrace.FieldLogTrace  : [29cf4845] OrderController.request() time=1011ms

[nio-8080-exec-8] h.advanced.trace.logtrace.FieldLogTrace  : [29cf4845] |   |   |-->OrderController.request()
[nio-8080-exec-8] h.advanced.trace.logtrace.FieldLogTrace  : [29cf4845] |   |   |   |-->OrderService.orderItem()
[nio-8080-exec-8] h.advanced.trace.logtrace.FieldLogTrace  : [29cf4845] |   |   |   |   |-->OrderRepository.save()
[nio-8080-exec-8] h.advanced.trace.logtrace.FieldLogTrace  : [29cf4845] |   |   |   |   |<--OrderRepository.save() time=1003ms
[nio-8080-exec-8] h.advanced.trace.logtrace.FieldLogTrace  : [29cf4845] |   |   |   |<--OrderService.orderItem() time=1004ms
[nio-8080-exec-8] h.advanced.trace.logtrace.FieldLogTrace  : [29cf4845] |   |   |<--OrderController.request() time=1006ms

• 위의 문제는 왜 그런 것일까?

🚨 동시성 문제

이 문제는 FieldLogTrace는 싱글톤으로 등록된 스프링 빈이다. 이 객체가 인스턴스가 애플리케이션에 딱 1 존재한다는 뜻이다. 이렇게 하나만 있는 인스턴스의 FieldLogTrace.traceIdHolder 필드를 여러 쓰레드가 동시에 접근하기 때문에 문제가 발생한다.

→ 실무에서 한번 나타나면 개발자들을 괴롭힌다.

4️⃣ 동시성 문제 - 예제 코드

• build.gradle - 추가

dependencies {
  ...
  
	//테스트에서 lombok 사용
	testCompileOnly 'org.projectlombok:lombok'
	testAnnotationProcessor 'org.projectlombok:lombok'
}

• FieldService

package hello.advanced.trace.threadlocal.code;

import lombok.extern.slf4j.Slf4j;

@Slf4j
public class FieldService {

    private String nameStore;

    public String logic(String name) {
        log.info("저장 name={} -> nameStore={}", name, nameStore);
        nameStore = name;
        sleep(1000);
        log.info("조회 nameStore={}", nameStore);
        reutrn nameStore;
    }

    public void sleep(long millis) {
        try {
            Thread.sleep(millis);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }

    }
}

• FieldServiceTest

package hello.advanced.trace.threadlocal;

import hello.advanced.trace.threadlocal.code.FieldService;
import lombok.extern.slf4j.Slf4j;
import org.junit.jupiter.api.Test;

@Slf4j
public class FieldServiceTest {
    private FieldService fieldService = new FieldService();

    @Test
    void field() {
        log.info("main start");

//        Runnable userA = new Runnable() {
//            @Override
//            public void run() {
//                fieldService.logic("userA");
//            }
//        };

        log.info("main start");
        Runnable userA = () -> {
            fieldService.logic("userA");
        };

        Runnable userB = () -> {
            fieldService.logic("userB");
        };

        Thread threadA = new Thread(userA);
        threadA.setName("thread-A");
        Thread threadB = new Thread(userB);
        threadB.setName("thread-B");

        threadA.start();
        sleep(2000); //동시성 문제 발생 X
        sleep(100); // 동시성 문제 발생 O
        threadB.start();

        sleep(3000); // 메인 쓰레드 종료 대기
        log.info("main exit");
    }

    private void sleep(int millis) {
        try {
            Thread.sleep(millis);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }
}

• 실행 결과

[Test worker] INFO hello.advanced.trace.threadlocal.FieldServiceTest -- main start
[thread-A] INFO hello.advanced.trace.threadlocal.code.FieldService -- 저장 name=userA -> nameStore=null
[thread-A] INFO hello.advanced.trace.threadlocal.code.FieldService -- 조회 nameStore=userA
[thread-B] INFO hello.advanced.trace.threadlocal.code.FieldService -- 저장 name=userB -> nameStore=userA
[thread-B] INFO hello.advanced.trace.threadlocal.code.FieldService -- 조회 nameStore=userB
[Test worker] INFO hello.advanced.trace.threadlocal.FieldServiceTest -- main exit

• 실행 결과를 보면 문제가 없다
• Thread-A 는 userA 를 nameStore 에 저장했다.
• Thread-A 는 userA 를 nameStore 에서 조회했다.
• Thread-B 는 userB 를 nameStore 에 저장했다.
• Thread-B 는 userB 를 nameStore 에서 조회했다.

✅ 동시성 문제 발생 코드

• 이번에는 sleep(100) 을 설정해서 thread-A 의 작업이 끝나기 전에 thread-B 가 실행되도록 해보자.
  참고로 FieldService.logic() 메서드는 내부에 sleep(1000)으로 1초의 지연이 있다. 따라서 1초 이후에 호출하면 순서대로 실행할 수 있다. 다음에 설정할 100(ms)는 0.1초이기 때문에 thread-A 의 작업이 끝나기 전에 thread-B 가 실행된다.

//sleep(2000); //동시성 문제 발생X
sleep(100); //동시성 문제 발생O

• 결과

[Test worker] INFO hello.advanced.trace.threadlocal.FieldServiceTest -- main start
[thread-A] INFO hello.advanced.trace.threadlocal.code.FieldService -- 저장 name=userA -> nameStore=null
[thread-A] INFO hello.advanced.trace.threadlocal.code.FieldService -- 조회 nameStore=userA
[thread-B] INFO hello.advanced.trace.threadlocal.code.FieldService -- 저장 name=userB -> nameStore=userA
[thread-B] INFO hello.advanced.trace.threadlocal.code.FieldService -- 조회 nameStore=userB
[Test worker] INFO hello.advanced.trace.threadlocal.FieldServiceTest -- main exit

• 먼저 thread-A 가 userA 값을 nameStore 에 보관한다.

• 0.1초 이후에 thread-B 가 userB 의 값을 nameStore 에 보관한다. 기존에 nameStore 에 보관되어 있던 userA 값은 제거되고 userB 값이 저장된다.

• thread-A 의 호출이 끝나면서 nameStore 의 결과를 반환받는데, 이때 nameStore 는 앞의 2번에서
  userB 의 값으로 대체되었다. 따라서 기대했던 userA 의 값이 아니라 userB 의 값이 반환된다.
• thread-B 의 호출이 끝나면서 nameStore 의 결과인 userB 를 반환받는다.

1. Thread-A 는 userA 를 nameStore 에 저장했다.
2. Thread-B 는 userB 를 nameStore 에 저장했다.
3. Thread-A 는 userB 를 nameStore 에서 조회했다.
4. Thread-B 는 userB 를 nameStore 에서 조회했다.

✅동시성 문제

• 결과적으로 Thread-A 입장에서는 저장한 데이터와 조회한 데이터가 다른 문제가 발생한다. 이처럼 여러 쓰레드가 동시에 같은 인스턴스의 필드 값을 변경하면서 발생하는 문제를 동시성 문제라 한다. 이런 동시성 문제는 여러 쓰레드가 같은 인스턴스의 필드에 접근해야 하기 때문에 트래픽이 적은 상황에서는 확률상 잘 나타나지 않고, 트래픽이 점점 많아 질 수 록 자주 발생한다. 특히 스프링 빈 처럼 싱글톤 객체의 필드를 변경하며 사용할 때 이러한 동시성 문제를 조심해야 한다.

5️⃣ ThreadLocal - 소개

• 쓰레드 로컬은 해당 쓰레드만 접근할 수 있는 특별한 저장소를 말한다. 쉽게 이야기해서 물건 보관 창구를 떠올리면 된다. 여러 사람이 같은 물건 보관 창구를 사용하더라도 창구 직원은 사용자를 인식해서 사용자별로 확실하게 물건을 구분해준다.
• 사용자A, 사용자B 모두 창구 직원을 통해서 물건을 보관하고, 꺼내지만 창구 지원이 사용자에 따라 보관한 물건을 구분해주는 것이다.

✅ 일반적인 변수 필드

• 여러 쓰레드가 같은 인스턴스의 필드에 접근하면 처음 쓰레드가 보관한 데이터가 사라질 수 있다.

• thread-A 가 userA 라는 값을 저장하고

• thread-B 가 userB 라는 값을 저장하면 직전에 thread-A 가 저장한 userA 값은 사라진다.

✅ 쓰레드 로컬

• 쓰레드 로컬을 사용하면 각 쓰레드마다 별도의 내부 저장소를 제공한다. 따라서 같은 인스턴스의 쓰레드 로컬 필드에 접근해도 문제 없다.

• thread-A가userA라는 값을 저장하면 쓰레드 로컬은thread-A 전용 보관소에 데이터를 안전하게 보관한다.

• 쓰레드 로컬을 통해서 데이터를 조회할 때도 thread-A 가 조회하면 쓰레드 로컬은 thread-A 전용 보관소에서userA 데이터를 반환해준다. 물론 thread-B 가 조회하면 thread-B 전용 보관소에서 userB 데이터를 반환해준다.

6️⃣ ThreadLocal - 예제 코드

• ThreadLocalService

package hello.advanced.trace.threadlocal.code;

import lombok.extern.slf4j.Slf4j;

@Slf4j
public class ThreadLocalService {

    private ThreadLocal<String> nameStore = new ThreadLocal<>();

    public String logic(String name) {
        log.info("저장 name={} -> nameStore={}", name, nameStore.get());
        nameStore.set(name);
        sleep(1000);
        log.info("조회 nameStore={}", nameStore.get());
        return nameStore.get();
    }

    public void sleep(long millis) {
        try {
            Thread.sleep(millis);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }

    }
}

✅ ThreadLocal 사용법

• 값 저장: ThreadLocal.set(xxx)
• 값 조회: ThreadLocal.get()
• 값 제거: ThreadLocal.remove()

🚨주의
해당 쓰레드가 쓰레드 로컬을 모두 사용하고 나면 ThreadLocal.remove() 를 호출해서 쓰레드 로컬에 저장된 값을 제거해주어야 한다. 제거하는 구체적인 예제는 조금 뒤에 설명하겠다.

7️⃣ 쓰레드 로컬 동기화 - 개발

• FieldLogTrace 에서 발생했던 동시성 문제를 ThreadLocal로 해결해보자.
• TraceId traceIdHolder 필드를 쓰레드 로컬을 사용하도록 ThreadLocal<TraceId> traceIdHolder로변경하면 된다.
• 필드 대신에 쓰레드 로컬을 사용해서 데이터를 동기화하는 ThreadLocalLogTrace 를 새로 만들자.

package hello.advanced.trace.logtrace;

import hello.advanced.trace.TraceId;
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<TraceId> traceIdHolder = new ThreadLocal<>();

    @Override
    public TraceStatus begin(String message) {
        syncTraceId();
        TraceId traceId = traceIdHolder.get();
        Long startTime = System.currentTimeMillis();
        log.info("[{}] {}{}", traceId.getId(), addSpace(START_PREFIX, traceId.getLevel()), message);
        return new TraceStatus(traceId, startTime, 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() {
        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
        } 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();
    }
}

• ThreadLocalLogTraceTest

package hello.advanced.trace.logtrace;

import hello.advanced.trace.TraceStatus;
import lombok.extern.slf4j.Slf4j;
import org.junit.jupiter.api.Test;

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

• begin_end_level2() - 실행 결과

[3f902f0b] hello1
[3f902f0b] |-->hello2
[3f902f0b] |<--hello2 time=2ms
[3f902f0b] hello1 time=6ms

• begin_exception_level2() - 실행 결과

[3dd9e4f1] hello
[3dd9e4f1] |-->hello2
[3dd9e4f1] |<X-hello2 time=3ms ex=java.lang.IllegalStateException
[3dd9e4f1] hello time=8ms ex=java.lang.IllegalStateException

8️⃣ 쓰레드 로컬 동기화 - 적용

• LogTraceConfig

package hello.advanced;

import hello.advanced.trace.logtrace.FieldLogTrace;
import hello.advanced.trace.logtrace.LogTrace;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;

@Configuration
public class LogTraceConfig {

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

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

• 정상로그

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

• 예외 로그 실행

[c426fcfc] OrderController.request()
[c426fcfc] |-->OrderService.orderItem()
[c426fcfc] | |-->OrderRepository.save()
[c426fcfc] | |<X-OrderRepository.save() time=0ms
ex=java.lang.IllegalStateException: 예외 발생!
[c426fcfc] |<X-OrderService.orderItem() time=7ms
ex=java.lang.IllegalStateException: 예외 발생!
[c426fcfc] OrderController.request() time=7ms
ex=java.lang.IllegalStateException: 예외 발생!

🚨 동시 요청

• 1초 안에 2번 실행해보자.

  • http://localhost:8080/v3/request?itemId=hello
  • http://localhost:8080/v3/request?itemId=hello

• 실행결과

[nio-8080-exec-3] [52808e46] OrderController.request()
[nio-8080-exec-3] [52808e46] |-->OrderService.orderItem()
[nio-8080-exec-3] [52808e46] | |-->OrderRepository.save()
[nio-8080-exec-4] [4568423c] OrderController.request()
[nio-8080-exec-4] [4568423c] |-->OrderService.orderItem()
[nio-8080-exec-4] [4568423c] | |-->OrderRepository.save()
[nio-8080-exec-3] [52808e46] | |<--OrderRepository.save() time=1001ms
[nio-8080-exec-3] [52808e46] |<--OrderService.orderItem() time=1001ms
[nio-8080-exec-3] [52808e46] OrderController.request() time=1003ms
[nio-8080-exec-4] [4568423c] | |<--OrderRepository.save() time=1000ms
[nio-8080-exec-4] [4568423c] |<--OrderService.orderItem() time=1001ms
[nio-8080-exec-4] [4568423c] OrderController.request() time=1001ms

[nio-8080-exec-3]
[nio-8080-exec-3] [52808e46] OrderController.request()
[nio-8080-exec-3] [52808e46] |-->OrderService.orderItem()
[nio-8080-exec-3] [52808e46] | |-->OrderRepository.save()
[nio-8080-exec-3] [52808e46] | |<--OrderRepository.save() time=1001ms
[nio-8080-exec-3] [52808e46] |<--OrderService.orderItem() time=1001ms
[nio-8080-exec-3] [52808e46] OrderController.request() time=1003ms

[nio-8080-exec-4]
[nio-8080-exec-4] [4568423c] OrderController.request()
[nio-8080-exec-4] [4568423c] |-->OrderService.orderItem()
[nio-8080-exec-4] [4568423c] | |-->OrderRepository.save()
[nio-8080-exec-4] [4568423c] | |<--OrderRepository.save() time=1000ms
[nio-8080-exec-4] [4568423c] |<--OrderService.orderItem() time=1001ms
[nio-8080-exec-4] [4568423c] OrderController.request() time=1001ms

• 로그를 직접 분리해서 확인해보면 각각의 쓰레드 nio-8080-exec-3 , nio-8080-exec-4 별로 로그가 정확하게 나누어 진 것을 확인할 수 있다.

9️⃣ 쓰레드 로컬 - 주의 사항

 

• 사용자A 저장 요청

1. 사용자A가 저장 HTTP를 요청했다.
2. WAS는 쓰레드 풀에서 쓰레드를 하나 조회한다.
3. 쓰레드 thread-A 가 할당되었다.
4. thread-A 는 사용자A 의 데이터를 쓰레드 로컬에 저장한다.
5. 쓰레드 로컬의 thread-A 전용 보관소에 사용자A 데이터를 보관한다.

• 사용자A 저장 요청 종료

1. 사용자A의 HTTP 응답이 끝난다.
2. WAS는 사용이 끝난 thread-A 를 쓰레드 풀에 반환한다. 쓰레드를 생성하는 비용은 비싸기 때문에 쓰레
   드를 제거하지 않고, 보통 쓰레드 풀을 통해서 쓰레드를 재사용한다.
3. thread-A 는 쓰레드풀에 아직 살아있다. 따라서 쓰레드 로컬의 thread-A 전용 보관소에 사용자A 데이
   터도 함께 살아있게 된다

• 사용자B 조회 요청

1. 사용자B가 조회를 위한 새로운 HTTP 요청을 한다.
2. WAS는 쓰레드 풀에서 쓰레드를 하나 조회한다.
3. 쓰레드 thread-A 가 할당되었다. (물론 다른 쓰레드가 할당될 수 도 있다.)
4. 이번에는 조회하는 요청이다. thread-A 는 쓰레드 로컬에서 데이터를 조회한다.
5. 쓰레드 로컬은 thread-A 전용 보관소에 있는 사용자A 값을 반환한다.
6. 결과적으로 사용자A 값이 반환된다.
7. 사용자B는 사용자A의 정보를 조회하게 된다.

• 결과적으로 사용자B는 사용자A의 데이터를 확인하게 되는 심각한 문제가 발생하게 된다.
• 이런 문제를 예방하려면 사용자A의 요청이 끝날 때 쓰레드 로컬의 값을 ThreadLocal.remove() 를 통해서 꼭 제
  거해야 한다.