스프링 핵심 원리 - 고급편_쓰레드 로컬(필드 동기화 적용, 동시성 문제)

필드 동기화 - 적용

LogTrace 스프링 빈 등록

컴포넌트 스캔을 사용하지 않고 수동으로 빈을 등록하면 향후 구현체를 편하게 변경할 수 있는 장점이 있다.
이후 V2 -> V3로 복사하자.

LogTraceConfig

@Configuration
public class LogTraceConfig {

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

V2 -> V3 코드

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

    @GetMapping("/v3/request")
    public String request(@RequestParam("itemId") String itemId) {
        TraceStatus status = trace.begin("OrderController.request()");
        try {
            orderService.orderItem(itemId);
            trace.end(status);
            return "ok";
        } catch (Exception e) {
            trace.exception(status, e);
            throw e; // 꼭 예외를 다시 던져야 함
        }
    }
}

@Service
@RequiredArgsConstructor
public class OrderServiceV3 {
    private final OrderRepositoryV3 orderRepository;
    private final LogTrace trace;

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

@Repository
@RequiredArgsConstructor
public class OrderRepositoryV3 {
    private final LogTrace trace;

    public void save(String itemId) {
        TraceStatus status = trace.begin("OrderRepository.save()");
        try {
            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 (Exception e) {
            e.printStackTrace();
        }
    }
}

로그

• 정상

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

• 예외

[2692aac7] OrderController.request()
[2692aac7] |-->OrderService.orderItem()
[2692aac7] |   |-->OrderRepository.save()
[2692aac7] |   |<X-OrderRepository.save() time=0ms ex=java.lang.IllegalStateException: 예외 발생
[2692aac7] |<X-OrderService.orderItem() time=1ms ex=java.lang.IllegalStateException: 예외 발생
[2692aac7] OrderController.request() time=2ms 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: 예외 발생

필드 동기화 - 동시성 문제

앞서 만든 로그 추적기를 실제 사용하면 큰 문제가 있다.

http://localhost:8080/v3/request?itemId=hello 위 요청을 빠르게 두번 호출해보자.

• 로그

[nio-8080-exec-2] c.e.a.trace.logtrace.FiledLogTrace       : [9322d43b] OrderController.request()
[nio-8080-exec-2] c.e.a.trace.logtrace.FiledLogTrace       : [9322d43b] |-->OrderService.orderItem()
[nio-8080-exec-2] c.e.a.trace.logtrace.FiledLogTrace       : [9322d43b] |   |-->OrderRepository.save()
[nio-8080-exec-3] c.e.a.trace.logtrace.FiledLogTrace       : [9322d43b] |   |   |-->OrderController.request()
[nio-8080-exec-3] c.e.a.trace.logtrace.FiledLogTrace       : [9322d43b] |   |   |   |-->OrderService.orderItem()
[nio-8080-exec-3] c.e.a.trace.logtrace.FiledLogTrace       : [9322d43b] |   |   |   |   |-->OrderRepository.save()
[nio-8080-exec-2] c.e.a.trace.logtrace.FiledLogTrace       : [9322d43b] |   |<--OrderRepository.save() time=1004ms
[nio-8080-exec-2] c.e.a.trace.logtrace.FiledLogTrace       : [9322d43b] |<--OrderService.orderItem() time=1004ms
[nio-8080-exec-2] c.e.a.trace.logtrace.FiledLogTrace       : [9322d43b] OrderController.request() time=1005ms
[nio-8080-exec-3] c.e.a.trace.logtrace.FiledLogTrace       : [9322d43b] |   |   |   |   |<--OrderRepository.save() time=1004ms
[nio-8080-exec-3] c.e.a.trace.logtrace.FiledLogTrace       : [9322d43b] |   |   |   |<--OrderService.orderItem() time=1004ms
[nio-8080-exec-3] c.e.a.trace.logtrace.FiledLogTrace       : [9322d43b] |   |   |<--OrderController.request() time=1004ms

기대하는 결과는 아래와 같이 서로 다른 ID를 가진 로그가 순차적으로 출력되는 것을 기대했는데, 로그 레벨도 꼬이고, ID도 동일한 엉뚱깽뚱한 결과가 나온다.

[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

문제

위 문제는 동시성 문제다.
왜 발생하냐면 LogTrace는 현재 Spring Bean으로 등록되어 있는 객체로 싱글톤이다.
하나의 인스턴스에 여러 요청이 접근하니 당연히 문제가 발생한다.

@Slf4j
public class FiledLogTrace implements LogTrace {
    // 생략
    private TraceId traceIdHolder;
    // 이하 생략
}

LogTrace의 구현체인 FieldLogTrace는 현재 가장 중요한 private TraceId traceIdHolder를 필드 객체로 등록하여 클래스 전체에서 사용하고 있기 때문에 문제가 발생한다.

 

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