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

본 내용은 인프런 김영한T 스프링 DB 2편 - 데이터 접근 활용 기술 강의를 공부하고 정리한 내용입니다:)

⬜ 섹션2 쓰레드 로컬 - ThreadLocal

◼️ 필드 동기화 - 개발

앞서 로그 추적기를 만들면서 다음 로그를 출력할 때 트랜잭션ID와 level을 동기화 하는 문제가 있었다.
이 문제를 해결하기 위해 TraceId를 매번 파라미터로 넘기도록 구현했다.

모든 메서드에 TraceId 파라미터를 추가하지 않기 위해 traceIdHolder필드를 사용하도록 해보자.

public interface LogTrace {
    TraceStatus begin(String message);
    void end(TraceStatus status);
    void exception(TraceStatus status, Exception e);
}

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

    @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() {
        if (traceIdHolder == null) { // 최초 호출이면 TraceId를 새로 만든다.
            traceIdHolder = new TraceId();
        } else { // 직전 로그가 있으면 동기화, level 증가
            traceIdHolder = traceIdHolder.createNextId();
        }
    }

    private void releaseTraceId() {
        if (traceIdHolder.isFirstLevel()) {
            traceIdHolder = null; //destroy
        }
        else { // level을 하나 감소
            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를 수동으로 스프링 빈으로 등록하자.

package hello.advanced;

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

아래는 순서대로 로그추적기 v3를 적용한 repository,service,controller이다.

@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")) {
                throw new IllegalStateException("예외 발생!");
            }
            sleep(1000);
            trace.end(status);
        }catch (Exception e) {
            trace.exception(status, e);
            throw e;
        }
    }

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

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

@RestController
@RequiredArgsConstructor
public class OrderControllerV3 {
    private final OrderServiceV3 orderService;
    private final LogTrace trace;
    @GetMapping("/v3/request")
    public String request(String itemId) {
        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; //예외를 꼭 다시 던져주어야 한다.
        }
    }
}

◼️ 필드 동기화 - 동시성 문제

동시에 여러번 호출하면 심각한 동시성 문제를 볼 수 있다. 트랜잭션 ID도 동일하고 level도 뭔가 꼬였다.

뭔가 이상한 실행결과...

FieldLongTrace는 싱글톤 스프링 빈인데, 하나만 있는 인스턴스 FieldLogTrace의 traceIdHolder 필드를 여러 쓰레드가 동시에 접근하기때문에 문제가 발생한다.

◼️ 동시성 문제 - 예제 코드

동시성 문제를 단순화해서 알아보자.

@Slf4j
public class FieldService {
    private String nameStore;

    public String logic(String name) {
        log.info("저장 name={} -> nameStore={}", name, nameStore);
        nameStore = name; // 파라미터로 넘어온 name을 nameStore 필드에 저장
        sleep(1000); // 1 초 쉼
        log.info("조회 nameStore={}",nameStore);
        return nameStore;
    }
    private void sleep(int millis){
        try {
            Thread.sleep(millis);
        } catch (InterruptedException e){
            e.printStackTrace();
        }
    }
}

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

    @Test
    void field() {
        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(); // A실행
        sleep(2000); // 동시성 문제 발생X
//        sleep(100); // 동시성 문제 발생O
        threadB.start(); // B실행

        sleep(3000); // 메인 쓰레드 종료 대기
        log.info("main exit");
    }
    private void sleep(int millis){
        try {
            Thread.sleep(millis);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }
}

🔵순서대로 실행

실행결과

순서대로 실행하면 문제가 없다.

🔵동시성 문제 발생

이번에는 sleep(100)으로 바꿔 실행해보자. thread-A 작업이 끝나기전에 thread-B가 실행되기때문에, 저장은 문제가 없지만 조회에서 문제가 발생한다. 

동시 실행 결과

thread-B가 A저장 0.1초후 B값을 nameStore에 보관하기 때문에, 기존 userA값은 제거되고 userB 값이 저장된다. 그후 조회할때는 A에게도 userB가 반환된다.

🟢동시성 문제

• 여러 쓰레드가 동시에 같은 인스턴스 필드 값을 변경하면서 발생하는 문제
• 특히 스프링 빈처럼 싱글톤 객체 필드를 변경하며 사용할 때 이런 동시성 문제를 조심해야 한다.

◼️ ThreadLocal - 소개

🟢쓰레드 로컬

• 해당 쓰레드만 접근할 수 있는 특별한 저장소
• 각 쓰레드마다 별도의 내부 저장소 제공
• 따라서 같은 인스턴스의 쓰레드 로컬 필드에 접근해도 문제X
• 값저장 set(...), 조회 get(), 제거 remove()

쓰레드로컬을 사용해 쓰레드 동시성 문제를 해결 가능하다. :)

🔵쓰레드 로컬 코드 적용

@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();
    }
    private void sleep(int millis) {
        try {
            Thread.sleep(millis);
        }
        catch (InterruptedException e) {
            e.printStackTrace();
        }
    }
}

아까의동시성 문제가 났던 코드를 ThreadLocalService로 바꾸고 실행해보면 이제는 정상동작함을 확인 가능하다.

@Slf4j
public class ThreadLocalServiceTest {
    private ThreadLocalService service = new ThreadLocalService();
    // ...생략
}

실행 결과

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

필드 대신 쓰레드 로컬을 사용해서 데이터를 동기화하는 ThreadLocalTrace를 새로 만들자.

TraceId traceIdHolder→ ThreadLocal<TraceId> traceIdHolder 로 변경한다.

참고로, 쓰레드로컬을 모두 사용하면 꼭 ThreadLocal.remove()를 호출해서 쓰레드 로컬에 저장된 값을 제거해야 한다.

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

이제 스프링 빈으로 등록 후 실행해본다.

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

실행 결과. 1초에 여러번 찍어도 정상적으로 로그가 찍히고, traceId도 구분된다! :)

◼️ 쓰레드 로컬 - 주의사항

WAS(톰캣)처럼 쓰레드 풀을 사용하는 경우 쓰레드 로컬 값은 사용 후 꼭! 제거해주어야한다.

쓰레드 생성 비용은 비싸기 때문에 쓰레드 풀을 통해 쓰레드를 재사용한다. 이 때, 이전 해당 쓰레드를 사용했던 사용자의 값이 반환될 수 있기 때문에 이는 심각한 문제가 될 수 있다.

사용자B가 A와 같은 쓰레드를 사용할때, Thread.remove()를 하지않으면 현재 스레드가 반환된다.:)